search

camunda / camunda-bpm-platform

Flexible framework for workflow and decision automation with BPMN and DMN. Integration with Quarkus, Spring, Spring Boot, CDI.
https://camunda.com/
Apache License 2.0
4.13k stars 1.56k forks source link

Camunda External client: Exceptions when the client has nothing todo #2272

Open ThorbenLindhauer opened 5 years ago

ThorbenLindhauer commented 5 years ago

This issue was imported from JIRA:

Field Value
JIRA Link CAM-10526
Reporter EXj0brz
What is this name? This pseudonym name was generated based on the user name in JIRA to protect the personal data of our JIRA users. You can use this identifier to search for issues by the same reporter.
Has restricted visibility comments true

We started with the implementation of a camunda based workflow solution. In the moment the setup is like this:

Everything is working fine so far. Our workflow is running and the external client is doing his job... But after a while (when there is nothing to do for the external client) is see an exception in the log of the external task client:

15:49:09.692 <E> <TopicSubscripti> client.logError:70 - TASK/CLIENT-03001 Exception while fetch and lock task.
org.camunda.bpm.client.impl.EngineClientException: TASK/CLIENT-02002 Exception while establishing connection for request 'POST http://localhost:8080/enrichmentservice/api/rest/1.0/rest/external-task/fetchAndLock HTTP/1.1'
at org.camunda.bpm.client.impl.EngineClientLogger.exceptionWhileEstablishingConnection(EngineClientLogger.java:36)
at org.camunda.bpm.client.impl.RequestExecutor.executeRequest(RequestExecutor.java:101)
at org.camunda.bpm.client.impl.RequestExecutor.postRequest(RequestExecutor.java:74)
at org.camunda.bpm.client.impl.EngineClient.fetchAndLock(EngineClient.java:72)
at org.camunda.bpm.client.topic.impl.TopicSubscriptionManager.fetchAndLock(TopicSubscriptionManager.java:135)
at org.camunda.bpm.client.topic.impl.TopicSubscriptionManager.acquire(TopicSubscriptionManager.java:101)
at org.camunda.bpm.client.topic.impl.TopicSubscriptionManager.run(TopicSubscriptionManager.java:87)
at java.lang.Thread.run(Thread.java:748)
Caused by: org.apache.http.NoHttpResponseException: localhost:8080 failed to respond
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:141)
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:56)
at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:259)
at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:163)
at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:165)
at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273)
at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125)
at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:272)
at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185)
at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)
at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:72)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:221)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:165)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:140)
at org.camunda.bpm.client.impl.RequestExecutor.executeRequest(RequestExecutor.java:88)
at org.camunda.bpm.client.impl.RequestExecutor.postRequest(RequestExecutor.java:74)
at org.camunda.bpm.client.impl.EngineClient.fetchAndLock(EngineClient.java:72)
at org.camunda.bpm.client.topic.impl.TopicSubscriptionManager.fetchAndLock(TopicSubscriptionManager.java:135)

What could be the reason for this? Maybe Configuration error in server or client? One remark: The execution of the external task is slow (like 10-30 seconds)

I created a complete example: See the attached Zip file with 2 eclipse projects

To create the error scenario you have to:

  1. Start the ExampleApplication inside the spring-boot project
  2. Start the ExternalClientApp inside the Spring-Boot-Client project
  3. Wait a few minutes the log output of the external client should look like this:
pojo before: ObjectValue <value=ExamplePojo [num=123, textVal=some text>, isDeserialized=true, serializationDataFormat=application/x-java-serialized-object, objectTypeName=org.camunda.bpm.example.tasks.ExamplePojo, serializedValue=156 chars, isTransient=false]
pojo changed: ObjectValue <value=ExamplePojo [num=123, textVal=external changed>, isDeserialized=true, serializationDataFormat=application/x-java-serialized-object, objectTypeName=org.camunda.bpm.example.tasks.ExamplePojo, serializedValue=156 chars, isTransient=false]
The External Task 28 has been completed!
The External Task 32 has been completed! (done = false)
The External Task 39 has been completed! (done = false)
The External Task 46 has been completed! (done = true)
149038 <TopicSubscriptionManager> ERROR org.camunda.bpm.client - TASK/CLIENT-03001 Exception while fetch and lock task.
org.camunda.bpm.client.impl.EngineClientException: TASK/CLIENT-02002 Exception while establishing connection for request 'POST http://localhost:8080/rest/external-task/fetchAndLock HTTP/1.1'
at org.camunda.bpm.client.impl.EngineClientLogger.exceptionWhileEstablishingConnection(EngineClientLogger.java:36)
at org.camunda.bpm.client.impl.RequestExecutor.executeRequest(RequestExecutor.java:101)
at org.camunda.bpm.client.impl.RequestExecutor.postRequest(RequestExecutor.java:74)
at org.camunda.bpm.client.impl.EngineClient.fetchAndLock(EngineClient.java:72)
at org.camunda.bpm.client.topic.impl.TopicSubscriptionManager.fetchAndLock(TopicSubscriptionManager.java:135)
at org.camunda.bpm.client.topic.impl.TopicSubscriptionManager.acquire(TopicSubscriptionManager.java:101)
at org.camunda.bpm.client.topic.impl.TopicSubscriptionManager.run(TopicSubscriptionManager.java:87)
at java.lang.Thread.run(Thread.java:748)
Caused by: org.apache.http.NoHttpResponseException: localhost:8080 failed to respond
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:141)
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:56)
at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:259)
at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:163)
at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:157)
at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273)
at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125)
at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:272)
at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185)
at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)
at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:72)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:221)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:165)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:140)
at org.camunda.bpm.client.impl.RequestExecutor.executeRequest(RequestExecutor.java:88)
... 6 more

Links: https://stackoverflow.com/questions/10558791/apache-httpclient-interim-error-nohttpresponseexception

ThorbenLindhauer commented 5 years ago

This comment was imported from JIRA and written by user @mboskamp

Hi EXj0brz,

thanks for raising this issue. Unfortunately, I can not reproduce the log output (and the exception) on my local machine. The error log you provided suggests that after some time a REST POST call is not answered by the application. Note that the two logs state different call URLs. POST http://localhost:8080/enrichmentservice/api/rest/1.0/rest/external-task/fetchAndLock HTTP/1.1 vs 'POST http://localhost:8080/rest/external-task/fetchAndLock HTTP/1.1'

Could you please

  1. verify that the URLs are correct
  2. after you see the exception in the log, verify that the application is indeed not responding (e.g. by calling a REST endpoint manually)

Cheers, Miklas

ThorbenLindhauer commented 5 years ago

This comment was imported from JIRA and written by user EXj0brz

What is this name? This pseudonym name was generated based on the user name in JIRA to protect the personal data of our JIRA users. You can use this identifier to search for issues by the same reporter.

I asked a colleague to execute both projects and he has the same problem. i can try it on a 3rd machine, but why should it behave differently? it is java and server and cleint are running on the same machine...

this is the log output from the second run:

Build external client for: http://localhost:8080/rest
1485 <main> INFO org.camunda.bpm.client - TASK/CLIENT-01026 Discovered data format provider: org.camunda.bpm.client.variable.impl.format.json.JacksonJsonDataFormatProvider<name = application/json>
1488 <main> INFO org.camunda.bpm.client - TASK/CLIENT-01025 Discovered data format: org.camunda.bpm.client.variable.impl.format.json.JacksonJsonDataFormat<name = application/json>
1488 <main> INFO org.camunda.bpm.client - TASK/CLIENT-01026 Discovered data format provider: org.camunda.bpm.client.variable.impl.format.serializable.SerializableDataFormatProvider<name = application/x-java-serialized-object>
1489 <main> INFO org.camunda.bpm.client - TASK/CLIENT-01025 Discovered data format: org.camunda.bpm.client.variable.impl.format.serializable.SerializableDataFormat<name = application/x-java-serialized-object>
1489 <main> INFO org.camunda.bpm.client - TASK/CLIENT-01026 Discovered data format provider: org.camunda.bpm.client.variable.impl.format.xml.DomXmlDataFormatProvider<name = application/xml>
1495 <main> INFO org.camunda.bpm.client - TASK/CLIENT-01025 Discovered data format: org.camunda.bpm.client.variable.impl.format.xml.DomXmlDataFormat<name = application/xml>
Subscribe client for: approveLoan
Subscription done
Subscribe client for: waitTask
Subscription done
pojo before: ObjectValue <value=ExamplePojo [num=123, textVal=some text>, isDeserialized=true, serializationDataFormat=application/x-java-serialized-object, objectTypeName=org.camunda.bpm.example.tasks.ExamplePojo, serializedValue=156 chars, isTransient=false]
pojo changed: ObjectValue <value=ExamplePojo [num=123, textVal=external changed>, isDeserialized=true, serializationDataFormat=application/x-java-serialized-object, objectTypeName=org.camunda.bpm.example.tasks.ExamplePojo, serializedValue=156 chars, isTransient=false]
The External Task 28 has been completed!
The External Task 32 has been completed! (done = false)
The External Task 39 has been completed! (done = false)
The External Task 46 has been completed! (done = true)
155544 <TopicSubscriptionManager> ERROR org.camunda.bpm.client - TASK/CLIENT-03001 Exception while fetch and lock task.
org.camunda.bpm.client.impl.EngineClientException: TASK/CLIENT-02002 Exception while establishing connection for request 'POST http://localhost:8080/rest/external-task/fetchAndLock HTTP/1.1'
       at org.camunda.bpm.client.impl.EngineClientLogger.exceptionWhileEstablishingConnection(EngineClientLogger.java:36)
       at org.camunda.bpm.client.impl.RequestExecutor.executeRequest(RequestExecutor.java:101)
       at org.camunda.bpm.client.impl.RequestExecutor.postRequest(RequestExecutor.java:74)
       at org.camunda.bpm.client.impl.EngineClient.fetchAndLock(EngineClient.java:72)
       at org.camunda.bpm.client.topic.impl.TopicSubscriptionManager.fetchAndLock(TopicSubscriptionManager.java:135)
       at org.camunda.bpm.client.topic.impl.TopicSubscriptionManager.acquire(TopicSubscriptionManager.java:101)
       at org.camunda.bpm.client.topic.impl.TopicSubscriptionManager.run(TopicSubscriptionManager.java:87)
       at java.lang.Thread.run(Unknown Source)
Caused by: org.apache.http.NoHttpResponseException: localhost:8080 failed to respond
       at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:141)
       at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:56)
       at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:259)
       at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:163)
       at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:157)
       at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273)
       at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125)
       at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:272)
       at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185)
       at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
       at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)
       at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
       at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:72)
       at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:221)
       at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:165)
       at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:140)
       at org.camunda.bpm.client.impl.RequestExecutor.executeRequest(RequestExecutor.java:88)
       ... 6 more
ThorbenLindhauer commented 5 years ago

This comment was imported from JIRA and written by user EXj0brz

What is this name? This pseudonym name was generated based on the user name in JIRA to protect the personal data of our JIRA users. You can use this identifier to search for issues by the same reporter.

important: it may take a few minutes until the error is logged!

ThorbenLindhauer commented 5 years ago

This comment was imported from JIRA and written by user @mboskamp

Hi EXj0brz,

I ran the provided application for ~1h. There were no errors and the External Task worker completed more Tasks than it seems to do for you. Everything looked fine. If you can provide more information or instructions on how to reproduce this we can look into this but until then I'm afraid, there is not much we can do here to help you. Maybe also consider posting this in our forum to see if somebody else ran into this issue.

Best, Miklas

ThorbenLindhauer commented 5 years ago

This comment was imported from JIRA and written by user EXj0brz

What is this name? This pseudonym name was generated based on the user name in JIRA to protect the personal data of our JIRA users. You can use this identifier to search for issues by the same reporter.

so if i see it as a given that we use the same camuda version, because it is defined in the POM, this leads to 2 other possible differences:

i will try it at home to have another test environment.

ThorbenLindhauer commented 5 years ago

This comment was imported from JIRA and written by user EXj0brz

What is this name? This pseudonym name was generated based on the user name in JIRA to protect the personal data of our JIRA users. You can use this identifier to search for issues by the same reporter.

tested at home: no errors:

so it could be everything or even some antivrus issues. will test it with different jdk at work

ThorbenLindhauer commented 5 years ago

This comment was imported from JIRA and written by user EXj0brz

What is this name? This pseudonym name was generated based on the user name in JIRA to protect the personal data of our JIRA users. You can use this identifier to search for issues by the same reporter.

Tested it on another machine. it looks like the problem is only on windows 7 machines. i think the error reason is described here: https://stackoverflow.com/questions/10558791/apache-httpclient-interim-error-nohttpresponseexception so the server is killing the http session because it has not been used for a longer time! my workaround is to configure a different backup strategy and so far i have no errors anymore: tldr: i think it is a bug in the external client that only happens on Win7 but i found a workaround:

        ExternalTaskClient client = ExternalTaskClient.create().baseUrl(baseUrl).backoffStrategy(new ExponentialBackoffStrategy(500L, 2, 30000L)).
                build();
ThorbenLindhauer commented 5 years ago

This comment was imported from JIRA and written by user @mboskamp

Hi EXj0brz,

thank you for digging deeper into this. We will discuss whether or not to act on this within the development team. Once a decision is made I will inform you via this ticket.

Cheers, Miklas

ThorbenLindhauer commented 5 years ago

This comment was imported from JIRA and written by user @ThorbenLindhauer

Hi Mark,

Thanks for reporting this and for sharing the workaround. We cannot schedule a fix for this problem as of now due to other commitments, however we would be happy to receive a contribution.

Cheers, Thorben