From 66ce56b4eef4e40912a4fd3a0fd57d5bdaba770f Mon Sep 17 00:00:00 2001 From: tallison Date: Mon, 23 Mar 2026 16:08:20 -0400 Subject: [PATCH] improve logging levels --- .../pipes-fork-server-default-log4j2.xml | 2 +- .../apache/tika/async/cli/TikaAsyncCLI.java | 4 ++-- .../pipes/core/PerClientServerManager.java | 14 +++++++----- .../apache/tika/pipes/core/PipesClient.java | 4 ++-- .../tika/pipes/core/SharedServerManager.java | 4 ++-- .../pipes/core/server/ConnectionHandler.java | 11 +++++++++- .../tika/pipes/core/server/EmitHandler.java | 10 ++++----- .../tika/pipes/core/server/FetchHandler.java | 4 ++-- .../tika/pipes/core/server/ParseHandler.java | 22 +++++++++---------- .../tika/pipes/core/server/PipesServer.java | 18 ++++++++++++++- .../tika/pipes/core/server/PipesWorker.java | 4 ++-- .../pipes-fork-server-default-log4j2.xml | 2 +- 12 files changed, 64 insertions(+), 35 deletions(-) diff --git a/tika-core/src/main/resources/pipes-fork-server-default-log4j2.xml b/tika-core/src/main/resources/pipes-fork-server-default-log4j2.xml index 5f946e6e5c2..9e87d348068 100644 --- a/tika-core/src/main/resources/pipes-fork-server-default-log4j2.xml +++ b/tika-core/src/main/resources/pipes-fork-server-default-log4j2.xml @@ -17,7 +17,7 @@ specific language governing permissions and limitations under the License. --> - + pipesIteratorOpt = PipesIteratorManager.load(TikaPluginManager.load(tikaJsonConfig), tikaJsonConfig); if (pipesIteratorOpt.isEmpty()) { diff --git a/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/PerClientServerManager.java b/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/PerClientServerManager.java index a8cf40ba10a..722f1ba3629 100644 --- a/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/PerClientServerManager.java +++ b/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/PerClientServerManager.java @@ -116,7 +116,11 @@ public int handleCrashAndGetExitCode() { process.waitFor(1, TimeUnit.SECONDS); if (!process.isAlive()) { int exitValue = process.exitValue(); - LOG.warn("clientId={}: process exited with code {}", clientId, exitValue); + if (exitValue == 0) { + LOG.info("clientId={}: process exited cleanly", clientId); + } else { + LOG.warn("clientId={}: process exited with code {}", clientId, exitValue); + } return exitValue; } else { LOG.warn("clientId={}: process still running after crash", clientId); @@ -193,7 +197,7 @@ private void startServer() throws IOException, InterruptedException, TimeoutExce serverSocket.bind(new InetSocketAddress(InetAddress.getLoopbackAddress(), 0), 50); port = serverSocket.getLocalPort(); - LOG.info("clientId={}: starting server on port={}", clientId, port); + LOG.trace("clientId={}: starting server on port={}", clientId, port); tmpDir = Files.createTempDirectory("pipes-server-" + clientId + "-"); ProcessBuilder pb = new ProcessBuilder(getCommandline()); @@ -341,7 +345,7 @@ private String[] getCommandline() throws IOException { commandLine.add("-Djava.awt.headless=true"); } if (hasExitOnOOM) { - LOG.warn("I notice that you have a jdk setting to exit/crash on OOM. If you run heavy external processes " + + LOG.info("I notice that you have a jdk setting to exit/crash on OOM. If you run heavy external processes " + "like tesseract, this setting may result in orphaned processes which could be disastrous for performance."); } if (!hasLog4j) { @@ -355,7 +359,7 @@ private String[] getCommandline() throws IOException { commandLine.add(Integer.toString(port)); commandLine.add(tikaConfigPath.toAbsolutePath().toString()); - LOG.info("clientId={}: commandline: {}", clientId, commandLine); + LOG.debug("clientId={}: commandline: {}", clientId, commandLine); return commandLine.toArray(new String[0]); } @@ -365,7 +369,7 @@ private Path writeArgFile() throws IOException { String normalizedClasspath = classpath.replace("\\", "/"); String content = "-cp\n\"" + normalizedClasspath + "\"\n"; Files.writeString(argFile, content, StandardCharsets.UTF_8); - LOG.info("clientId={}: wrote argfile with classpath ({} chars) to {}, content starts with: {}", + LOG.debug("clientId={}: wrote argfile with classpath ({} chars) to {}, content starts with: {}", clientId, classpath.length(), argFile, content.substring(0, Math.min(100, content.length()))); return argFile; } diff --git a/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/PipesClient.java b/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/PipesClient.java index b65a0627b74..be1b1e60340 100644 --- a/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/PipesClient.java +++ b/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.warn("clientId={}: Socket timeout exception while waiting for server", pipesClientId, e); + LOG.info("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(); @@ -431,7 +431,7 @@ private PipesResult buildFatalResult(String id, EmitKey emitKey, PipesResult.RES private void waitForStartup() throws IOException { PipesMessage msg = PipesMessage.read(connectionTuple.input); if (msg.type() == PipesMessageType.READY) { - LOG.debug("clientId={}: server ready", pipesClientId); + LOG.info("clientId={}: server successfully started", pipesClientId); } else if (msg.type() == PipesMessageType.STARTUP_FAILED) { // Send ACK for startup failure PipesMessage.ack().write(connectionTuple.output); diff --git a/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/SharedServerManager.java b/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/SharedServerManager.java index e323dd160ef..a28148f684c 100644 --- a/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/SharedServerManager.java +++ b/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/SharedServerManager.java @@ -255,7 +255,7 @@ private void startServer() throws IOException, InterruptedException, TimeoutExce new SecureRandom().nextBytes(token); currentToken = token; - LOG.warn("\n\n" + + LOG.info("\n\n" + " __ __ ___ _ ___ \n" + " \\ \\ / / / _ \\ | | / _ \\ \n" + " \\ V / | | | | | | | | | |\n" + @@ -446,7 +446,7 @@ private String[] getCommandline() throws IOException { commandLine.add("-Djava.awt.headless=true"); } if (hasExitOnOOM) { - LOG.warn("ExitOnOutOfMemoryError/CrashOnOutOfMemoryError is set. In shared mode, " + + LOG.info("ExitOnOutOfMemoryError/CrashOnOutOfMemoryError is set. In shared mode, " + "an OOM will kill the shared server, affecting all clients."); } if (!hasLog4j) { diff --git a/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/server/ConnectionHandler.java b/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/server/ConnectionHandler.java index 8cf84ca064a..3162f0922a4 100644 --- a/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/server/ConnectionHandler.java +++ b/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/server/ConnectionHandler.java @@ -24,6 +24,7 @@ import java.io.IOException; import java.net.Socket; import java.net.SocketException; +import java.net.SocketTimeoutException; import java.time.Duration; import java.time.Instant; import java.util.Locale; @@ -133,7 +134,15 @@ private void mainLoop() { while (running) { try { - PipesMessage msg = PipesMessage.read(input); + PipesMessage msg; + try { + msg = PipesMessage.read(input); + } catch (SocketTimeoutException e) { + // Socket timeout while idle is the normal inactivity shutdown path. + LOG.info("handlerId={}: socket timeout while waiting for task, closing connection", + handlerId); + return; + } LOG.trace("handlerId={}: received message type={}", handlerId, msg.type()); switch (msg.type()) { diff --git a/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/server/EmitHandler.java b/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/server/EmitHandler.java index 78a21bfa23b..aeede973460 100644 --- a/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/server/EmitHandler.java +++ b/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.warn(noEmitterMsg); + LOG.info(noEmitterMsg); return new PipesResult(PipesResult.RESULT_STATUS.EMITTER_NOT_FOUND, noEmitterMsg); } catch (IOException | TikaException e) { - LOG.warn("Couldn't initialize emitter for task id '" + taskId + "'", e); + LOG.info("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.warn("emit exception", e); + LOG.info("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.warn("problem filtering for pass back", e); + LOG.info("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.warn("failed to filter metadata list", e); + LOG.info("failed to filter metadata list", e); } } diff --git a/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/server/FetchHandler.java b/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/server/FetchHandler.java index c14ee246562..915ba5b0578 100644 --- a/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/server/FetchHandler.java +++ b/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.warn(noFetcherMsg); + LOG.info(noFetcherMsg); return new FetcherOrResult(null, new PipesResult(PipesResult.RESULT_STATUS.FETCHER_NOT_FOUND, noFetcherMsg)); } catch (IOException | TikaException e) { - LOG.warn("Couldn't initialize fetcher for fetch id={}", t.getId(), e); + LOG.info("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))); } diff --git a/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/server/ParseHandler.java b/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/server/ParseHandler.java index cd02d997679..8916acbafe3 100644 --- a/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/server/ParseHandler.java +++ b/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/server/ParseHandler.java @@ -142,7 +142,7 @@ private void _preParse(FetchEmitTuple t, TikaInputStream tis, Metadata metadata, parseContext.set(SkipContainerDocumentDigest.class, SkipContainerDocumentDigest.INSTANCE); } catch (IOException e) { - LOG.warn("problem digesting: " + t.getId(), e); + LOG.info("problem digesting: " + t.getId(), e); } } // Signal to detectors that parsing will follow, so they can prepare @@ -154,7 +154,7 @@ private void _preParse(FetchEmitTuple t, TikaInputStream tis, Metadata metadata, EmbeddedDocumentUtil.normalizeMediaType(mt.toString())); metadata.set(TikaCoreProperties.CONTENT_TYPE_PARSER_OVERRIDE, mt.toString()); } catch (IOException e) { - LOG.warn("problem detecting: " + t.getId(), e); + LOG.info("problem detecting: " + t.getId(), e); } UnpackConfig unpackConfig = parseContext.get(UnpackConfig.class); if (unpackConfig != null && @@ -163,7 +163,7 @@ private void _preParse(FetchEmitTuple t, TikaInputStream tis, Metadata metadata, try (InputStream is = Files.newInputStream(tis.getPath())) { unpackHandler.add(0, metadata, is); } catch (IOException e) { - LOG.warn("problem reading source file into embedded document byte store", e); + LOG.info("problem reading source file into embedded document byte store", e); } } } @@ -201,14 +201,14 @@ public List parseRecursive(FetchEmitTuple fetchEmitTuple, try { recursiveParserWrapper.parse(stream, handler, metadata, parseContext); } catch (SAXException e) { - LOG.warn("sax problem:" + fetchEmitTuple.getId(), e); + LOG.info("sax problem:" + fetchEmitTuple.getId(), e); } catch (EncryptedDocumentException e) { - LOG.warn("encrypted document:" + fetchEmitTuple.getId(), e); + LOG.info("encrypted document:" + fetchEmitTuple.getId(), e); } catch (SecurityException e) { - LOG.warn("security exception:" + fetchEmitTuple.getId(), e); + LOG.info("security exception:" + fetchEmitTuple.getId(), e); throw e; } catch (Exception e) { - LOG.warn("parse exception: " + fetchEmitTuple.getId(), e); + LOG.info("parse exception: " + fetchEmitTuple.getId(), e); } finally { if (LOG.isTraceEnabled()) { LOG.trace("timer -- parse only time: {} ms", System.currentTimeMillis() - start); @@ -242,19 +242,19 @@ public List parseConcatenated(FetchEmitTuple fetchEmitTuple, autoDetectParser.parse(stream, handler, metadata, parseContext); } catch (SAXException e) { containerException = ExceptionUtils.getStackTrace(e); - LOG.warn("sax problem:" + fetchEmitTuple.getId(), e); + LOG.info("sax problem:" + fetchEmitTuple.getId(), e); if (WriteLimitReachedException.isWriteLimitReached(e)) { writeLimitReached = true; } } catch (EncryptedDocumentException e) { containerException = ExceptionUtils.getStackTrace(e); - LOG.warn("encrypted document:" + fetchEmitTuple.getId(), e); + LOG.info("encrypted document:" + fetchEmitTuple.getId(), e); } catch (SecurityException e) { - LOG.warn("security exception:" + fetchEmitTuple.getId(), e); + LOG.info("security exception:" + fetchEmitTuple.getId(), e); throw e; } catch (Exception e) { containerException = ExceptionUtils.getStackTrace(e); - LOG.warn("parse exception: " + fetchEmitTuple.getId(), e); + LOG.info("parse exception: " + fetchEmitTuple.getId(), e); } finally { metadata.add(TikaCoreProperties.TIKA_CONTENT, handler.toString()); metadata.set(TikaCoreProperties.TIKA_CONTENT_HANDLER_TYPE, diff --git a/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/server/PipesServer.java b/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/server/PipesServer.java index e2b9e3b7fad..dc214514be3 100644 --- a/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/server/PipesServer.java +++ b/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/server/PipesServer.java @@ -24,6 +24,7 @@ import java.net.InetAddress; import java.net.InetSocketAddress; import java.net.Socket; +import java.net.SocketTimeoutException; import java.nio.charset.StandardCharsets; import java.nio.file.Path; import java.nio.file.Paths; @@ -319,7 +320,22 @@ public void mainLoop() { //main loop try { while (true) { - PipesMessage msg = PipesMessage.read(input); + PipesMessage msg; + try { + msg = PipesMessage.read(input); + } catch (SocketTimeoutException e) { + // Socket timeout while idle is the normal inactivity shutdown path. + // Exit cleanly — PipesClient will restart the server if needed. + LOG.info("pipesClientId={}: socket timeout while waiting for task, shutting down", + pipesClientId); + try { + close(); + } catch (Exception ex) { + //swallow + } + System.exit(0); + return; // unreachable, but needed for compilation + } LOG.trace("pipesClientId={}: received message type={}", pipesClientId, msg.type()); switch (msg.type()) { diff --git a/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/server/PipesWorker.java b/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/server/PipesWorker.java index 141989b27db..136853e5d2c 100644 --- a/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/server/PipesWorker.java +++ b/tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/server/PipesWorker.java @@ -560,7 +560,7 @@ protected ParseDataOrPipesResult parseFromTuple() throws TikaException, Interrup try { localContext = setupParseContext(); } catch (IOException e) { - LOG.warn("fetcher initialization exception id={}", fetchEmitTuple.getId(), e); + LOG.info("fetcher initialization exception id={}", fetchEmitTuple.getId(), e); return new ParseDataOrPipesResult(null, new PipesResult(PipesResult.RESULT_STATUS.FETCHER_INITIALIZATION_EXCEPTION, ExceptionUtils.getStackTrace(e))); } @@ -587,7 +587,7 @@ protected ParseDataOrPipesResult parseFromTuple() throws TikaException, Interrup LOG.error("security exception id={}", fetchEmitTuple.getId(), e); throw e; } catch (TikaException | IOException e) { - LOG.warn("fetch exception id={}", fetchEmitTuple.getId(), e); + LOG.info("fetch exception id={}", fetchEmitTuple.getId(), e); return new ParseDataOrPipesResult(null, new PipesResult(PipesResult.RESULT_STATUS.UNSPECIFIED_CRASH, ExceptionUtils.getStackTrace(e))); } diff --git a/tika-pipes/tika-pipes-core/src/main/resources/pipes-fork-server-default-log4j2.xml b/tika-pipes/tika-pipes-core/src/main/resources/pipes-fork-server-default-log4j2.xml index 5f946e6e5c2..9e87d348068 100644 --- a/tika-pipes/tika-pipes-core/src/main/resources/pipes-fork-server-default-log4j2.xml +++ b/tika-pipes/tika-pipes-core/src/main/resources/pipes-fork-server-default-log4j2.xml @@ -17,7 +17,7 @@ specific language governing permissions and limitations under the License. --> - +