Hi JB, Thanks for the offer, but I am afraid it would be too complex to share. The application is made of many projects and bundles, including native libraries, etc. it would be very hard to set up the environment. I can share the entire Karaf log if needed.
What I am looking for is help on how to troubleshoot this issue. Any information (given the provided stack trace) about what setting controls this timeout, and what exactly is the code waiting for? How to enable more logging? Is there something failing and not logging an error perhaps? How can I figure out what is blocking, or not finishing? Best regards, Alex soto > On May 8, 2019, at 9:35 AM, Jean-Baptiste Onofré <[email protected]> wrote: > > Hi Alex, > > Can you share your itest ? I'm not able to reproduce the issue, so hard > to investigate. > > Regards > JB > > On 08/05/2019 15:31, Alex Soto wrote: >> Still having this problem. I am setting log level: >> >> logLevel(LogLevel.TRACE), >> >> And >> >> log4j2.logger.paxexam.name=org.ops4j.pax.exam >> log4j2.logger.paxexam.level=TRACE >> >> And >> >> static final long SERVICE_TIMEOUT = 300_000; >> systemTimeout(SERVICE_TIMEOUT), >> RBCRemoteTargetOptions.waitForRBCFor((int) SERVICE_TIMEOUT), >> >> I removed all services references that used the /@Inject/ annotation, >> and replaced them with service lookup code. >> Logs don’t show any error or warning that can help pinpoint the cause of >> this error. >> >> Increasing the timeout just delays the reporting of the error by the >> FailSafe driver, but the error is logged a lot earlier in the Karaf log >> file. >> >> For easy reference, here is the stack trace again: >> >> 2019-05-08T09:15:18,654 | ERROR | BundleWatcher: 1 | BundleWatcher >> | 201 - org.ops4j.pax.swissbox.extender - 1.8.2 | >> Exception in executor thread >> org.ops4j.pax.swissbox.tracker.ServiceLookupException: gave up waiting >> for service org.ops4j.pax.exam.ProbeInvokerFactory >> at >> org.ops4j.pax.swissbox.tracker.ServiceLookup.getService(ServiceLookup.java:161) >> ~[204:org.ops4j.pax.swissbox.tracker:1.8.2] >> at >> org.ops4j.pax.swissbox.tracker.ServiceLookup.getService(ServiceLookup.java:104) >> ~[204:org.ops4j.pax.swissbox.tracker:1.8.2] >> at >> org.ops4j.pax.swissbox.tracker.ServiceLookup.getService(ServiceLookup.java:87) >> ~[204:org.ops4j.pax.swissbox.tracker:1.8.2] >> at >> org.ops4j.pax.exam.raw.extender.intern.Parser.createInvoker(Parser.java:79) >> ~[?:?] >> at org.ops4j.pax.exam.raw.extender.intern.Parser.make(Parser.java:68) ~[?:?] >> at org.ops4j.pax.exam.raw.extender.intern.Parser.<init>(Parser.java:54) >> ~[?:?] >> at >> org.ops4j.pax.exam.raw.extender.intern.TestBundleObserver.addingEntries(TestBundleObserver.java:69) >> ~[?:?] >> at >> org.ops4j.pax.swissbox.extender.BundleWatcher$3.run(BundleWatcher.java:226) >> [201:org.ops4j.pax.swissbox.extender:1.8.2] >> at >> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) >> [?:?] >> at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?] >> at >> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) >> [?:?] >> at >> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) >> [?:?] >> at >> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) >> [?:?] >> at >> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) >> [?:?] >> at java.lang.Thread.run(Thread.java:748) [?:?] >> >> >> Any hint? >> >> Best regards, >> Alex soto >> >> >> >> >>> On May 1, 2019, at 3:47 PM, Alex Soto <[email protected] >>> <mailto:[email protected] <mailto:[email protected]>>> wrote: >>> >>> Do you mean any of these options? >>> >>> RBCRemoteTargetOptions.waitForRBCFor(final Integer timeoutInMillis) >>> CoreOptions.systemTimeout(systemTimeout(finallongtimeoutInMillis) >>> >>> >>> >>> Best regards, >>> Alex soto >>> >>> >>> >>> >>>> On May 1, 2019, at 12:12 PM, Jean-Baptiste Onofré <[email protected] >>>> <mailto:[email protected]> >>>> <mailto:[email protected] <mailto:[email protected]>>> wrote: >>>> >>>> You can increase the startup timeout on the @Configuration method (on >>>> the distribution). >>>> >>>> Regards >>>> JB >>>> >>>> On 01/05/2019 17:46, Alex Soto wrote: >>>>> No, I am not waiting for the service explicitly, it comes from Pax Exam >>>>> itself (AFIK, based on the stack trace below). >>>>> My tests have a bunch of /@Inject/ed services, but they are all >>>>> decorated with /@Filter(timeout = SERVICE_TIMEOUT) >>>>> /where SERVICE_TIMEOUT = 240_000. >>>>> >>>>> Java version is 8. >>>>> Karaf version is 4.2.0. >>>>> The exception: >>>>> >>>>> 2019-05-01T11:28:58,500 | ERROR | BundleWatcher: 1 | BundleWatcher >>>>> | 202 - org.ops4j.pax.swissbox.extender - 1.8.2 | >>>>> Exception in executor thread >>>>> org.ops4j.pax.swissbox.tracker.ServiceLookupException: gave up waiting >>>>> for service org.ops4j.pax.exam.ProbeInvokerFactory >>>>> at >>>>> org.ops4j.pax.swissbox.tracker.ServiceLookup.getService(ServiceLookup.java:161) >>>>> ~[205:org.ops4j.pax.swissbox.tracker:1.8.2] >>>>> at >>>>> org.ops4j.pax.swissbox.tracker.ServiceLookup.getService(ServiceLookup.java:104) >>>>> ~[205:org.ops4j.pax.swissbox.tracker:1.8.2] >>>>> at >>>>> org.ops4j.pax.swissbox.tracker.ServiceLookup.getService(ServiceLookup.java:87) >>>>> ~[205:org.ops4j.pax.swissbox.tracker:1.8.2] >>>>> at >>>>> org.ops4j.pax.exam.raw.extender.intern.Parser.createInvoker(Parser.java:79) >>>>> ~[?:?] >>>>> at >>>>> org.ops4j.pax.exam.raw.extender.intern.Parser.make(Parser.java:68) >>>>> ~[?:?] >>>>> at org.ops4j.pax.exam.raw.extender.intern.Parser.<init>(Parser.java:54) >>>>> ~[?:?] >>>>> at >>>>> org.ops4j.pax.exam.raw.extender.intern.TestBundleObserver.addingEntries(TestBundleObserver.java:69) >>>>> ~[?:?] >>>>> at >>>>> org.ops4j.pax.swissbox.extender.BundleWatcher$3.run(BundleWatcher.java:226) >>>>> [202:org.ops4j.pax.swissbox.extender:1.8.2] >>>>> at >>>>> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) >>>>> [?:?] >>>>> at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?] >>>>> at >>>>> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) >>>>> [?:?] >>>>> at >>>>> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) >>>>> [?:?] >>>>> at >>>>> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) >>>>> [?:?] >>>>> at >>>>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) >>>>> [?:?] >>>>> at java.lang.Thread.run(Thread.java:748) [?:?] >>>>> >>>>> >>>>> These integration tests have been working in the past, so I suspect, as >>>>> the application complexity increased (i.e., more services being added >>>>> overtime), it now takes more time for the container to finish >>>>> initialization (my guess). I would like to increase the timeout value >>>>> to accommodate for a longer startup time, but so far, what I've tried >>>>> has not made a difference. >>>>> >>>>> >>>>> Best regards, >>>>> Alex soto >>>>> >>>>> >>>>> >>>>> >>>>>> On May 1, 2019, at 11:31 AM, Jean-Baptiste Onofré <[email protected] >>>>>> <mailto:[email protected]> >>>>>> <mailto:[email protected] <mailto:[email protected]>> >>>>>> <mailto:[email protected] <mailto:[email protected]>>> wrote: >>>>>> >>>>>> Are you waiting for the service in your test explicitly or does it come >>>>>> from pax exam itself ? >>>>>> >>>>>> What JDK and Karaf version are you using ? >>>>>> >>>>>> As reminder, Pax Exam is used in Karaf itests themselves, and I don't >>>>>> have such issue. It could be related to JDK 11 if you are using >>>>>> this JDK >>>>>> version. >>>>>> >>>>>> Regards >>>>>> JB >>>>>> >>>>>> On 01/05/2019 17:13, Alex Soto wrote: >>>>>>> Thanks JB, no there are no errors in the log file, besides this one. >>>>>>> >>>>>>> Best regards, >>>>>>> Alex soto >>>>>>> >>>>>>> >>>>>>> >>>>>>> >>>>>>>> On May 1, 2019, at 12:10 AM, Jean-Baptiste Onofré >>>>>>>> <[email protected] <mailto:[email protected]> >>>>>>>> <mailto:[email protected] <mailto:[email protected]>> >>>>>>>> <mailto:[email protected] <mailto:[email protected]>> >>>>>>>> <mailto:[email protected] <mailto:[email protected]>>> wrote: >>>>>>>> >>>>>>>> Hi Alex, >>>>>>>> >>>>>>>> Most of the time, this is a consequence of another error. >>>>>>>> >>>>>>>> Can you take a look in the target/exam karaf.log to see if there's >>>>>>>> something special there ? >>>>>>>> >>>>>>>> Regards >>>>>>>> JB >>>>>>>> >>>>>>>> On 29/04/2019 18:09, Alex Soto wrote: >>>>>>>>> Hello, >>>>>>>>> >>>>>>>>> I am using pax-exam 4.11.0 for integration tests. I am consistently >>>>>>>>> getting the following exception. >>>>>>>>> >>>>>>>>> >>>>>>>>> org.ops4j.pax.swissbox.tracker.ServiceLookupException: gave up >>>>>>>>> waiting >>>>>>>>> for service org.ops4j.pax.exam.ProbeInvoker >>>>>>>>> at >>>>>>>>> org.ops4j.pax.swissbox.tracker.ServiceLookup.getService(ServiceLookup.java:199) >>>>>>>>> at >>>>>>>>> org.ops4j.pax.swissbox.tracker.ServiceLookup.getService(ServiceLookup.java:136) >>>>>>>>> at >>>>>>>>> org.ops4j.pax.exam.rbc.internal.RemoteBundleContextImpl.remoteCall(RemoteBundleContextImpl.java:80) >>>>>>>>> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) >>>>>>>>> at >>>>>>>>> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) >>>>>>>>> at >>>>>>>>> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) >>>>>>>>> at java.lang.reflect.Method.invoke(Method.java:498) >>>>>>>>> at >>>>>>>>> sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:357) >>>>>>>>> at sun.rmi.transport.Transport$1.run(Transport.java:200) >>>>>>>>> at sun.rmi.transport.Transport$1.run(Transport.java:197) >>>>>>>>> at java.security.AccessController.doPrivileged(Native Method) >>>>>>>>> at sun.rmi.transport.Transport.serviceCall(Transport.java:196) >>>>>>>>> at >>>>>>>>> sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:573) >>>>>>>>> at >>>>>>>>> sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:835) >>>>>>>>> at >>>>>>>>> sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:688) >>>>>>>>> at java.security.AccessController.doPrivileged(Native Method) >>>>>>>>> at >>>>>>>>> sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:687) >>>>>>>>> at >>>>>>>>> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) >>>>>>>>> at >>>>>>>>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) >>>>>>>>> at java.lang.Thread.run(Thread.java:748) >>>>>>>>> at >>>>>>>>> sun.rmi.transport.StreamRemoteCall.exceptionReceivedFromServer(StreamRemoteCall.java:283) >>>>>>>>> at >>>>>>>>> sun.rmi.transport.StreamRemoteCall.executeCall(StreamRemoteCall.java:260) >>>>>>>>> at sun.rmi.server.UnicastRef.invoke(UnicastRef.java:161) >>>>>>>>> at >>>>>>>>> java.rmi.server.RemoteObjectInvocationHandler.invokeRemoteMethod(RemoteObjectInvocationHandler.java:227) >>>>>>>>> at >>>>>>>>> java.rmi.server.RemoteObjectInvocationHandler.invoke(RemoteObjectInvocationHandler.java:179) >>>>>>>>> at com.sun.proxy.$Proxy14.remoteCall(Unknown Source) >>>>>>>>> at >>>>>>>>> org.ops4j.pax.exam.rbc.client.intern.RemoteBundleContextClientImpl$1.invoke(RemoteBundleContextClientImpl.java:102) >>>>>>>>> at com.sun.proxy.$Proxy15.call(Unknown Source) >>>>>>>>> at >>>>>>>>> org.ops4j.pax.exam.rbc.client.intern.RemoteBundleContextClientImpl.call(RemoteBundleContextClientImpl.java:290) >>>>>>>>> at >>>>>>>>> org.ops4j.pax.exam.container.remote.RBCRemoteTarget.call(RBCRemoteTarget.java:60) >>>>>>>>> at >>>>>>>>> org.ops4j.pax.exam.karaf.container.internal.KarafTestContainer.call(KarafTestContainer.java:652) >>>>>>>>> at >>>>>>>>> org.ops4j.pax.exam.spi.reactors.EagerSingleStagedReactor.invoke(EagerSingleStagedReactor.java:109) >>>>>>>>> at >>>>>>>>> org.ops4j.pax.exam.junit.impl.ProbeRunner$2.evaluate(ProbeRunner.java:267) >>>>>>>>> at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325) >>>>>>>>> at >>>>>>>>> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78) >>>>>>>>> at >>>>>>>>> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57) >>>>>>>>> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290) >>>>>>>>> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71) >>>>>>>>> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288) >>>>>>>>> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58) >>>>>>>>> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268) >>>>>>>>> at org.junit.runners.ParentRunner.run(ParentRunner.java:363) >>>>>>>>> at >>>>>>>>> org.ops4j.pax.exam.junit.impl.ProbeRunner.run(ProbeRunner.java:98) >>>>>>>>> at org.ops4j.pax.exam.junit.PaxExam.run(PaxExam.java:93) >>>>>>>>> at >>>>>>>>> org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:365) >>>>>>>>> at >>>>>>>>> org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:273) >>>>>>>>> at >>>>>>>>> org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:238) >>>>>>>>> at >>>>>>>>> org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:159) >>>>>>>>> at >>>>>>>>> org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:379) >>>>>>>>> at >>>>>>>>> org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:340) >>>>>>>>> at >>>>>>>>> org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:125) >>>>>>>>> at >>>>>>>>> org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:413) >>>>>>>>> >>>>>>>>> >>>>>>>>> What causes this? How to troubleshoot or how to increase the >>>>>>>>> timeout? >>>>>>>>> >>>>>>>>> Best regards, >>>>>>>>> Alex soto >>>>>>>>> >>>>>>>>> >>>>>>>>> >>>>>>>>> >>>>>>>> >>>>>>>> -- >>>>>>>> Jean-Baptiste Onofré >>>>>>>> [email protected] <mailto:[email protected]> >>>>>>>> <mailto:[email protected] <mailto:[email protected]>> >>>>>>>> <mailto:[email protected] <mailto:[email protected]>> >>>>>>>> <mailto:[email protected] <mailto:[email protected]>> >>>>>>>> http://blog.nanthrax.net <http://blog.nanthrax.net/> >>>>>>>> <http://blog.nanthrax.net/ <http://blog.nanthrax.net/>> >>>>>>>> <http://blog.nanthrax.net/ <http://blog.nanthrax.net/>> >>>>>>>> Talend - http://www.talend.com <http://www.talend.com/> >>>>>>>> <http://www.talend.com/ <http://www.talend.com/>> >>>>>>>> <http://www.talend.com/ <http://www.talend.com/>> >>>>>>> >>>>>> >>>>>> -- >>>>>> Jean-Baptiste Onofré >>>>>> [email protected] <mailto:[email protected]> >>>>>> <mailto:[email protected] <mailto:[email protected]>> >>>>>> <mailto:[email protected] <mailto:[email protected]>> >>>>>> http://blog.nanthrax.net <http://blog.nanthrax.net/> >>>>>> <http://blog.nanthrax.net/ <http://blog.nanthrax.net/>> >>>>>> <http://blog.nanthrax.net/ <http://blog.nanthrax.net/>> >>>>>> Talend - http://www.talend.com <http://www.talend.com/> >>>>>> <http://www.talend.com/ <http://www.talend.com/>> >>>>>> <http://www.talend.com/ <http://www.talend.com/>> >>>>> >>>> >>>> -- >>>> Jean-Baptiste Onofré >>>> [email protected] <mailto:[email protected]> >>>> <mailto:[email protected] <mailto:[email protected]>> >>>> http://blog.nanthrax.net <http://blog.nanthrax.net/> >>>> <http://blog.nanthrax.net/ <http://blog.nanthrax.net/>> >>>> Talend - http://www.talend.com <http://www.talend.com/> >>>> <http://www.talend.com/ <http://www.talend.com/>> >>> >> > > -- > Jean-Baptiste Onofré > [email protected] <mailto:[email protected]> > http://blog.nanthrax.net <http://blog.nanthrax.net/> > Talend - http://www.talend.com <http://www.talend.com/>
