TIKA-4742 -- refactor logging for beta-1

docs/modules/ROOT/pages/pipes/troubleshooting.adoc

@@ -62,6 +62,37 @@ pick them up automatically. The default `pipes-fork-server-default-log4j2.xml`
 writes to `SYSTEM_ERR`, so inheritance is what makes those records visible
 to your observability stack.
 
+=== Telling fork lines from parent lines
+
+Since the fork and parent share a single stdio stream, the bundled
+`pipes-fork-server-default-log4j2.xml` pattern adds two orthogonal markers
+so you can read the interleaved output:
+
+* `[fork]` -- present only on lines emitted by a forked `PipesServer`
+  JVM. Lines from the parent process (`PipesClient`, `AsyncProcessor`,
+  `ConnectionHandler`, `tika-server`, `tika-grpc`, etc.) do not carry
+  this tag. Different mechanism on each side: the fork has it injected
+  via the bundled pattern's literal `[fork]` token; the parent does
+  not include it in its own log4j2/logback patterns.
+
+* `pipesClientId=N` -- *the same value on both sides of a pair*. The
+  parent's `PipesClient #N` always connects to the fork running with
+  `-DpipesClientId=N`, so the same N enables correlation across the
+  process boundary. Use it to gather every log line about one
+  conversation, regardless of which side emitted them.
+
+A typical interleaved snippet:
+
+[source]
+----
+INFO  [main] 14:23:45,123 [fork] pipesClientId=0 o.a.t.p.c.server.PipesServer received SHUT_DOWN
+DEBUG [Thread-3] 14:23:45,124 o.a.t.p.c.async.AsyncProcessor pipesClientId=0, status=PARSE_SUCCESS
+----
+
+The first line is from inside fork 0 (`[fork]` present). The second is
+the parent talking *about* fork 0 (`[fork]` absent, but the same client
+id appears in the message body).
+
 If you don't want the pipes-server's output interleaved with your own --
 e.g. an embedded use case where the parent is producing its own structured
 stdout, or a test environment where you want a quieter console -- set the
@@ -112,6 +143,55 @@ When the watcher fires, the child exits via `System.exit`, which runs
 `AbstractExternalProcessParser`'s shutdown hook and cleans up any
 in-flight external subprocesses.
 
+== Log levels and sensitive data
+
+Tika Pipes treats `FetchKey` and `EmitKey` values as potentially sensitive --
+they typically contain file paths, URLs, object-store keys, or other identifiers
+that may be private to the data owner. The convention across pipes core and the
+bundled plugins is:
+
+[cols="1,3"]
+|===
+|Level |What is logged
+
+|`ERROR` / `WARN`
+|Failures, exceptions, and configuration problems. *Never* the literal
+ `fetchKey`/`emitKey` or any file content. When a failure refers to a
+ specific document, it is identified by the non-sensitive `FetchEmitTuple.id`
+ (e.g. `parse exception: id=abc-123`).
+
+|`INFO`
+|Lifecycle events -- server start/stop, plugin start/stop, mode banners,
+ restart events. Per-document or per-request lines have been demoted from
+ INFO to DEBUG so production logs stay quiet.
+
+|`DEBUG`
+|Per-document progress and aggregated counts (e.g. `pipesClientId=2,
+ status=PARSE_SUCCESS`, `successfully emitted N docs`). Safe to enable in
+ production for troubleshooting; correlation is by `FetchEmitTuple.id` only.
+
+|`TRACE`
+|Verbose per-fetch and per-emit detail including the literal
+ `fetchKey`/`emitKey` (URL, S3 key, blob path, etc.). Enable only when you
+ need to correlate a Tika log line back to a specific resource, and accept
+ that those keys will appear in the log destination.
+|===
+
+The fetcher and emitter SPIs (`Fetcher.fetch`, `Emitter.emit`,
+`StreamEmitter.emit`) receive the literal key but not the tuple id, so
+plugin code can only log the literal key. Keeping that at TRACE keeps it
+out of any log destination that is configured at DEBUG or higher.
+
+If you write your own fetcher or emitter plugin, please follow the same
+convention: literal keys at TRACE, everything else at DEBUG or above with
+no key in the message.
+
+NOTE: Exception messages thrown out of a fetcher may still include
+response-body bytes for HTTP-style fetchers (configurable via
+`maxErrMsgSize` on `HttpFetcherConfig`). Those bytes appear in whatever
+log catches the thrown exception. Lower `maxErrMsgSize` -- or set it to
+zero -- if your responses can contain sensitive data.
+
 == Configuration knobs reference
 
 [cols="2,3"]

tika-parsers/tika-parsers-extended/tika-parser-ocr-encode-module/src/main/java/org/apache/tika/parser/ocrencode/EncodeOCRParser.java

@@ -229,7 +229,7 @@ private void doEncode(
                 int processed = counter != null
                         ? counter.get()
                         : config.getMaxImagesToOcr();
-                LOG.info("Skipping OCR encode for image because "
+                LOG.debug("Skipping OCR encode for image because "
                                 + "the configured limit of {} images "
                                 + "has been reached ({} already processed)",
                         config.getMaxImagesToOcr(), processed);
@@ -288,7 +288,7 @@ private void encodeToBase64(
         xhtml.endElement(XHTML, "div", "div");
 
         long durationMs = (System.nanoTime() - startTime) / 1_000_000;
-        LOG.info("OCR encoding - input file size: {} bytes, "
+        LOG.debug("OCR encoding - input file size: {} bytes, "
                         + "output size: {} characters, "
                         + "time taken: {} ms",
                 fileSize, sink.totalChars(), durationMs);

tika-parsers/tika-parsers-ml/tika-parser-nlp-module/src/main/java/org/apache/tika/parser/ner/grobid/GrobidNERecogniser.java

@@ -74,7 +74,7 @@ public GrobidNERecogniser() {
             this.available = isServerAlive(restHostUrlStr);
 
         } catch (Exception e) {
-            LOG.info(e.getMessage(), e);
+            LOG.warn(e.getMessage(), e);
         }
     }
 
@@ -88,10 +88,10 @@ private static boolean isServerAlive(String restHostUrlStr) {
             if (responseCode == 200) {
                 available = true;
             } else {
-                LOG.info("Grobid Quantities REST Server is not running");
+                LOG.warn("Grobid Quantities REST Server is not running");
             }
         } catch (Exception e) {
-            LOG.info("Grobid Quantities REST Server is not running", e);
+            LOG.warn("Grobid Quantities REST Server is not running", e);
         }
 
         return available;
@@ -146,7 +146,7 @@ public JSONArray convertToJSONArray(JSONObject obj, String key) {
         try {
             jsonArray = (JSONArray) obj.get(key);
         } catch (Exception e) {
-            LOG.info(e.getMessage(), e);
+            LOG.warn(e.getMessage(), e);
         }
         return jsonArray;
     }
@@ -162,7 +162,7 @@ public JSONObject convertToJSONObject(String jsonString) {
         try {
             jsonObject = (JSONObject) parser.parse(jsonString);
         } catch (Exception e) {
-            LOG.info(e.getMessage(), e);
+            LOG.warn(e.getMessage(), e);
         }
         return jsonObject;
     }
@@ -261,7 +261,7 @@ public Map<String, Set<String>> recognise(String text) {
                 }
             }
         } catch (Exception e) {
-            LOG.info(e.getMessage(), e);
+            LOG.warn(e.getMessage(), e);
 
         }
         ENTITY_TYPES.clear();

tika-parsers/tika-parsers-ml/tika-parser-nlp-module/src/main/java/org/apache/tika/parser/ner/nltk/NLTKNERecogniser.java

@@ -79,7 +79,7 @@ public NLTKNERecogniser() {
             if (responseCode == 200) {
                 available = true;
             } else {
-                LOG.info("NLTKRest Server is not running");
+                LOG.debug("NLTKRest Server is not running");
             }
 
         } catch (Exception e) {

tika-parsers/tika-parsers-standard/tika-parsers-standard-modules/tika-parser-microsoft-module/src/main/java/org/apache/tika/detect/microsoft/POIFSContainerDetector.java

@@ -560,7 +560,7 @@ private Set<String> getTopLevelNames(TikaInputStream stream) throws IOException
         Path file = stream.getPath();
 
         if (file == null) {
-            LOG.warn("Stream does not support file access; skipping POIFS detection");
+            LOG.debug("Stream does not support file access; skipping POIFS detection");
             return Collections.emptySet();
         }
 

tika-parsers/tika-parsers-standard/tika-parsers-standard-modules/tika-parser-microsoft-module/src/main/java/org/apache/tika/parser/microsoft/libpst/LibPstParser.java

@@ -101,7 +101,8 @@ private void _parse(Path pst, ContentHandler contentHandler, Metadata metadata,
                 throw new TikaException("Timeout exception: " + fileProcessResult.getProcessTimeMillis());
             }
             if (fileProcessResult.getExitValue() != 0) {
-                LOGGER.warn("libpst bad exit value {}: {}", fileProcessResult.getExitValue(), fileProcessResult.getStderr());
+                LOGGER.warn("libpst bad exit value {}", fileProcessResult.getExitValue());
+                LOGGER.debug("libpst stderr: {}", fileProcessResult.getStderr());
                 throw new TikaException("Bad exit value: " + fileProcessResult.getExitValue());
             }
             xhtml.endDocument();

tika-parsers/tika-parsers-standard/tika-parsers-standard-modules/tika-parser-microsoft-module/src/main/java/org/apache/tika/parser/microsoft/msg/ExtendedMetadataExtractor.java

@@ -261,7 +261,7 @@ private static ClassID parseClassId(String s, Map<String, ClassID> knownClassIDs
         if (knownClassIDs.containsKey(s)) {
             return knownClassIDs.get(s);
         }
-        LOGGER.warn("Add '{}' to list of known property set IDs", s);
+        LOGGER.debug("Add '{}' to list of known property set IDs", s);
         ClassID classID = new ClassID(s);
         knownClassIDs.put(classID.toUUIDString(), classID);
         return classID;

tika-parsers/tika-parsers-standard/tika-parsers-standard-modules/tika-parser-microsoft-module/src/main/java/org/apache/tika/parser/microsoft/ooxml/TikaSheetXMLHandler.java

@@ -147,11 +147,8 @@ public void startElement(String uri, String localName, String qName,
                 String ref = attributes.getValue("ref");
                 if (ref != null) {
                     fIsOpen = true;
-                } else {
-                    if (formulasNotResults) {
-                        LOG.warn("shared formulas not yet supported!");
-                    }
                 }
+                // shared-formula reference without a `ref` attribute is not yet supported
             } else {
                 fIsOpen = true;
             }

tika-parsers/tika-parsers-standard/tika-parsers-standard-modules/tika-parser-miscoffice-module/src/main/java/org/apache/tika/parser/hwp/HwpTextExtractorV5.java

@@ -264,7 +264,7 @@ private void parseBodyText(FileHeader header, DirectoryNode root, XHTMLContentHa
                 parse(reader, xhtml);
 
             } else {
-                LOG.warn("Unknown Entry '{}'({})", entry.getName(), entry);
+                LOG.debug("Unknown Entry '{}'({})", entry.getName(), entry);
             }
         }
     }
@@ -309,7 +309,7 @@ private void parseViewText(FileHeader header, DirectoryNode root, XHTMLContentHa
                     IOUtils.closeQuietly(input);
                 }
             } else {
-                LOG.warn("unknown Entry '{}'({})", entry.getName(), entry);
+                LOG.debug("unknown Entry '{}'({})", entry.getName(), entry);
             }
         }
     }

tika-parsers/tika-parsers-standard/tika-parsers-standard-modules/tika-parser-ocr-module/src/main/java/org/apache/tika/parser/ocr/tess4j/ImageDeskew.java

@@ -18,14 +18,10 @@
 
 import java.awt.image.BufferedImage;
 
-import org.slf4j.Logger;
-import org.slf4j.LoggerFactory;
-
 /**
  * Copied and pasted from Tess4j (https://sourceforge.net/projects/tess4j/)
  */
 public class ImageDeskew {
-    private static final Logger LOG = LoggerFactory.getLogger(ImageDeskew.class);
 
     private final BufferedImage cImage;
     private final int cSteps = 200;
@@ -112,7 +108,8 @@ private void calc(int var1, int var2) {
             try {
                 this.cHMatrix[var6]++;
             } catch (Exception var9) {
-                LOG.warn("", var9);
+                // out-of-bounds increments are skipped intentionally;
+                // the Hough transform tolerates dropped pixels
             }
 
         }

tika-parsers/tika-parsers-standard/tika-parsers-standard-modules/tika-parser-ocr-module/src/main/java/org/apache/tika/parser/ocr/tess4j/ImageUtil.java

@@ -23,11 +23,7 @@
 import java.awt.image.BufferedImage;
 import java.awt.image.WritableRaster;
 
-import org.slf4j.Logger;
-import org.slf4j.LoggerFactory;
-
 public class ImageUtil {
-    private static final Logger LOG = LoggerFactory.getLogger(ImageUtil.class);
 
     public ImageUtil() {
     }
@@ -53,7 +49,8 @@ public static boolean isBlack(BufferedImage var0, int var1, int var2, int var3)
                 int var7 = var4 & 255;
                 var8 = (double) var5 * 0.299D + (double) var6 * 0.587D + (double) var7 * 0.114D;
             } catch (Exception var11) {
-                LOG.warn("", var11);
+                // pixel access out of bounds is benign here — the
+                // algorithm handles it via the default var8=0 path
             }
 
             return var8 < (double) var3;

tika-pipes/tika-httpclient-commons/src/main/java/org/apache/tika/client/HttpClientFactory.java

@@ -272,7 +272,7 @@ public HttpClient build() throws TikaConfigException {
             sslsf = new SSLConnectionSocketFactory(sslContext,
                     SSLConnectionSocketFactory.getDefaultHostnameVerifier());
         } else {
-            LOG.info("http client does not verify ssl at this point.  " +
+            LOG.warn("http client does not verify ssl at this point.  " +
                     "If you need that, please open a ticket.");
             TrustStrategy acceptingTrustStrategy = (cert, authType) -> true;
             try {
@@ -438,7 +438,7 @@ public boolean isRedirected(HttpRequest request, HttpResponse response,
                     return true;
                 }
                 if (!allowedHosts.isEmpty() && !allowedHosts.contains(uri.getHost())) {
-                    LOG.info("Not allowing external redirect. OriginalUrl={}," +
+                    LOG.warn("Not allowing external redirect. OriginalUrl={}," +
                             " RedirectLocation={}", request.getRequestLine().getUri(), location);
                     return false;
                 }

tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/PipesClient.java

@@ -382,7 +382,7 @@ private PipesResult waitForServer(FetchEmitTuple t, IntermediateResult intermedi
                         throw new IOException("Unexpected message type from server: " + msg.type());
                 }
             } catch (SocketTimeoutException e) {
-                LOG.info("clientId={}: Socket timeout exception while waiting for server", pipesClientId, e);
+                LOG.warn("clientId={}: Socket timeout exception while waiting for server", pipesClientId, e);
                 // Mark for restart - server is stuck on current request and needs to be restarted
                 serverManager.markServerForRestart();
                 closeConnection();

tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/async/AsyncProcessor.java

@@ -416,8 +416,7 @@ public Integer call() throws Exception {
                         long start = System.currentTimeMillis();
                         try {
                             result = pipesClient.process(t);
-                            //TODO -- drop this back to debug or even trace once we have stability in ci
-                            LOG.info("pipesClientId={}, status={}", pipesClient.getPipesClientId(), result.status());
+                            LOG.debug("pipesClientId={}, status={}", pipesClient.getPipesClientId(), result.status());
                         } catch (IOException e) {
                             LOG.warn("pipesClientId={} crash", pipesClient.getPipesClientId(), e);
                             result = PipesResults.UNSPECIFIED_CRASH;

tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/server/EmitHandler.java

@@ -107,10 +107,10 @@ private PipesResult emit(String taskId, EmitKey emitKey,
             emitter = emitterManager.getEmitter(emitKey.getEmitterId());
         } catch (org.apache.tika.pipes.api.emitter.EmitterNotFoundException e) {
             String noEmitterMsg = getNoEmitterMsg(taskId);
-            LOG.info(noEmitterMsg);
+            LOG.warn(noEmitterMsg);
             return new PipesResult(PipesResult.RESULT_STATUS.EMITTER_NOT_FOUND, noEmitterMsg);
         } catch (IOException | TikaException e) {
-            LOG.info("Couldn't initialize emitter for task id '" + taskId + "'", e);
+            LOG.warn("Couldn't initialize emitter for task id '" + taskId + "'", e);
             return new PipesResult(PipesResult.RESULT_STATUS.EMITTER_INITIALIZATION_EXCEPTION, ExceptionUtils.getStackTrace(e));
         }
         try {
@@ -124,7 +124,7 @@ private PipesResult emit(String taskId, EmitKey emitKey,
                 emitter.emit(emitKey.getEmitKey(), parseData.getMetadataList(), parseContext);
             }
         } catch (IOException e) {
-            LOG.info("emit exception", e);
+            LOG.warn("emit exception", e);
             String msg = ExceptionUtils.getStackTrace(e);
             //for now, we're hiding the parse exception if there was also an emit exception
             return new PipesResult(PipesResult.RESULT_STATUS.EMIT_EXCEPTION, msg);
@@ -134,7 +134,7 @@ private PipesResult emit(String taskId, EmitKey emitKey,
             try {
                 passbackFilter.filter(parseData.metadataList);
             } catch (TikaException e) {
-                LOG.info("problem filtering for pass back", e);
+                LOG.warn("problem filtering for pass back", e);
             }
             if (StringUtils.isBlank(parseExceptionStack)) {
                 return new PipesResult(PipesResult.RESULT_STATUS.EMIT_SUCCESS_PASSBACK, new EmitDataImpl(emitKey.getEmitKey(), parseData.metadataList));
@@ -250,7 +250,7 @@ private void filterMetadata(MetadataListAndEmbeddedBytes parseData, ParseContext
         try {
             parseData.filter(filter, parseContext);
         } catch (TikaException e) {
-            LOG.info("failed to filter metadata list", e);
+            LOG.warn("failed to filter metadata list", e);
         }
     }
 

tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/server/FetchHandler.java

@@ -60,10 +60,10 @@ private FetcherOrResult getFetcher(FetchEmitTuple t) {
             return new FetcherOrResult(fetcherManager.getFetcher(t.getFetchKey().getFetcherId()), null);
         } catch (IllegalArgumentException e) {
             String noFetcherMsg = getNoFetcherMsg(t.getFetchKey().getFetcherId());
-            LOG.info(noFetcherMsg);
+            LOG.warn(noFetcherMsg);
             return new FetcherOrResult(null, new PipesResult(PipesResult.RESULT_STATUS.FETCHER_NOT_FOUND, noFetcherMsg));
         } catch (IOException | TikaException e) {
-            LOG.info("Couldn't initialize fetcher for fetch id={}", t.getId(), e);
+            LOG.warn("Couldn't initialize fetcher for fetch id={}", t.getId(), e);
             return new FetcherOrResult(null, new PipesResult(PipesResult.RESULT_STATUS.FETCHER_INITIALIZATION_EXCEPTION,
                     ExceptionUtils.getStackTrace(e)));
         }