Investigation `io.elastic.sailor.UnexpectedStatusCodeException: Got 408 response`

[HannaTrotsenko]

Infobip faced this error on their custom Infobip component

io.elastic.sailor.UnexpectedStatusCodeException: Got 408 response

java.lang.RuntimeException: io.elastic.sailor.UnexpectedStatusCodeException: Got 408 response
	at io.elastic.sailor.impl.HttpUtils.sendHttpRequest(HttpUtils.java:219)
	at io.elastic.sailor.impl.HttpUtils.post(HttpUtils.java:78)
	at io.elastic.sailor.impl.ObjectStorageImpl.post(ObjectStorageImpl.java:68)
	at io.elastic.sailor.impl.MessageResolverImpl.externalizeObject(MessageResolverImpl.java:164)
	at io.elastic.sailor.impl.MessageResolverImpl.externalize(MessageResolverImpl.java:151)
	at io.elastic.sailor.impl.DataCallback.receiveData(DataCallback.java:57)
	at io.elastic.sailor.impl.CountingCallbackImpl.receive(CountingCallbackImpl.java:13)
	at io.elastic.api.EventEmitter.emit(EventEmitter.java:119)
	at io.elastic.api.EventEmitter.emitData(EventEmitter.java:65)
	at com.infobip.ipaas.actions.RawRequest.execute(RawRequest.groovy:112)
	at io.elastic.sailor.impl.MessageProcessorImpl.processMessage(MessageProcessorImpl.java:69)
	at io.elastic.sailor.impl.MessageConsumer.lambda$handleDelivery$0(MessageConsumer.java:79)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
	at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at java.base/java.lang.Thread.run(Unknown Source)
Caused by: io.elastic.sailor.UnexpectedStatusCodeException: Got 408 response
	at io.elastic.sailor.impl.HttpUtils.sendHttpRequest(HttpUtils.java:203)
	... 16 more

Logs:

[2025-03-28 08:49:59.301]: messageId=7fa88a01-7506-40ca-b1fc-672ba37b1ed1, parentMessageId=3c33380a-2901-4242-b3ef-0b221330a5c6, threadId=27b6f1a9-f652-47f8-aeb8-665da2b93347

[2025-03-28 08:49:59.301]: Sending GET request to /v1/tasks/66c30f4db5d3ea001208b48a/steps/step_5

[2025-03-28 08:49:59.358]: Parsing message JSON

[2025-03-28 08:49:59.358]: About to retrieve message body from storage

[2025-03-28 08:49:59.359]: About to retrieve object by id=f353aaab-d11b-4251-8c91-8b8a751867d0

[2025-03-28 08:49:59.360]: Sending GET request to /objects/f353aaab-d11b-4251-8c91-8b8a751867d0

[2025-03-28 08:49:59.405]: Parsing message JSON

[2025-03-28 08:49:59.417]: About to retrieve passthrough from storage

[2025-03-28 08:49:59.417]: About to retrieve object by id=a7d08426-2742-46b7-8683-3e0e77bbd3a6

[2025-03-28 08:49:59.420]: Sending GET request to /objects/a7d08426-2742-46b7-8683-3e0e77bbd3a6

[2025-03-28 08:49:59.708]: Parsing message JSON

[2025-03-28 08:49:59.786]: About to retrieve object by id=9e18eb6c-d622-4b3a-9331-eeea33c3c485

[2025-03-28 08:49:59.787]: Sending GET request to /objects/9e18eb6c-d622-4b3a-9331-eeea33c3c485

[2025-03-28 08:49:59.798]: Parsing message JSON

[2025-03-28 08:49:59.800]: About to retrieve object by id=667d8274-0a68-4c45-bbf7-d9f8bf77cd4d

[2025-03-28 08:49:59.801]: Sending GET request to /objects/667d8274-0a68-4c45-bbf7-d9f8bf77cd4d

[2025-03-28 08:49:59.814]: Parsing message JSON

[2025-03-28 08:49:59.814]: About to retrieve object by id=f353aaab-d11b-4251-8c91-8b8a751867d0

[2025-03-28 08:49:59.814]: Sending GET request to /objects/f353aaab-d11b-4251-8c91-8b8a751867d0

[2025-03-28 08:49:59.825]: Parsing message JSON

[2025-03-28 08:49:59.866]: Component descriptor from classpath: /component.json

[2025-03-28 08:50:01.194]: Using retry with configuration: retryCodes: <[429]>, retryDelay: 300ms, retryMaxAttempts: 5, retryBackoffMultiplier: 1.0

[2025-03-28 08:50:02.526]: Got 200 response status from PATCH https://api.infobip.com/people/2/integrations/companies/batch/upsert

[2025-03-28 08:50:02.777]: Unsupported content: com.infobip.ipaas.response.StringResponse(error:false, status:200, body:)

[2025-03-28 08:50:02.777]: Adding message of step 'step_5' into pass-through

[2025-03-28 08:50:02.777]: Externalizing message body

[2025-03-28 08:50:02.777]: Step produced data to be published

[2025-03-28 08:50:02.777]: Externalizing passthrough step=step_1

[2025-03-28 08:50:02.879]: Externalizing passthrough step=step_3

[2025-03-28 08:50:02.888]: Externalizing passthrough step=step_6

[2025-03-28 08:50:02.888]: Externalizing passthrough step=step_5

[2025-03-28 08:50:02.888]: Message total size (body+passthrough): 2304879 bytes

[2025-03-28 08:50:02.888]: Externalizing passthrough step=step_2

[2025-03-28 08:50:02.888]: About to post an object into the storage

[2025-03-28 08:50:02.888]: Sending POST request to /objects/

[2025-03-28 08:50:02.929]: Stored object with id="cdde5e69-095c-4665-940b-203cea79928f"

[2025-03-28 08:50:02.929]: Successfully posted content

[2025-03-28 08:50:02.963]: Externalizing passthrough step=step_1

[2025-03-28 08:50:02.964]: About to post an object into the storage

[2025-03-28 08:50:03.075]: Sending POST request to /objects/

[2025-03-28 08:55:03.180]: Component execution failed

[2025-03-28 08:55:03.184]: Pushing to exchange=6245ac5004944200129bf33e_org, routingKey=6245ac5004944200129bf33e.66c30f4db5d3ea001208b48a/ordinary.step_5.error

[2025-03-28 08:55:03.193]: Opened publish channel

[2025-03-28 08:55:03.193]: Waiting for publish confirm

[2025-03-28 08:55:03.213]: Successfully published data to 6245ac5004944200129bf33e_org

Slack:

• https://elasticio.slack.com/archives/C6G1E4WB1/p1742893782316699
• https://elasticio.slack.com/archives/C01FLMQ0PB5/p1742893416100859
• https://elasticio.slack.com/archives/C01FLMQ0PB5/p1743148646107389

Definition of Done

• Review / Analyse Sailor behaviour/logic. How retry works.
• Provide report

[HannaTrotsenko]

@Legendmiha pls also fix dependencies #102

[Legendmiha]

#104 - here's first iteration of this task, where I tried to fix dependecies #102, but it required me to update minimal supported java version to 17 and also update gradle version. This, in turn, also triggered a lot of changes, which are almost finished.
The only problem, is when I try to run petstore java component with this sailor, the petstore code throws SSLHandshakeException (which seems not to be related to the sailor, but I couldn't verify).
When I tried to use different component (jdbc) - mismatch in java version required update to the component itself, after which I couldn't start it at all. This is why I gave up this idea, and simply moved the changes that do not require java update to the separate branch and made PR with that.

PR is still open, because it can be used later as a reference to what needs to be changed when updating java and gradlew.
Also, it includes test.sh script which allows to run locally some component with local version of the sailor

[Legendmiha]

New PR - #105
It provides 2 imporvements - use streams for lightweight messages during communication with maester and reuse HttpClient, instead of creating a new one on each http request.
IMPORTANT NOTE - this does not guarantee that the 408 error, that customer faced, will be fixed. The big reason for this is that we are not sure what caused it in the first place. So, no way to reproduce it and check if these changes fix it

[A3a3e1]

The 408 issue means that the component due to a network congestion, a large file etc., fails to upload a file to Maester within (what I can see from the logs) 5 minutes.
Maester is waiting for 5 min, then closes the connection and throws 408 error.

Not to be mixed up with the 504 Gateway Timeout code.