TIKA-4742 -- refactor logging for beta-1 (#2844)

Author: tballison

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-core/src/main/resources/pipes-fork-server-default-log4j2.xml

@@ -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-extended/tika-parser-ocr-encode-module/src/main/java/org/apache/tika/parser/ocrencode/EncodeOCRParser.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/grobid/GrobidNERecogniser.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-ml/tika-parser-nlp-module/src/main/java/org/apache/tika/parser/ner/nltk/NLTKNERecogniser.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/detect/microsoft/POIFSContainerDetector.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/libpst/LibPstParser.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/msg/ExtendedMetadataExtractor.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-microsoft-module/src/main/java/org/apache/tika/parser/microsoft/ooxml/TikaSheetXMLHandler.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);
             }
         }
     }