Exception thrown when requesting service docs #149

dannylamb · 2017-09-05T16:59:16Z

Using the latest SNAPSHOT build of Api-X, I'm getting a RuntimeException when requesting the service document for a resource:

daniel@daniel-Latitude-3560:~/Code$ curl -I "http://localhost:8081/fcrepo/rest/a9/ed/cb/bc/a9edcbbc-1ffe-45c7-84c9-c8991f27a08a"
HTTP/1.1 200 OK
Content-Type: application/n-triples
Accept: */*
Accept-Patch: application/sparql-update
Accept-Post: text/turtle,text/rdf+n3,text/n3,application/rdf+xml,application/n-triples,application/ld+json,multipart/form-data,application/sparql-update
Allow: MOVE,COPY,DELETE,POST,HEAD,GET,PUT,PATCH,OPTIONS
Apix-Modality: intercept; outgoing
breadcrumbId: ID-claw-42556-1504240117103-0-61
ETag: W/"915c25ec6dea9b717d8c1a13af8d4faa76145412"
Expires: Thu, 01 Jan 1970 00:00:00 UTC
Last-Modified: Tue, 05 Sep 2017 16:42:26 GMT
Link: <http://www.w3.org/ns/ldp#Container>;rel="type"
Link: <http://localhost:8081/discovery/a9/ed/cb/bc/a9edcbbc-1ffe-45c7-84c9-c8991f27a08a>; rel="service"
Link: <http://www.w3.org/ns/ldp#Resource>;rel="type"
Link: <http://www.w3.org/ns/ldp#BasicContainer>;rel="type"
Server: Apache-Coyote/1.1
Content-Length: 0

daniel@daniel-Latitude-3560:~/Code$ curl http://localhost:8081/discovery/a9/ed/cb/bc/a9edcbbc-1ffe-45c7-84c9-c8991f27a08a
java.lang.RuntimeException: java.lang.IllegalStateException: getService() returned null for [org.fcrepo.apix.model.components.ExtensionBinding]
	at org.fcrepo.apix.routing.impl.ServiceDocumentGenerator.getServiceDocumentFor(ServiceDocumentGenerator.java:119)
	at org.fcrepo.apix.routing.impl.RoutingImpl.lambda$new$29(RoutingImpl.java:296)
	at org.apache.camel.processor.DelegateSyncProcessor.process(DelegateSyncProcessor.java:63)
	at org.apache.camel.management.InstrumentationProcessor.process(InstrumentationProcessor.java:77)
	at org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:541)
	at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:198)
	at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:198)
	at org.apache.camel.component.jetty.CamelContinuationServlet.doService(CamelContinuationServlet.java:206)
	at org.apache.camel.http.common.CamelServlet.service(CamelServlet.java:74)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:812)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1669)
	at org.eclipse.jetty.servlets.MultiPartFilter.doFilter(MultiPartFilter.java:146)
	at org.apache.camel.component.jetty.CamelFilterWrapper.doFilter(CamelFilterWrapper.java:43)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:585)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
	at org.eclipse.jetty.server.Server.handle(Server.java:499)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)
	at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
	at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.IllegalStateException: getService() returned null for [org.fcrepo.apix.model.components.ExtensionBinding]
	at org.apache.aries.blueprint.container.ReferenceRecipe.getService(ReferenceRecipe.java:250)
	at org.apache.aries.blueprint.container.ReferenceRecipe.access$000(ReferenceRecipe.java:56)
	at org.apache.aries.blueprint.container.ReferenceRecipe$ServiceDispatcher.call(ReferenceRecipe.java:306)
	at Proxyc9accdd2_64c6_4239_b481_c231ef2b48e7.getExtensionsFor(Unknown Source)
	at org.fcrepo.apix.routing.impl.ServiceDocumentGenerator.getServiceDocumentFor(ServiceDocumentGenerator.java:114)
	... 27 more

In the karaf logs I'm eventually getting this as well:

2017-09-05 16:51:12,248 | ERROR | tp2102087898-200 | DefaultErrorHandler              | 86 - org.apache.camel.camel-core - 2.19.2 | Failed delivery for (MessageId: ID-claw-42556-1504240117103-0-64 on ExchangeId: ID-claw-42556-1504240117103-0-63). Exhausted after delivery attempt: 1 caught: java.lang.RuntimeException: java.lang.IllegalStateException: getService() returned null for [org.fcrepo.apix.model.components.ExtensionBinding]

Message History
---------------------------------------------------------------------------------------------------------------------------------------
RouteId              ProcessorId          Processor                                                                        Elapsed (ms)
[service-doc-endpoi] [service-doc-endpoi] [jetty:http://0.0.0.0:8081/discovery?matchOnUriPrefix=true&optionsEnabled=true ] [        19]
[service-doc-endpoi] [process1          ] [Processor@0x4834d186                                                          ] [        18]

Stacktrace
---------------------------------------------------------------------------------------------------------------------------------------
java.lang.RuntimeException: java.lang.IllegalStateException: getService() returned null for [org.fcrepo.apix.model.components.ExtensionBinding]
	at org.fcrepo.apix.routing.impl.ServiceDocumentGenerator.getServiceDocumentFor(ServiceDocumentGenerator.java:119)[70:fcrepo-api-x-routing:0.3.0.SNAPSHOT]
	at org.fcrepo.apix.routing.impl.RoutingImpl.lambda$new$29(RoutingImpl.java:296)[70:fcrepo-api-x-routing:0.3.0.SNAPSHOT]
	at org.apache.camel.processor.DelegateSyncProcessor.process(DelegateSyncProcessor.java:63)[86:org.apache.camel.camel-core:2.19.2]
	at org.apache.camel.management.InstrumentationProcessor.process(InstrumentationProcessor.java:77)[86:org.apache.camel.camel-core:2.19.2]
	at org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:541)[86:org.apache.camel.camel-core:2.19.2]
	at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:198)[86:org.apache.camel.camel-core:2.19.2]
	at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:198)[86:org.apache.camel.camel-core:2.19.2]
	at org.apache.camel.component.jetty.CamelContinuationServlet.doService(CamelContinuationServlet.java:206)[90:org.apache.camel.camel-jetty-common:2.19.2]
	at org.apache.camel.http.common.CamelServlet.service(CamelServlet.java:74)[87:org.apache.camel.camel-http-common:2.19.2]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)[75:javax.servlet-api:3.1.0]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:812)[135:org.eclipse.jetty.servlet:9.2.19.v20160908]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1669)[135:org.eclipse.jetty.servlet:9.2.19.v20160908]
	at org.eclipse.jetty.servlets.MultiPartFilter.doFilter(MultiPartFilter.java:146)[136:org.eclipse.jetty.servlets:9.2.19.v20160908]
	at org.apache.camel.component.jetty.CamelFilterWrapper.doFilter(CamelFilterWrapper.java:43)[90:org.apache.camel.camel-jetty-common:2.19.2]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)[135:org.eclipse.jetty.servlet:9.2.19.v20160908]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:585)[135:org.eclipse.jetty.servlet:9.2.19.v20160908]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127)[134:org.eclipse.jetty.server:9.2.19.v20160908]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515)[135:org.eclipse.jetty.servlet:9.2.19.v20160908]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061)[134:org.eclipse.jetty.server:9.2.19.v20160908]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)[134:org.eclipse.jetty.server:9.2.19.v20160908]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)[134:org.eclipse.jetty.server:9.2.19.v20160908]
	at org.eclipse.jetty.server.Server.handle(Server.java:499)[134:org.eclipse.jetty.server:9.2.19.v20160908]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311)[134:org.eclipse.jetty.server:9.2.19.v20160908]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)[134:org.eclipse.jetty.server:9.2.19.v20160908]
	at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)[126:org.eclipse.jetty.io:9.2.19.v20160908]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)[137:org.eclipse.jetty.util:9.2.19.v20160908]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)[137:org.eclipse.jetty.util:9.2.19.v20160908]
	at java.lang.Thread.run(Thread.java:748)[:1.8.0_131]
Caused by: java.lang.IllegalStateException: getService() returned null for [org.fcrepo.apix.model.components.ExtensionBinding]
	at org.apache.aries.blueprint.container.ReferenceRecipe.getService(ReferenceRecipe.java:250)
	at org.apache.aries.blueprint.container.ReferenceRecipe.access$000(ReferenceRecipe.java:56)
	at org.apache.aries.blueprint.container.ReferenceRecipe$ServiceDispatcher.call(ReferenceRecipe.java:306)
	at Proxyc9accdd2_64c6_4239_b481_c231ef2b48e7.getExtensionsFor(Unknown Source)
	at org.fcrepo.apix.routing.impl.ServiceDocumentGenerator.getServiceDocumentFor(ServiceDocumentGenerator.java:114)[70:fcrepo-api-x-routing:0.3.0.SNAPSHOT]
	... 27 more

The text was updated successfully, but these errors were encountered:

birkland · 2017-09-05T17:47:24Z

@dannylamb Wow, that is weird. Blueprint thinks there are no instances of ExtensionBinding in the OSGi registry. Is the fcrepo-api-x-binding bundle running? When did this occur or start occuring?

dannylamb · 2017-09-05T17:59:49Z

I first noticed this last Thursday.

I can confirm that fcrepo-api-x-binding has an Active state.

dannylamb · 2017-09-05T18:01:45Z

@birkland Logs seem to give me what I would expect to see. Some startup messages, then it notifies me it's waiting for dependencies, then it gets some blueprint events and starts up without issue.

dannylamb · 2017-09-21T12:58:20Z

@birkland I have finally tracked down what's triggered this issue. Ever since we moved our camel and activemq versions to be in lockstep with Api-X, we're getting this consistently.

dannylamb · 2017-10-10T16:41:55Z

@birkland I upgraded my environment to use Karaf 4.1.2 in an attempt to fix the issue but I still receive the same error message.

birkland · 2017-10-10T16:55:26Z

@dannylamb Ugh, Is this in a VM, or otherwise reproducible externally (by the likes of me)? As mentioned on the last API-X call, there doesn't seem to be any explanation as to why the (published-in-OSGi) service is unavailable. I'm happy to look at it, but haven't ever seen this.

In general, though, my confidence in Karaf (and of OSGi in general) is at a low point; they've proven to be a net liability. In my mind, the best solution is to move to deployment environment that doesn't involve either! Until then, let's see if this can be reproduced?

dannylamb · 2017-10-11T13:45:23Z

@birkland I'm right there with ya. I'm going to do some more digging, like verifying this only occurs when both API-X and Alpaca are deployed within the same Karaf. That would be enough for me to move away from Karaf and towards Spring Boot and fat jars.

If you want to give it a go, our https://github.com/Islandora-CLAW/claw_vagrant will bring up an environment with API-X and Alpaca.

dannylamb · 2017-10-24T14:34:38Z

After lots more digging, I have found this to boils down to some weird timing issues in our CLAW installs (both https://github.com/Islandora-CLAW/claw_vagrant and https://github.com/Islandora-Devops/claw-playbook).

It seems to resolve itself if I go through the following hurdles in order:

shut down karaf
shut down tomcat with fedora
shut down active mq
start activemq and wait a bit
start tomcat and wait a bit
start karaf

I'm loathe to introduce waits into our install code, but worse things have happened. I'm hoping that once we start doing distributed setups instead of these all-in-one installs, these sorts of issues will resolve themselves.

dannylamb mentioned this issue Oct 11, 2017

Consider deployment alternatives for Alpaca Islandora/documentation#731

Open

This was referenced Oct 24, 2017

Issue 640 islandora-deprecated/claw_vagrant#55

Merged

Reset Karaf, Tomcat, and Activemq in Sequence to ensure Api-X comes up right Islandora/documentation#738

Closed

dannylamb mentioned this issue Oct 31, 2017

Cycling Api-X stack and loading Crayfish microservices into Api-X Islandora-Devops/islandora-playbook#22

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Exception thrown when requesting service docs #149

Exception thrown when requesting service docs #149

dannylamb commented Sep 5, 2017

birkland commented Sep 5, 2017

dannylamb commented Sep 5, 2017

dannylamb commented Sep 5, 2017

dannylamb commented Sep 21, 2017

dannylamb commented Oct 10, 2017

birkland commented Oct 10, 2017

dannylamb commented Oct 11, 2017

dannylamb commented Oct 24, 2017

Exception thrown when requesting service docs #149

Exception thrown when requesting service docs #149

Comments

dannylamb commented Sep 5, 2017

birkland commented Sep 5, 2017

dannylamb commented Sep 5, 2017

dannylamb commented Sep 5, 2017

dannylamb commented Sep 21, 2017

dannylamb commented Oct 10, 2017

birkland commented Oct 10, 2017

dannylamb commented Oct 11, 2017

dannylamb commented Oct 24, 2017