timeout in pax tests

[codefromthecrypt]

@cschneider @reta either of you know a workaround to what seems to be a Java 11 related hang after pax? the tests actually succeed..

[INFO] -------------------------------------------------------

[INFO]  T E S T S

[INFO] -------------------------------------------------------

[INFO] Running io.zipkin.brave.itests.ITBrave

06:17:59.681 [main] INFO  o.o.pax.exam.spi.DefaultExamSystem - Pax Exam System (Version: 4.13.4) created.

06:17:59.727 [main] INFO  o.o.pax.exam.junit.impl.ProbeRunner - creating PaxExam runner for class io.zipkin.brave.itests.ITBrave

06:17:59.898 [main] INFO  o.o.pax.exam.junit.impl.ProbeRunner - running test class io.zipkin.brave.itests.ITBrave

06:17:59.996 [main] INFO  o.o.p.e.k.c.i.KarafTestContainer - Created RMI registry server on 127.0.0.1:21000

06:18:01.071 [main] INFO  o.o.p.e.k.c.i.KarafTestContainer - Found 0 options when requesting OverrideJUnitBundlesOption.class

06:18:01.092 [main] INFO  o.o.p.e.k.c.i.KarafTestContainer - Wait for test container to finish its initialization [ RelativeTimeout value = 180000 ]

06:18:01.093 [main] INFO  o.o.p.e.r.c.RemoteBundleContextClient - Waiting for remote bundle context.. on 21000 name: 7760514e-6723-4646-b8a0-c40e9fe01557 timout: [ RelativeTimeout value = 180000 ]

WARNING: An illegal reflective access operation has occurred

WARNING: Illegal reflective access by org.apache.felix.framework.ext.ClassPathExtenderFactory$DefaultClassLoaderExtender (file:/home/travis/.pax/exam/system/org/apache/felix/org.apache.felix.framework/5.6.12/org.apache.felix.framework-5.6.12.jar) to method java.net.URLClassLoader.addURL(java.net.URL)

WARNING: Please consider reporting this to the maintainers of org.apache.felix.framework.ext.ClassPathExtenderFactory$DefaultClassLoaderExtender

WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations

WARNING: All illegal access operations will be denied in a future release

06:18:18.349 [main] INFO  o.o.p.e.spi.reactors.ReactorManager - suite finished

[INFO] Tests run: 8, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 19.094 s - in io.zipkin.brave.itests.ITBrave

[ERROR] System Exit has timed out in the forked process 1

[reta]

@adriancole I thought is was related to java.lang.NoClassDefFoundError: org/apache/karaf/specs/locator/OsgiLocator issue which appears in Karaf test container logs, but not really (still may be worth fixing, #53).

What I have noticed, for me the System Exit has timed out in the forked process 1 happens randomly, and when it does, I see a number of warnings like:

.pax/exam/data/log/karaf.log:2020-10-25T12:53:02,562 | WARN  | FelixStartLevel  | AsyncReporter$BoundedAsyncReporter | 29 - io.zipkin.reporter2.zipkin-reporter - 2.15.2 | Timed out waiting for in-flight spans to send
.pax/exam/data/log/karaf.log:2020-10-25T12:53:03,591 | WARN  | FelixStartLevel  | AsyncReporter$BoundedAsyncReporter | 29 - io.zipkin.reporter2.zipkin-reporter - 2.15.2 | Timed out waiting for in-flight spans to send
.pax/exam/data/log/karaf.log:2020-10-25T12:53:04,608 | WARN  | FelixStartLevel  | AsyncReporter$BoundedAsyncReporter | 29 - io.zipkin.reporter2.zipkin-reporter - 2.15.2 | Timed out waiting for in-flight spans to send

It seems like on container's shutdown the BoundedAsyncReporter tries to send the spans on close() call?

[reta]

Digging more into this, I clearly observe that Karaf process exists normally once the tests reporter reports:

[INFO] Tests run: 8, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 10.141 s - in io.zipkin.brave.itests.ITBrave

At this point, only Failsafe / Surefire is running, dumping the following error (itests/target/failsafe-reports/2020-10-25T12-52-55_210-jvmRun1.dumpstream):

TestSet has not finished before stream error has appeared >> initializing exit by non-null configuration: EXIT                        
java.io.EOFException                                                                                                                  
        at org.apache.maven.surefire.booter.spi.LegacyMasterProcessChannelDecoder.decode(LegacyMasterProcessChannelDecoder.java:135)  
        at org.apache.maven.surefire.booter.CommandReader$CommandRunnable.run(CommandReader.java:343)                                 
        at java.base/java.lang.Thread.run(Thread.java:834)                                                                            

[reta]

Ok, seems to be it, at least it is gone in the build: #54