Error requeued messages in JASMIN persistently

[jaur-jaur]

Hello, When I try to send sms by http API, messages are not delivered but enqueued by jasmin. Thus smpp_connector unbind and bind after user request timeout and I got the following output in messages.log.

--http request http://xx.xx.xx.xx:1401/send?username=user&password=pass&dlr=yes&dlr-level=2&from=sender&to=xxxxxxxx&content=s.ssss..........sssss

**--smpp connector logfile 2022-03-08 12:47:00 ERROR 4671 Connection failed. Reason: [Failure instance: Traceback (failure with no frames): <class 'twisted.internet.error.TimeoutError'>: User timeout caused connection failure. 2022-03-08 12:47:40 INFO 4671 Reconnecting after 10 seconds ... 2022-03-08 12:47:50 INFO 4671 Connecting to IPv4Address(TCP, 'ipxx.xx.xx', xx) ... 2022-03-08 12:47:50 WARNING 4671 SMPP connection established from Xxxx to port xX 2022-03-08 12:47:50 INFO 4671 Connection made to @ip:port 2022-03-08 12:47:50 WARNING 4671 Requesting bind as transceiver 2022-03-08 12:47:50 WARNING 4671 Bind succeeded...now in state BOUND_TRX

--mesages.log 2022-03-08 12:47:50 ERROR 4671 SMPPC [cid:NET4] is not bound: Requeuing (#5412) SubmitSmPDU[6452c6ef-86f9-4da0-8c1a-0fbb9aa88639], aged 0:12:10.376918 seconds. 2022-03-08 12:47:50 ERROR 4671 SMPPC [cid:NET4_BF] is not bound: Requeuing (#5414) SubmitSmPDU[6452c6ef-86f9-4da0-8c1a-0fbb9aa88639], aged 0:12:10.381598 seconds. 2022-03-08 12:47:50 ERROR 4671 SMPPC [cid:NET4_BF] is not bound: Requeuing (#5416) SubmitSmPDU[6452c6ef-86f9-4da0-8c1a-0fbb9aa88639], aged 0:12:10.385117 seconds.

Please could anyone explain me if I miss something ?

Thanks in advance

[magojr]

Hi Jaur-jaur, is there anithing else in message.log after the 3 lines you reported? Your logs show that the connector was NOT connected, and during the re-connection, the message has been retried 3 times and requeued (correct because the message can be sent only when the connector is bound). Checking the time, at 12:47:50 "Bind succeded" may (or may not) be after the last Requeuing so probably the message has been sent just after the Bound event but that's not possibe to say with those lines. Note that in the connection option there is an Enquire Link Interval parameter in seconds that check the status of the connection in order to reconnect (another paramenter is involved: connection fail retry, a bolean one). These params should avoid the link is lost and keep it always active if needed and according with the upstream provider. Anyway the message should be sent just after the reconnect in your example because it has been Requeued for the time needed to get the connector bound.

Check the whole parameters on the documentation. They may help you: https://docs.jasminsms.com/en/latest/management/jcli/modules.html#smpp-client-connector-manager

[jaur-jaur]

I cannot put all lines here as it is too many. Here are some one : 2022-03-08 12:47:50 ERROR 4671 SMPPC [cid:NET4_BF] is not bound: Requeuing (#5418) SubmitSmPDU[6452c6ef-86f9-4da0-8c1a-0fbb9aa88639], aged 0:12:10.388618 seconds. 2022-03-08 12:47:50 ERROR 4671 SMPPC [cid:NET4_BF] is not bound: Requeuing (#5420) SubmitSmPDU[6452c6ef-86f9-4da0-8c1a-0fbb9aa88639], aged 0:12:10.392193 seconds. 2022-03-08 12:47:50 ERROR 4671 SMPPC [cid:NET4_BF] is not bound: Requeuing (#5422) SubmitSmPDU[6452c6ef-86f9-4da0-8c1a-0fbb9aa88639], aged 0:12:10.395731 seconds. 2022-03-08 12:47:50 ERROR 4671 SMPPC [cid:NET4_BF] is not bound: Requeuing (#5424) SubmitSmPDU[6452c6ef-86f9-4da0-8c1a-0fbb9aa88639], aged 0:12:10.399432 seconds. 2022-03-08 12:47:50 ERROR 4671 SMPPC [cid:NET4_BF] is not bound: Requeuing (#5426) SubmitSmPDU[6452c6ef-86f9-4da0-8c1a-0fbb9aa88639], aged 0:12:10.402962 seconds. 2022-03-08 12:47:50 ERROR 4671 SMPPC [cid:NET4_BF] is not bound: Requeuing (#5428) SubmitSmPDU[6452c6ef-86f9-4da0-8c1a-0fbb9aa88639], aged 0:12:10.407590 seconds. 2022-03-08 12:47:50 ERROR 4671 SMPPC [cid:NET4_BF] is not bound: Requeuing (#5430) SubmitSmPDU[6452c6ef-86f9-4da0-8c1a-0fbb9aa88639], aged 0:12:10.411152 seconds. 2022-03-08 12:47:50 ERROR 4671 SMPPC [cid:NET4_BF] is not bound: Requeuing (#5432) SubmitSmPDU[6452c6ef-86f9-4da0-8c1a-0fbb9aa88639], aged 0:12:10.414764 seconds. 2022-03-08 12:47:50 ERROR 4671 SMPPC [cid:NET4_BF] is not bound: Requeuing (#5434) SubmitSmPDU[6452c6ef-86f9-4da0-8c1a-0fbb9aa88639], aged 0:12:10.418298 seconds.

*Note that there are more than 30 lines after those on top.

--smpp_connector log 2022-03-08 12:49:50 ERROR 4671 Request timed out after 120 secs: PDU [command: submit_sm, sequence_number: 2, command_status: ESME_ROK service_type: None source_addr_ton: EnumValue(<jasmin.vendor.enum.Enum object at 0x7fd148a30810>, 4, 'NATIONAL') source_addr_npi: EnumValue(<jasmin.vendor.enum.Enum object at 0x7fd148a30c10>, 9, 'ISDN') source_addr: 'INFO NET' dest_addr_ton: EnumValue(<jasmin.vendor.enum.Enum object at 0x7fd148a30810>, 6, 'INTERNATIONAL') dest_addr_npi: EnumValue(<jasmin.vendor.enum.Enum object at 0x7fd148a30c10>, 9, 'ISDN') destination_addr: 'xxxxxx' esm_class: EsmClass[mode: STORE_AND_FORWARD, type: DEFAULT, gsmFeatures: set([])] protocol_id: None priority_flag: EnumValue(<jasmin.vendor.enum.Enum object at 0x7fd148a30650>, 0, 'LEVEL_0') schedule_delivery_time: None validity_period: None registered_delivery: RegisteredDelivery[receipt: SMSC_DELIVERY_RECEIPT_REQUESTED, smeOriginatedAcks: set([]), intermediateNotification: False] replace_if_present_flag: EnumValue(<jasmin.vendor.enum.Enum object at 0x7fd148a30910>, 0, 'DO_NOT_REPLACE') data_coding: DataCoding[scheme: DEFAULT, schemeData: SMSC_DEFAULT_ALPHABET] sm_default_msg_id: 0 short_message: 'G-** : votre code de validation 0' ] 2022-03-08 12:49:50 WARNING 4671 Shutdown requested...unbinding 2022-03-08 12:49:50 INFO 4671 Waiting for in-progress transactions to finish... 2022-03-08 12:49:50 WARNING 4671 Issuing unbind request 2022-03-08 12:49:50 WARNING 4671 Unbind succeeded 2022-03-08 12:49:50 WARNING 4671 Disconnecting... 2022-03-08 12:49:50 WARNING 4671 SMPP x.x.x.x.x disconnected from port xxx: [Failure instance: Traceback (failure with no frames): <class 'twisted.internet.error.ConnectionDone'>: Connection was closed cleanly. ] 2022-03-08 12:49:50 ERROR 4671 Connection lost. Reason: [Failure instance: Traceback (failure with no frames): <class 'twisted.internet.error.ConnectionDone'>: Connection was closed cleanly. ] 2022-03-08 12:49:50 INFO 4671 Reconnecting after 10 seconds ... 2022-03-08 12:50:00 INFO 4671 Connecting to IPv4Address(TCP, 'x.x.x.x', xx) ... 2022-03-08 12:50:01 WARNING 4671 SMPP connection established from xxxx to port xxxx 2022-03-08 12:50:01 INFO 4671 Connection made to x.x.x.x:xx 2022-03-08 12:50:01 WARNING 4671 Requesting bind as transceiver 2022-03-08 12:50:01 WARNING 4671 Bind succeeded...now in state BOUND_TRX 2022-03-08 12:53:50 ERROR 4671 Request timed out after 120 secs: PDU [command: submit_sm, sequence_number: 5, command_status: ESME_ROK service_type: None

I check the parameters mentioned con_fail_retry, elink_interval on smpp_connnector : Respectively "yes" and "30". Besides in jasmin.cfg, enquire link interval is 30 also.

[magojr]

The point is not to paste here the entire log but to check what happens after this event: "2022-03-08 12:47:50 WARNING 4671 Bind succeeded...now in state BOUND_TRX" In other word, after a lot of similar lines of "requeued" there should be a differnet lines saying the final status of the message that may give you the info if it has been sent or an error occurred.

The "requeue" lines are just a useless information that are "expected" until the connection is ready. After the connection has been enstabilished, you should find a different info in the log, hopefully, the message has been sent to the upstream provider.

About the elink_interval paramenter, check it with your provider. Nobody else can say you if the upstream provider expect that you enquire the link keeping it always active or how long the timeout is set on his side.

[jaur-jaur]

In fact, the sms get actually queued over 1200 sec and so discarded thereafter by Jasmin. It is weird as the binding was made during that time.

--messagess.log 2022-03-08 13:17:37 ERROR 10606 SMPPC [cid:NET4] is not connected: Discarding (#1) SubmitSmPDU[6452c6ef-86f9-4da0-8c1a-0fbb9aa88639], over-aged 2517 seconds.

--smpp conn log 2022-03-08 13:14:20 WARNING 4671 Bind succeeded...now in state BOUND_TRX 2022-03-08 13:17:36 WARNING 4671 SMPP x.x.x.x. disconnected from port 42950: [Failure instance: Traceback (failure with no frames): <class 'twisted.internet.error.ConnectionLost'>: Connection to the other side was lost in a non-clean fashion: Connection lost.

[github-actions[bot]]

Stale issue detected, remove stale label or comment or this will be closed soon.

[github-actions[bot]]

This issue was closed because it has been stalled more than a year with no activity.