REST

Posted by Roger Blanchard on 05-Feb-2015 11:30

We have created/deployed a rest project and are intermittently receiving a 500 (Internal server Error) as a response. If you try the REST call again it then works. If you then wait an hour and try again...same 500 error.

We are using basic authentication with ssl on the server. On the client we are using the .NET HttpWebRequest.

Any ideas how to track this error down?

OpenEdge Development - Forum

All Replies

Posted by Mike Fechner on 05-Feb-2015 11:40

Anything in the AppServer agent log? Maybe the appserver shut down and needs a little longer to start?

Von meinem Windows Phone gesendet
Von: rblanchard
Gesendet: ‎05.‎02.‎2015 17:31
An: TU.OE.Development@community.progress.com
Betreff: [Technical Users - OE Development] REST

Thread created by rblanchard

We have created/deployed a rest project and are intermittently receiving a 500 (Internal server Error) as a response. If you try the REST call again it then works. If you then wait an hour and try again...same 500 error.

We are using basic authentication with ssl on the server. On the client we are using the .NET HttpWebRequest.

Any ideas how to track this error down?

Stop receiving emails on this subject.

Flag this post as spam/abuse.

Posted by Roger Blanchard on 05-Feb-2015 11:51

Nothing in the appserver agent log at all when the error is returned. It is strange...I can run a test routine to hit the server over and over with no issue. However, if I let my app sit there for an hour and then test again it will fail on the first test.

Posted by egarcia on 05-Feb-2015 12:02

Hello,

If there are no entries in the AppServer server log file, the error may be happening at the REST Adapter level.

Are there any messages in the the service log file (WEB-INF/adapters/logs)?

What is the text returned with the error 500?

I hope this helps.

Posted by Roger Blanchard on 05-Feb-2015 12:10

Hey Edsel,

The test is "The remote server returned an error: (500) Internal Server Error.

In the adapters log file I see a bunch of errors at that timestamp.

2015-02-05 12:09:00.980 [INFO][REST] An HTTP Request received in Enabled State. Sending Request to the Adapter Servlet.

2015-02-05 12:09:00.980 [INFO][REST] OpenEdge Procedure name: PingServerRest.p

2015-02-05 12:09:00.980 [ERROR][REST] _REST [----------------] WRITEDATALAST IOException : java.net.SocketException: Connection reset by peer: socket write error (Connection reset by peer: socket write error)

2015-02-05 12:09:00.980 [ERROR][REST] java.net.SocketException: Connection reset by peer: socket write error

2015-02-05 12:09:00.980 [ERROR][REST] at java.net.SocketOutputStream.socketWrite0(Native Method)

2015-02-05 12:09:00.980 [ERROR][REST] at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:113)

2015-02-05 12:09:00.980 [ERROR][REST] at java.net.SocketOutputStream.write(SocketOutputStream.java:159)

2015-02-05 12:09:00.980 [ERROR][REST] at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)

2015-02-05 12:09:00.980 [ERROR][REST] at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)

2015-02-05 12:09:00.980 [ERROR][REST] at com.progress.ubroker.client.TcpClientMsgOutputStream.flushMsg(TcpClientMsgOutputStream.java:189)

2015-02-05 12:09:00.980 [ERROR][REST] at com.progress.ubroker.client.BrokerSystem.writeLastPacket(BrokerSystem.java:2818)

2015-02-05 12:09:00.980 [ERROR][REST] at com.progress.ubroker.client.BrokerSystem.prepareToReceive(BrokerSystem.java:1176)

2015-02-05 12:09:00.980 [ERROR][REST] at com.progress.open4gl.dynamicapi.SrcOutputStream.close(SrcOutputStream.java:105)

2015-02-05 12:09:00.980 [ERROR][REST] at com.progress.open4gl.dynamicapi.Session.runProcedure0(Session.java:1106)

2015-02-05 12:09:00.980 [ERROR][REST] at com.progress.open4gl.dynamicapi.Session.runProcedure(Session.java:799)

2015-02-05 12:09:00.980 [ERROR][REST] at com.progress.open4gl.dynamicapi.Session.runProcedure(Session.java:650)

2015-02-05 12:09:00.980 [ERROR][REST] at com.progress.open4gl.javaproxy.ProObject.runProcedure(ProObject.java:418)

2015-02-05 12:09:00.980 [ERROR][REST] at com.progress.open4gl.javaproxy.ProObject.runProcedure(ProObject.java:293)

2015-02-05 12:09:00.980 [ERROR][REST] at com.progress.open4gl.javaproxy.OpenAppObjectImpl.runProc(OpenAppObjectImpl.java:49)

2015-02-05 12:09:00.980 [ERROR][REST] at com.progress.open4gl.javaproxy.OpenAppObject.runProc(OpenAppObject.java:338)

2015-02-05 12:09:00.980 [ERROR][REST] at com.progress.caf.camel.component.oe.AppServerCamelEndpoint.runProcedure(AppServerCamelEndpoint.java:409)

2015-02-05 12:09:00.980 [ERROR][REST] at com.progress.caf.camel.component.oe.AppServerProducer.process(AppServerProducer.java:121)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.util.AsyncProcessorConverterHelper$ProcessorToAsyncProcessorBridge.process(AsyncProcessorConverterHelper.java:61)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.util.AsyncProcessorHelper.process(AsyncProcessorHelper.java:73)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.processor.SendProcessor$2.doInAsyncProducer(SendProcessor.java:120)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.impl.ProducerCache.doInAsyncProducer(ProducerCache.java:292)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.processor.SendProcessor.process(SendProcessor.java:115)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.util.AsyncProcessorHelper.process(AsyncProcessorHelper.java:73)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.processor.DelegateAsyncProcessor.processNext(DelegateAsyncProcessor.java:99)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.processor.DelegateAsyncProcessor.process(DelegateAsyncProcessor.java:90)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.management.InstrumentationProcessor.process(InstrumentationProcessor.java:73)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.util.AsyncProcessorHelper.process(AsyncProcessorHelper.java:73)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.processor.DelegateAsyncProcessor.processNext(DelegateAsyncProcessor.java:99)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.processor.DelegateAsyncProcessor.process(DelegateAsyncProcessor.java:90)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.processor.interceptor.TraceInterceptor.process(TraceInterceptor.java:91)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.util.AsyncProcessorHelper.process(AsyncProcessorHelper.java:73)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.processor.RedeliveryErrorHandler.processErrorHandler(RedeliveryErrorHandler.java:330)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:220)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.processor.RouteContextProcessor.processNext(RouteContextProcessor.java:45)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.processor.DelegateAsyncProcessor.process(DelegateAsyncProcessor.java:90)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.processor.interceptor.DefaultChannel.process(DefaultChannel.java:303)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.processor.RouteContextProcessor.processNext(RouteContextProcessor.java:45)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.processor.DelegateAsyncProcessor.process(DelegateAsyncProcessor.java:90)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.processor.UnitOfWorkProcessor.processAsync(UnitOfWorkProcessor.java:150)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.processor.UnitOfWorkProcessor.process(UnitOfWorkProcessor.java:117)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.processor.RouteInflightRepositoryProcessor.processNext(RouteInflightRepositoryProcessor.java:48)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.processor.DelegateAsyncProcessor.process(DelegateAsyncProcessor.java:90)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.util.AsyncProcessorHelper.process(AsyncProcessorHelper.java:73)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.processor.DelegateAsyncProcessor.processNext(DelegateAsyncProcessor.java:99)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.processor.DelegateAsyncProcessor.process(DelegateAsyncProcessor.java:90)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.management.InstrumentationProcessor.process(InstrumentationProcessor.java:73)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.util.AsyncProcessorHelper.process(AsyncProcessorHelper.java:99)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.camel.processor.DelegateAsyncProcessor.process(DelegateAsyncProcessor.java:86)

2015-02-05 12:09:00.980 [ERROR][REST] at com.progress.caf.camel.component.cxf.jaxrs.PrgRsInvoker.syncInvoke(PrgRsInvoker.java:162)

2015-02-05 12:09:00.980 [ERROR][REST] at com.progress.caf.camel.component.cxf.jaxrs.PrgRsInvoker.performInvocation(PrgRsInvoker.java:76)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:167)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:94)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:58)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:94)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:262)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:211)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:213)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:154)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:130)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:221)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doPost(AbstractHTTPServlet.java:141)

2015-02-05 12:09:00.980 [ERROR][REST] at javax.servlet.http.HttpServlet.service(HttpServlet.java:646)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:197)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)

2015-02-05 12:09:00.980 [ERROR][REST] at com.progress.rest.adapters.oe.OERestAdapterFilter.doFilter(OERestAdapterFilter.java:73)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)

2015-02-05 12:09:00.980 [ERROR][REST] at com.progress.rest.adapters.oe.OERequestFilter.doFilter(OERequestFilter.java:38)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)

2015-02-05 12:09:00.980 [ERROR][REST] at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:322)

2015-02-05 12:09:00.980 [ERROR][REST] at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:116)

2015-02-05 12:09:00.980 [ERROR][REST] at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:83)

2015-02-05 12:09:00.980 [ERROR][REST] at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)

2015-02-05 12:09:00.980 [ERROR][REST] at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:113)

2015-02-05 12:09:00.980 [ERROR][REST] at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)

2015-02-05 12:09:00.980 [ERROR][REST] at com.progress.rest.security.OEClientPrincipalFilter.doFilter(OEClientPrincipalFilter.java:291)

2015-02-05 12:09:00.980 [ERROR][REST] at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)

2015-02-05 12:09:00.980 [ERROR][REST] at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:113)

2015-02-05 12:09:00.980 [ERROR][REST] at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)

2015-02-05 12:09:00.980 [ERROR][REST] at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:54)

2015-02-05 12:09:00.980 [ERROR][REST] at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)

2015-02-05 12:09:00.980 [ERROR][REST] at org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilter(BasicAuthenticationFilter.java:201)

2015-02-05 12:09:00.980 [ERROR][REST] at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)

2015-02-05 12:09:00.980 [ERROR][REST] at com.progress.rest.security.OERequestHeaderAuthenticationFilter.doFilter(OERequestHeaderAuthenticationFilter.java:127)

2015-02-05 12:09:00.980 [ERROR][REST] at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)

2015-02-05 12:09:00.980 [ERROR][REST] at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:105)

2015-02-05 12:09:00.980 [ERROR][REST] at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)

2015-02-05 12:09:00.980 [ERROR][REST] at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:87)

2015-02-05 12:09:00.980 [ERROR][REST] at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)

2015-02-05 12:09:00.980 [ERROR][REST] at com.progress.rest.security.OECORSFilter.doFilter(OECORSFilter.java:362)

2015-02-05 12:09:00.980 [ERROR][REST] at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)

2015-02-05 12:09:00.980 [ERROR][REST] at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:184)

2015-02-05 12:09:00.980 [ERROR][REST] at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:155)

2015-02-05 12:09:00.980 [ERROR][REST] at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:237)

2015-02-05 12:09:00.980 [ERROR][REST] at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:167)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1040)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:607)

2015-02-05 12:09:00.980 [ERROR][REST] at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:315)

2015-02-05 12:09:00.980 [ERROR][REST] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

2015-02-05 12:09:00.980 [ERROR][REST] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

2015-02-05 12:09:00.980 [ERROR][REST] at java.lang.Thread.run(Thread.java:744)

2015-02-05 12:09:00.995 [ERROR][REST] _REST [----------------] READPACKET IOException : java.net.SocketException: Connection reset (Connection reset)

2015-02-05 12:09:00.995 [ERROR][REST] java.net.SocketException: Connection reset

2015-02-05 12:09:00.995 [ERROR][REST] at java.net.SocketInputStream.read(SocketInputStream.java:196)

2015-02-05 12:09:00.995 [ERROR][REST] at java.net.SocketInputStream.read(SocketInputStream.java:122)

2015-02-05 12:09:00.995 [ERROR][REST] at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)

2015-02-05 12:09:00.995 [ERROR][REST] at java.io.BufferedInputStream.read1(BufferedInputStream.java:275)

Posted by Michael Jacobs on 05-Feb-2015 12:10

The 500 response probably indicates the problem originates from the REST web application running in your Tomcat server.   The 500 may come from a number of places in that web application.  Because the 500 response appears to be related to elapsed clock time,  I might consider that the REST service is losing its connection to the back-end AppServer and the error comes during the reconnection.   Just a guess.

Perhaps increasing the logging level In the REST service's WEB-INF/adapters/runtime.props and then looking in the REST service's log file will provide additional information.

Posted by Michael Jacobs on 05-Feb-2015 12:41

The log file snippet you posted shows that the TCP/IP connection to the AppServer was dropped and the REST service stil thinks it exists.  It may be why you see one error and then things work again because the REST service now knows that it must reconnect.  

Is the AppServer being restarted during the idle time, or some network appliance is interrupting the connection?

Posted by Roger Blanchard on 05-Feb-2015 13:07

Hi Mike,

The appserver is not being restarted but it is possible we may have a config issue with our sonicwall. The tomcat server is in a segmented network outside of our LAN. We had to configure the sonic wall to open the appropriate ports to allow tomcat to communicate with the appserver.

Posted by Roger Blanchard on 05-Feb-2015 14:04

Michael,

We had to adjust our timeout for the access rule in our sonicwall. It was set to 15 minutes so after 15 minutes (not an hour as I said in my previous post) the sonic wall would drop the connection. We bumped it up and will monitor.

Thanks for looking at the log snippet...much appreciated.

Posted by Michael Jacobs on 05-Feb-2015 14:34

Happy to be of assistance.

Will you not still have the same problem of a single 500 status being returned when sonic wall times out after an hour?

Posted by Roger Blanchard on 05-Feb-2015 14:40

We bumped it up to 24 hours…we should never have inactivity for that long.
 
Thanks.
 
Roger Blanchard

.

This thread is closed