[CAMEL-17859] camel-smpp: Consumer sometimes tries to reconnect only once

• Type: Bug
• Status: Resolved
• Priority: Minor
• Resolution: Fixed
• Affects Version/s: 3.15.0
• Fix Version/s: 3.18.3, 3.19.0
• Component/s: camel-smpp
• Estimated Complexity: Unknown
• Regression: Regression
• Assignee: Otavio Rodolfo Piske
• Reporter: Pascal Schumacher
• Created: 27/Mar/22 17:50
• Updated: 01/Dec/22 07:23
• Resolved: 01/Dec/22 07:23

Description

We have been running multiple applications using Camel SMPP with a consumer with lazy session creation for years without any problems.

Recently we observed that sometimes Camel 3.15.0 only tries to reconnect once.

Log:

Time - thread_name - logger_name - message
Mar 22, 2022 @ 01:16:59.798 - PDUReaderWorker-b333f18a - org.jsmpp.session.SMPPSession - Reading PDU session b333f18a in state BOUND_TX: Connection reset
Mar 22, 2022 @ 01:16:59.801 - EnquireLinkSender-b333f18a - org.jsmpp.session.AbstractSession - Response timeout on enquireLink
Mar 22, 2022 @ 01:16:59.801 - EnquireLinkSender-b333f18a - org.apache.camel.component.smpp.SmppProducer - Lost connection to: smpp://USER@HOST:PORT - trying to reconnect...
Mar 22, 2022 @ 01:16:59.824 - EnquireLinkSender-b333f18a - org.apache.camel.support.task.BackgroundTask - Interrupted while waiting for the repeatable task to execute: null
java.lang.InterruptedException: null
               at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(Unknown Source)
               at java.base/java.util.concurrent.CountDownLatch.await(Unknown Source)
               at org.apache.camel.support.task.BackgroundTask.waitForTaskCompletion(BackgroundTask.java:153)
               at org.apache.camel.support.task.BackgroundTask.run(BackgroundTask.java:144)
               at org.apache.camel.component.smpp.SmppProducer.reconnect(SmppProducer.java:197)
               at org.apache.camel.component.smpp.SmppProducer.lambda$new$0(SmppProducer.java:76)
               at org.apache.camel.component.smpp.SmppProducer$$Lambda$1087/0x000000002b4df3c8.onStateChange(Unknown Source)
               at org.jsmpp.session.AbstractSessionContext.fireStateChanged(AbstractSessionContext.java:85)
               at org.jsmpp.session.SMPPSessionContext.changeState(SMPPSessionContext.java:61)
               at org.jsmpp.session.AbstractSessionContext.close(AbstractSessionContext.java:66)
               at org.jsmpp.session.AbstractSession.close(AbstractSession.java:257)
               at org.jsmpp.session.AbstractSession$EnquireLinkSender.run(AbstractSession.java:503)
Mar 22, 2022 @ 01:17:04.824 - Camel (camel-1) thread #3797 - smpp-producer-reconnect - org.apache.camel.component.smpp.SmppProducer - Trying to reconnect to smpp://USER@HOST:PORT
Mar 22, 2022 @ 01:17:04.833 - Camel (camel-1) thread #3797 - smpp-producer-reconnect - org.jsmpp.session.SMPPSession - Connected from port 59810 to /PORT:PORT
Mar 22, 2022 @ 01:17:04.834 - PDUReaderWorker-d0566380 - org.jsmpp.session.SMPPSession - Starting PDUReaderWorker
Mar 22, 2022 @ 01:17:04.844 - PDUReaderWorker-d0566380 - org.jsmpp.session.SMPPSession - Reading PDU session d0566380 in state OPEN: null
Mar 22, 2022 @ 01:17:04.845 - pool-58909-thread-1 - org.jsmpp.session.SMPPSession - Failed setting so_timeout for session timer
java.net.SocketException: Socket is closed
               at java.base/java.net.Socket.setSoTimeout(Unknown Source)
               at org.jsmpp.session.connection.socket.SocketConnection.setSoTimeout(SocketConnection.java:60)
               at org.jsmpp.session.SMPPSession$BoundSessionStateListener.onStateChange(SMPPSession.java:721)
               at org.jsmpp.session.AbstractSessionContext.fireStateChanged(AbstractSessionContext.java:85)
               at org.jsmpp.session.SMPPSessionContext.changeState(SMPPSessionContext.java:61)
               at org.jsmpp.session.AbstractSessionContext.bound(AbstractSessionContext.java:49)
               at org.jsmpp.session.state.SMPPSessionOpen.processBindResp(SMPPSessionOpen.java:73)
               at org.jsmpp.session.PDUProcessTask.run(PDUProcessTask.java:62)
               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)
Mar 22, 2022 @ 01:17:04.845 - pool-58909-thread-1 - org.jsmpp.session.SMPPSession - Changing processor degree to 1
Mar 22, 2022 @ 01:17:04.847 - Camel (camel-1) thread #3797 - smpp-producer-reconnect - org.jsmpp.session.SMPPSession - Receive negative bind response
Mar 22, 2022 @ 01:17:04.847 - PDUReaderWorker-d0566380 - org.apache.camel.component.smpp.SmppProducer - Lost connection to: smpp://USER@HOST:PORT - trying to reconnect...

[no further reconnects or anything related to smpp producing]

[almost seven hours later the application tries to produce the first sms (this and all further tries to produce fail):] 
org.apache.camel.processor.errorhandler.DefaultErrorHandler - Failed delivery for (MessageId: XZY on ExchangeId: XZY). Exhausted after delivery attempt: 1 caught: java.io.IOException: Lost connection to smpp://USER@HOST:PORT and yet not reconnected

The log of another instance showed the same behavior.

orpiske I am not sure, but I think this may be another regression caused by CAMEL-17121 It would be great if you could have a look at this. Thank you very much!

Issue Links

• links to: GitHub Pull Request #7281