search

ozwillo / ozwillo-datacore

Ozwillo Datacore is a Cloud of shared Open Linked Data. Its goal is cross-business data collaboration and integration. By linking data from different business together, it allows creating value by developing new Ozwillo services on top of it.
http://www.ozwillo.com
GNU Affero General Public License v3.0
3 stars 2 forks source link

500 Server Error thrown on error in kernel communication #36

Closed schambon closed 9 years ago

schambon commented 10 years ago

This is not really a data core issue, but we have infrequently the following error:

20-02-2014 11:36:03 AntPathRequestMatcher [DEBUG] Checking match of request : '/dc/type/citizenkin.procedure.envelope/9a3addfd-0541-4aac-a251-dd24a206a4
3f'; against '/dc/**'
20-02-2014 11:36:03 FilterChainProxy [DEBUG] /dc/type/citizenkin.procedure.envelope/9a3addfd-0541-4aac-a251-dd24a206a43f at position 1 of 9 in additiona
l filter chain; firing Filter: 'SecurityContextPersistenceFilter'
20-02-2014 11:36:03 HttpSessionSecurityContextRepository [DEBUG] No HttpSession currently exists
20-02-2014 11:36:03 HttpSessionSecurityContextRepository [DEBUG] No SecurityContext was available from the HttpSession: null. A new one will be created.
20-02-2014 11:36:03 FilterChainProxy [DEBUG] /dc/type/citizenkin.procedure.envelope/9a3addfd-0541-4aac-a251-dd24a206a43f at position 2 of 9 in additiona
l filter chain; firing Filter: 'BasicAuthenticationFilter'
20-02-2014 11:36:03 FilterChainProxy [DEBUG] /dc/type/citizenkin.procedure.envelope/9a3addfd-0541-4aac-a251-dd24a206a43f at position 3 of 9 in additiona
l filter chain; firing Filter: 'OAuth2AuthenticationProcessingFilter'
20-02-2014 11:36:03 RestTemplate [DEBUG] Created POST request for "https://oasis-demo.atolcd.com/a/tokeninfo"
20-02-2014 11:36:03 RestTemplate [DEBUG] Setting request Accept header to [application/json]
20-02-2014 11:36:03 RestTemplate [DEBUG] Writing [{token=[eyJpZCI6IjM3MGIyYWFlLTU0OWEtNDQxMC1hNmEyLTc1N2Q1MDc4MTkyZiIsImlhdCI6MTM5Mjg5MTk2NjUxNSwiZXhwIj
oxMzkyODk1NTY2NTE1fQ]}] as "application/x-www-form-urlencoded" using [org.springframework.http.converter.xml.XmlAwareFormHttpMessageConverter@94611a]
20-02-2014 11:36:03 HttpSessionSecurityContextRepository [DEBUG] SecurityContext is empty or contents are anonymous - context will not be stored in Http
Session.
20-02-2014 11:36:03 SecurityContextPersistenceFilter [DEBUG] SecurityContextHolder now cleared, as request processing completed
2014-02-20 11:36:03.097:WARN:oejs.ServletHandler:/dc/type/citizenkin.procedure.envelope/9a3addfd-0541-4aac-a251-dd24a206a43f
org.springframework.web.client.ResourceAccessException: I/O error: Unexpected end of file from server; nested exception is java.net.SocketException: Une
xpected end of file from server
        at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:461)
        at org.springframework.web.client.RestTemplate.execute(RestTemplate.java:409)
        at org.springframework.web.client.RestTemplate.exchange(RestTemplate.java:385)
        at org.oasis.datacore.core.security.oauth2.RemoteTokenServices.postForMap(RemoteTokenServices.java:178)
        at org.oasis.datacore.core.security.oauth2.RemoteTokenServices.loadAuthentication(RemoteTokenServices.java:102)
        at org.springframework.security.oauth2.provider.authentication.OAuth2AuthenticationManager.authenticate(OAuth2AuthenticationManager.java:70)
        at org.springframework.security.oauth2.provider.authentication.OAuth2AuthenticationProcessingFilter.doFilter(OAuth2AuthenticationProcessingFilte
r.java:108)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilter(BasicAuthenticationFilter.java:150)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:87)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:192)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:160)
        at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:346)
        at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:259)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1474)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:499)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137)
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:557)
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:231)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1086)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:428)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1020)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
        at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:255)
        at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:154)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
        at org.eclipse.jetty.server.Server.handle(Server.java:370)
        at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:489)
        at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:949)
        at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:1011)
        at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:644)
        at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235)
        at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)
        at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:668)
        at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:52)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
        at java.lang.Thread.run(Thread.java:744)
Caused by: 
java.net.SocketException: Unexpected end of file from server
        at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:772)
        at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:633)
        at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1323)
        at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:468)
        at sun.net.www.protocol.https.HttpsURLConnectionImpl.getResponseCode(HttpsURLConnectionImpl.java:338)
        at org.springframework.http.client.SimpleClientHttpResponse.getRawStatusCode(SimpleClientHttpResponse.java:47)
        at org.springframework.http.client.AbstractClientHttpResponse.getStatusCode(AbstractClientHttpResponse.java:32)
        at org.springframework.web.client.DefaultResponseErrorHandler.getStatusCode(DefaultResponseErrorHandler.java:54)
        at org.springframework.web.client.DefaultResponseErrorHandler.hasError(DefaultResponseErrorHandler.java:48)
        at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:447)
        at org.springframework.web.client.RestTemplate.execute(RestTemplate.java:409)
        at org.springframework.web.client.RestTemplate.exchange(RestTemplate.java:385)
        at org.oasis.datacore.core.security.oauth2.RemoteTokenServices.postForMap(RemoteTokenServices.java:178)
        at org.oasis.datacore.core.security.oauth2.RemoteTokenServices.loadAuthentication(RemoteTokenServices.java:102)
        at org.springframework.security.oauth2.provider.authentication.OAuth2AuthenticationManager.authenticate(OAuth2AuthenticationManager.java:70)
        at org.springframework.security.oauth2.provider.authentication.OAuth2AuthenticationProcessingFilter.doFilter(OAuth2AuthenticationProcessingFilte
r.java:108)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilter(BasicAuthenticationFilter.java:150)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:87)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:192)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:160)
        at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:346)
        at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:259)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1474)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:499)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137)
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:557)
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:231)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1086)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:428)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1020)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
        at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:255)
        at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:154)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
        at org.eclipse.jetty.server.Server.handle(Server.java:370)
        at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:489)
        at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:949)
        at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:1011)
        at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:644)
        at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235)
        at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)
        at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:668)
        at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:52)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
        at java.lang.Thread.run(Thread.java:744)

From a client's POV we just get a 500 error (i.e. datacore unavailable).

A few things I can see from there:

schambon commented 10 years ago

NB - of course, this is a "random" event. We can't supply steps to reproduce.

tbroyer commented 10 years ago

I cannot find anything on our side: absolutely nothing in today's logs on the kernel side (just one line, at 12:05 UTC+1, from Citizen Kin trying to register a webHook for an event it already had subscribed to), and I can't find anything wrong on the reverse-proxy side either (a few timeouts and invalid Content-Length, but the timestamps don't match).

mdutoo commented 10 years ago

nothing in datacore logs:

at 11:33 a spammer GET error (looks for mysqladmin), then

20-02-2014 13:28:46 LoggingInInterceptor [INFO] Inbound Message

ID: 521 Address: http://srv2-polenum.fingerprint-technologies.net/dc/type/citizenkin.procedure.envelope?start=0&limit=100&initiator=%22organization:a2342900-f9eb-4d54-bf30-1e0d763ec4af,person:bb2c6f76-362f-46aa-982c-1fc60d54b8ef%22&state=$in%5B%22DRAFT%22,%22SENT%22,%22SENTBACK%22,%22RECEIVED%22%5D Http-Method: GET

=> your error is not visible on our side (though it should be as the above log shows), and the business id 9a3addfd-0541-4aac-a251-dd24a206a43f is nowhere on our logs either.

schambon commented 10 years ago

Hi Marc,

This happened not on the integration dc, but on my local deployment on my machine. Which is why I copied the logs in the issue. (This is, however, plugged into the integration kernel).

We have both seen this several times. So far not on the integration server, but we've used it a lot less extensively.

It's strange that nothing shows up on the kernel server. It could possibly be our network connection, we have had weird behaviours in the past.

In any case we should remain vigilant lest this bug appears in production.

mdutoo commented 10 years ago

OK, I get it.

mdutoo commented 9 years ago

This bug has not been seen for a long time, and there is nothing in current logs, neither Datacore's in dev or prod since 22 of July, nor Portal's in preprod since 27of July (which is since end of July Datacore's biggest user with the new Organization feature), so I'm closing it for now.