View Javadoc
1   package org.apache.maven.plugin.surefire.booterclient.output;
2   
3   /*
4    * Licensed to the Apache Software Foundation (ASF) under one
5    * or more contributor license agreements.  See the NOTICE file
6    * distributed with this work for additional information
7    * regarding copyright ownership.  The ASF licenses this file
8    * to you under the Apache License, Version 2.0 (the
9    * "License"); you may not use this file except in compliance
10   * with the License.  You may obtain a copy of the License at
11   *
12   *     http://www.apache.org/licenses/LICENSE-2.0
13   *
14   * Unless required by applicable law or agreed to in writing,
15   * software distributed under the License is distributed on an
16   * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
17   * KIND, either express or implied.  See the License for the
18   * specific language governing permissions and limitations
19   * under the License.
20   */
21  
22  import org.apache.maven.plugin.surefire.booterclient.lazytestprovider.NotifiableTestStream;
23  import org.apache.maven.plugin.surefire.log.api.ConsoleLogger;
24  import org.apache.maven.plugin.surefire.report.DefaultReporterFactory;
25  import org.apache.maven.shared.utils.cli.StreamConsumer;
26  import org.apache.maven.surefire.report.ConsoleOutputReceiver;
27  import org.apache.maven.surefire.report.ReportEntry;
28  import org.apache.maven.surefire.report.RunListener;
29  import org.apache.maven.surefire.report.StackTraceWriter;
30  import org.apache.maven.surefire.report.TestSetReportEntry;
31  
32  import java.io.BufferedReader;
33  import java.io.File;
34  import java.io.IOException;
35  import java.io.StringReader;
36  import java.nio.ByteBuffer;
37  import java.util.Collections;
38  import java.util.Map;
39  import java.util.Queue;
40  import java.util.Set;
41  import java.util.StringTokenizer;
42  import java.util.TreeSet;
43  import java.util.concurrent.ConcurrentHashMap;
44  import java.util.concurrent.ConcurrentLinkedQueue;
45  import java.util.concurrent.atomic.AtomicBoolean;
46  import java.util.concurrent.atomic.AtomicLong;
47  
48  import static java.lang.Integer.decode;
49  import static java.lang.System.currentTimeMillis;
50  import static java.util.Collections.unmodifiableMap;
51  import static org.apache.maven.surefire.booter.ForkingRunListener.BOOTERCODE_BYE;
52  import static org.apache.maven.surefire.booter.ForkingRunListener.BOOTERCODE_CONSOLE;
53  import static org.apache.maven.surefire.booter.ForkingRunListener.BOOTERCODE_DEBUG;
54  import static org.apache.maven.surefire.booter.ForkingRunListener.BOOTERCODE_ERROR;
55  import static org.apache.maven.surefire.booter.ForkingRunListener.BOOTERCODE_NEXT_TEST;
56  import static org.apache.maven.surefire.booter.ForkingRunListener.BOOTERCODE_STDERR;
57  import static org.apache.maven.surefire.booter.ForkingRunListener.BOOTERCODE_STDOUT;
58  import static org.apache.maven.surefire.booter.ForkingRunListener.BOOTERCODE_STOP_ON_NEXT_TEST;
59  import static org.apache.maven.surefire.booter.ForkingRunListener.BOOTERCODE_SYSPROPS;
60  import static org.apache.maven.surefire.booter.ForkingRunListener.BOOTERCODE_TESTSET_COMPLETED;
61  import static org.apache.maven.surefire.booter.ForkingRunListener.BOOTERCODE_TESTSET_STARTING;
62  import static org.apache.maven.surefire.booter.ForkingRunListener.BOOTERCODE_TEST_ASSUMPTIONFAILURE;
63  import static org.apache.maven.surefire.booter.ForkingRunListener.BOOTERCODE_TEST_ERROR;
64  import static org.apache.maven.surefire.booter.ForkingRunListener.BOOTERCODE_TEST_FAILED;
65  import static org.apache.maven.surefire.booter.ForkingRunListener.BOOTERCODE_TEST_SKIPPED;
66  import static org.apache.maven.surefire.booter.ForkingRunListener.BOOTERCODE_TEST_STARTING;
67  import static org.apache.maven.surefire.booter.ForkingRunListener.BOOTERCODE_TEST_SUCCEEDED;
68  import static org.apache.maven.surefire.booter.ForkingRunListener.BOOTERCODE_WARNING;
69  import static org.apache.maven.surefire.booter.Shutdown.KILL;
70  import static org.apache.maven.surefire.report.CategorizedReportEntry.reportEntry;
71  import static org.apache.maven.surefire.util.internal.StringUtils.isNotBlank;
72  import static org.apache.maven.surefire.util.internal.StringUtils.unescapeBytes;
73  import static org.apache.maven.surefire.util.internal.StringUtils.unescapeString;
74  
75  // todo move to the same package with ForkStarter
76  
77  /**
78   * Knows how to reconstruct *all* the state transmitted over stdout by the forked process.
79   *
80   * @author Kristian Rosenvold
81   */
82  public class ForkClient
83       implements StreamConsumer
84  {
85      private static final String PRINTABLE_JVM_NATIVE_STREAM = "Listening for transport dt_socket at address:";
86      private static final long START_TIME_ZERO = 0L;
87      private static final long START_TIME_NEGATIVE_TIMEOUT = -1L;
88  
89      private final DefaultReporterFactory defaultReporterFactory;
90  
91      private final Map<String, String> testVmSystemProperties = new ConcurrentHashMap<String, String>();
92  
93      private final NotifiableTestStream notifiableTestStream;
94  
95      private final Queue<String> testsInProgress = new ConcurrentLinkedQueue<String>();
96  
97      /**
98       * {@code testSetStartedAt} is set to non-zero after received
99       * {@link org.apache.maven.surefire.booter.ForkingRunListener#BOOTERCODE_TESTSET_STARTING test-set}.
100      */
101     private final AtomicLong testSetStartedAt = new AtomicLong( START_TIME_ZERO );
102 
103     private final ConsoleLogger log;
104 
105     private final boolean debug;
106 
107     /**
108      * prevents from printing same warning
109      */
110     private final AtomicBoolean printedErrorStream;
111 
112     /**
113      * Used by single Thread started by {@link ThreadedStreamConsumer} and therefore does not need to be volatile.
114      */
115     private RunListener testSetReporter;
116 
117     /**
118      * Written by one Thread and read by another: Main Thread and ForkStarter's Thread.
119      */
120     private volatile boolean saidGoodBye;
121 
122     private volatile StackTraceWriter errorInFork;
123 
124     private volatile int forkNumber;
125 
126     public ForkClient( DefaultReporterFactory defaultReporterFactory, NotifiableTestStream notifiableTestStream,
127                        ConsoleLogger log, boolean debug, AtomicBoolean printedErrorStream )
128     {
129         this.defaultReporterFactory = defaultReporterFactory;
130         this.notifiableTestStream = notifiableTestStream;
131         this.log = log;
132         this.debug = debug;
133         this.printedErrorStream = printedErrorStream;
134     }
135 
136     protected void stopOnNextTest()
137     {
138     }
139 
140     public void kill()
141     {
142         if ( !saidGoodBye )
143         {
144             notifiableTestStream.shutdown( KILL );
145         }
146     }
147 
148     /**
149      * Called in concurrent Thread.
150      * Will shutdown if timeout was reached.
151      *
152      * @param currentTimeMillis    current time in millis seconds
153      * @param forkedProcessTimeoutInSeconds timeout in seconds given by MOJO
154      */
155     public final void tryToTimeout( long currentTimeMillis, int forkedProcessTimeoutInSeconds )
156     {
157         if ( forkedProcessTimeoutInSeconds > 0 )
158         {
159             final long forkedProcessTimeoutInMillis = 1000 * forkedProcessTimeoutInSeconds;
160             final long startedAt = testSetStartedAt.get();
161             if ( startedAt > START_TIME_ZERO && currentTimeMillis - startedAt >= forkedProcessTimeoutInMillis )
162             {
163                 testSetStartedAt.set( START_TIME_NEGATIVE_TIMEOUT );
164                 notifiableTestStream.shutdown( KILL );
165             }
166         }
167     }
168 
169     public final DefaultReporterFactory getDefaultReporterFactory()
170     {
171         return defaultReporterFactory;
172     }
173 
174     @Override
175     public final void consumeLine( String s )
176     {
177         if ( isNotBlank( s ) )
178         {
179             processLine( s );
180         }
181     }
182 
183     private void setCurrentStartTime()
184     {
185         if ( testSetStartedAt.get() == START_TIME_ZERO ) // JIT can optimize <= no JNI call
186         {
187             // Not necessary to call JNI library library #currentTimeMillis
188             // which may waste 10 - 30 machine cycles in callback. Callbacks should be fast.
189             testSetStartedAt.compareAndSet( START_TIME_ZERO, currentTimeMillis() );
190         }
191     }
192 
193     public final boolean hadTimeout()
194     {
195         return testSetStartedAt.get() == START_TIME_NEGATIVE_TIMEOUT;
196     }
197 
198     private RunListener getTestSetReporter()
199     {
200         if ( testSetReporter == null )
201         {
202             testSetReporter = defaultReporterFactory.createReporter();
203         }
204         return testSetReporter;
205     }
206 
207     private void processLine( String event )
208     {
209         final OperationalData op;
210         try
211         {
212             op = new OperationalData( event );
213         }
214         catch ( RuntimeException e )
215         {
216             logStreamWarning( e, event );
217             return;
218         }
219         final String remaining = op.getData();
220         switch ( op.getOperationId() )
221         {
222             case BOOTERCODE_TESTSET_STARTING:
223                 getTestSetReporter().testSetStarting( createReportEntry( remaining ) );
224                 setCurrentStartTime();
225                 break;
226             case BOOTERCODE_TESTSET_COMPLETED:
227                 testsInProgress.clear();
228 
229                 getTestSetReporter().testSetCompleted( createReportEntry( remaining, testVmSystemProperties ) );
230                 break;
231             case BOOTERCODE_TEST_STARTING:
232                 ReportEntry reportEntry = createReportEntry( remaining );
233                 testsInProgress.offer( reportEntry.getSourceName() );
234 
235                 getTestSetReporter().testStarting( createReportEntry( remaining ) );
236                 break;
237             case BOOTERCODE_TEST_SUCCEEDED:
238                 reportEntry = createReportEntry( remaining );
239                 testsInProgress.remove( reportEntry.getSourceName() );
240 
241                 getTestSetReporter().testSucceeded( createReportEntry( remaining ) );
242                 break;
243             case BOOTERCODE_TEST_FAILED:
244                 reportEntry = createReportEntry( remaining );
245                 testsInProgress.remove( reportEntry.getSourceName() );
246 
247                 getTestSetReporter().testFailed( createReportEntry( remaining ) );
248                 break;
249             case BOOTERCODE_TEST_SKIPPED:
250                 reportEntry = createReportEntry( remaining );
251                 testsInProgress.remove( reportEntry.getSourceName() );
252 
253                 getTestSetReporter().testSkipped( createReportEntry( remaining ) );
254                 break;
255             case BOOTERCODE_TEST_ERROR:
256                 reportEntry = createReportEntry( remaining );
257                 testsInProgress.remove( reportEntry.getSourceName() );
258 
259                 getTestSetReporter().testError( createReportEntry( remaining ) );
260                 break;
261             case BOOTERCODE_TEST_ASSUMPTIONFAILURE:
262                 reportEntry = createReportEntry( remaining );
263                 testsInProgress.remove( reportEntry.getSourceName() );
264 
265                 getTestSetReporter().testAssumptionFailure( createReportEntry( remaining ) );
266                 break;
267             case BOOTERCODE_SYSPROPS:
268                 int keyEnd = remaining.indexOf( "," );
269                 StringBuilder key = new StringBuilder();
270                 StringBuilder value = new StringBuilder();
271                 unescapeString( key, remaining.substring( 0, keyEnd ) );
272                 unescapeString( value, remaining.substring( keyEnd + 1 ) );
273                 testVmSystemProperties.put( key.toString(), value.toString() );
274                 break;
275             case BOOTERCODE_STDOUT:
276                 writeTestOutput( remaining, true );
277                 break;
278             case BOOTERCODE_STDERR:
279                 writeTestOutput( remaining, false );
280                 break;
281             case BOOTERCODE_CONSOLE:
282                 getOrCreateConsoleLogger()
283                         .info( createConsoleMessage( remaining ) );
284                 break;
285             case BOOTERCODE_NEXT_TEST:
286                 notifiableTestStream.provideNewTest();
287                 break;
288             case BOOTERCODE_ERROR:
289                 errorInFork = deserializeStackTraceWriter( new StringTokenizer( remaining, "," ) );
290                 break;
291             case BOOTERCODE_BYE:
292                 saidGoodBye = true;
293                 notifiableTestStream.acknowledgeByeEventReceived();
294                 break;
295             case BOOTERCODE_STOP_ON_NEXT_TEST:
296                 stopOnNextTest();
297                 break;
298             case BOOTERCODE_DEBUG:
299                 getOrCreateConsoleLogger()
300                         .debug( createConsoleMessage( remaining ) );
301                 break;
302             case BOOTERCODE_WARNING:
303                 getOrCreateConsoleLogger()
304                         .warning( createConsoleMessage( remaining ) );
305                 break;
306             default:
307                 logStreamWarning( event );
308         }
309     }
310 
311     private void logStreamWarning( String event )
312     {
313         logStreamWarning( null, event );
314     }
315 
316     private void logStreamWarning( Throwable e, String event )
317     {
318         if ( event == null || !event.contains( PRINTABLE_JVM_NATIVE_STREAM ) )
319         {
320             String msg = "Corrupted STDOUT by directly writing to native stream in forked JVM " + forkNumber + ".";
321 
322             InPluginProcessDumpSingleton util = InPluginProcessDumpSingleton.getSingleton();
323             File dump =
324                     e == null
325                     ? util.dumpText( msg + " Stream '" + event + "'.", defaultReporterFactory, forkNumber )
326                     : util.dumpException( e, msg + " Stream '" + event + "'.", defaultReporterFactory, forkNumber );
327 
328             if ( printedErrorStream.compareAndSet( false, true ) )
329             {
330                 log.warning( msg + " See FAQ web page and the dump file " + dump.getAbsolutePath() );
331             }
332 
333             if ( debug && event != null )
334             {
335                 log.debug( event );
336             }
337         }
338         else if ( debug )
339         {
340             log.debug( event );
341         }
342         else
343         {
344             log.info( event );
345         }
346     }
347 
348     private void writeTestOutput( String remaining, boolean isStdout )
349     {
350         int csNameEnd = remaining.indexOf( ',' );
351         String charsetName = remaining.substring( 0, csNameEnd );
352         String byteEncoded = remaining.substring( csNameEnd + 1 );
353         ByteBuffer unescaped = unescapeBytes( byteEncoded, charsetName );
354 
355         if ( unescaped.hasArray() )
356         {
357             byte[] convertedBytes = unescaped.array();
358             getOrCreateConsoleOutputReceiver()
359                 .writeTestOutput( convertedBytes, unescaped.position(), unescaped.remaining(), isStdout );
360         }
361         else
362         {
363             byte[] convertedBytes = new byte[unescaped.remaining()];
364             unescaped.get( convertedBytes, 0, unescaped.remaining() );
365             getOrCreateConsoleOutputReceiver()
366                 .writeTestOutput( convertedBytes, 0, convertedBytes.length, isStdout );
367         }
368     }
369 
370     public final void consumeMultiLineContent( String s )
371             throws IOException
372     {
373         BufferedReader stringReader = new BufferedReader( new StringReader( s ) );
374         for ( String s1 = stringReader.readLine(); s1 != null; s1 = stringReader.readLine() )
375         {
376             consumeLine( s1 );
377         }
378     }
379 
380     private String createConsoleMessage( String remaining )
381     {
382         return unescape( remaining );
383     }
384 
385     private TestSetReportEntry createReportEntry( String untokenized )
386     {
387         return createReportEntry( untokenized, Collections.<String, String>emptyMap() );
388     }
389 
390     private TestSetReportEntry createReportEntry( String untokenized, Map<String, String> systemProperties )
391     {
392         StringTokenizer tokens = new StringTokenizer( untokenized, "," );
393         try
394         {
395             String source = nullableCsv( tokens.nextToken() );
396             String name = nullableCsv( tokens.nextToken() );
397             String group = nullableCsv( tokens.nextToken() );
398             String message = nullableCsv( tokens.nextToken() );
399             String elapsedStr = tokens.nextToken();
400             Integer elapsed = "null".equals( elapsedStr ) ? null : decode( elapsedStr );
401             final StackTraceWriter stackTraceWriter =
402                     tokens.hasMoreTokens() ? deserializeStackTraceWriter( tokens ) : null;
403 
404             return reportEntry( source, name, group, stackTraceWriter, elapsed, message, systemProperties );
405         }
406         catch ( RuntimeException e )
407         {
408             throw new RuntimeException( untokenized, e );
409         }
410     }
411 
412     private StackTraceWriter deserializeStackTraceWriter( StringTokenizer tokens )
413     {
414         String stackTraceMessage = nullableCsv( tokens.nextToken() );
415         String smartStackTrace = nullableCsv( tokens.nextToken() );
416         String stackTrace = tokens.hasMoreTokens() ? nullableCsv( tokens.nextToken() ) : null;
417         boolean hasTrace = stackTrace != null;
418         return hasTrace ? new DeserializedStacktraceWriter( stackTraceMessage, smartStackTrace, stackTrace ) : null;
419     }
420 
421     private String nullableCsv( String source )
422     {
423         return "null".equals( source ) ? null : unescape( source );
424     }
425 
426     private String unescape( String source )
427     {
428         StringBuilder stringBuffer = new StringBuilder( source.length() );
429         unescapeString( stringBuffer, source );
430         return stringBuffer.toString();
431     }
432 
433     public final Map<String, String> getTestVmSystemProperties()
434     {
435         return unmodifiableMap( testVmSystemProperties );
436     }
437 
438     /**
439      * Used when getting reporters on the plugin side of a fork.
440      * Used by testing purposes only. May not be volatile variable.
441      *
442      * @return A mock provider reporter
443      */
444     public final RunListener getReporter()
445     {
446         return getTestSetReporter();
447     }
448 
449     private ConsoleOutputReceiver getOrCreateConsoleOutputReceiver()
450     {
451         return (ConsoleOutputReceiver) getTestSetReporter();
452     }
453 
454     private ConsoleLogger getOrCreateConsoleLogger()
455     {
456         return (ConsoleLogger) getTestSetReporter();
457     }
458 
459     public void close( boolean hadTimeout )
460     {
461         // no op
462     }
463 
464     public final boolean isSaidGoodBye()
465     {
466         return saidGoodBye;
467     }
468 
469     public final StackTraceWriter getErrorInFork()
470     {
471         return errorInFork;
472     }
473 
474     public final boolean isErrorInFork()
475     {
476         return errorInFork != null;
477     }
478 
479     public Set<String> testsInProgress()
480     {
481         return new TreeSet<String>( testsInProgress );
482     }
483 
484     public boolean hasTestsInProgress()
485     {
486         return !testsInProgress.isEmpty();
487     }
488 
489     public void setForkNumber( int forkNumber )
490     {
491         assert this.forkNumber == 0;
492         this.forkNumber = forkNumber;
493     }
494 
495     private static final class OperationalData
496     {
497         private final byte operationId;
498         private final String data;
499 
500         OperationalData( String event )
501         {
502             operationId = (byte) event.charAt( 0 );
503             int comma = event.indexOf( ",", 3 );
504             if ( comma < 0 )
505             {
506                 throw new IllegalArgumentException( "Stream stdin corrupted. Expected comma after third character "
507                                                             + "in command '" + event + "'." );
508             }
509             int rest = event.indexOf( ",", comma );
510             data = event.substring( rest + 1 );
511         }
512 
513         byte getOperationId()
514         {
515             return operationId;
516         }
517 
518         String getData()
519         {
520             return data;
521         }
522     }
523 }