Service is stuck / not responding

[shaig4]

on windows machine, happens sporadicly, sometimes after 30~ minutes of work, sometimes starting in a stuck mode.

logs:

[INFO ] 2019-06-12 10:47:50,330 org.hibernate.validator.internal.util.Version - HV000001: Hibernate Validator 6.0.16.Final [INFO ] 2019-06-12 10:47:50,607 org.springframework.security.web.DefaultSecurityFilterChain - Creating filter chain: Ant [pattern='/static/'], [] [INFO ] 2019-06-12 10:47:50,607 org.springframework.security.web.DefaultSecurityFilterChain - Creating filter chain: Ant [pattern='/views/'], [] [INFO ] 2019-06-12 10:47:50,640 org.springframework.security.web.DefaultSecurityFilterChain - Creating filter chain: any request, [org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter@2cc7b63d, org.springframework.security.web.context.SecurityContextPersistenceFilter@d96f413, org.springframework.security.web.header.HeaderWriterFilter@555b3ec9, org.springframework.security.web.csrf.CsrfFilter@7893b8c, org.springframework.security.web.authentication.logout.LogoutFilter@4a4352b4, org.springframework.security.web.authentication.UsernamePasswordAuthenticationFilter@1f9a5d3b, org.springframework.security.web.authentication.www.BasicAuthenticationFilter@56adb75e, org.springframework.security.web.savedrequest.RequestCacheAwareFilter@3423f353, org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter@301b89e1, org.springframework.security.web.authentication.AnonymousAuthenticationFilter@6179551b, org.springframework.security.web.session.SessionManagementFilter@43945480, org.springframework.security.web.access.ExceptionTranslationFilter@144fc5fa, org.springframework.security.web.access.intercept.FilterSecurityInterceptor@4dfbe8c2] [INFO ] 2019-06-12 10:47:50,809 org.springframework.web.context.ContextLoader - Root WebApplicationContext initialized in 4879 ms [INFO ] 2019-06-12 10:47:50,871 org.eclipse.jetty.server.handler.ContextHandler.steve - Initializing Spring DispatcherServlet 'spring-dispatcher' [INFO ] 2019-06-12 10:47:50,871 org.springframework.web.servlet.DispatcherServlet - Initializing Servlet 'spring-dispatcher' [INFO ] 2019-06-12 10:47:50,877 org.springframework.web.servlet.DispatcherServlet - Completed initialization in 6 ms [INFO ] 2019-06-12 10:47:50,896 org.eclipse.jetty.server.handler.ContextHandler - Started o.e.j.w.WebAppContext@6921ce3f{/steve,jar:file:/C:/projects/ocpp/steve/target/steve.jar!/webapp,AVAILABLE} [INFO ] 2019-06-12 10:47:50,917 org.eclipse.jetty.server.AbstractConnector - Started ServerConnector@273c4b3{HTTP/1.1,[http/1.1]}{127.0.0.1:8080} [INFO ] 2019-06-12 10:47:50,917 org.eclipse.jetty.server.Server - Started @6606ms [INFO ] 2019-06-12 10:53:08,051 org.eclipse.jetty.server.AbstractConnector - Stopped ServerConnector@273c4b3{HTTP/1.1,[http/1.1]}{127.0.0.1:8080} [INFO ] 2019-06-12 10:53:08,051 org.eclipse.jetty.server.session - node0 Stopped scavenging [INFO ] 2019-06-12 10:53:08,055 org.eclipse.jetty.server.handler.ContextHandler.steve - Destroying Spring FrameworkServlet 'spring-dispatcher' [INFO ] 2019-06-12 10:53:08,060 com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Shutdown initiated... [INFO ] 2019-06-12 10:53:08,073 com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Shutdown completed. [INFO ] 2019-06-12 10:53:08,076 org.eclipse.jetty.server.handler.ContextHandler.steve - Closing Spring root WebApplicationContext [INFO ] 2019-06-12 10:53:08,094 org.eclipse.jetty.server.handler.ContextHandler - Stopped o.e.j.w.WebAppContext@6921ce3f{/steve,jar:file:/C:/projects/ocpp/steve/target/steve.jar!/webapp,UNAVAILABLE} [INFO ] 2019-06-12 10:55:08,870 de.rwth.idsg.steve.utils.PropertiesFileLoader - Hint: The Java system property 'main.properties' can be set to point to an external properties file, which will be prioritized over the bundled one [INFO ] 2019-06-12 10:55:09,259 de.rwth.idsg.steve.Application - Loaded the properties. Starting with the 'PROD' profile [INFO ] 2019-06-12 10:55:09,275 de.rwth.idsg.steve.Application - Date/time zone of the application is set to UTC. Current date/time: 2019-06-12T07:55:09.264Z [INFO ] 2019-06-12 10:55:09,299 org.eclipse.jetty.util.log - Logging initialized @1126ms to org.eclipse.jetty.util.log.Slf4jLog [INFO ] 2019-06-12 10:55:09,481 org.eclipse.jetty.server.Server - jetty-9.4.17.v20190418; built: 2019-04-18T19:45:35.259Z; git: aa1c656c315c011c01e7b21aabb04066635b9f67; jvm 11.0.2+9-LTS [INFO ] 2019-06-12 10:55:09,591 org.eclipse.jetty.server.session - DefaultSessionIdManager workerName=node0 [INFO ] 2019-06-12 10:55:09,591 org.eclipse.jetty.server.session - No SessionScavenger set, using defaults [INFO ] 2019-06-12 10:55:09,591 org.eclipse.jetty.server.session - node0 Scavenging every 600000ms [INFO ] 2019-06-12 10:55:09,595 org.eclipse.jetty.server.handler.ContextHandler.steve - Initializing Spring root WebApplicationContext

[goekay]

can you give more info about your hardware and environment? can you recognise any pattern when and why this happens? what do you mean with stuck? the application becomes unresponsive or something else?

[shaig4]

after some time the service is on, it becomes unresponsive, ie it any connection to port 8080 are falling on timeout. both website and websocket. i have no logs for the crash , last log line - is "org.eclipse.jetty.server.Server - Started @6765ms"

JDK 11

OS Name: Microsoft Windows 10 Pro OS Version: 10.0.17134 N/A Build 17134 OS Manufacturer: Microsoft Corporation OS Configuration: Member Workstation OS Build Type: Multiprocessor Free Product ID: 00330-80000-00000-AA310 Original Install Date: 03-Feb-19, 10:18:02 System Boot Time: 11-Jun-19, 11:46:45 System Manufacturer: Dell Inc. System Model: Latitude 5490 System Type: x64-based PC Processor(s): 1 Processor(s) Installed. [01]: Intel64 Family 6 Model 142 Stepping 10 GenuineIntel ~1910 Mhz BIOS Version: Dell Inc. 1.5.0, 27-Aug-18 Windows Directory: C:\Windows System Directory: C:\Windows\system32 Boot Device: \Device\HarddiskVolume2 System Locale: en-us;English (United States) Input Locale: en-us;English (United States) Time Zone: (UTC+02:00) Jerusalem Total Physical Memory: 16,245 MB Available Physical Memory: 4,142 MB Virtual Memory: Max Size: 27,014 MB Virtual Memory: Available: 3,556 MB Virtual Memory: In Use: 23,458 MB

[goekay]

i really cannot pinpoint the cause. but here are my thoughts:

• i guess the java application itself (and therefore java virtual machine) continues to work fine, since otherwise you should get some error and the jvm process would be killed, which should appear in the logs. maybe look at the java process in windows task manager to see if there are any suspicious cues.
• try changing the log level from INFO to DEBUG to enable more events to be logged. these might indicate what might be wrong. especially in cases where you make http requests (website and websocket), from the arrival of the request until finishing the processing and returning a response you should see many logged steps.
• i suspect some problem with your networking. check your network configuration etc.

[goekay]

closing this issue due to inactivity.

[shaig4]

our workaround: installed this on ubuntu machine, and it works (very) good there...

[lincomatic]

I'm having the same problem on Debian 9. I had previously been running 3.2.0 with MariaDB for months, and it worked great. I had to upgrade to MySQL 8.0 to install 3.3.0. It runs OK in 3.3.0 for a few minutes, then stops responding. Both the web interface freezes and the CS stops talking to my charge point. The web UI and CS still have sockets open, just no data get sent. When I kill steve, then the web UI and the CP get their sockets closed. I checked the log, and there is nothing unusual. How do I change the log level to DEBUG? I can't find anything in settings or the properties file. Should I open a new case, or just use this one?

[lincomatic]

I opened a new issue https://github.com/RWTH-i5-IDSG/steve/issues/160

[goekay]

@shaig4 we identified and fixed the problem (see my comment). i just made a bugfix release with this change only.