RFR(S): 8198655: test/lib/jdk/test/lib/apps/LingeredApp shouldn't inherit cout/cerr

Chris Plummer chris.plummer at oracle.com
Wed Mar 14 17:24:16 UTC 2018 

On 3/12/18 1:51 PM, Chris Plummer wrote:
> Hi Igor,
>
> On 3/12/18 1:26 PM, Igor Ignatyev wrote:
>>
>>
>>> On Mar 12, 2018, at 8:53 AM, Chris Plummer <chris.plummer at oracle.com 
>>> <mailto:chris.plummer at oracle.com>> wrote:
>>>
>>> On 3/11/18 7:52 PM, David Holmes wrote:
>>>> Hi Chris,
>>>>
>>>> On 10/03/2018 6:46 AM, Chris Plummer wrote:
>>>>> Hello,
>>>>>
>>>>> Please help review the following:
>>>>>
>>>>> https://bugs.openjdk.java.net/browse/JDK-8198655
>>>>> http://cr.openjdk.java.net/~cjplummer/8198655/webrev.00/webrev/
>>>>>
>>>>> In the end there were two issues. The first was that the 
>>>>> pb.redirectError() call was redirecting the LingeredApp's stderr 
>>>>> to the console, which we don't want. The second was that nothing 
>>>>> was capturing the LingeredApp's output and sending it to the 
>>>>> driver app's output (jtr file). These changes make all the 
>>>>> LingeredApp's output end up in the jtr file.
>>>>
>>>> It isn't clear to me how the interleaving of the two streams by the 
>>>> two threads is handled in the copy routine. Are we guaranteed to 
>>>> get complete lines of output from each stream before writing to 
>>>> System.out?
>>> Hi David,
>>>
>>> I'm hoping Igor will chime in here, since this is just cloned from 
>>> some closed code he wrote, and he recommended this fix. Perhaps we 
>>> are just doing something a bit non standard here. When spawning a 
>>> separate test process, don't we normally just dump stdout and stderr 
>>> separately via OutputAnalyzer.reportDiagnosticSummary() after the 
>>> test completes, and then only if there is an error. I'm not sure why 
>>> Igor felt LingeredApp tests should be handled differently.
>>
>> I recommended this fix as one of possibilities and never claimed it's 
>> the best solution ;)  I don't know much of LingeredApp tests, so I 
>> just suggested the patch which only solves the problem I noticed 
>> (LingeredApp's cerr being printed into jtreg agent's cerr).
> If by "into jtreg agent's cerr" you are referring to the presence of 
> JDWP "ERROR" messages in the jtreg console, that is fixed simply by 
> removing the following:
>
>    pb.redirectError(ProcessBuilder.Redirect.INHERIT);
>
> And that is already part of this fix. But it actually makes the ERROR 
> messages completely disappear. The copy() part of the fix makes all 
> the LingeredApp output appear in the .jtr file (including the JDWP 
> "ERROR" messages).
>> OutputAnalyzer might not fit the use case of LingeredApp b/c it 
>> blocks till the process is finished. again, I don't know much about 
>> LingeredApp itself and the tests which use it.
> My point was that other jtreg tests that use ProcessBuilder and 
> OutputAnalyzer don't print out anything from the spawned process/app 
> until it is done, and even then usually only if there was a test 
> failure. Why is there a need here to print out messages as they are 
> generated.
I played around with OutputAnalyzer a bit to see if we can do something 
more like are other uses of ProcessBuilder. Unfortunately it did not work:

         appProcess = pb.start();
         OutputAnalyzer output = new OutputAnalyzer(appProcess);

The problem is that OutputAnalyzer(appProcess) will not return until 
appProcess exits, but the test requires interaction with appProcess 
before it will exit, and this is done from the same thread. So unless 
appProcess aborts unexpectedly, we block in OutputAnalyzer(appProcess).

So next I tried getting the InputGobbler output by calling 
LingeredApp.getOutput(). This was missing the stderr output. So I 
created a separate gobbler for LingeredApp.getErrorStream(). It only 
contained the following:

  [Debugger failed to attach: ERROR: Peer not allowed to connect: 
127.0.0.1, ]------------

Yet the console (without disabling the 
pb.redirectError(ProcessBuilder.Redirect.INHERIT) code) normally would 
contain:

[2018-03-14 09:49:38,354] Agent[1]: stderr: Debugger failed to attach: 
ERROR: Peer not allowed to connect: 127.0.0.1
[2018-03-14 09:49:38,355] Agent[1]: stderr:
[2018-03-14 09:49:39,075] Agent[1]: stderr: Error in allow option: 
'127.0.0.1;192.168.0.0/24'
[2018-03-14 09:49:39,075] Agent[1]: stderr: ERROR: transport error 103: 
invalid IP address in allow option
[2018-03-14 09:49:39,075] Agent[1]: stderr: ERROR: JDWP Transport 
dt_socket failed to initialize, TRANSPORT_INIT(510)
[2018-03-14 09:49:39,075] Agent[1]: stderr: JDWP exit error 
AGENT_ERROR_TRANSPORT_INIT(197): No transports initialized [:732]
[2018-03-14 09:49:40,064] Agent[1]: stderr: ERROR: JDWP option syntax 
error: 
-agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=*:50103,allow=
[2018-03-14 09:49:41,289] Agent[1]: stderr: Error in allow option: 
'*+allow=127.0.0.1'
[2018-03-14 09:49:41,289] Agent[1]: stderr: ERROR: transport error 103: 
allow option '*' cannot be expanded
[2018-03-14 09:49:41,289] Agent[1]: stderr: ERROR: JDWP Transport 
dt_socket failed to initialize, TRANSPORT_INIT(510)
[2018-03-14 09:49:41,289] Agent[1]: stderr: JDWP exit error 
AGENT_ERROR_TRANSPORT_INIT(197): No transports initialized [:732]
[2018-03-14 09:49:42,418] Agent[1]: stderr: Error in allow option: 
'allow=127.0.0.1+*'
[2018-03-14 09:49:42,418] Agent[1]: stderr: ERROR: transport error 103: 
invalid IP address in allow option
[2018-03-14 09:49:42,418] Agent[1]: stderr: ERROR: JDWP Transport 
dt_socket failed to initialize, TRANSPORT_INIT(510)
[2018-03-14 09:49:42,418] Agent[1]: stderr: JDWP exit error 
AGENT_ERROR_TRANSPORT_INIT(197): No transports initialized [:732]

Just to summarize, if I don't disable 
pb.redirectError(ProcessBuilder.Redirect.INHERIT), all the above appears 
in the console. If I disable it, none of the above is in the console. It 
is just lost. If I disable and try to capture it from 
LingeredApp.getErrorStream() using an InputGobller, I only get the first 
ERROR, and the rest seem to be lost. (note the copy() approach in the 
original fix does capture all the ERROR messages).

I looked a bit closer at what InputGobbler does vs Igor's copy() 
approach. They are both very similar in that they spawn a separate 
thread to read from the InputStream. The difference is the InputGobbler 
uses BufferedReader.readline() whereas Igor's copy() directly uses 
InputStream.read(). So it seems the InputGobbler buffering is preventing 
us from seeing all the stderr output.

So one conclusion is that there probably is not much point in having two 
approaches to getting the LingeredApp's output. I think we should just 
create an InputGobbler for both stdout and stderr (currently we only 
created one for stdout), and then fix the buffering issue with 
InputGobbler on stderr. That still leaves the question of whether we 
should always dump stdout and stderr. I think that should be left to the 
test to decide, and probably only done if there is an error.

Chris

>>
>> answering to David's question, copy routine handles interleaving of 
>> two streams similarly to printf routine, it does not do that at all. 
>> we are writing to System.out as we read data, the only guarantee we 
>> have is all the bytes we read into buffer will be written together 
>> (which might mean 1 byte at a time), no guarantees about lines. the 
>> behavior is pretty much the same as you expect to get from an 
>> interactive shell w/ both cout and cerr are being printed on the 
>> console.
> Not quite. If a single threaded app is sending to both System.out and 
> System.err (and/or stdout and stderr) and does something to ensure 
> flushing after each print or each line, then the output should appear 
> cleanly in the order executed. By having two different threads read 
> these two streams, order might be changed, and possibly even 
> interleaved within lines.
>
> cheers,
>
> Chris
>>
>> Thanks,
>> -- Igor
>>>
>>> thanks,
>>>
>>> Chris
>>>>
>>>> Thanks,
>>>> David
>>>> -----
>>>>
>>>>> Tested by running all tests that use LingeredApp.
>>>>>
>>>>> thanks,
>>>>>
>>>>> Chris
>>
>
>

More information about the serviceability-dev mailing list