Skip to content

Commit d02dc13

Browse files
tballisontballison
authored
1 parent 1abcd65 commit d02dc13

6 files changed

Lines changed: 288 additions & 165 deletions

File tree

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

Lines changed: 78 additions & 54 deletions
Original file line numberDiff line numberDiff line change
@@ -33,19 +33,10 @@ ERROR clientId=2: Process exited with code 1 before connecting to socket
3333
ERROR Shared server process exited with code 1 before becoming ready
3434
----
3535

36-
For most failures (bad JVM args, missing classpath entry, OOM at boot), the
37-
parent logger additionally prints the tail of the child's stderr immediately
38-
after the exit-code line:
39-
40-
[source]
41-
----
42-
ERROR clientId=2: child stderr tail:
43-
Error: Could not find or load main class org.apache.tika.pipes.core.server.PipesServer
44-
----
45-
46-
For native crashes (segfault in a JNI parser, JVM bug), the JVM writes an
47-
`hs_err_pid<N>.log` file to the child's working directory. The parent logger
48-
will read and print that file too:
36+
For *native* JVM crashes (e.g. a segfault in a JNI parser), the JVM writes an
37+
`hs_err_pid<N>.log` file. We direct that via `-XX:ErrorFile=` into the
38+
manager's per-server temp directory, then read it into the parent's SLF4J
39+
logger before cleanup:
4940

5041
[source]
5142
----
@@ -57,51 +48,84 @@ ERROR clientId=2: JVM crash log hs_err_pid12345.log:
5748
...
5849
----
5950

60-
In short: read the *parent* application's log first. The diagnostics from the
61-
dead child are inlined there, so you don't have to find anything on disk.
51+
So for native crashes, read the parent application's log first -- the hs_err
52+
contents are inlined there.
6253

63-
== Keeping child log files for post-mortem analysis
54+
== Child JVM stdout/stderr
6455

65-
By default, each forked server's stdout, stderr, and any JVM crash logs are
66-
written into a per-server temp directory. The temp directory is cleaned up
67-
when the manager shuts the server down. If you need to keep those files
68-
around -- for example, to diff stderr across multiple failed restart attempts,
69-
or to ship crash logs to a support contact -- set the
70-
`tika.pipes.server.logDir` system property on the *parent* JVM:
56+
By default the child `PipesServer` JVM inherits its stdout and stderr from
57+
the parent. This is the 12-factor / container-friendly default: when Tika
58+
runs in Docker or Kubernetes, the pipes-server's log records flow through
59+
to the container's stdio stream where the runtime (Docker, containerd) and
60+
any log aggregator (fluentd, fluent-bit, Promtail, the K8s log API, etc.)
61+
pick them up automatically. The default `pipes-fork-server-default-log4j2.xml`
62+
writes to `SYSTEM_ERR`, so inheritance is what makes those records visible
63+
to your observability stack.
7164

72-
[source,bash]
73-
----
74-
java -Dtika.pipes.server.logDir=/var/log/tika-pipes-crashes \
75-
-jar your-app.jar ...
76-
----
65+
If you don't want the pipes-server's output interleaved with your own --
66+
e.g. an embedded use case where the parent is producing its own structured
67+
stdout, or a test environment where you want a quieter console -- set the
68+
system property `tika.pipes.server.stdio=discard` on the parent JVM:
7769

78-
When set, the manager copies the child's `server-stdout.log`,
79-
`server-stderr.log`, and any `hs_err_pid*.log` files to that directory on
80-
every abnormal exit, with a timestamp prefix:
81-
82-
[source]
70+
[source,bash]
8371
----
84-
/var/log/tika-pipes-crashes/
85-
1748307123456-server-stderr.log
86-
1748307123456-hs_err_pid12345.log
87-
1748307145001-server-stderr.log # later restart attempt
72+
java -Dtika.pipes.server.stdio=discard -jar your-app.jar ...
8873
----
8974

90-
The property is off by default. Leave it off in steady-state production; turn
91-
it on when you are actively debugging a recurring fork failure.
92-
93-
== What does *not* go to those files
94-
95-
Steady-state log output from the parser (every parse, every emitter, every
96-
embedded-document warning) does **not** go to `server-stderr.log`. It goes
97-
through SLF4J inside the child JVM and lands in whatever your `log4j2.xml` or
98-
`logback.xml` directs it to. The child's stderr is only useful for things the
99-
JVM writes before logging is wired up, or that bypass logging entirely:
100-
101-
* JVM startup errors (bad classpath, unrecognized flag, "could not find main
102-
class").
103-
* Uncaught throwables on the main thread that never reached an SLF4J logger.
104-
* Output from `System.err.println` calls (if any).
105-
106-
For native crash investigation, the JVM-generated `hs_err_pid<N>.log` is the
107-
primary artifact, and it is collected automatically as described above.
75+
With this set, the child's stdout and stderr are routed to the null sink
76+
and the pipes server's log records are silently dropped at the OS level.
77+
(Records written via SLF4J inside the child can still be captured by
78+
configuring `log4j2.xml` / `logback.xml` to write to your own file or
79+
network appender, independent of the stdio setting.)
80+
81+
=== Safety of the inherit default on Windows
82+
83+
Earlier versions of Tika hit a surefire hang on Windows when inheriting
84+
child stdio: a forked child held a duplicate of the parent JVM's stderr
85+
handle, and any reader upstream of the parent (a maven-surefire controller,
86+
typically) never saw EOF after the parent died -- the child kept the pipe
87+
open. That class of hang is now mitigated structurally: every child
88+
`PipesServer` watches its parent's process handle via
89+
`ProcessHandle.onExit()` (see <<parent-death-detection>>) and self-
90+
terminates within milliseconds of parent exit. The inherited handle is
91+
released essentially synchronously with the parent's death, and upstream
92+
readers see EOF promptly.
93+
94+
[#parent-death-detection]
95+
== Parent-death detection
96+
97+
The child `PipesServer` JVMs watch their parent's PID via
98+
`ProcessHandle.onExit()` and self-terminate within milliseconds if the
99+
parent dies. The parent passes its own PID via the
100+
`TIKA_PIPES_PARENT_PID` environment variable when spawning the child.
101+
102+
This matters because the parent (e.g. tika-server) can be killed in ways
103+
that skip its JVM shutdown hooks -- for instance,
104+
`Process.destroy()` on Windows is equivalent to `TerminateProcess`, which
105+
bypasses all hooks. Without parent-death detection, an orphaned PipesServer
106+
would only notice via TCP RST on its next socket read, and would not
107+
notice at all while busy in a parse, leaving it (and any external
108+
subprocess it had spawned, such as a tesseract OCR worker) running
109+
indefinitely.
110+
111+
When the watcher fires, the child exits via `System.exit`, which runs
112+
`AbstractExternalProcessParser`'s shutdown hook and cleans up any
113+
in-flight external subprocesses.
114+
115+
== Configuration knobs reference
116+
117+
[cols="2,3"]
118+
|===
119+
|System property / env var |Effect
120+
121+
|`tika.pipes.server.stdio` (system property)
122+
|`discard` suppresses child stdout/stderr at the OS level. Anything else
123+
(or unset) inherits the child's stdio from the parent JVM. Default: inherit.
124+
125+
|`TIKA_PIPES_PARENT_PID` (env var)
126+
|Set automatically by the parent manager when spawning a `PipesServer`
127+
child. The child uses it to watch its parent and self-terminate if the
128+
parent dies. Not normally set by users; if you launch `PipesServer`
129+
standalone (outside the normal manager flow) and leave it unset, the
130+
parent-watch is simply skipped.
131+
|===

‎tika-pipes/tika-pipes-core/src/main/java/org/apache/tika/pipes/core/PerClientServerManager.java‎

Lines changed: 42 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -34,6 +34,7 @@
3434
import org.slf4j.Logger;
3535
import org.slf4j.LoggerFactory;
3636

37+
import org.apache.tika.pipes.core.server.PipesServer;
3738
import org.apache.tika.utils.ProcessUtils;
3839

3940
/**
@@ -270,15 +271,33 @@ private void startServer() throws IOException, InterruptedException, TimeoutExce
270271

271272
tmpDir = Files.createTempDirectory("pipes-server-" + clientId + "-");
272273
ProcessBuilder pb = new ProcessBuilder(getCommandline());
273-
// Run the child in tmpDir so any hs_err_pid<N>.log JVM crash log lands
274-
// where surfaceCrashDiagnostics() looks for it. Redirect stdio to per-
275-
// server files instead of inheriting the parent JVM's handles -- on
276-
// Windows inheritIO() duplicates surefire's stderr handle into the
277-
// child, blocking the controller's pipe reader past parent exit and
278-
// hanging CI.
279-
pb.directory(tmpDir.toFile());
280-
pb.redirectOutput(ServerProcessIO.stdoutLog(tmpDir));
281-
pb.redirectError(ServerProcessIO.stderrLog(tmpDir));
274+
// Tell the child our PID so it can watch ProcessHandle.onExit() and
275+
// self-terminate promptly if we die. Without this, an orphan child
276+
// can only notice via socket-read timeout (default 60s) and can't
277+
// notice at all while it is mid-parse -- the leak that TIKA-4740
278+
// surfaced via @TempDir cleanup failures.
279+
pb.environment().put(PipesServer.PARENT_PID_ENV,
280+
Long.toString(ProcessHandle.current().pid()));
281+
// Default: inherit stdio so the pipes-server's log records show up
282+
// in the parent's stdio stream (the production case is Docker/K8s
283+
// where container stdio is picked up by log aggregators -- writing
284+
// to files in a container is anti-pattern). Set
285+
// -Dtika.pipes.server.stdio=discard on the parent to suppress.
286+
//
287+
// The Windows surefire hang that previously made inheritIO() risky
288+
// is mitigated by PipesServer.watchParentProcess(): when the parent
289+
// exits, the child detects it via ProcessHandle.onExit() within
290+
// milliseconds and System.exit()s, releasing its inherited stderr
291+
// handle so upstream pipe readers see EOF promptly.
292+
//
293+
// hs_err crash logs are pointed at tmpDir via -XX:ErrorFile in
294+
// getCommandline() and surfaced via SLF4J on abnormal exit.
295+
if (ServerProcessIO.inheritStdio()) {
296+
pb.inheritIO();
297+
} else {
298+
pb.redirectOutput(ProcessBuilder.Redirect.DISCARD);
299+
pb.redirectError(ProcessBuilder.Redirect.DISCARD);
300+
}
282301

283302
try {
284303
process = pb.start();
@@ -383,6 +402,7 @@ private String[] getCommandline() throws IOException {
383402
boolean hasExitOnOOM = false;
384403
boolean hasLog4j = false;
385404
boolean hasActiveProcessorCount = false;
405+
boolean hasErrorFile = false;
386406
String origGCString = null;
387407
String newGCLogString = null;
388408

@@ -402,12 +422,25 @@ private String[] getCommandline() throws IOException {
402422
if (arg.startsWith("-XX:ActiveProcessorCount=")) {
403423
hasActiveProcessorCount = true;
404424
}
425+
if (arg.startsWith("-XX:ErrorFile=")) {
426+
hasErrorFile = true;
427+
}
405428
if (arg.startsWith("-Xloggc:")) {
406429
origGCString = arg;
407430
newGCLogString = arg.replace("${pipesClientId}", "id-" + clientId);
408431
}
409432
}
410433

434+
// Direct native-crash dumps (hs_err_pid<N>.log) into tmpDir so
435+
// ServerProcessIO.surfaceCrashDiagnostics() can find and emit them on
436+
// abnormal exit. The child JVM inherits the parent's CWD (we do NOT
437+
// call pb.directory()), so without this the JVM would write hs_err
438+
// wherever the parent was launched -- typically lost.
439+
if (!hasErrorFile) {
440+
configArgs.add("-XX:ErrorFile=" + tmpDir.resolve("hs_err_pid%p.log")
441+
.toAbsolutePath());
442+
}
443+
411444
// If the user hasn't explicitly set -XX:ActiveProcessorCount, size each
412445
// forked JVM's view of CPUs to a fair slice of the host. Otherwise each
413446
// JVM defaults its GC, JIT, and common ForkJoinPool to "all cores", which

0 commit comments

Comments
 (0)