search

riesgos / async

0 stars 0 forks source link

Sometimes one or more processes just get stuck running #44

Open MichaelLangbein opened 1 year ago

MichaelLangbein commented 1 year ago

This is hard to debug, I'm afraid ... Sometimes processes will just remain in Running state. The logs for their wrapper or for the wps show nothing notable.

Example: currently, my shakyground process is stuck.

Logs shakyground-wrapper:

async-shakyground_wrapper-1  | order message handler receiver: {"orderId":1}
async-shakyground_wrapper-1  | 2023-01-17 08:14:43,607 [shakyground-asyncwrapper_new-order_subscription] INFO  AbstractWrapper: Got new order to handle with wrapper 1
async-shakyground_wrapper-1  | 2023-01-17 08:14:43,608 [shakyground-asyncwrapper_new-order_subscription] INFO  AbstractWrapper: Added literal input constraint for shakyground vsgrid: USGSSlopeBasedTopographyProxy
async-shakyground_wrapper-1  | 2023-01-17 08:14:43,608 [shakyground-asyncwrapper_new-order_subscription] INFO  AbstractWrapper: Added literal input constraint for shakyground gmpe: MontalvaEtAl2016SInter
async-shakyground_wrapper-1  | 2023-01-17 08:14:43,608 [shakyground-asyncwrapper_new-order_subscription] INFO  AbstractWrapper: Added complex input constraint for shakyground quakeMLFile
async-shakyground_wrapper-1  | 2023-01-17 08:14:43,608 [shakyground-asyncwrapper_new-order_subscription] INFO  AbstractWrapper: Parsed constraints
async-shakyground_wrapper-1  | 2023-01-17 08:14:43,608 [shakyground-asyncwrapper_new-order_subscription] INFO  AbstractWrapper: Define the literal constraints for the jobs
async-shakyground_wrapper-1  | 2023-01-17 08:14:43,608 [shakyground-asyncwrapper_new-order_subscription] INFO  AbstractWrapper: Define the complex constraints for the jobs
async-shakyground_wrapper-1  | 2023-01-17 08:14:43,608 [shakyground-asyncwrapper_new-order_subscription] INFO  AbstractWrapper: Define the bbox constraints for the jobs
async-shakyground_wrapper-1  | 2023-01-17 08:14:43,608 [shakyground-asyncwrapper_new-order_subscription] INFO  AbstractWrapper: Process job
async-shakyground_wrapper-1  | 2023-01-17 08:14:43,610 [shakyground-asyncwrapper_new-order_subscription] INFO  AbstractWrapper: Lookup the process id
async-shakyground_wrapper-1  | 2023-01-17 08:14:43,610 [shakyground-asyncwrapper_new-order_subscription] INFO  AbstractWrapper: Got the procss id 4
async-shakyground_wrapper-1  | 2023-01-17 08:14:43,611 [shakyground-asyncwrapper_new-order_subscription] INFO  AbstractWrapper: Created one job
async-shakyground_wrapper-1  | 2023-01-17 08:14:43,612 [shakyground-asyncwrapper_new-order_subscription] INFO  AbstractWrapper: Added literal input for vsgrid: USGSSlopeBasedTopographyProxy
async-shakyground_wrapper-1  | 2023-01-17 08:14:43,612 [shakyground-asyncwrapper_new-order_subscription] INFO  AbstractWrapper: Added literal input for gmpe: MontalvaEtAl2016SInter
async-shakyground_wrapper-1  | 2023-01-17 08:14:43,613 [shakyground-asyncwrapper_new-order_subscription] INFO  AbstractWrapper: Added complex input (as value) for quakeMLFile
async-shakyground_wrapper-1  | 2023-01-17 08:14:43,613 [shakyground-asyncwrapper_new-order_subscription] INFO  AbstractWrapper: Added job to order
async-shakyground_wrapper-1  | 2023-01-17 08:14:43,614 [shakyground-asyncwrapper_new-order_subscription] INFO  AbstractWrapper: Start mapping to wps inputs
async-shakyground_wrapper-1  | 2023-01-17 08:14:43,614 [shakyground-asyncwrapper_new-order_subscription] INFO  org.n52.geoprocessing.wps.client.WPSClientSession: CONNECT
async-shakyground_wrapper-1  | order message handler receiver: {"orderId":1}
async-shakyground_wrapper-1  | 2023-01-17 08:14:45,934 [shakyground-asyncwrapper_quakeledger-success_subscription] INFO  AbstractWrapper: Got new order to handle with wrapper 1
async-shakyground_wrapper-1  | 2023-01-17 08:14:45,935 [shakyground-asyncwrapper_quakeledger-success_subscription] INFO  AbstractWrapper: Added literal input constraint for shakyground vsgrid: USGSSlopeBasedTopographyProxy
async-shakyground_wrapper-1  | 2023-01-17 08:14:45,935 [shakyground-asyncwrapper_quakeledger-success_subscription] INFO  AbstractWrapper: Added literal input constraint for shakyground gmpe: MontalvaEtAl2016SInter
async-shakyground_wrapper-1  | 2023-01-17 08:14:45,935 [shakyground-asyncwrapper_quakeledger-success_subscription] INFO  AbstractWrapper: Added complex input constraint for shakyground quakeMLFile
async-shakyground_wrapper-1  | 2023-01-17 08:14:45,935 [shakyground-asyncwrapper_quakeledger-success_subscription] INFO  AbstractWrapper: Parsed constraints
async-shakyground_wrapper-1  | 2023-01-17 08:14:45,935 [shakyground-asyncwrapper_quakeledger-success_subscription] INFO  AbstractWrapper: Define the literal constraints for the jobs
async-shakyground_wrapper-1  | 2023-01-17 08:14:45,935 [shakyground-asyncwrapper_quakeledger-success_subscription] INFO  AbstractWrapper: Define the complex constraints for the jobs
async-shakyground_wrapper-1  | 2023-01-17 08:14:45,936 [shakyground-asyncwrapper_quakeledger-success_subscription] INFO  AbstractWrapper: Define the bbox constraints for the jobs
async-shakyground_wrapper-1  | 2023-01-17 08:14:45,936 [shakyground-asyncwrapper_quakeledger-success_subscription] INFO  AbstractWrapper: Process job
async-shakyground_wrapper-1  | 2023-01-17 08:14:45,938 [shakyground-asyncwrapper_quakeledger-success_subscription] INFO  AbstractWrapper: Lookup the process id
async-shakyground_wrapper-1  | 2023-01-17 08:14:45,938 [shakyground-asyncwrapper_quakeledger-success_subscription] INFO  AbstractWrapper: Got the procss id 4
async-shakyground_wrapper-1  | 2023-01-17 08:14:45,939 [shakyground-asyncwrapper_quakeledger-success_subscription] INFO  AbstractWrapper: Created one job
async-shakyground_wrapper-1  | 2023-01-17 08:14:45,939 [shakyground-asyncwrapper_quakeledger-success_subscription] INFO  AbstractWrapper: Added literal input for vsgrid: USGSSlopeBasedTopographyProxy
async-shakyground_wrapper-1  | 2023-01-17 08:14:45,940 [shakyground-asyncwrapper_quakeledger-success_subscription] INFO  AbstractWrapper: Added literal input for gmpe: MontalvaEtAl2016SInter
async-shakyground_wrapper-1  | 2023-01-17 08:14:45,941 [shakyground-asyncwrapper_quakeledger-success_subscription] INFO  AbstractWrapper: Added complex input (as value) for quakeMLFile
async-shakyground_wrapper-1  | 2023-01-17 08:14:45,941 [shakyground-asyncwrapper_quakeledger-success_subscription] INFO  AbstractWrapper: Added job to order
async-shakyground_wrapper-1  | 2023-01-17 08:14:45,942 [shakyground-asyncwrapper_quakeledger-success_subscription] INFO  AbstractWrapper: Start mapping to wps inputs
async-shakyground_wrapper-1  | 2023-01-17 08:14:45,942 [shakyground-asyncwrapper_quakeledger-success_subscription] INFO  org.n52.geoprocessing.wps.client.WPSClientSession: CONNECT
async-shakyground_wrapper-1  | 2023-01-17 08:15:34,439 [pulsar-timer-9-1] INFO  org.apache.pulsar.client.impl.ConsumerStatsRecorderImpl: [new-order] [shakyground-asyncwrapper_new-order_subscription] [3f3b9] Prefetched messages: 0 --- Consume throughput received: 0.05 msgs/s --- 0.00 Mbit/s --- Ack sent rate: 0.03 ack/s --- Failed messages: 0 --- batch messages: 0 ---Failed acks: 0
async-shakyground_wrapper-1  | 2023-01-17 08:15:34,441 [pulsar-timer-8-1] INFO  org.apache.pulsar.client.impl.ConsumerStatsRecorderImpl: [quakeledger-success] [shakyground-asyncwrapper_quakeledger-success_subscription] [24cc5] Prefetched messages: 0 --- Consume throughput received: 0.02 msgs/s --- 0.00 Mbit/s --- Ack sent rate: 0.00 ack/s --- Failed messages: 0 --- batch messages: 0 ---Failed acks: 0

Logs wps:

async-riesgos-wps-1  | 17-Jan-2023 07:22:29.727 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
async-riesgos-wps-1  | 17-Jan-2023 07:22:29.736 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in [13611] milliseconds
async-riesgos-wps-1  | 2023-01-17 08:14:43,202 [http-nio-8080-exec-3] WARN  org.n52.wps.server.request.Request: Parameter <language> not found.
async-riesgos-wps-1  | 2023-01-17 08:14:43,202 [http-nio-8080-exec-1] WARN  org.n52.wps.server.request.Request: Parameter <language> not found.
async-riesgos-wps-1  | 2023-01-17 08:14:43,202 [http-nio-8080-exec-2] WARN  org.n52.wps.server.request.Request: Parameter <language> not found.
async-riesgos-wps-1  | 2023-01-17 08:14:43,202 [http-nio-8080-exec-4] WARN  org.n52.wps.server.request.Request: Parameter <language> not found.
async-riesgos-wps-1  | 2023-01-17 08:14:43,203 [http-nio-8080-exec-3] INFO  org.n52.wps.server.request.Request: Handled GetCapabilitiesRequest successfully!
async-riesgos-wps-1  | 2023-01-17 08:14:43,203 [http-nio-8080-exec-1] INFO  org.n52.wps.server.request.Request: Handled GetCapabilitiesRequest successfully!
async-riesgos-wps-1  | 2023-01-17 08:14:43,203 [http-nio-8080-exec-4] INFO  org.n52.wps.server.request.Request: Handled GetCapabilitiesRequest successfully!
async-riesgos-wps-1  | 2023-01-17 08:14:43,203 [http-nio-8080-exec-2] INFO  org.n52.wps.server.request.Request: Handled GetCapabilitiesRequest successfully!
async-riesgos-wps-1  | 2023-01-17 08:14:43,206 [http-nio-8080-exec-2] INFO  org.n52.wps.webapp.util.ResourcePathUtil: Resolved webapp resource'config/wpsCapabilitiesSkeleton.xml' to '/usr/local/tomcat/webapps/wps/config/wpsCapabilitiesSkeleton.xml'
async-riesgos-wps-1  | 2023-01-17 08:14:43,218 [http-nio-8080-exec-2] INFO  org.n52.wps.webapp.util.JDomUtil: /usr/local/tomcat/webapps/wps/config/wpsCapabilitiesSkeleton.xml is parsed and a Document is returned.
async-riesgos-wps-1  | 2023-01-17 08:14:43,220 [http-nio-8080-exec-2] INFO  org.n52.wps.webapp.dao.XmlCapabilitiesDAO: '/usr/local/tomcat/webapps/wps/config/wpsCapabilitiesSkeleton.xml' is parsed and a ServiceIdentification object is returned
async-riesgos-wps-1  | 2023-01-17 08:14:43,220 [http-nio-8080-exec-2] INFO  org.n52.wps.webapp.util.ResourcePathUtil: Resolved webapp resource'config/wpsCapabilitiesSkeleton.xml' to '/usr/local/tomcat/webapps/wps/config/wpsCapabilitiesSkeleton.xml'
async-riesgos-wps-1  | 2023-01-17 08:14:43,221 [http-nio-8080-exec-2] INFO  org.n52.wps.webapp.util.JDomUtil: /usr/local/tomcat/webapps/wps/config/wpsCapabilitiesSkeleton.xml is parsed and a Document is returned.
async-riesgos-wps-1  | 2023-01-17 08:14:43,222 [http-nio-8080-exec-2] INFO  org.n52.wps.webapp.dao.XmlCapabilitiesDAO: '/usr/local/tomcat/webapps/wps/config/wpsCapabilitiesSkeleton.xml' is parsed and a ServiceProvider object is returned
async-riesgos-wps-1  | 2023-01-17 08:14:43,408 [http-nio-8080-exec-5] WARN  org.n52.wps.server.request.Request: Parameter <language> not found.
async-riesgos-wps-1  | 2023-01-17 08:14:43,409 [http-nio-8080-exec-5] INFO  org.n52.wps.server.request.Request: Handled GetCapabilitiesRequest successfully!
async-riesgos-wps-1  | 2023-01-17 08:14:43,472 [http-nio-8080-exec-6] WARN  org.n52.wps.server.request.Request: Parameter <language> not found.
async-riesgos-wps-1  | 2023-01-17 08:14:43,472 [http-nio-8080-exec-6] INFO  org.n52.wps.server.request.Request: Handled GetCapabilitiesRequest successfully!
async-riesgos-wps-1  | 2023-01-17 08:14:43,520 [http-nio-8080-exec-7] WARN  org.n52.wps.server.request.Request: Parameter <language> not found.
async-riesgos-wps-1  | 2023-01-17 08:14:43,520 [http-nio-8080-exec-7] INFO  org.n52.wps.server.request.Request: Handled GetCapabilitiesRequest successfully!
async-riesgos-wps-1  | 2023-01-17 08:14:43,579 [http-nio-8080-exec-8] WARN  org.n52.wps.server.request.Request: Parameter <language> not found.
async-riesgos-wps-1  | 2023-01-17 08:14:43,580 [http-nio-8080-exec-8] INFO  org.n52.wps.server.request.Request: Handled GetCapabilitiesRequest successfully!
async-riesgos-wps-1  | 2023-01-17 08:14:43,586 [http-nio-8080-exec-9] WARN  org.n52.wps.server.request.Request: Parameter <language> not found.
async-riesgos-wps-1  | 2023-01-17 08:14:43,586 [http-nio-8080-exec-9] INFO  org.n52.wps.server.request.Request: Handled GetCapabilitiesRequest successfully!
async-riesgos-wps-1  | 2023-01-17 08:14:43,661 [http-nio-8080-exec-10] WARN  org.n52.wps.server.request.Request: Parameter <language> not found.
async-riesgos-wps-1  | 2023-01-17 08:14:43,661 [http-nio-8080-exec-10] INFO  org.n52.wps.server.request.Request: Handled GetCapabilitiesRequest successfully!
async-riesgos-wps-1  | 2023-01-17 08:14:43,756 [http-nio-8080-exec-3] WARN  org.n52.wps.server.request.Request: Parameter <language> not found.
async-riesgos-wps-1  | 2023-01-17 08:14:43,762 [http-nio-8080-exec-3] INFO  org.n52.wps.server.request.Request: Handled Request successfully for: org.n52.gfz.riesgos.algorithm.impl.QuakeledgerProcess
async-riesgos-wps-1  | 2023-01-17 08:14:43,892 [pool-7-thread-1] INFO  org.n52.wps.commons.context.ExecutionContextFactory: Context registered
async-riesgos-wps-1  | 2023-01-17 08:14:43,900 [pool-7-thread-1] WARN  org.n52.wps.server.request.InputHandler: Could not find class org.n52.gfz.riesgos.algorithm.impl.QuakeledgerProcess
async-riesgos-wps-1  | 2023-01-17 08:14:44,027 [pool-7-thread-1] INFO  org.n52.gfz.riesgos.algorithm.impl.QuakeledgerProcess: Cache-Hash: a32746c8d6107d2763a12b2a3d7ae9cf
async-riesgos-wps-1  | 2023-01-17 08:14:44,027 [pool-7-thread-1] INFO  org.n52.gfz.riesgos.algorithm.impl.QuakeledgerProcess: There is no result in the cache
async-riesgos-wps-1  | 2023-01-17 08:14:45,290 [pool-7-thread-1] INFO  org.n52.wps.server.response.ResponseData: Using generator org.n52.gfz.riesgos.formats.quakeml.generators.QuakeMLValidatedXmlGenerator for Schema: http://quakeml.org/xmlns/quakeml/1.2/QuakeML-1.2.xsd
async-riesgos-wps-1  | 2023-01-17 08:14:45,294 [pool-7-thread-1] INFO  org.n52.wps.server.response.ResponseData: Using generator org.n52.gfz.riesgos.formats.quakeml.generators.QuakeMLGeoJsonGenerator for Schema: null
async-riesgos-wps-1  | 2023-01-17 08:14:45,528 [pool-7-thread-1] INFO  org.n52.wps.commons.context.ExecutionContextFactory: Context unregistered
async-riesgos-wps-1  | 2023-01-17 08:14:45,528 [http-nio-8080-exec-1] INFO  org.n52.wps.server.handler.RequestHandler: Served ExecuteRequest.
async-riesgos-wps-1  | 2023-01-17 08:14:45,873 [http-nio-8080-exec-6] INFO  org.n52.wps.server.RetrieveResultServlet: 42 bytes written in response to id c8c1433e-551f-4cc0-a332-8c7372525ae5selectedRows.5e76b1a9-32b8-47cf-a51e-05ea13fbe50b
async-riesgos-wps-1  | 2023-01-17 08:22:22,201 [FlatFileDatabase File Wiper] INFO  org.n52.wps.server.database.FlatFileDatabase: FlatFileDatabase file wiper, checking /usr/local/tomcat/temp/Database/Results for files older than 604800000 ms
async-riesgos-wps-1  | 2023-01-17 09:22:22,201 [FlatFileDatabase File Wiper] INFO  org.n52.wps.server.database.FlatFileDatabase: FlatFileDatabase file wiper, checking /usr/local/tomcat/temp/Database/Results for files older than 604800000 ms
MichaelLangbein commented 1 year ago

@Michael: provide reproduction

nbrinckm commented 1 year ago

Seems to be that the wrapper is stuck on checking if the server is already done.

Question here: You used the local wps that is inside the docker-compose right?

MichaelLangbein commented 1 year ago

Yes, I did. This issue is from last week, though - things might have changed by now! I'll look out for this error re-surfacing with our current setup.