RUT241 SMPP daemon segmentation fault and unable to cope with multiple long SMS

Hello,

Below refers to RUT241 routers to use as SMS gateways with the SMPP protocol.

I have encountered errors when attempting to send long SMS messages (over 160 characters). Specifically, I receive a ‘timed out’ error intermittently when using our simple Python script with smpplib and message_payload to send a long SMS.

Additionally, when I logged into the router and ran the following command:

/usr/sbin/smppd --port 2776 --username admin --password somepass -n1

I encountered a ‘Segmentation fault’ error. This suggests there might be an issue with managing long SMS messages in the SMPP daemon.

For your reference, the script I am using can be accessed here: Private Seafile

On the RUT241, I ran smppd in debug mode using the following command:

/usr/sbin/smppd --port 2776 --username admin --password somepass -l 0 -t 2 -c 30 -s 30

When sending multiple long SMS messages using the command below:

python3 send_sms2.py -m "1234567890 123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890" -n my_telephone_number -c 20

I receive a ‘timed out’ error and cannot connect to the smppd for some time.

Could you please assist me with resolving this issue?

Thank you.

Best regards,
Lukas

Hello,

SMS messages are limited in size, typically 160 characters for a standard SMS. However, if you need to send longer messages, they can be split into multiple parts and sent as separate SMS messages. These multiple parts are referred to as “multipart SMS.”

The -n, --nsms <count> option allows you to specify the maximum number of messages that can be included in a multipart SMS. For example, if you set -n 3, it means that a long message can be split into a maximum of 3 parts. If the message exceeds this limit, it might not be delivered properly or might be truncated.

Setting this parameter appropriately ensures that your SMS gateway can handle long messages correctly and avoids potential issues with message fragmentation or delivery.

Best regards,

SMS messages are limited in size, typically 160 characters for a standard SMS

Yes, I know, therefore I am using message_payload from smpplib library.
In other script than the one mentioned in the first message, I even have tried splitting the message with make_parts, but only received SMS that had only question mark in its body ‘?’.

Below relevant part of the script:

# Convert message to ASCII if needed
        ascii_message = unidecode(message)
        parts, encoding_flag, msg_type_flag = smpplib.gsm.make_parts(ascii_message)
        
        for part in parts:
            pdu = client.send_message(
                source_addr_ton=5,
                source_addr_npi=0,
                source_addr='Tralala',
                dest_addr_ton=smpplib.consts.SMPP_TON_INTL,
                dest_addr_npi=smpplib.consts.SMPP_NPI_ISDN,
                destination_addr=number,
                short_message=part,
                data_coding=smpplib.consts.SMPP_ENCODING_DEFAULT,
                esm_class=smpplib.consts.SMPP_MSGMODE_STOREFORWARD,
                registered_delivery=False,
            )

            seq_nr = pdu.sequence
            print('# Message part sent.')
            print(f'Send sequence nr: {seq_nr}')

For example, if you set -n 3, it means that a long message can be split into a maximum of 3 parts.

I understand all of that, but:

ssh root@sms1
root@sms1's password: 


BusyBox v1.34.1 (2024-04-29 07:31:19 UTC) built-in shell (ash)

     ____        _    ___  ____
    |  _ \ _   _| |_ / _ \/ ___|
    | |_) | | | | __| | | \___ \
    |  _ <| |_| | |_| |_| |___) |
    |_| \_\\__,_|\__|\___/|____/
-------------------------------------
     Teltonika RUT2M series 2024
-------------------------------------
   Device:     RUT241
   Kernel:     5.15.149
   Firmware:   RUT2M_R_00.07.07.1
   Build:      dde6d53e902
   Build date: 2024-04-30 09:56:09
-------------------------------------
root@sms1:~# /usr/sbin/smppd --port 2776 --username admin --password somepass -n3
Segmentation fault

That’s not what you would expect, right?

In addition, after more debugging, I can say that after running gsmd in debug mode (gsmd -D) the /usr/var/log/messages showed some more interesting information. I am using standard smppd at 2775 port here.

So I send messages in a loop. Every message has its number at the front: “text”:"1. 123…, “text”:"2. 123… and so on). The message is longer than 160 chars, but I see that it is divided to 2 requests to modem and is handled properly until the modem suddenly reports that it is busy:

Message nr 1:

Wed May 29 11:00:14 2024 daemon.info gsmd[733]: [ubus_handle_arg_request:444] debug: Ubus call: send_sms {"number":"601xxxxxx","text":"1. 1234567890 12345678901234567890123456789012345678901234567890123456789012345678901234567890123456789
0123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890"}
Wed May 29 11:00:14 2024 daemon.info gsmd[733]: [__new_request:413] debug: [MODEM] New request (Function) for `1-1 [2c7c:0125]` modem (338)
Wed May 29 11:00:14 2024 daemon.info gsmd[733]: [common_write_handle:206] debug: [CMM] Modem `1-1 [2c7c:0125]` cmd len: 499
Wed May 29 11:00:14 2024 daemon.info gsmd[733]: Wed May 29 11:00:14 2024 AT+CMGS=153\r005100098106316728F30000FFA0050003AE0201622E504C36A3D56C375C0E068AC966B49AED86CBC162B219AD66BBE172B0986C46ABD96EB81C2C269BD16AB61B2E078BC966B49AED86CBC1
62B219AD66BBE172B0986C46ABD96EB81C2C269BD16AB61B2E078BC966B49AED86CBC162B219AD66BBE172B0986C46ABD96EB81C2C269BD16AB61B2E078BC966B49AED86CBC162B219AD66BBE172�AT+CMGS=82\r005100098106316728F30000FF4E050003AE02026031D98C56B3DD7039584C36A3D56
C375C0E1693CD6835DB0D9783C564335ACD76C3E56031D98C56B3DD7039584C36A3D56C375C0E1693CD6835DB0D978301�
Wed May 29 11:00:14 2024 daemon.info gsmd[733]: [common_write_handle:214] debug: [CMM] Modem `1-1 [2c7c:0125]` len: 12, writing:
Wed May 29 11:00:14 2024 daemon.info gsmd[733]: Wed May 29 11:00:14 2024 AT+CMGS=153\r
Wed May 29 11:00:14 2024 daemon.info gsmd[733]: [process_response:449] debug: [CMM] Modem `1-1 [2c7c:0125]` received len: 4
Wed May 29 11:00:14 2024 daemon.info gsmd[733]: Wed May 29 11:00:14 2024 \r\n>
Wed May 29 11:00:14 2024 daemon.info gsmd[733]: [process_response:510] debug: [CMM] Modem `1-1 [2c7c:0125]` len: 309, writing second request part:
Wed May 29 11:00:14 2024 daemon.info gsmd[733]: Wed May 29 11:00:14 2024 005100098106316728F30000FFA0050003AE0201622E504C36A3D56C375C0E068AC966B49AED86CBC162B219AD66BBE172B0986C46ABD96EB81C2C269BD16AB61B2E078BC966B49AED86CBC162B219AD66BBE
172B0986C46ABD96EB81C2C269BD16AB61B2E078BC966B49AED86CBC162B219AD66BBE172B0986C46ABD96EB81C2C269BD16AB61B2E078BC966B49AED86CBC162B219AD66BBE172�
Wed May 29 11:00:15 2024 daemon.info gsmd[733]: [process_response:449] debug: [CMM] Modem `1-1 [2c7c:0125]` received len: 20
Wed May 29 11:00:15 2024 daemon.info gsmd[733]: Wed May 29 11:00:15 2024 \r\n+CMGS: 217\r\n\r\nOK\r\n
Wed May 29 11:00:15 2024 daemon.info gsmd[733]: [process_response:510] debug: [CMM] Modem `1-1 [2c7c:0125]` len: 11, writing second request part:
Wed May 29 11:00:15 2024 daemon.info gsmd[733]: Wed May 29 11:00:15 2024 AT+CMGS=82\r
Wed May 29 11:00:15 2024 daemon.info gsmd[733]: [process_response:449] debug: [CMM] Modem `1-1 [2c7c:0125]` received len: 4
Wed May 29 11:00:15 2024 daemon.info gsmd[733]: Wed May 29 11:00:15 2024 \r\n>
Wed May 29 11:00:15 2024 daemon.info gsmd[733]: [process_response:510] debug: [CMM] Modem `1-1 [2c7c:0125]` len: 167, writing second request part:
Wed May 29 11:00:15 2024 daemon.info gsmd[733]: Wed May 29 11:00:15 2024 005100098106316728F30000FF4E050003AE02026031D98C56B3DD7039584C36A3D56C375C0E1693CD6835DB0D9783C564335ACD76C3E56031D98C56B3DD7039584C36A3D56C375C0E1693CD6835DB0D97830
1�
Wed May 29 11:00:15 2024 daemon.info gsmd[733]: [process_response:449] debug: [CMM] Modem `1-1 [2c7c:0125]` received len: 20
Wed May 29 11:00:15 2024 daemon.info gsmd[733]: Wed May 29 11:00:15 2024 \r\n+CMGS: 218\r\n\r\nOK\r\n
Wed May 29 11:00:15 2024 daemon.info gsmd[733]: [handle_data:308] debug: [CMM] Parsed data:
Wed May 29 11:00:15 2024 daemon.info gsmd[733]: Wed May 29 11:00:15 2024 \r\n> \r\n+CMGS: 217\r\n\r\nOK\r\n\r\n> \r\n+CMGS: 218\r\n\r\nOK\r\n
Wed May 29 11:00:15 2024 daemon.info gsmd[733]: [__push:236] debug: [EVT] New event pushed: 6 (snd_sms) for `1-1 [2c7c:0125]` modem
Wed May 29 11:00:15 2024 daemon.info gsmd[733]: SMS was sent to: 601xxxxxx
Wed May 29 11:00:15 2024 daemon.info gsmd[733]: [handle_external:376] debug: Response to request (338): {"sms_used":2}
Wed May 29 11:00:15 2024 daemon.info gsmd[733]: [__worker_cb:160] debug: [EVT] Received new event ping!
Wed May 29 11:00:15 2024 daemon.info gsmd[733]: [evt_handle:103] debug: [EVT] Item changed: snd_sms on `1-1 [2c7c:0125]` modem
Wed May 29 11:00:15 2024 daemon.info gsmd[733]: [__queue_cb:620] debug: [CMM] No request available for `1-1 [2c7c:0125]` modem!
Wed May 29 11:00:15 2024 kern.info kernel: Sent 2 PDUs to 601xxxxxx

[…]
Message nr 12 (modem show ‘is busy’ message):

Wed May 29 11:00:28 2024 daemon.info gsmd[733]: [ubus_handle_arg_request:444] debug: Ubus call: send_sms {"number":"601xxxxxx","text":"12. 1234567890 1234567890123456789012345678901234567890123456789012345678901234567890123456789012345678
90123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890"}
Wed May 29 11:00:28 2024 daemon.info gsmd[733]: [__new_request:413] debug: [MODEM] New request (Function) for `1-1 [2c7c:0125]` modem (349)
Wed May 29 11:00:28 2024 daemon.info gsmd[733]: [common_write_handle:206] debug: [CMM] Modem `1-1 [2c7c:0125]` cmd len: 501
Wed May 29 11:00:28 2024 daemon.info gsmd[733]: Wed May 29 11:00:28 2024 AT+CMGS=153\r005100098106316728F30000FFA00500032D020162321728269BD16AB61B2E0703C564335ACD76C3E56031D98C56B3DD7039584C36A3D56C375C0E1693CD6835DB0D9783C564335ACD76C3E5
6031D98C56B3DD7039584C36A3D56C375C0E1693CD6835DB0D9783C564335ACD76C3E56031D98C56B3DD7039584C36A3D56C375C0E1693CD6835DB0D9783C564335ACD76C3E56031D98C56B3DD70�AT+CMGS=83\r005100098106316728F30000FF4F0500032D020272B0986C46ABD96EB81C2C269BD16
AB61B2E078BC966B49AED86CBC162B219AD66BBE172B0986C46ABD96EB81C2C269BD16AB61B2E078BC966B49AED86CBC100�
Wed May 29 11:00:28 2024 daemon.info gsmd[733]: [common_write_handle:214] debug: [CMM] Modem `1-1 [2c7c:0125]` len: 12, writing:
Wed May 29 11:00:28 2024 daemon.info gsmd[733]: Wed May 29 11:00:28 2024 AT+CMGS=153\r
Wed May 29 11:00:28 2024 daemon.info gsmd[733]: [__queue_cb:603] debug: [CMM] **Modem `1-1 [2c7c:0125]` is busy!**
Wed May 29 11:00:28 2024 daemon.info gsmd[733]: [__queue_cb:606] debug: [CMM] Setting up pending queue dispatcher...
Wed May 29 11:00:28 2024 daemon.info gsmd[733]: [process_response:449] debug: [CMM] Modem `1-1 [2c7c:0125]` received len: 4
Wed May 29 11:00:28 2024 daemon.info gsmd[733]: Wed May 29 11:00:28 2024 \r\n>
Wed May 29 11:00:28 2024 daemon.info gsmd[733]: [process_response:510] debug: [CMM] Modem `1-1 [2c7c:0125]` len: 309, writing second request part:
Wed May 29 11:00:28 2024 daemon.info gsmd[733]: Wed May 29 11:00:28 2024 005100098106316728F30000FFA00500032D020162321728269BD16AB61B2E0703C564335ACD76C3E56031D98C56B3DD7039584C36A3D56C375C0E1693CD6835DB0D9783C564335ACD76C3E56031D98C56B3DD7039584C36A3D56C375C0E1693CD6835DB0D9783C564335ACD76C3E56031D98C56B3DD7039584C36A3D56C375C0E1693CD6835DB0D9783C564335ACD76C3E56031D98C56B3DD70�
Wed May 29 11:00:29 2024 daemon.info gsmd[733]: [process_response:449] debug: [CMM] Modem `1-1 [2c7c:0125]` received len: 20
Wed May 29 11:00:29 2024 daemon.info gsmd[733]: Wed May 29 11:00:29 2024 \r\n+CMGS: 239\r\n\r\nOK\r\n
Wed May 29 11:00:29 2024 daemon.info gsmd[733]: [process_response:510] debug: [CMM] Modem `1-1 [2c7c:0125]` len: 11, writing second request part:
Wed May 29 11:00:29 2024 daemon.info gsmd[733]: Wed May 29 11:00:29 2024 AT+CMGS=83\r
Wed May 29 11:00:29 2024 daemon.info gsmd[733]: [process_response:449] debug: [CMM] Modem `1-1 [2c7c:0125]` received len: 4
Wed May 29 11:00:29 2024 daemon.info gsmd[733]: Wed May 29 11:00:29 2024 \r\n>
Wed May 29 11:00:29 2024 daemon.info gsmd[733]: [process_response:510] debug: [CMM] Modem `1-1 [2c7c:0125]` len: 169, writing second request part:
Wed May 29 11:00:29 2024 daemon.info gsmd[733]: Wed May 29 11:00:29 2024 005100098106316728F30000FF4F0500032D020272B0986C46ABD96EB81C2C269BD16AB61B2E078BC966B49AED86CBC162B219AD66BBE172B0986C46ABD96EB81C2C269BD16AB61B2E078BC966B49AED86CBC100�
Wed May 29 11:00:29 2024 kern.info kernel: Sent 2 PDUs to 601xxxxxx

Then it goes into ‘modem is still busy’:

Wed May 29 11:00:30 2024 daemon.info gsmd[733]: [ubus_handle_arg_request:444] debug: Ubus call: send_sms {"number":"601xxxxxx","text":"14. 1234567890 1234567890123456789012345678901234567890123456789012345678901234567890123456789012345678
90123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890"}
Wed May 29 11:00:30 2024 daemon.info gsmd[733]: [__new_request:413] debug: [MODEM] New request (Function) for `1-1 [2c7c:0125]` modem (351)
Wed May 29 11:00:30 2024 daemon.info gsmd[733]: [common_write_handle:206] debug: [CMM] Modem `1-1 [2c7c:0125]` cmd len: 501
Wed May 29 11:00:30 2024 daemon.info gsmd[733]: Wed May 29 11:00:30 2024 AT+CMGS=153\r005100098106316728F30000FFA005000380020162341728269BD16AB61B2E0703C564335ACD76C3E56031D98C56B3DD7039584C36A3D56C375C0E1693CD6835DB0D9783C564335ACD76C3E5
6031D98C56B3DD7039584C36A3D56C375C0E1693CD6835DB0D9783C564335ACD76C3E56031D98C56B3DD7039584C36A3D56C375C0E1693CD6835DB0D9783C564335ACD76C3E56031D98C56B3DD70�AT+CMGS=83\r005100098106316728F30000FF4F05000380020272B0986C46ABD96EB81C2C269BD16
AB61B2E078BC966B49AED86CBC162B219AD66BBE172B0986C46ABD96EB81C2C269BD16AB61B2E078BC966B49AED86CBC100�
Wed May 29 11:00:30 2024 daemon.info gsmd[733]: [common_write_handle:214] debug: [CMM] Modem `1-1 [2c7c:0125]` len: 12, writing:
Wed May 29 11:00:30 2024 daemon.info gsmd[733]: Wed May 29 11:00:30 2024 AT+CMGS=153\r
Wed May 29 11:00:30 2024 daemon.info gsmd[733]: [__dispatch_cb:403] debug: [CMM] **Modem `1-1 [2c7c:0125]` is still busy!**

And then I think the modem does something to reconnect itself to the GSM operator (correct me if I’m wrong):

Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [__periodic_cb:53] debug: [MODEM] Running periodic work for `1-1 [2c7c:0125]` modem
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [__new_internal_request:443] debug: [MODEM] New internal request (Function) for `1-1 [2c7c:0125]` modem (356)
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [__new_internal_request:443] debug: [MODEM] New internal request (Function) for `1-1 [2c7c:0125]` modem (357)
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [__new_internal_request:443] debug: [MODEM] New internal request (Function) for `1-1 [2c7c:0125]` modem (358)
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [__new_internal_request:443] debug: [MODEM] New internal request (Function) for `1-1 [2c7c:0125]` modem (359)
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [__new_internal_request:443] debug: [MODEM] New internal request (Function) for `1-1 [2c7c:0125]` modem (360)
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [__queue_cb:603] debug: [CMM] Modem `1-1 [2c7c:0125]` is busy!
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [process_response:449] debug: [CMM] Modem `1-1 [2c7c:0125]` received len: 101
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 \r\n+QENG: "servingcell","NOCONN","LTE","FDD",260,01,3B9A203,224,1300,3,5,5,A412,-91,-8,-63,9,-\r\n\r\nOK\r\n
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [handle_data:308] debug: [CMM] Parsed data:
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 \r\n+QENG: "servingcell","NOCONN","LTE","FDD",260,01,3B9A203,224,1300,3,5,5,A412,-91,-8,-63,9,-\r\n\r\nOK\r\n
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [common_write_handle:206] debug: [CMM] Modem `1-1 [2c7c:0125]` cmd len: 9
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 AT+QTEMP\r
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [common_write_handle:214] debug: [CMM] Modem `1-1 [2c7c:0125]` len: 9, writing:
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 AT+QTEMP\r
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [__queue_cb:603] debug: [CMM] Modem `1-1 [2c7c:0125]` is busy!
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [__queue_cb:603] debug: [CMM] Modem `1-1 [2c7c:0125]` is busy!
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [__queue_cb:603] debug: [CMM] Modem `1-1 [2c7c:0125]` is busy!
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [__queue_cb:603] debug: [CMM] Modem `1-1 [2c7c:0125]` is busy!
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [process_response:449] debug: [CMM] Modem `1-1 [2c7c:0125]` received len: 24
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 \r\n+QTEMP: 42,37,36\r\nOK\r\n
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [handle_data:308] debug: [CMM] Parsed data:
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 \r\n+QTEMP: 42,37,36\r\nOK\r\n
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [common_write_handle:206] debug: [CMM] Modem `1-1 [2c7c:0125]` cmd len: 18
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 AT+CFUN?\rAT+CPIN?\r
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [common_write_handle:214] debug: [CMM] Modem `1-1 [2c7c:0125]` len: 9, writing:
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 AT+CFUN?\r
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [process_response:449] debug: [CMM] Modem `1-1 [2c7c:0125]` received len: 18
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 \r\n+CFUN: 1\r\n\r\nOK\r\n
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [process_response:510] debug: [CMM] Modem `1-1 [2c7c:0125]` len: 9, writing second request part:
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 AT+CPIN?\r
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [process_response:449] debug: [CMM] Modem `1-1 [2c7c:0125]` received len: 22
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 \r\n+CPIN: READY\r\n\r\nOK\r\n
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [handle_data:308] debug: [CMM] Parsed data:
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 \r\n+CFUN: 1\r\n\r\nOK\r\n\r\n+CPIN: READY\r\n\r\nOK\r\n
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [__push:236] debug: [EVT] New event pushed: 1 (pin_state) for `1-1 [2c7c:0125]` modem
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [__worker_cb:160] debug: [EVT] Received new event ping!
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [common_write_handle:206] debug: [CMM] Modem `1-1 [2c7c:0125]` cmd len: 10
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 AT+QPINC?\r
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [common_write_handle:214] debug: [CMM] Modem `1-1 [2c7c:0125]` len: 10, writing:
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 AT+QPINC?\r
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [process_response:449] debug: [CMM] Modem `1-1 [2c7c:0125]` received len: 46
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 \r\n+QPINC: "SC",3,10\r\n+QPINC: "P2",3,10\r\n\r\nOK\r\n
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [handle_data:308] debug: [CMM] Parsed data:
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 \r\n+QPINC: "SC",3,10\r\n+QPINC: "P2",3,10\r\n\r\nOK\r\n
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [common_write_handle:206] debug: [CMM] Modem `1-1 [2c7c:0125]` cmd len: 8
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 AT+QCSQ\r
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [common_write_handle:214] debug: [CMM] Modem `1-1 [2c7c:0125]` len: 8, writing:
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 AT+QCSQ\r
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [process_response:449] debug: [CMM] Modem `1-1 [2c7c:0125]` received len: 37
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 \r\n+QCSQ: "LTE",62,-92,117,-13\r\n\r\nOK\r\n
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [handle_data:308] debug: [CMM] Parsed data:
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 \r\n+QCSQ: "LTE",62,-92,117,-13\r\n\r\nOK\r\n
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [__push:236] debug: [EVT] New event pushed: 7 (rssi_value) for `1-1 [2c7c:0125]` modem
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [__push:236] debug: [EVT] New event pushed: 10 (rsrp_value) for `1-1 [2c7c:0125]` modem
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [__push:236] debug: [EVT] New event pushed: 11 (sinr_value) for `1-1 [2c7c:0125]` modem
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [__push:236] debug: [EVT] New event pushed: 12 (rsrq_value) for `1-1 [2c7c:0125]` modem
ed May 29 11:00:31 2024 daemon.info gsmd[733]: [__worker_cb:160] debug: [EVT] Received new event ping!
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [evt_handle:103] debug: [EVT] Item changed: rssi_value on `1-1 [2c7c:0125]` modem
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [common_write_handle:206] debug: [CMM] Modem `1-1 [2c7c:0125]` cmd len: 8
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 AT+QSPN\r
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [common_write_handle:214] debug: [CMM] Modem `1-1 [2c7c:0125]` len: 8, writing:
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 AT+QSPN\r
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [__worker_cb:160] debug: [EVT] Received new event ping!
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [evt_handle:103] debug: [EVT] Item changed: rsrp_value on `1-1 [2c7c:0125]` modem
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [__worker_cb:160] debug: [EVT] Received new event ping!
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [evt_handle:103] debug: [EVT] Item changed: sinr_value on `1-1 [2c7c:0125]` modem
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [process_response:449] debug: [CMM] Modem `1-1 [2c7c:0125]` received len: 43
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 \r\n+QSPN: "Plus","Plus","",0,"26001"\r\n\r\nOK\r\n
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [handle_data:308] debug: [CMM] Parsed data:
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 \r\n+QSPN: "Plus","Plus","",0,"26001"\r\n\r\nOK\r\n
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [__worker_cb:160] debug: [EVT] Received new event ping!

… and then goes to sending the SMSes further:

Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [evt_handle:103] debug: [EVT] Item changed: rsrq_value on `1-1 [2c7c:0125]` modem
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [common_write_handle:206] debug: [CMM] Modem `1-1 [2c7c:0125]` cmd len: 8
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 AT+CIMI\r
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [common_write_handle:214] debug: [CMM] Modem `1-1 [2c7c:0125]` len: 8, writing:
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 AT+CIMI\r
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [ubus_handle_arg_request:444] debug: Ubus call: send_sms {"number":"601xxxxxx","text":"15. 1234567890 123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890"}
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [__new_request:413] debug: [MODEM] New request (Function) for `1-1 [2c7c:0125]` modem (361)
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [__queue_cb:603] debug: [CMM] Modem `1-1 [2c7c:0125]` is busy!
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [__queue_cb:603] debug: [CMM] Modem `1-1 [2c7c:0125]` is busy!
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [process_response:449] debug: [CMM] Modem `1-1 [2c7c:0125]` received len: 25
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 \r\n260011605589397\r\n\r\nOK\r\n
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [handle_data:308] debug: [CMM] Parsed data:
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 \r\n260011605589397\r\n\r\nOK\r\n
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [common_write_handle:206] debug: [CMM] Modem `1-1 [2c7c:0125]` cmd len: 501
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 AT+CMGS=153\r005100098106316728F30000FFA005000360020162351728269BD16AB61B2E0703C564335ACD76C3E56031D98C56B3DD7039584C36A3D56C375C0E1693CD6835DB0D9783C564335ACD76C3E56031D98C56B3DD7039584C36A3D56C375C0E1693CD6835DB0D9783C564335ACD76C3E56031D98C56B3DD7039584C36A3D56C375C0E1693CD6835DB0D9783C564335ACD76C3E56031D98C56B3DD70�AT+CMGS=83\r005100098106316728F30000FF4F05000360020272B0986C46ABD96EB81C2C269BD16AB61B2E078BC966B49AED86CBC162B219AD66BBE172B0986C46ABD96EB81C2C269BD16AB61B2E078BC966B49AED86CBC100�
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [common_write_handle:214] debug: [CMM] Modem `1-1 [2c7c:0125]` len: 12, writing:
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 AT+CMGS=153\r
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [process_response:449] debug: [CMM] Modem `1-1 [2c7c:0125]` received len: 4
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 \r\n>
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: [process_response:510] debug: [CMM] Modem `1-1 [2c7c:0125]` len: 309, writing second request part:
Wed May 29 11:00:31 2024 daemon.info gsmd[733]: Wed May 29 11:00:31 2024 005100098106316728F30000FFA005000360020162351728269BD16AB61B2E0703C564335ACD76C3E56031D98C56B3DD7039584C36A3D56C375C0E1693CD6835DB0D9783C564335ACD76C3E56031D98C56B3DD7039584C36A3D56C375C0E1693CD6835DB0D9783C564335ACD76C3E56031D98C56B3DD7039584C36A3D56C375C0E1693CD6835DB0D9783C564335ACD76C3E56031D98C56B3DD70�
Wed May 29 11:00:32 2024 kern.info kernel: **Sent 2 PDUs to 601xxxxxx**

But then it enters ‘still busy’ and won’t send SMS for long time:

Wed May 29 11:00:33 2024 daemon.info gsmd[733]: [process_response:449] debug: [CMM] Modem `1-1 [2c7c:0125]` received len: 20
Wed May 29 11:00:33 2024 daemon.info gsmd[733]: Wed May 29 11:00:33 2024 \r\n+CMGS: 247\r\n\r\nOK\r\n
Wed May 29 11:00:33 2024 daemon.info gsmd[733]: [process_response:510] debug: [CMM] Modem `1-1 [2c7c:0125]` len: 11, writing second request part:
Wed May 29 11:00:33 2024 daemon.info gsmd[733]: Wed May 29 11:00:33 2024 AT+CMGS=83\r
Wed May 29 11:00:33 2024 daemon.info gsmd[733]: [process_response:449] debug: [CMM] Modem `1-1 [2c7c:0125]` received len: 4
Wed May 29 11:00:33 2024 daemon.info gsmd[733]: Wed May 29 11:00:33 2024 \r\n>
Wed May 29 11:00:33 2024 daemon.info gsmd[733]: [process_response:510] debug: [CMM] Modem `1-1 [2c7c:0125]` len: 169, writing second request part:
Wed May 29 11:00:33 2024 daemon.info gsmd[733]: Wed May 29 11:00:33 2024 005100098106316728F30000FF4F050003B1020272B0986C46ABD96EB81C2C269BD16AB61B2E078BC966B49AED86CBC162B219AD66BBE172B0986C46ABD96EB81C2C269BD16AB61B2E078BC966B49AED86CBC
100�
Wed May 29 11:00:34 2024 daemon.info gsmd[733]: [__dispatch_cb:403] debug: [CMM] Modem `1-1 [2c7c:0125]` is still busy!
Wed May 29 11:00:35 2024 daemon.info gsmd[733]: [__dispatch_cb:403] debug: [CMM] Modem `1-1 [2c7c:0125]` is still busy!
Wed May 29 11:00:36 2024 daemon.info gsmd[733]: [__periodic_cb:53] debug: [MODEM] Running periodic work for `1-1 [2c7c:0125]` modem
Wed May 29 11:00:36 2024 daemon.info gsmd[733]: [__dispatch_cb:403] debug: [CMM] Modem `1-1 [2c7c:0125]` is still busy!
Wed May 29 11:00:37 2024 daemon.info gsmd[733]: [__dispatch_cb:403] debug: [CMM] Modem `1-1 [2c7c:0125]` is still busy!
Wed May 29 11:00:39 2024 daemon.info gsmd[733]: [__dispatch_cb:403] debug: [CMM] Modem `1-1 [2c7c:0125]` is still busy!
Wed May 29 11:00:40 2024 daemon.info gsmd[733]: [__dispatch_cb:403] debug: [CMM] Modem `1-1 [2c7c:0125]` is still busy!
Wed May 29 11:00:41 2024 daemon.info gsmd[733]: [__cache_update_cb:86] debug: [MODEM] Running cache update work for `1-1 [2c7c:0125]` modem
Wed May 29 11:00:41 2024 daemon.info gsmd[733]: [__periodic_cb:53] debug: [MODEM] Running periodic work for `1-1 [2c7c:0125]` modem
Wed May 29 11:00:41 2024 daemon.info gsmd[733]: [__dispatch_cb:403] debug: [CMM] Modem `1-1 [2c7c:0125]` is still busy!
Wed May 29 11:00:42 2024 daemon.info gsmd[733]: [__dispatch_cb:403] debug: [CMM] Modem `1-1 [2c7c:0125]` is still busy!
Wed May 29 11:00:44 2024 daemon.info gsmd[733]: [__dispatch_cb:403] debug: [CMM] Modem `1-1 [2c7c:0125]` is still busy!
Wed May 29 11:00:45 2024 daemon.info gsmd[733]: [__dispatch_cb:403] debug: [CMM] Modem `1-1 [2c7c:0125]` is still busy!

[…]

Wed May 29 11:01:21 2024 daemon.info gsmd[733]: [__dispatch_cb:403] debug: [CMM] Modem `1-1 [2c7c:0125]` is still busy!
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [process_response:449] debug: [CMM] Modem `1-1 [2c7c:0125]` received len: 476
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: Wed May 29 11:01:22 2024 \r\n+CMGS: 248\r\n\r\nOK\r\n\r\n+QCSQ: "LTE",56,-92,107,-13\r\n\r\n+QCSQ: "LTE",62,-92,117,-13\r\n\r\n+QCSQ: "LTE",62,-92,124,-13\r\n\r\n+QCSQ: "LTE",62,-92,139,-13\r\n\r\n+QCSQ: "LTE",62,-92,146,-8\r\n\r\n+QCSQ: "LTE",62,-92,122,-8\r\n\r\n+QCSQ: "LTE",62,-92,124,-8\r\n\r\n+QCSQ: "LTE",62,-92,126,-8\r\n\r\n+QCSQ: "LTE",62,-92,135,-8\r\n\r\n+QCSQ: "LTE",62,-92,141,-13\r\n\r\n+QCSQ: "LTE",62,-92,116,-13\r\n\r\n+QCSQ: "LTE",62,-92,123,-8\r\n\r\n+QCSQ: "LTE",62,-92,121,-8\r\n\r\n+QCSQ: "LTE",62,-92,133,-8\r\n\r\n+QCSQ: "LTE",62,-92,130,-8\r\n
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [handle_urc:252] debug: [CMM] Parsed URC:
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: Wed May 29 11:01:22 2024 \r\n+QCSQ: "LTE",56,-92,107,-13\r\n
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [urc_qcsq:1719] debug: [QUECTEL_DRIVER] Modem `1-1 [2c7c:0125]` URC Event: Network Mode => LTE
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [urc_qcsq:1721] debug: [QUECTEL_DRIVER] Modem `1-1 [2c7c:0125]` URC Event: RSSI Signal  => -56 dBm
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [urc_qcsq:1723] debug: [QUECTEL_DRIVER] Modem `1-1 [2c7c:0125]` URC Event: RSRP Signal  => -92 dBm
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [urc_qcsq:1725] debug: [QUECTEL_DRIVER] Modem `1-1 [2c7c:0125]` URC Event: SINR Signal  => 1 dB
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [urc_qcsq:1727] debug: [QUECTEL_DRIVER] Modem `1-1 [2c7c:0125]` URC Event: RSRQ Signal  => -13 dB
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [__push:236] debug: [EVT] New event pushed: 7 (rssi_value) for `1-1 [2c7c:0125]` modem
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [__push:236] debug: [EVT] New event pushed: 10 (rsrp_value) for `1-1 [2c7c:0125]` modem
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [__push:236] debug: [EVT] New event pushed: 11 (sinr_value) for `1-1 [2c7c:0125]` modem
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [__push:236] debug: [EVT] New event pushed: 12 (rsrq_value) for `1-1 [2c7c:0125]` modem
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [handle_urc:252] debug: [CMM] Parsed URC:

[…]
until it takes on the work again:

Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [__push:236] debug: [EVT] New event pushed: 7 (rssi_value) for `1-1 [2c7c:0125]` modem
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [__push:236] debug: [EVT] New event pushed: 10 (rsrp_value) for `1-1 [2c7c:0125]` modem
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [__push:236] debug: [EVT] New event pushed: 11 (sinr_value) for `1-1 [2c7c:0125]` modem
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [__push:236] debug: [EVT] New event pushed: 12 (rsrq_value) for `1-1 [2c7c:0125]` modem
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [handle_data:308] debug: [CMM] Parsed data:
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: Wed May 29 11:01:22 2024 \r\n> \r\n+CMGS: 247\r\n\r\nOK\r\n\r\n> \r\n+CMGS: 248\r\n\r\nOK\r\n
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [__push:236] debug: [EVT] New event pushed: 6 (snd_sms) for `1-1 [2c7c:0125]` modem
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: **SMS was sent to: 601xxxxxx**
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [handle_external:376] debug: Response to request (362): {"sms_used":2}
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [__worker_cb:160] debug: [EVT] Received new event ping!
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [ubus_handle_arg_request:444] debug: Ubus call: send_sms {"number":"601xxxxxx","text":"17. 1234567890 1234567890123456789012345678901234567890123456789012345678901234567890123456789012345678
90123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890"}
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [__new_request:413] debug: [MODEM] New request (Function) for `1-1 [2c7c:0125]` modem (363)
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [common_write_handle:206] debug: [CMM] Modem `1-1 [2c7c:0125]` cmd len: 501
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: Wed May 29 11:01:22 2024 AT+CMGS=153\r005100098106316728F30000FFA005000307020162371728269BD16AB61B2E0703C564335ACD76C3E56031D98C56B3DD7039584C36A3D56C375C0E1693CD6835DB0D9783C564335ACD76C3E5
6031D98C56B3DD7039584C36A3D56C375C0E1693CD6835DB0D9783C564335ACD76C3E56031D98C56B3DD7039584C36A3D56C375C0E1693CD6835DB0D9783C564335ACD76C3E56031D98C56B3DD70�AT+CMGS=83\r005100098106316728F30000FF4F05000307020272B0986C46ABD96EB81C2C269BD16
AB61B2E078BC966B49AED86CBC162B219AD66BBE172B0986C46ABD96EB81C2C269BD16AB61B2E078BC966B49AED86CBC100�
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [common_write_handle:214] debug: [CMM] Modem `1-1 [2c7c:0125]` len: 12, writing:
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: Wed May 29 11:01:22 2024 AT+CMGS=153\r
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [__worker_cb:160] debug: [EVT] Received new event ping!
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [__queue_cb:603] debug: [CMM] Modem `1-1 [2c7c:0125]` is busy!
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [process_response:449] debug: [CMM] Modem `1-1 [2c7c:0125]` received len: 4
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: Wed May 29 11:01:22 2024 \r\n>
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [process_response:510] debug: [CMM] Modem `1-1 [2c7c:0125]` len: 309, writing second request part:
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: Wed May 29 11:01:22 2024 005100098106316728F30000FFA005000307020162371728269BD16AB61B2E0703C564335ACD76C3E56031D98C56B3DD7039584C36A3D56C375C0E1693CD6835DB0D9783C564335ACD76C3E56031D98C56B3D
D7039584C36A3D56C375C0E1693CD6835DB0D9783C564335ACD76C3E56031D98C56B3DD7039584C36A3D56C375C0E1693CD6835DB0D9783C564335ACD76C3E56031D98C56B3DD70�
Wed May 29 11:01:22 2024 daemon.info gsmd[733]: [__worker_cb:160] debug: [EVT] Received new event ping!
[...]
Wed May 29 11:01:22 2024 kern.info kernel: **Sent 2 PDUs to 601xxxxxx**

Does anyone makes some sense from all of that?

The signal to the operator when doing all of these operations seems to be at the same level.

I have did some more testing and here’s what I have found.

I am using gsmctl directly from the RUT241 CLI so to shorten the possible problem path to minimum.

  1. 40 short messages is sent without any sleep and without any problems from the router to my phone. No hangs here, ever.
for i in `seq 1 40`; do gsmctl -D -S -s "<MY_PHONE_NUMBER> $i. 100000000020000000003000000000400000000050000000006000000000700000000080000000009000000000100000000011000000001200000000"; done
  1. Trying to send 10 long (not so long, because they are only divided to 2 short messages) using 10 seconds sleep can result in about 40-50 seconds hang during sending even the 3rd message, sometimes it is later and the hang can happen at trying to send the 10th message.
for i in `seq 1 10`; do gsmctl -D -S -s "<MY_PHONE_NUMBER> $i. 10000000002000000000300000000040000000005000000000600000000070000000008000000000900000000010000000001100000000120000000013000000001400000000150000000016000
000001700000000180000000019000000002000000000"; sleep 10; done

Why is that the modem and gsmd can handle 40 short messages without any hangs and using 2-part message can make the modem to become busy and hang for several dozen of seconds?

This topic was automatically closed after 15 days. New replies are no longer allowed.