It's weird you don't have anything in the karaf log (in target/exam folder).
Maybe you can execute service:list commaand in the itest to check the actual service available. Regards JB On 08/05/2019 15:52, Alex Soto wrote: > 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] >> <mailto:[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]>> 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]>> 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]>> 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]> >>>>>>>>> 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]> >>>>>>> <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]> <mailto:[email protected]> >>>>> 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/> >>>> >>> >> >> -- >> 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/> > -- Jean-Baptiste Onofré [email protected] http://blog.nanthrax.net Talend - http://www.talend.com
