Dear all,
I run a handle server (version 9.3) on Debian 11 in a development environment (I hope to go into production in the next few months).
It works almost fine but I have an issue when I test our system with the creation of a few hundred handles (with the REST API).
Handle Server restarts every 90sec and is unavailable during restart.
I can see in the error.log
grep "25 S" error.log-20230917
[...]
"2023-09-19 07:40:32.124+0200" 25 Started new run.
"2023-09-19 07:42:01.239+0200" 25 Shutting down server at Tue Sep 19 07:42:01 CEST 2023
"2023-09-19 07:42:03.600+0200" 25 Started new run.
"2023-09-19 07:43:32.751+0200" 25 Shutting down server at Tue Sep 19 07:43:32 CEST 2023
"2023-09-19 07:43:35.361+0200" 25 Started new run.
"2023-09-19 07:45:04.482+0200" 25 Shutting down server at Tue Sep 19 07:45:04 CEST 2023
"2023-09-19 07:45:06.882+0200" 25 Started new run.
"2023-09-19 07:46:35.997+0200" 25 Shutting down server at Tue Sep 19 07:46:35 CEST 2023
"2023-09-19 07:46:38.664+0200" 25 Started new run.
"2023-09-19 07:48:07.742+0200" 25 Shutting down server at Tue Sep 19 07:48:07 CEST 2023
"2023-09-19 07:48:10.363+0200" 25 Started new run.
"2023-09-19 07:49:39.496+0200" 25 Shutting down server at Tue Sep 19 07:49:39 CEST 2023
"2023-09-19 07:49:41.883+0200" 25 Started new run.
"2023-09-19 07:51:11.003+0200" 25 Shutting down server at Tue Sep 19 07:51:10 CEST 2023
"2023-09-19 07:51:13.345+0200" 25 Started new run.
"2023-09-19 07:52:42.493+0200" 25 Shutting down server at Tue Sep 19 07:52:42 CEST 2023
"2023-09-19 07:52:44.889+0200" 25 Started new run.
A complete sequence of a restart in the error.log
"2023-09-19 07:55:45.501+0200" 25 Shutting down server at Tue Sep 19 07:55:45 CEST 2023
2023-09-19 07:55:45.630+0200 [Thread-21] INFO org.eclipse.jetty.server.handler.ContextHandler - Stopped o.e.j.w.WebAppContext@7cc9ce8{admin,/admin,null,UNAVAILABLE}{/admin.war}
2023-09-19 07:55:45.657+0200 [Thread-21] INFO org.eclipse.jetty.server.AbstractConnector - Stopped ServerConnector@6c15fb9d{ssl|other,[ssl|other, ssl, http/1.1]}{192.168.178.224:8000} 2023-09-19 07:55:45.660+0200 [Thread-21] INFO org.eclipse.jetty.server.session - node0 Stopped scavenging
2023-09-19 07:55:45.661+0200 [Thread-21] INFO org.eclipse.jetty.server.handler.ContextHandler - Stopped o.e.j.s.ServletContextHandler@5af9926a{/,jar:file:/usr/local/handle-9.3.0/lib/handle-9.3.0.jar!/net/handle/apps/servlet_proxy/resources/,UNAVAILABLE}
"2023-09-19 07:55:47.924+0200" 25 Started new run.
"2023-09-19 07:55:47.925+0200" 25 Handle.net Server Software version 9.3.0
2023-09-19 07:55:51.720+0200 [main] INFO org.eclipse.jetty.util.log - Logging initialized @4952ms to org.eclipse.jetty.util.log.Slf4jLog
2023-09-19 07:55:52.227+0200 [main] INFO org.eclipse.jetty.deploy.providers.ScanningAppProvider - Deployment monitor [file:///usr/local/hdl/webapps-priority] at interval 10
2023-09-19 07:55:52.228+0200 [main] WARN org.eclipse.jetty.deploy.providers.ScanningAppProvider - Does not exist: file:///usr/local/hdl/webapps-priority
2023-09-19 07:55:52.254+0200 [main] INFO org.eclipse.jetty.server.Server - jetty-9.4.15.v20190215; built: 2019-02-15T16:53:49.381Z; git: eb70b240169fcf1abbd86af36482d1c49826fa0b; jvm 11.0.13+8-post-Debian-1deb11u1
2023-09-19 07:55:52.323+0200 [main] INFO org.eclipse.jetty.server.session - DefaultSessionIdManager workerName=node0
2023-09-19 07:55:52.323+0200 [main] INFO org.eclipse.jetty.server.session - No SessionScavenger set, using defaults
2023-09-19 07:55:52.329+0200 [main] INFO org.eclipse.jetty.server.session - node0 Scavenging every 600000ms
2023-09-19 07:55:52.417+0200 [main] INFO org.eclipse.jetty.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@5af9926a{/,jar:file:/usr/local/handle-9.3.0/lib/handle-9.3.0.jar!/net/handle/apps/servlet_proxy/resources/,AVAILABLE}
2023-09-19 07:55:52.440+0200 [main] WARN org.eclipse.jetty.util.ssl.SslContextFactory.config - No Client EndPointIdentificationAlgorithm configured for SslContextFactory@7692cd34[provider=null,keyStore=null,trustStore=null]
2023-09-19 07:55:52.483+0200 [main] INFO org.eclipse.jetty.server.AbstractConnector - Started ServerConnector@69b7efbc{ssl|other,[ssl|other, ssl, http/1.1]}{192.168.178.224:8000} 2023-09-19 07:55:52.484+0200 [main] INFO org.eclipse.jetty.server.Server - Started @5717ms
2023-09-19 07:55:52.484+0200 [main] INFO org.eclipse.jetty.deploy.providers.ScanningAppProvider - Deployment monitor [file:///usr/local/hdl/webapps/] at interval 10
2023-09-19 07:55:53.412+0200 [main] INFO org.eclipse.jetty.server.handler.ContextHandler - Started o.e.j.w.WebAppContext@7cc9ce8{admin,/admin,file:///usr/local/hdl/webapps-temp/jetty-192.168.178.224-8000-admin.war-_admin-any-12581886331657068280.dir/webapp/,AVAILABLE}{/admin.war}
So the server is unavailable during around 7 sec. every 90 sec.
Our system creates Handle through the Rest API. And as we can see in the client Log, the creation request fails (of course) when the handle server restarts.
Client log :
2023/09/18 20:36:05 [error] 1628086#1628086: *137931 FastCGI sent in stderr: "PHP message: [info] Matched route "create_new".PHP message: [debug] Notified event "kernel.request" to listener "Symfony\Component\HttpKernel\EventListener\DebugHandlersListener::configure".PHP message: [debug] Notified event "kernel.request" to listener "Symfony\Component\HttpKernel\EventListener\ValidateRequestListener::onKernelRequest".PHP message: [debug] Notified event "kernel.request" to listener "Symfony\Component\HttpKernel\EventListener\LocaleListener::setDefaultLocale".PHP message: [debug] Notified event "kernel.request" to listener "Symfony\Component\HttpKernel\EventListener\RouterListener::onKernelRequest".PHP message: [debug] Notified event "kernel.request" to listener "Symfony\Component\HttpKernel\EventListener\LocaleListener::onKernelRequest".PHP message: [debug] Notified event "kernel.request" to listener "Symfony\Component\HttpKernel\EventListener\LocaleAwareListener::onKernelRequest".PHP message: [debug] Notified event "kernel.controller_arguments" to listener "Symfony\Component\HttpKernel\EventListener\ErrorListener::onControllerArguments".PHP message: [info] Request: "PUT https://192.168.178.224:8000/api/handles/20.500.13090/1io"PHP message: [critical] Uncaught PHP Exception Symfony\Component\Messenger\Exception\HandlerFailedException: "Handling "HandleApi\Message\HandleNotification" failed: Failed to connect to 192.168.178.224 port 8000: Connection refused for "https://192.168.178.224:8000/api/handles/20.500.13090/1io"." at /var/www/handle-api/vendor/symfony/messenger/Middleware/HandleMessageMiddleware.php line 130PHP message: [debug] Notified event "kernel.request" to listener "Symfony\Component\HttpKernel\EventListener\DebugHandlersListener::configure".PHP message: [debug] Notified event "kernel.request" to listener "Symfony\Component\HttpKernel\EventListener\ValidateRequestListener::onKernelRequest".PHP message: [debug] Notified event "kernel.request" to listener "Symfony\Component\HttpKernel\EventListener\Local
Handle logs (The server was restarting at this time) :
2023-09-18 20:36:00.702+0200" 25 Shutting down server at Mon Sep 18 20:36:00 CEST 2023
2023-09-18 20:36:00.855+0200 [Thread-21] INFO org.eclipse.jetty.server.handler.ContextHandler - Stopped o.e.j.w.WebAppContext@7cc9ce8{admin,/admin,null,UNAVAILABLE}{/admin.war}
2023-09-18 20:36:00.878+0200 [Thread-21] INFO org.eclipse.jetty.server.AbstractConnector - Stopped ServerConnector@7b804ef0{ssl|other,[ssl|other, ssl, http/1.1]}{192.168.178.224:8000} 2023-09-18 20:36:00.880+0200 [Thread-21] INFO org.eclipse.jetty.server.session - node0 Stopped scavenging
2023-09-18 20:36:00.882+0200 [Thread-21] INFO org.eclipse.jetty.server.handler.ContextHandler - Stopped o.e.j.s.ServletContextHandler@5af9926a{/,jar:file:/usr/local/handle-9.3.0/lib/handle-9.3.0.jar!/net/handle/apps/servlet_proxy/resources/,UNAVAILABLE}
"2023-09-18 20:36:03.179+0200" 25 Started new run.
"2023-09-18 20:36:03.182+0200" 25 Handle.net Server Software version 9.3.0
2023-09-18 20:36:06.231+0200 [main] INFO org.eclipse.jetty.util.log - Logging initialized @4210ms to org.eclipse.jetty.util.log.Slf4jLog
2023-09-18 20:36:06.419+0200 [main] INFO org.eclipse.jetty.deploy.providers.ScanningAppProvider - Deployment monitor [file:///usr/local/hdl/webapps-priority] at interval 10
2023-09-18 20:36:06.419+0200 [main] WARN org.eclipse.jetty.deploy.providers.ScanningAppProvider - Does not exist: file:///usr/local/hdl/webapps-priority
2023-09-18 20:36:06.439+0200 [main] INFO org.eclipse.jetty.server.Server - jetty-9.4.15.v20190215; built: 2019-02-15T16:53:49.381Z; git: eb70b240169fcf1abbd86af36482d1c49826fa0b; jvm 11.0.13+8-post-Debian-1deb11u1
2023-09-18 20:36:06.467+0200 [main] INFO org.eclipse.jetty.server.session - DefaultSessionIdManager workerName=node0
2023-09-18 20:36:06.467+0200 [main] INFO org.eclipse.jetty.server.session - No SessionScavenger set, using defaults
2023-09-18 20:36:06.469+0200 [main] INFO org.eclipse.jetty.server.session - node0 Scavenging every 660000ms
2023-09-18 20:36:06.517+0200 [main] INFO org.eclipse.jetty.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@5af9926a{/,jar:file:/usr/local/handle-9.3.0/lib/handle-9.3.0.jar!/net/handle/apps/servlet_proxy/resources/,AVAILABLE}
2023-09-18 20:36:06.528+0200 [main] WARN org.eclipse.jetty.util.ssl.SslContextFactory.config - No Client EndPointIdentificationAlgorithm configured for SslContextFactory@7692cd34[provider=null,keyStore=null,trustStore=null]
2023-09-18 20:36:06.551+0200 [main] INFO org.eclipse.jetty.server.AbstractConnector - Started ServerConnector@13bb9b3a{ssl|other,[ssl|other, ssl, http/1.1]}{192.168.178.224:8000} 2023-09-18 20:36:06.552+0200 [main] INFO org.eclipse.jetty.server.Server - Started @4533ms
2023-09-18 20:36:06.552+0200 [main] INFO org.eclipse.jetty.deploy.providers.ScanningAppProvider - Deployment monitor [file:///usr/local/hdl/webapps/] at interval 10
2023-09-18 20:36:07.000+0200 [main] INFO org.eclipse.jetty.server.handler.ContextHandler - Started o.e.j.w.WebAppContext@7cc9ce8{admin,/admin,file:///usr/local/hdl/webapps-temp/jetty-192.168.178.224-8000-admin.war-_admin-any-17601826751320838032.dir/webapp/,AVAILABLE}{/admin.war}
Do you know why the Handle server restarts so often?
Could it restart (much) less often? And how can I configure it to do so?
Thanks in advance for your help.
Regards,
Jean-François
-- Jean-François Rivière
OpenEdition, service données