The code in AgentServer.java is responsible for controlling the agents executing actual tests. When created, AgentServers are passed a logFile to write their log output to. These files are usually called "agentServer.$ID.trace" where $ID is the id of the agent. The contents of these files can be important in troubleshooting issues with jtreg itself, especially when unusual error conditions cause the execution of jtreg testing to fail somehow, or when there are issues in the communication between jtreg and its agents.
Agents log to their log files with the log() method in AgentServer.java.
log() calls logWriter.printf(), where logWriter is an instance of PrintWriter initialized with
pw = new PrintWriter(new FileWriter(logFile));
According to the PrintWriter documentation, this way of constructing it leaves auto-flushing disabled by default. This in turn means that calls to printf() are NOT guaranteed to flush the output, but might instead buffer it for quite some time.
I've also observed this experimentally. When running a passing test, a normal agent.2.trace contains for example:
[2023-05-08 13:56:04,031] AgentServer[2]: Started
[2023-05-08 13:56:04,048] AgentServer[2]: Listening on port 35677
[2023-05-08 13:56:04,091] AgentServer[2]: Running
[2023-05-08 13:56:04,093] AgentServer[2]: Test.java: starting execution of Test
[2023-05-08 13:56:04,162] AgentServer[2]: Test.java: finished execution of Test
[2023-05-08 13:56:04,195] AgentServer[2]: Exiting
Now, if the test instead sleeps indefinitely, and we kill jtreg a few seconds into the sleeping, we want to see the following:
[2023-05-08 13:56:04,031] AgentServer[2]: Started
[2023-05-08 13:56:04,048] AgentServer[2]: Listening on port 35677
[2023-05-08 13:56:04,091] AgentServer[2]: Running
[2023-05-08 13:56:04,093] AgentServer[2]: Test.java: starting execution of Test
However, instead agent.2.trace is just empty.
I've built jtreg myself, added a "flush()" call, and run the above experiment again, and this time agent.2.trace does contain all the output logged up to that point as it should be.
So I'm proposing to add a "flush()" call to log() in AgentServer.java.
Agents log to their log files with the log() method in AgentServer.java.
log() calls logWriter.printf(), where logWriter is an instance of PrintWriter initialized with
pw = new PrintWriter(new FileWriter(logFile));
According to the PrintWriter documentation, this way of constructing it leaves auto-flushing disabled by default. This in turn means that calls to printf() are NOT guaranteed to flush the output, but might instead buffer it for quite some time.
I've also observed this experimentally. When running a passing test, a normal agent.2.trace contains for example:
[2023-05-08 13:56:04,031] AgentServer[2]: Started
[2023-05-08 13:56:04,048] AgentServer[2]: Listening on port 35677
[2023-05-08 13:56:04,091] AgentServer[2]: Running
[2023-05-08 13:56:04,093] AgentServer[2]: Test.java: starting execution of Test
[2023-05-08 13:56:04,162] AgentServer[2]: Test.java: finished execution of Test
[2023-05-08 13:56:04,195] AgentServer[2]: Exiting
Now, if the test instead sleeps indefinitely, and we kill jtreg a few seconds into the sleeping, we want to see the following:
[2023-05-08 13:56:04,031] AgentServer[2]: Started
[2023-05-08 13:56:04,048] AgentServer[2]: Listening on port 35677
[2023-05-08 13:56:04,091] AgentServer[2]: Running
[2023-05-08 13:56:04,093] AgentServer[2]: Test.java: starting execution of Test
However, instead agent.2.trace is just empty.
I've built jtreg myself, added a "flush()" call, and run the above experiment again, and this time agent.2.trace does contain all the output logged up to that point as it should be.
So I'm proposing to add a "flush()" call to log() in AgentServer.java.