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