Actions
Bug #2237
openofono: Gobi modem: successful SMS delivery is evaluated as not successful
Added by neels almost 7 years ago. Updated almost 6 years ago.
Start date:
05/05/2017
Due date:
% Done:
50%
Spec Reference:
Description
For Gobi modem: when successfully sending an SMS via ofono, successful delivery is interpreted as failure and the SMS is re-sent N times until ending in state "failed".
Detailed logs follow.
Files
| nitb.log.txt | nitb.log.txt | 100 KB | pespin, 08/29/2017 11:08 AM | ||
| ofono.log.txt | ofono.log.txt | 5.94 KB | pespin, 08/29/2017 11:08 AM | ||
| gsmtap_rsl.pcapng | gsmtap_rsl.pcapng | 140 KB | pespin, 08/29/2017 11:08 AM |
Related issues
Updated by neels almost 7 years ago
Setup: added a very long sleep() to the end of a test case, i.e. an osmo-gsm-tester run is setup and idling, ready for manual interaction.
Manual SMS sent:
root@osmo-gsm-tester-rnd:~# mdbus2 -s org.ofono /gobi_3 org.ofono.MessageManager.SendMessage 1010 "test sms being resent though it was successful"
('/gobi_3/message_AF25C4D36D2D0BA86D5A7445F99D2C8B7BBFF196',)
dbus signals:
[SIGNAL] org.ofono.MessageManager.MessageAdded /gobi_3 :1.873
('/gobi_3/message_AF25C4D36D2D0BA86D5A7445F99D2C8B7BBFF196', {'State': <'pending'>})
[SIGNAL] org.ofono.MessageManager.IncomingMessage /sierra_1 :1.873
('test sms being resent though it was successful', {'LocalSentTime': <'2017-05-05T14:56:18+0200'>, 'SentTime': <'2017-05-05T12:56:18+0000'>, 'Sender': <'1009'>})
[SIGNAL] org.ofono.MessageManager.IncomingMessage /sierra_1 :1.873
('test sms being resent though it was successful', {'LocalSentTime': <'2017-05-05T14:56:26+0200'>, 'SentTime': <'2017-05-05T12:56:26+0000'>, 'Sender': <'1009'>})
[SIGNAL] org.ofono.MessageManager.IncomingMessage /sierra_1 :1.873
('test sms being resent though it was successful', {'LocalSentTime': <'2017-05-05T14:56:41+0200'>, 'SentTime': <'2017-05-05T12:56:41+0000'>, 'Sender': <'1009'>})
[SIGNAL] org.ofono.Message.PropertyChanged /gobi_3/message_AF25C4D36D2D0BA86D5A7445F99D2C8B7BBFF196 :1.873
('State', <'failed'>)
[SIGNAL] org.ofono.MessageManager.MessageRemoved /gobi_3 :1.873
('/gobi_3/message_AF25C4D36D2D0BA86D5A7445F99D2C8B7BBFF196',)
[SIGNAL] org.ofono.MessageManager.IncomingMessage /sierra_1 :1.873
('test sms being resent though it was successful', {'LocalSentTime': <'2017-05-05T14:56:58+0200'>, 'SentTime': <'2017-05-05T12:56:58+0000'>, 'Sender': <'1009'>})
NITB log:
20170505145614107 DRSL <0004> abis_rsl.c:1867 (bts=0,trx=0,ts=0,ss=1) Activating ARFCN(868) SS(1) lctype SDCCH r=OTHER ra=0x10 ta=0 20170505145614108 DRSL <0004> abis_rsl.c:586 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) Tx RSL Channel Activate with act_type=INITIAL 20170505145614108 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state NONE -> ACTIVATION REQUESTED 20170505145614116 DRSL <0004> abis_rsl.c:1590 (bts=0,trx=0,ts=0,ss=1) CHANNEL ACTIVATE ACK 20170505145614116 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state ACTIVATION REQUESTED -> ACTIVE ****************************** SENDING 20170505145614459 DMM <0002> gsm_04_08.c:1016 <- CM SERVICE REQUEST serv_type=0x04 MI(TMSI)=737688935 20170505145614482 DMM <0002> gsm_04_08_utils.c:662 -> CM SERVICE ACK 20170505145616108 DLSMS <0022> gsm_04_11.c:805 receiving data (trans_id=8) 20170505145616108 DLSMS <0022> gsm_04_11.c:820 -> (new transaction) 20170505145616108 DLSMS <0022> gsm0411_smc.c:87 SMC(0) instance created for network 20170505145616108 DLSMS <0022> gsm0411_smr.c:85 SMR(0) instance created for network. 20170505145616108 DLSMS <0022> gsm0411_smc.c:567 SMC(0) message MMSMS-EST-IND (CP DATA) received in state IDLE 20170505145616108 DLSMS <0022> gsm0411_smc.c:284 SMC(0) received CP-DATA 20170505145616108 DLSMS <0022> gsm0411_smc.c:133 SMC(0) new CP state IDLE -> MM_ESTABLISHED 20170505145616108 DLSMS <0022> gsm_04_11.c:143 sending CP message (trans=8) 20170505145616108 DLSMS <0022> gsm_04_11.c:127 GSM4.11 TX 89 04 20170505145616108 DLSMS <0022> gsm_04_11.c:769 MNSMS-DATA/EST-IND 20170505145616108 DLSMS <0022> gsm0411_smr.c:483 SMR(0) message MNSMS-EST-IND received in state IDLE 20170505145616108 DLSMS <0022> gsm0411_smr.c:257 SMR(0) RX SMS RP-DATA 20170505145616108 DLSMS <0022> gsm0411_smr.c:139 SMR(0) new RP state IDLE -> WAIT_TO_TX_RP_ACK 20170505145616108 DLSMS <0022> gsm_04_11.c:686 RX SMS RP-DATA (MO) 20170505145616108 DLSMS <0022> gsm_04_11.c:586 RX_RP-DATA: src_len=0, dst_len=2 ud_len=51 20170505145616108 DLSMS <0022> gsm_04_11.c:554 DST(2,91 f7 ) 20170505145616108 DLSMS <0022> gsm_04_11.c:478 RX SMS: Sender: 901700000009032, MTI: 0x01, VPF: 0x02, MR: 0x35 PID: 0x00, DCS: 0x00, DA: 1010, UserDataLength: 0x2e, UserData: "test sms being resent though it was successful" 20170505145616108 DLSMS <0022> sms_queue.c:333 Triggering SMS queue 20170505145616130 DLSMS <0022> sms_queue.c:333 Triggering SMS queue 20170505145616130 DLSMS <0022> gsm_04_11.c:513 TX: SMS RP ACK 20170505145616130 DLSMS <0022> gsm0411_smr.c:416 SMR(0) message SM-RL-REPORT_REQ received in state WAIT_TO_TX_RP_ACK 20170505145616130 DLSMS <0022> gsm0411_smr.c:226 SMR(0) TX SMS REPORT 20170505145616130 DLSMS <0022> gsm0411_smr.c:139 SMR(0) new RP state WAIT_TO_TX_RP_ACK -> IDLE 20170505145616130 DLSMS <0022> gsm0411_smc.c:467 SMC(0) message MNSMS-DATA-REQ received in state MM_ESTABLISHED 20170505145616130 DLSMS <0022> gsm0411_smc.c:180 SMC(0) send CP data 20170505145616131 DLSMS <0022> gsm0411_smc.c:133 SMC(0) new CP state MM_ESTABLISHED -> WAIT_CP_ACK 20170505145616131 DLSMS <0022> gsm_04_11.c:143 sending CP message (trans=8) 20170505145616131 DLSMS <0022> gsm_04_11.c:127 GSM4.11 TX 89 01 02 03 2b 20170505145616131 DLSMS <0022> gsm0411_smr.c:185 SMR(0) TX: MNSMS-REL-REQ 20170505145616131 DLSMS <0022> gsm0411_smc.c:467 SMC(0) message MNSMS-REL-REQ received in state WAIT_CP_ACK 20170505145616131 DLSMS <0022> gsm0411_smc.c:332 SMC(0) cannot release yet current state: WAIT_CP_ACK 20170505145616814 DLSMS <0022> gsm_04_11.c:805 receiving data (trans_id=8) 20170505145616814 DLSMS <0022> gsm0411_smc.c:567 SMC(0) message MMSMS-DATA-IND (CP ACK) received in state WAIT_CP_ACK 20170505145616814 DLSMS <0022> gsm0411_smc.c:256 SMC(0) received CP-ACK 20170505145616814 DLSMS <0022> gsm0411_smc.c:133 SMC(0) new CP state WAIT_CP_ACK -> MM_ESTABLISHED 20170505145616814 DLSMS <0022> gsm0411_smc.c:268 SMC(0) we have pending release. 20170505145616814 DLSMS <0022> gsm0411_smc.c:133 SMC(0) new CP state MM_ESTABLISHED -> IDLE 20170505145616814 DLSMS <0022> gsm_04_11.c:166 Got MMSMS_REL_REQ, destroying transaction. 20170505145616814 DLSMS <0022> gsm0411_smr.c:92 SMR(0) clearing SMR instance 20170505145616814 DLSMS <0022> gsm0411_smc.c:94 SMC(0) clearing instance 20170505145616840 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state ACTIVE -> RELEASE REQUESTED 20170505145616841 DRR <0003> gsm_04_08_utils.c:251 Sending Channel Release: Chan: Number: 1 Type: 1 20170505145616841 DRSL <0004> abis_rsl.c:768 (bts=0,trx=0,ts=0,ss=1) DEACTivate SACCH CMD 20170505145616845 DRSL <0004> abis_rsl.c:2027 (bts=0,trx=0,ts=0,ss=1) waiting for SAPI=0 to be released. 20170505145617049 DRSL <0004> abis_rsl.c:1718 (bts=0,trx=0,ts=0,ss=1) T3111 expired: releasing RF Channel 20170505145617049 DRSL <0004> abis_rsl.c:860 (bts=0,trx=0,ts=0,ss=1) RF Channel Release 20170505145617053 DRSL <0004> abis_rsl.c:931 (bts=0,trx=0,ts=0,ss=1) RF CHANNEL RELEASE ACK 20170505145617054 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state RELEASE REQUESTED -> NONE 20170505145617109 DLSMS <0022> sms_queue.c:220 Attempting to send 20 SMS 20170505145617121 DLSMS <0022> sms_queue.c:235 Sending SMS round 1 20170505145617121 DLSMS <0022> gsm_04_11.c:1008 Sending SMS: no connection open, start paging 901700000009031 20170505145617121 DMM <0002> gsm_subscriber.c:190 Subscriber 901700000009031 not paged yet. 20170505145617133 DLSMS <0022> sms_queue.c:235 Sending SMS round 2 20170505145617133 DLSMS <0022> sms_queue.c:251 Sending SMS done (loop) (1 attempted) 20170505145617133 DLSMS <0022> sms_queue.c:286 SMSqueue added 1 messages in 2 rounds 20170505145618376 DRSL <0004> abis_rsl.c:1867 (bts=0,trx=0,ts=0,ss=1) Activating ARFCN(868) SS(1) lctype SDCCH r=OTHER ra=0x10 ta=0 20170505145618376 DRSL <0004> abis_rsl.c:586 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) Tx RSL Channel Activate with act_type=INITIAL 20170505145618376 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state NONE -> ACTIVATION REQUESTED 20170505145618385 DRSL <0004> abis_rsl.c:1590 (bts=0,trx=0,ts=0,ss=1) CHANNEL ACTIVATE ACK 20170505145618385 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state ACTIVATION REQUESTED -> ACTIVE ****************************** DELIVERY 20170505145618696 DRR <0003> gsm_04_08.c:1462 PAGING RESPONSE: MI(TMSI)=3660505949 20170505145618696 DRR <0003> gsm_04_08.c:1495 <- Channel was requested by 901700000009031 20170505145618715 DLSMS <0022> gsm_04_11.c:965 paging_cb_send_sms(hooknum=1, event=0, msg=(nil),conn=0xe7cff0, sms=0xe7daf0/id: 9) 20170505145618715 DLSMS <0022> gsm_04_11.c:893 gsm411_send_sms() 20170505145618715 DLSMS <0022> gsm0411_smc.c:87 SMC(9) instance created for network 20170505145618715 DLSMS <0022> gsm0411_smr.c:85 SMR(9) instance created for network. 20170505145618715 DLSMS <0022> gsm_04_11.c:946 TX: SMS DELIVER 20170505145618731 DLSMS <0022> gsm0411_smr.c:416 SMR(9) message SM-RL-DATA_REQ received in state IDLE 20170505145618731 DLSMS <0022> gsm0411_smr.c:215 SMR(9) TX SMS RP-DATA 20170505145618731 DLSMS <0022> gsm0411_smr.c:139 SMR(9) new RP state IDLE -> WAIT_FOR_RP_ACK 20170505145618731 DLSMS <0022> gsm0411_smc.c:467 SMC(9) message MNSMS-EST-REQ received in state IDLE 20170505145618732 DLSMS <0022> gsm0411_smc.c:133 SMC(9) new CP state IDLE -> MM_CONN_PENDING 20170505145618732 DLSMS <0022> gsm0411_smc.c:567 SMC(9) message MMSMS-EST-CNF received in state MM_CONN_PENDING 20170505145618732 DLSMS <0022> gsm0411_smc.c:180 SMC(9) send CP data 20170505145618732 DLSMS <0022> gsm0411_smc.c:133 SMC(9) new CP state MM_CONN_PENDING -> WAIT_CP_ACK 20170505145618732 DLSMS <0022> gsm_04_11.c:143 sending CP message (trans=0) 20170505145618732 DLSMS <0022> gsm_04_11.c:127 GSM4.11 TX 09 01 44 01 00 07 91 44 77 58 10 06 50 00 38 00 04 80 01 90 00 00 71 50 50 21 65 81 00 2e f4 f2 9c 0e 9a b7 e7 20 71 39 ed 3e 83 e4 e5 79 d9 4d 07 d1 d1 ef fa 19 0d 4a d3 41 f7 f0 1c 34 af 8f c7 e5 f9 dc 5c 67 03 20170505145620344 DLSMS <0022> gsm_04_11.c:805 receiving data (trans_id=0) 20170505145620344 DLSMS <0022> gsm0411_smc.c:567 SMC(9) message MMSMS-DATA-IND (CP ACK) received in state WAIT_CP_ACK 20170505145620344 DLSMS <0022> gsm0411_smc.c:256 SMC(9) received CP-ACK 20170505145620344 DLSMS <0022> gsm0411_smc.c:133 SMC(9) new CP state WAIT_CP_ACK -> MM_ESTABLISHED 20170505145620579 DLSMS <0022> gsm_04_11.c:805 receiving data (trans_id=0) 20170505145620579 DLSMS <0022> gsm0411_smc.c:567 SMC(9) message MMSMS-DATA-IND (CP DATA) received in state MM_ESTABLISHED 20170505145620579 DLSMS <0022> gsm0411_smc.c:284 SMC(9) received CP-DATA 20170505145620579 DLSMS <0022> gsm_04_11.c:143 sending CP message (trans=0) 20170505145620579 DLSMS <0022> gsm_04_11.c:127 GSM4.11 TX 09 04 20170505145620579 DLSMS <0022> gsm_04_11.c:769 MNSMS-DATA/EST-IND 20170505145620579 DLSMS <0022> gsm0411_smr.c:483 SMR(9) message MNSMS-DATA-IND received in state WAIT_FOR_RP_ACK 20170505145620579 DLSMS <0022> gsm0411_smr.c:309 SMR(9) RX SMS RP-ACK 20170505145620579 DLSMS <0022> gsm0411_smr.c:139 SMR(9) new RP state WAIT_FOR_RP_ACK -> IDLE 20170505145620579 DLSMS <0022> gsm_04_11.c:712 RX SMS RP-ACK (MO) 20170505145620606 DLSMS <0022> sms_queue.c:220 Attempting to send 20 SMS 20170505145620619 DLSMS <0022> sms_queue.c:230 Sending SMS done (0 attempted) 20170505145620619 DLSMS <0022> sms_queue.c:286 SMSqueue added 0 messages in 0 rounds 20170505145620619 DLSMS <0022> gsm0411_smr.c:185 SMR(9) TX: MNSMS-REL-REQ 20170505145620619 DLSMS <0022> gsm0411_smc.c:467 SMC(9) message MNSMS-REL-REQ received in state MM_ESTABLISHED 20170505145620619 DLSMS <0022> gsm0411_smc.c:133 SMC(9) new CP state MM_ESTABLISHED -> IDLE 20170505145620619 DLSMS <0022> gsm_04_11.c:166 Got MMSMS_REL_REQ, destroying transaction. 20170505145620620 DLSMS <0022> gsm0411_smr.c:92 SMR(9) clearing SMR instance 20170505145620620 DLSMS <0022> gsm0411_smc.c:94 SMC(9) clearing instance 20170505145620646 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state ACTIVE -> RELEASE REQUESTED 20170505145620646 DRR <0003> gsm_04_08_utils.c:251 Sending Channel Release: Chan: Number: 1 Type: 1 20170505145620646 DRSL <0004> abis_rsl.c:768 (bts=0,trx=0,ts=0,ss=1) DEACTivate SACCH CMD 20170505145620653 DRSL <0004> abis_rsl.c:2027 (bts=0,trx=0,ts=0,ss=1) waiting for SAPI=0 to be released. 20170505145620814 DRSL <0004> abis_rsl.c:1718 (bts=0,trx=0,ts=0,ss=1) T3111 expired: releasing RF Channel 20170505145620814 DRSL <0004> abis_rsl.c:860 (bts=0,trx=0,ts=0,ss=1) RF Channel Release 20170505145620819 DRSL <0004> abis_rsl.c:931 (bts=0,trx=0,ts=0,ss=1) RF CHANNEL RELEASE ACK 20170505145620819 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state RELEASE REQUESTED -> NONE 20170505145622326 DRSL <0004> abis_rsl.c:1867 (bts=0,trx=0,ts=0,ss=1) Activating ARFCN(868) SS(1) lctype SDCCH r=OTHER ra=0x1d ta=0 20170505145622326 DRSL <0004> abis_rsl.c:586 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) Tx RSL Channel Activate with act_type=INITIAL 20170505145622327 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state NONE -> ACTIVATION REQUESTED 20170505145622335 DRSL <0004> abis_rsl.c:1590 (bts=0,trx=0,ts=0,ss=1) CHANNEL ACTIVATE ACK 20170505145622335 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state ACTIVATION REQUESTED -> ACTIVE ****************************** SENDING 20170505145622697 DMM <0002> gsm_04_08.c:1016 <- CM SERVICE REQUEST serv_type=0x04 MI(TMSI)=737688935 20170505145622837 DMM <0002> gsm_04_08_utils.c:662 -> CM SERVICE ACK 20170505145624345 DLSMS <0022> gsm_04_11.c:805 receiving data (trans_id=8) 20170505145624345 DLSMS <0022> gsm_04_11.c:820 -> (new transaction) 20170505145624345 DLSMS <0022> gsm0411_smc.c:87 SMC(0) instance created for network 20170505145624345 DLSMS <0022> gsm0411_smr.c:85 SMR(0) instance created for network. 20170505145624345 DLSMS <0022> gsm0411_smc.c:567 SMC(0) message MMSMS-EST-IND (CP DATA) received in state IDLE 20170505145624345 DLSMS <0022> gsm0411_smc.c:284 SMC(0) received CP-DATA 20170505145624345 DLSMS <0022> gsm0411_smc.c:133 SMC(0) new CP state IDLE -> MM_ESTABLISHED 20170505145624345 DLSMS <0022> gsm_04_11.c:143 sending CP message (trans=8) 20170505145624345 DLSMS <0022> gsm_04_11.c:127 GSM4.11 TX 89 04 20170505145624345 DLSMS <0022> gsm_04_11.c:769 MNSMS-DATA/EST-IND 20170505145624345 DLSMS <0022> gsm0411_smr.c:483 SMR(0) message MNSMS-EST-IND received in state IDLE 20170505145624345 DLSMS <0022> gsm0411_smr.c:257 SMR(0) RX SMS RP-DATA 20170505145624345 DLSMS <0022> gsm0411_smr.c:139 SMR(0) new RP state IDLE -> WAIT_TO_TX_RP_ACK 20170505145624345 DLSMS <0022> gsm_04_11.c:686 RX SMS RP-DATA (MO) 20170505145624346 DLSMS <0022> gsm_04_11.c:586 RX_RP-DATA: src_len=0, dst_len=2 ud_len=51 20170505145624346 DLSMS <0022> gsm_04_11.c:554 DST(2,91 f7 ) 20170505145624346 DLSMS <0022> gsm_04_11.c:478 RX SMS: Sender: 901700000009032, MTI: 0x01, VPF: 0x02, MR: 0x36 PID: 0x00, DCS: 0x00, DA: 1010, UserDataLength: 0x2e, UserData: "test sms being resent though it was successful" 20170505145624346 DLSMS <0022> sms_queue.c:333 Triggering SMS queue 20170505145624366 DLSMS <0022> sms_queue.c:333 Triggering SMS queue 20170505145624367 DLSMS <0022> gsm_04_11.c:513 TX: SMS RP ACK 20170505145624367 DLSMS <0022> gsm0411_smr.c:416 SMR(0) message SM-RL-REPORT_REQ received in state WAIT_TO_TX_RP_ACK 20170505145624367 DLSMS <0022> gsm0411_smr.c:226 SMR(0) TX SMS REPORT 20170505145624367 DLSMS <0022> gsm0411_smr.c:139 SMR(0) new RP state WAIT_TO_TX_RP_ACK -> IDLE 20170505145624367 DLSMS <0022> gsm0411_smc.c:467 SMC(0) message MNSMS-DATA-REQ received in state MM_ESTABLISHED 20170505145624367 DLSMS <0022> gsm0411_smc.c:180 SMC(0) send CP data 20170505145624367 DLSMS <0022> gsm0411_smc.c:133 SMC(0) new CP state MM_ESTABLISHED -> WAIT_CP_ACK 20170505145624367 DLSMS <0022> gsm_04_11.c:143 sending CP message (trans=8) 20170505145624367 DLSMS <0022> gsm_04_11.c:127 GSM4.11 TX 89 01 02 03 2c 20170505145624367 DLSMS <0022> gsm0411_smr.c:185 SMR(0) TX: MNSMS-REL-REQ 20170505145624367 DLSMS <0022> gsm0411_smc.c:467 SMC(0) message MNSMS-REL-REQ received in state WAIT_CP_ACK 20170505145624367 DLSMS <0022> gsm0411_smc.c:332 SMC(0) cannot release yet current state: WAIT_CP_ACK 20170505145625051 DLSMS <0022> gsm_04_11.c:805 receiving data (trans_id=8) 20170505145625051 DLSMS <0022> gsm0411_smc.c:567 SMC(0) message MMSMS-DATA-IND (CP ACK) received in state WAIT_CP_ACK 20170505145625051 DLSMS <0022> gsm0411_smc.c:256 SMC(0) received CP-ACK 20170505145625052 DLSMS <0022> gsm0411_smc.c:133 SMC(0) new CP state WAIT_CP_ACK -> MM_ESTABLISHED 20170505145625052 DLSMS <0022> gsm0411_smc.c:268 SMC(0) we have pending release. 20170505145625052 DLSMS <0022> gsm0411_smc.c:133 SMC(0) new CP state MM_ESTABLISHED -> IDLE 20170505145625052 DLSMS <0022> gsm_04_11.c:166 Got MMSMS_REL_REQ, destroying transaction. 20170505145625052 DLSMS <0022> gsm0411_smr.c:92 SMR(0) clearing SMR instance 20170505145625052 DLSMS <0022> gsm0411_smc.c:94 SMC(0) clearing instance 20170505145625078 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state ACTIVE -> RELEASE REQUESTED 20170505145625078 DRR <0003> gsm_04_08_utils.c:251 Sending Channel Release: Chan: Number: 1 Type: 1 20170505145625078 DRSL <0004> abis_rsl.c:768 (bts=0,trx=0,ts=0,ss=1) DEACTivate SACCH CMD 20170505145625083 DRSL <0004> abis_rsl.c:2027 (bts=0,trx=0,ts=0,ss=1) waiting for SAPI=0 to be released. 20170505145625286 DRSL <0004> abis_rsl.c:1718 (bts=0,trx=0,ts=0,ss=1) T3111 expired: releasing RF Channel 20170505145625286 DRSL <0004> abis_rsl.c:860 (bts=0,trx=0,ts=0,ss=1) RF Channel Release 20170505145625291 DRSL <0004> abis_rsl.c:931 (bts=0,trx=0,ts=0,ss=1) RF CHANNEL RELEASE ACK 20170505145625291 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state RELEASE REQUESTED -> NONE 20170505145625346 DLSMS <0022> sms_queue.c:220 Attempting to send 20 SMS 20170505145625358 DLSMS <0022> sms_queue.c:235 Sending SMS round 1 20170505145625358 DLSMS <0022> gsm_04_11.c:1008 Sending SMS: no connection open, start paging 901700000009031 20170505145625358 DMM <0002> gsm_subscriber.c:190 Subscriber 901700000009031 not paged yet. 20170505145625369 DLSMS <0022> sms_queue.c:235 Sending SMS round 2 20170505145625369 DLSMS <0022> sms_queue.c:251 Sending SMS done (loop) (1 attempted) 20170505145625369 DLSMS <0022> sms_queue.c:286 SMSqueue added 1 messages in 2 rounds 20170505145626651 DRSL <0004> abis_rsl.c:1867 (bts=0,trx=0,ts=0,ss=1) Activating ARFCN(868) SS(1) lctype SDCCH r=OTHER ra=0x1d ta=0 20170505145626651 DRSL <0004> abis_rsl.c:586 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) Tx RSL Channel Activate with act_type=INITIAL 20170505145626651 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state NONE -> ACTIVATION REQUESTED 20170505145626659 DRSL <0004> abis_rsl.c:1590 (bts=0,trx=0,ts=0,ss=1) CHANNEL ACTIVATE ACK 20170505145626659 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state ACTIVATION REQUESTED -> ACTIVE ****************************** DELIVERY 20170505145626933 DRR <0003> gsm_04_08.c:1462 PAGING RESPONSE: MI(TMSI)=3660505949 20170505145626933 DRR <0003> gsm_04_08.c:1495 <- Channel was requested by 901700000009031 20170505145626955 DLSMS <0022> gsm_04_11.c:965 paging_cb_send_sms(hooknum=1, event=0, msg=(nil),conn=0xe7cff0, sms=0xe7daf0/id: 10) 20170505145626955 DLSMS <0022> gsm_04_11.c:893 gsm411_send_sms() 20170505145626956 DLSMS <0022> gsm0411_smc.c:87 SMC(10) instance created for network 20170505145626956 DLSMS <0022> gsm0411_smr.c:85 SMR(10) instance created for network. 20170505145626956 DLSMS <0022> gsm_04_11.c:946 TX: SMS DELIVER 20170505145626973 DLSMS <0022> gsm0411_smr.c:416 SMR(10) message SM-RL-DATA_REQ received in state IDLE 20170505145626973 DLSMS <0022> gsm0411_smr.c:215 SMR(10) TX SMS RP-DATA 20170505145626973 DLSMS <0022> gsm0411_smr.c:139 SMR(10) new RP state IDLE -> WAIT_FOR_RP_ACK 20170505145626973 DLSMS <0022> gsm0411_smc.c:467 SMC(10) message MNSMS-EST-REQ received in state IDLE 20170505145626973 DLSMS <0022> gsm0411_smc.c:133 SMC(10) new CP state IDLE -> MM_CONN_PENDING 20170505145626973 DLSMS <0022> gsm0411_smc.c:567 SMC(10) message MMSMS-EST-CNF received in state MM_CONN_PENDING 20170505145626973 DLSMS <0022> gsm0411_smc.c:180 SMC(10) send CP data 20170505145626973 DLSMS <0022> gsm0411_smc.c:133 SMC(10) new CP state MM_CONN_PENDING -> WAIT_CP_ACK 20170505145626973 DLSMS <0022> gsm_04_11.c:143 sending CP message (trans=0) 20170505145626973 DLSMS <0022> gsm_04_11.c:127 GSM4.11 TX 09 01 44 01 00 07 91 44 77 58 10 06 50 00 38 00 04 80 01 90 00 00 71 50 50 21 65 62 00 2e f4 f2 9c 0e 9a b7 e7 20 71 39 ed 3e 83 e4 e5 79 d9 4d 07 d1 d1 ef fa 19 0d 4a d3 41 f7 f0 1c 34 af 8f c7 e5 f9 dc 5c 67 03 20170505145628582 DLSMS <0022> gsm_04_11.c:805 receiving data (trans_id=0) 20170505145628582 DLSMS <0022> gsm0411_smc.c:567 SMC(10) message MMSMS-DATA-IND (CP ACK) received in state WAIT_CP_ACK 20170505145628582 DLSMS <0022> gsm0411_smc.c:256 SMC(10) received CP-ACK 20170505145628582 DLSMS <0022> gsm0411_smc.c:133 SMC(10) new CP state WAIT_CP_ACK -> MM_ESTABLISHED 20170505145628816 DLSMS <0022> gsm_04_11.c:805 receiving data (trans_id=0) 20170505145628816 DLSMS <0022> gsm0411_smc.c:567 SMC(10) message MMSMS-DATA-IND (CP DATA) received in state MM_ESTABLISHED 20170505145628816 DLSMS <0022> gsm0411_smc.c:284 SMC(10) received CP-DATA 20170505145628817 DLSMS <0022> gsm_04_11.c:143 sending CP message (trans=0) 20170505145628817 DLSMS <0022> gsm_04_11.c:127 GSM4.11 TX 09 04 20170505145628817 DLSMS <0022> gsm_04_11.c:769 MNSMS-DATA/EST-IND 20170505145628817 DLSMS <0022> gsm0411_smr.c:483 SMR(10) message MNSMS-DATA-IND received in state WAIT_FOR_RP_ACK 20170505145628817 DLSMS <0022> gsm0411_smr.c:309 SMR(10) RX SMS RP-ACK 20170505145628817 DLSMS <0022> gsm0411_smr.c:139 SMR(10) new RP state WAIT_FOR_RP_ACK -> IDLE 20170505145628817 DLSMS <0022> gsm_04_11.c:712 RX SMS RP-ACK (MO) 20170505145628846 DLSMS <0022> sms_queue.c:220 Attempting to send 20 SMS 20170505145628857 DLSMS <0022> sms_queue.c:230 Sending SMS done (0 attempted) 20170505145628857 DLSMS <0022> sms_queue.c:286 SMSqueue added 0 messages in 0 rounds 20170505145628857 DLSMS <0022> gsm0411_smr.c:185 SMR(10) TX: MNSMS-REL-REQ 20170505145628857 DLSMS <0022> gsm0411_smc.c:467 SMC(10) message MNSMS-REL-REQ received in state MM_ESTABLISHED 20170505145628857 DLSMS <0022> gsm0411_smc.c:133 SMC(10) new CP state MM_ESTABLISHED -> IDLE 20170505145628858 DLSMS <0022> gsm_04_11.c:166 Got MMSMS_REL_REQ, destroying transaction. 20170505145628858 DLSMS <0022> gsm0411_smr.c:92 SMR(10) clearing SMR instance 20170505145628858 DLSMS <0022> gsm0411_smc.c:94 SMC(10) clearing instance 20170505145628879 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state ACTIVE -> RELEASE REQUESTED 20170505145628879 DRR <0003> gsm_04_08_utils.c:251 Sending Channel Release: Chan: Number: 1 Type: 1 20170505145628879 DRSL <0004> abis_rsl.c:768 (bts=0,trx=0,ts=0,ss=1) DEACTivate SACCH CMD 20170505145628886 DRSL <0004> abis_rsl.c:2027 (bts=0,trx=0,ts=0,ss=1) waiting for SAPI=0 to be released. 20170505145629052 DRSL <0004> abis_rsl.c:1718 (bts=0,trx=0,ts=0,ss=1) T3111 expired: releasing RF Channel 20170505145629052 DRSL <0004> abis_rsl.c:860 (bts=0,trx=0,ts=0,ss=1) RF Channel Release 20170505145629056 DRSL <0004> abis_rsl.c:931 (bts=0,trx=0,ts=0,ss=1) RF CHANNEL RELEASE ACK 20170505145629056 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state RELEASE REQUESTED -> NONE 20170505145635303 DRSL <0004> abis_rsl.c:1867 (bts=0,trx=0,ts=0,ss=1) Activating ARFCN(868) SS(1) lctype SDCCH r=OTHER ra=0x1e ta=0 20170505145635303 DRSL <0004> abis_rsl.c:586 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) Tx RSL Channel Activate with act_type=INITIAL 20170505145635303 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state NONE -> ACTIVATION REQUESTED 20170505145635312 DRSL <0004> abis_rsl.c:1590 (bts=0,trx=0,ts=0,ss=1) CHANNEL ACTIVATE ACK 20170505145635312 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state ACTIVATION REQUESTED -> ACTIVE ****************************** SENDING 20170505145635641 DMM <0002> gsm_04_08.c:1016 <- CM SERVICE REQUEST serv_type=0x04 MI(TMSI)=737688935 20170505145636555 DMM <0002> gsm_04_08_utils.c:662 -> CM SERVICE ACK 20170505145637996 DLSMS <0022> gsm_04_11.c:805 receiving data (trans_id=8) 20170505145637996 DLSMS <0022> gsm_04_11.c:820 -> (new transaction) 20170505145637996 DLSMS <0022> gsm0411_smc.c:87 SMC(0) instance created for network 20170505145637996 DLSMS <0022> gsm0411_smr.c:85 SMR(0) instance created for network. 20170505145637996 DLSMS <0022> gsm0411_smc.c:567 SMC(0) message MMSMS-EST-IND (CP DATA) received in state IDLE 20170505145637996 DLSMS <0022> gsm0411_smc.c:284 SMC(0) received CP-DATA 20170505145637996 DLSMS <0022> gsm0411_smc.c:133 SMC(0) new CP state IDLE -> MM_ESTABLISHED 20170505145637996 DLSMS <0022> gsm_04_11.c:143 sending CP message (trans=8) 20170505145637996 DLSMS <0022> gsm_04_11.c:127 GSM4.11 TX 89 04 20170505145637996 DLSMS <0022> gsm_04_11.c:769 MNSMS-DATA/EST-IND 20170505145637996 DLSMS <0022> gsm0411_smr.c:483 SMR(0) message MNSMS-EST-IND received in state IDLE 20170505145637996 DLSMS <0022> gsm0411_smr.c:257 SMR(0) RX SMS RP-DATA 20170505145637996 DLSMS <0022> gsm0411_smr.c:139 SMR(0) new RP state IDLE -> WAIT_TO_TX_RP_ACK 20170505145637996 DLSMS <0022> gsm_04_11.c:686 RX SMS RP-DATA (MO) 20170505145637996 DLSMS <0022> gsm_04_11.c:586 RX_RP-DATA: src_len=0, dst_len=2 ud_len=51 20170505145637996 DLSMS <0022> gsm_04_11.c:554 DST(2,91 f7 ) 20170505145637996 DLSMS <0022> gsm_04_11.c:478 RX SMS: Sender: 901700000009032, MTI: 0x01, VPF: 0x02, MR: 0x37 PID: 0x00, DCS: 0x00, DA: 1010, UserDataLength: 0x2e, UserData: "test sms being resent though it was successful" 20170505145637996 DLSMS <0022> sms_queue.c:333 Triggering SMS queue 20170505145638020 DLSMS <0022> sms_queue.c:333 Triggering SMS queue 20170505145638020 DLSMS <0022> gsm_04_11.c:513 TX: SMS RP ACK 20170505145638020 DLSMS <0022> gsm0411_smr.c:416 SMR(0) message SM-RL-REPORT_REQ received in state WAIT_TO_TX_RP_ACK 20170505145638020 DLSMS <0022> gsm0411_smr.c:226 SMR(0) TX SMS REPORT 20170505145638020 DLSMS <0022> gsm0411_smr.c:139 SMR(0) new RP state WAIT_TO_TX_RP_ACK -> IDLE 20170505145638021 DLSMS <0022> gsm0411_smc.c:467 SMC(0) message MNSMS-DATA-REQ received in state MM_ESTABLISHED 20170505145638021 DLSMS <0022> gsm0411_smc.c:180 SMC(0) send CP data 20170505145638021 DLSMS <0022> gsm0411_smc.c:133 SMC(0) new CP state MM_ESTABLISHED -> WAIT_CP_ACK 20170505145638021 DLSMS <0022> gsm_04_11.c:143 sending CP message (trans=8) 20170505145638021 DLSMS <0022> gsm_04_11.c:127 GSM4.11 TX 89 01 02 03 2d 20170505145638021 DLSMS <0022> gsm0411_smr.c:185 SMR(0) TX: MNSMS-REL-REQ 20170505145638021 DLSMS <0022> gsm0411_smc.c:467 SMC(0) message MNSMS-REL-REQ received in state WAIT_CP_ACK 20170505145638021 DLSMS <0022> gsm0411_smc.c:332 SMC(0) cannot release yet current state: WAIT_CP_ACK 20170505145638702 DLSMS <0022> gsm_04_11.c:805 receiving data (trans_id=8) 20170505145638702 DLSMS <0022> gsm0411_smc.c:567 SMC(0) message MMSMS-DATA-IND (CP ACK) received in state WAIT_CP_ACK 20170505145638702 DLSMS <0022> gsm0411_smc.c:256 SMC(0) received CP-ACK 20170505145638702 DLSMS <0022> gsm0411_smc.c:133 SMC(0) new CP state WAIT_CP_ACK -> MM_ESTABLISHED 20170505145638702 DLSMS <0022> gsm0411_smc.c:268 SMC(0) we have pending release. 20170505145638702 DLSMS <0022> gsm0411_smc.c:133 SMC(0) new CP state MM_ESTABLISHED -> IDLE 20170505145638702 DLSMS <0022> gsm_04_11.c:166 Got MMSMS_REL_REQ, destroying transaction. 20170505145638702 DLSMS <0022> gsm0411_smr.c:92 SMR(0) clearing SMR instance 20170505145638702 DLSMS <0022> gsm0411_smc.c:94 SMC(0) clearing instance 20170505145638728 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state ACTIVE -> RELEASE REQUESTED 20170505145638728 DRR <0003> gsm_04_08_utils.c:251 Sending Channel Release: Chan: Number: 1 Type: 1 20170505145638728 DRSL <0004> abis_rsl.c:768 (bts=0,trx=0,ts=0,ss=1) DEACTivate SACCH CMD 20170505145638731 DRSL <0004> abis_rsl.c:2027 (bts=0,trx=0,ts=0,ss=1) waiting for SAPI=0 to be released. 20170505145638937 DRSL <0004> abis_rsl.c:1718 (bts=0,trx=0,ts=0,ss=1) T3111 expired: releasing RF Channel 20170505145638937 DRSL <0004> abis_rsl.c:860 (bts=0,trx=0,ts=0,ss=1) RF Channel Release 20170505145638942 DRSL <0004> abis_rsl.c:931 (bts=0,trx=0,ts=0,ss=1) RF CHANNEL RELEASE ACK 20170505145638942 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state RELEASE REQUESTED -> NONE 20170505145638997 DLSMS <0022> sms_queue.c:220 Attempting to send 20 SMS 20170505145639009 DLSMS <0022> sms_queue.c:235 Sending SMS round 1 20170505145639009 DLSMS <0022> gsm_04_11.c:1008 Sending SMS: no connection open, start paging 901700000009031 20170505145639009 DMM <0002> gsm_subscriber.c:190 Subscriber 901700000009031 not paged yet. 20170505145639021 DLSMS <0022> sms_queue.c:235 Sending SMS round 2 20170505145639021 DLSMS <0022> sms_queue.c:251 Sending SMS done (loop) (1 attempted) 20170505145639021 DLSMS <0022> sms_queue.c:286 SMSqueue added 1 messages in 2 rounds 20170505145640735 DRSL <0004> abis_rsl.c:1867 (bts=0,trx=0,ts=0,ss=1) Activating ARFCN(868) SS(1) lctype SDCCH r=OTHER ra=0x16 ta=0 20170505145640735 DRSL <0004> abis_rsl.c:586 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) Tx RSL Channel Activate with act_type=INITIAL 20170505145640735 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state NONE -> ACTIVATION REQUESTED 20170505145640743 DRSL <0004> abis_rsl.c:1590 (bts=0,trx=0,ts=0,ss=1) CHANNEL ACTIVATE ACK 20170505145640744 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state ACTIVATION REQUESTED -> ACTIVE ****************************** DELIVERY 20170505145641085 DRR <0003> gsm_04_08.c:1462 PAGING RESPONSE: MI(TMSI)=3660505949 20170505145641085 DRR <0003> gsm_04_08.c:1495 <- Channel was requested by 901700000009031 20170505145641103 DLSMS <0022> gsm_04_11.c:965 paging_cb_send_sms(hooknum=1, event=0, msg=(nil),conn=0xe7cff0, sms=0xe7daf0/id: 11) 20170505145641104 DLSMS <0022> gsm_04_11.c:893 gsm411_send_sms() 20170505145641104 DLSMS <0022> gsm0411_smc.c:87 SMC(11) instance created for network 20170505145641104 DLSMS <0022> gsm0411_smr.c:85 SMR(11) instance created for network. 20170505145641104 DLSMS <0022> gsm_04_11.c:946 TX: SMS DELIVER 20170505145641121 DLSMS <0022> gsm0411_smr.c:416 SMR(11) message SM-RL-DATA_REQ received in state IDLE 20170505145641121 DLSMS <0022> gsm0411_smr.c:215 SMR(11) TX SMS RP-DATA 20170505145641121 DLSMS <0022> gsm0411_smr.c:139 SMR(11) new RP state IDLE -> WAIT_FOR_RP_ACK 20170505145641121 DLSMS <0022> gsm0411_smc.c:467 SMC(11) message MNSMS-EST-REQ received in state IDLE 20170505145641121 DLSMS <0022> gsm0411_smc.c:133 SMC(11) new CP state IDLE -> MM_CONN_PENDING 20170505145641121 DLSMS <0022> gsm0411_smc.c:567 SMC(11) message MMSMS-EST-CNF received in state MM_CONN_PENDING 20170505145641121 DLSMS <0022> gsm0411_smc.c:180 SMC(11) send CP data 20170505145641121 DLSMS <0022> gsm0411_smc.c:133 SMC(11) new CP state MM_CONN_PENDING -> WAIT_CP_ACK 20170505145641121 DLSMS <0022> gsm_04_11.c:143 sending CP message (trans=0) 20170505145641121 DLSMS <0022> gsm_04_11.c:127 GSM4.11 TX 09 01 44 01 00 07 91 44 77 58 10 06 50 00 38 00 04 80 01 90 00 00 71 50 50 21 65 14 00 2e f4 f2 9c 0e 9a b7 e7 20 71 39 ed 3e 83 e4 e5 79 d9 4d 07 d1 d1 ef fa 19 0d 4a d3 41 f7 f0 1c 34 af 8f c7 e5 f9 dc 5c 67 03 20170505145642703 DLSMS <0022> gsm_04_11.c:805 receiving data (trans_id=0) 20170505145642703 DLSMS <0022> gsm0411_smc.c:567 SMC(11) message MMSMS-DATA-IND (CP ACK) received in state WAIT_CP_ACK 20170505145642703 DLSMS <0022> gsm0411_smc.c:256 SMC(11) received CP-ACK 20170505145642703 DLSMS <0022> gsm0411_smc.c:133 SMC(11) new CP state WAIT_CP_ACK -> MM_ESTABLISHED 20170505145642938 DLSMS <0022> gsm_04_11.c:805 receiving data (trans_id=0) 20170505145642938 DLSMS <0022> gsm0411_smc.c:567 SMC(11) message MMSMS-DATA-IND (CP DATA) received in state MM_ESTABLISHED 20170505145642938 DLSMS <0022> gsm0411_smc.c:284 SMC(11) received CP-DATA 20170505145642938 DLSMS <0022> gsm_04_11.c:143 sending CP message (trans=0) 20170505145642938 DLSMS <0022> gsm_04_11.c:127 GSM4.11 TX 09 04 20170505145642938 DLSMS <0022> gsm_04_11.c:769 MNSMS-DATA/EST-IND 20170505145642938 DLSMS <0022> gsm0411_smr.c:483 SMR(11) message MNSMS-DATA-IND received in state WAIT_FOR_RP_ACK 20170505145642938 DLSMS <0022> gsm0411_smr.c:309 SMR(11) RX SMS RP-ACK 20170505145642938 DLSMS <0022> gsm0411_smr.c:139 SMR(11) new RP state WAIT_FOR_RP_ACK -> IDLE 20170505145642938 DLSMS <0022> gsm_04_11.c:712 RX SMS RP-ACK (MO) 20170505145642966 DLSMS <0022> sms_queue.c:220 Attempting to send 20 SMS 20170505145642978 DLSMS <0022> sms_queue.c:230 Sending SMS done (0 attempted) 20170505145642978 DLSMS <0022> sms_queue.c:286 SMSqueue added 0 messages in 0 rounds 20170505145642978 DLSMS <0022> gsm0411_smr.c:185 SMR(11) TX: MNSMS-REL-REQ 20170505145642978 DLSMS <0022> gsm0411_smc.c:467 SMC(11) message MNSMS-REL-REQ received in state MM_ESTABLISHED 20170505145642978 DLSMS <0022> gsm0411_smc.c:133 SMC(11) new CP state MM_ESTABLISHED -> IDLE 20170505145642978 DLSMS <0022> gsm_04_11.c:166 Got MMSMS_REL_REQ, destroying transaction. 20170505145642978 DLSMS <0022> gsm0411_smr.c:92 SMR(11) clearing SMR instance 20170505145642978 DLSMS <0022> gsm0411_smc.c:94 SMC(11) clearing instance 20170505145643000 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state ACTIVE -> RELEASE REQUESTED 20170505145643000 DRR <0003> gsm_04_08_utils.c:251 Sending Channel Release: Chan: Number: 1 Type: 1 20170505145643000 DRSL <0004> abis_rsl.c:768 (bts=0,trx=0,ts=0,ss=1) DEACTivate SACCH CMD 20170505145643007 DRSL <0004> abis_rsl.c:2027 (bts=0,trx=0,ts=0,ss=1) waiting for SAPI=0 to be released. 20170505145643173 DRSL <0004> abis_rsl.c:1718 (bts=0,trx=0,ts=0,ss=1) T3111 expired: releasing RF Channel 20170505145643173 DRSL <0004> abis_rsl.c:860 (bts=0,trx=0,ts=0,ss=1) RF Channel Release 20170505145643178 DRSL <0004> abis_rsl.c:931 (bts=0,trx=0,ts=0,ss=1) RF CHANNEL RELEASE ACK 20170505145643178 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state RELEASE REQUESTED -> NONE 20170505145654362 DRSL <0004> abis_rsl.c:1867 (bts=0,trx=0,ts=0,ss=1) Activating ARFCN(868) SS(1) lctype SDCCH r=OTHER ra=0x17 ta=0 20170505145654362 DRSL <0004> abis_rsl.c:586 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) Tx RSL Channel Activate with act_type=INITIAL 20170505145654363 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state NONE -> ACTIVATION REQUESTED 20170505145654371 DRSL <0004> abis_rsl.c:1590 (bts=0,trx=0,ts=0,ss=1) CHANNEL ACTIVATE ACK 20170505145654371 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state ACTIVATION REQUESTED -> ACTIVE ****************************** SENDING 20170505145654705 DMM <0002> gsm_04_08.c:1016 <- CM SERVICE REQUEST serv_type=0x04 MI(TMSI)=737688935 20170505145654729 DMM <0002> gsm_04_08_utils.c:662 -> CM SERVICE ACK 20170505145656353 DLSMS <0022> gsm_04_11.c:805 receiving data (trans_id=8) 20170505145656353 DLSMS <0022> gsm_04_11.c:820 -> (new transaction) 20170505145656353 DLSMS <0022> gsm0411_smc.c:87 SMC(0) instance created for network 20170505145656353 DLSMS <0022> gsm0411_smr.c:85 SMR(0) instance created for network. 20170505145656353 DLSMS <0022> gsm0411_smc.c:567 SMC(0) message MMSMS-EST-IND (CP DATA) received in state IDLE 20170505145656353 DLSMS <0022> gsm0411_smc.c:284 SMC(0) received CP-DATA 20170505145656353 DLSMS <0022> gsm0411_smc.c:133 SMC(0) new CP state IDLE -> MM_ESTABLISHED 20170505145656353 DLSMS <0022> gsm_04_11.c:143 sending CP message (trans=8) 20170505145656353 DLSMS <0022> gsm_04_11.c:127 GSM4.11 TX 89 04 20170505145656353 DLSMS <0022> gsm_04_11.c:769 MNSMS-DATA/EST-IND 20170505145656354 DLSMS <0022> gsm0411_smr.c:483 SMR(0) message MNSMS-EST-IND received in state IDLE 20170505145656354 DLSMS <0022> gsm0411_smr.c:257 SMR(0) RX SMS RP-DATA 20170505145656354 DLSMS <0022> gsm0411_smr.c:139 SMR(0) new RP state IDLE -> WAIT_TO_TX_RP_ACK 20170505145656354 DLSMS <0022> gsm_04_11.c:686 RX SMS RP-DATA (MO) 20170505145656354 DLSMS <0022> gsm_04_11.c:586 RX_RP-DATA: src_len=0, dst_len=2 ud_len=51 20170505145656354 DLSMS <0022> gsm_04_11.c:554 DST(2,91 f7 ) 20170505145656354 DLSMS <0022> gsm_04_11.c:478 RX SMS: Sender: 901700000009032, MTI: 0x01, VPF: 0x02, MR: 0x38 PID: 0x00, DCS: 0x00, DA: 1010, UserDataLength: 0x2e, UserData: "test sms being resent though it was successful" 20170505145656354 DLSMS <0022> sms_queue.c:333 Triggering SMS queue 20170505145656376 DLSMS <0022> sms_queue.c:333 Triggering SMS queue 20170505145656376 DLSMS <0022> gsm_04_11.c:513 TX: SMS RP ACK 20170505145656376 DLSMS <0022> gsm0411_smr.c:416 SMR(0) message SM-RL-REPORT_REQ received in state WAIT_TO_TX_RP_ACK 20170505145656376 DLSMS <0022> gsm0411_smr.c:226 SMR(0) TX SMS REPORT 20170505145656376 DLSMS <0022> gsm0411_smr.c:139 SMR(0) new RP state WAIT_TO_TX_RP_ACK -> IDLE 20170505145656376 DLSMS <0022> gsm0411_smc.c:467 SMC(0) message MNSMS-DATA-REQ received in state MM_ESTABLISHED 20170505145656376 DLSMS <0022> gsm0411_smc.c:180 SMC(0) send CP data 20170505145656376 DLSMS <0022> gsm0411_smc.c:133 SMC(0) new CP state MM_ESTABLISHED -> WAIT_CP_ACK 20170505145656376 DLSMS <0022> gsm_04_11.c:143 sending CP message (trans=8) 20170505145656376 DLSMS <0022> gsm_04_11.c:127 GSM4.11 TX 89 01 02 03 2e 20170505145656376 DLSMS <0022> gsm0411_smr.c:185 SMR(0) TX: MNSMS-REL-REQ 20170505145656376 DLSMS <0022> gsm0411_smc.c:467 SMC(0) message MNSMS-REL-REQ received in state WAIT_CP_ACK 20170505145656376 DLSMS <0022> gsm0411_smc.c:332 SMC(0) cannot release yet current state: WAIT_CP_ACK 20170505145657060 DLSMS <0022> gsm_04_11.c:805 receiving data (trans_id=8) 20170505145657060 DLSMS <0022> gsm0411_smc.c:567 SMC(0) message MMSMS-DATA-IND (CP ACK) received in state WAIT_CP_ACK 20170505145657060 DLSMS <0022> gsm0411_smc.c:256 SMC(0) received CP-ACK 20170505145657060 DLSMS <0022> gsm0411_smc.c:133 SMC(0) new CP state WAIT_CP_ACK -> MM_ESTABLISHED 20170505145657060 DLSMS <0022> gsm0411_smc.c:268 SMC(0) we have pending release. 20170505145657060 DLSMS <0022> gsm0411_smc.c:133 SMC(0) new CP state MM_ESTABLISHED -> IDLE 20170505145657060 DLSMS <0022> gsm_04_11.c:166 Got MMSMS_REL_REQ, destroying transaction. 20170505145657060 DLSMS <0022> gsm0411_smr.c:92 SMR(0) clearing SMR instance 20170505145657060 DLSMS <0022> gsm0411_smc.c:94 SMC(0) clearing instance 20170505145657083 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state ACTIVE -> RELEASE REQUESTED 20170505145657083 DRR <0003> gsm_04_08_utils.c:251 Sending Channel Release: Chan: Number: 1 Type: 1 20170505145657083 DRSL <0004> abis_rsl.c:768 (bts=0,trx=0,ts=0,ss=1) DEACTivate SACCH CMD 20170505145657088 DRSL <0004> abis_rsl.c:2027 (bts=0,trx=0,ts=0,ss=1) waiting for SAPI=0 to be released. 20170505145657294 DRSL <0004> abis_rsl.c:1718 (bts=0,trx=0,ts=0,ss=1) T3111 expired: releasing RF Channel 20170505145657294 DRSL <0004> abis_rsl.c:860 (bts=0,trx=0,ts=0,ss=1) RF Channel Release 20170505145657299 DRSL <0004> abis_rsl.c:931 (bts=0,trx=0,ts=0,ss=1) RF CHANNEL RELEASE ACK 20170505145657299 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state RELEASE REQUESTED -> NONE 20170505145657354 DLSMS <0022> sms_queue.c:220 Attempting to send 20 SMS 20170505145657365 DLSMS <0022> sms_queue.c:235 Sending SMS round 1 20170505145657366 DLSMS <0022> gsm_04_11.c:1008 Sending SMS: no connection open, start paging 901700000009031 20170505145657366 DMM <0002> gsm_subscriber.c:190 Subscriber 901700000009031 not paged yet. 20170505145657377 DLSMS <0022> sms_queue.c:235 Sending SMS round 2 20170505145657377 DLSMS <0022> sms_queue.c:251 Sending SMS done (loop) (1 attempted) 20170505145657377 DLSMS <0022> sms_queue.c:286 SMSqueue added 1 messages in 2 rounds 20170505145658424 DRSL <0004> abis_rsl.c:1867 (bts=0,trx=0,ts=0,ss=1) Activating ARFCN(868) SS(1) lctype SDCCH r=OTHER ra=0x1e ta=0 20170505145658424 DRSL <0004> abis_rsl.c:586 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) Tx RSL Channel Activate with act_type=INITIAL 20170505145658424 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state NONE -> ACTIVATION REQUESTED 20170505145658432 DRSL <0004> abis_rsl.c:1590 (bts=0,trx=0,ts=0,ss=1) CHANNEL ACTIVATE ACK 20170505145658432 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state ACTIVATION REQUESTED -> ACTIVE ****************************** DELIVERY 20170505145658706 DRR <0003> gsm_04_08.c:1462 PAGING RESPONSE: MI(TMSI)=3660505949 20170505145658706 DRR <0003> gsm_04_08.c:1495 <- Channel was requested by 901700000009031 20170505145658727 DLSMS <0022> gsm_04_11.c:965 paging_cb_send_sms(hooknum=1, event=0, msg=(nil),conn=0xe7cff0, sms=0xe7daf0/id: 12) 20170505145658727 DLSMS <0022> gsm_04_11.c:893 gsm411_send_sms() 20170505145658727 DLSMS <0022> gsm0411_smc.c:87 SMC(12) instance created for network 20170505145658728 DLSMS <0022> gsm0411_smr.c:85 SMR(12) instance created for network. 20170505145658728 DLSMS <0022> gsm_04_11.c:946 TX: SMS DELIVER 20170505145658744 DLSMS <0022> gsm0411_smr.c:416 SMR(12) message SM-RL-DATA_REQ received in state IDLE 20170505145658745 DLSMS <0022> gsm0411_smr.c:215 SMR(12) TX SMS RP-DATA 20170505145658745 DLSMS <0022> gsm0411_smr.c:139 SMR(12) new RP state IDLE -> WAIT_FOR_RP_ACK 20170505145658745 DLSMS <0022> gsm0411_smc.c:467 SMC(12) message MNSMS-EST-REQ received in state IDLE 20170505145658745 DLSMS <0022> gsm0411_smc.c:133 SMC(12) new CP state IDLE -> MM_CONN_PENDING 20170505145658745 DLSMS <0022> gsm0411_smc.c:567 SMC(12) message MMSMS-EST-CNF received in state MM_CONN_PENDING 20170505145658745 DLSMS <0022> gsm0411_smc.c:180 SMC(12) send CP data 20170505145658745 DLSMS <0022> gsm0411_smc.c:133 SMC(12) new CP state MM_CONN_PENDING -> WAIT_CP_ACK 20170505145658745 DLSMS <0022> gsm_04_11.c:143 sending CP message (trans=0) 20170505145658745 DLSMS <0022> gsm_04_11.c:127 GSM4.11 TX 09 01 44 01 00 07 91 44 77 58 10 06 50 00 38 00 04 80 01 90 00 00 71 50 50 21 65 85 00 2e f4 f2 9c 0e 9a b7 e7 20 71 39 ed 3e 83 e4 e5 79 d9 4d 07 d1 d1 ef fa 19 0d 4a d3 41 f7 f0 1c 34 af 8f c7 e5 f9 dc 5c 67 03 20170505145700354 DLSMS <0022> gsm_04_11.c:805 receiving data (trans_id=0) 20170505145700355 DLSMS <0022> gsm0411_smc.c:567 SMC(12) message MMSMS-DATA-IND (CP ACK) received in state WAIT_CP_ACK 20170505145700355 DLSMS <0022> gsm0411_smc.c:256 SMC(12) received CP-ACK 20170505145700355 DLSMS <0022> gsm0411_smc.c:133 SMC(12) new CP state WAIT_CP_ACK -> MM_ESTABLISHED 20170505145700589 DLSMS <0022> gsm_04_11.c:805 receiving data (trans_id=0) 20170505145700589 DLSMS <0022> gsm0411_smc.c:567 SMC(12) message MMSMS-DATA-IND (CP DATA) received in state MM_ESTABLISHED 20170505145700589 DLSMS <0022> gsm0411_smc.c:284 SMC(12) received CP-DATA 20170505145700589 DLSMS <0022> gsm_04_11.c:143 sending CP message (trans=0) 20170505145700590 DLSMS <0022> gsm_04_11.c:127 GSM4.11 TX 09 04 20170505145700590 DLSMS <0022> gsm_04_11.c:769 MNSMS-DATA/EST-IND 20170505145700590 DLSMS <0022> gsm0411_smr.c:483 SMR(12) message MNSMS-DATA-IND received in state WAIT_FOR_RP_ACK 20170505145700590 DLSMS <0022> gsm0411_smr.c:309 SMR(12) RX SMS RP-ACK 20170505145700590 DLSMS <0022> gsm0411_smr.c:139 SMR(12) new RP state WAIT_FOR_RP_ACK -> IDLE 20170505145700590 DLSMS <0022> gsm_04_11.c:712 RX SMS RP-ACK (MO) 20170505145700616 DLSMS <0022> sms_queue.c:220 Attempting to send 20 SMS 20170505145700629 DLSMS <0022> sms_queue.c:230 Sending SMS done (0 attempted) 20170505145700629 DLSMS <0022> sms_queue.c:286 SMSqueue added 0 messages in 0 rounds 20170505145700629 DLSMS <0022> gsm0411_smr.c:185 SMR(12) TX: MNSMS-REL-REQ 20170505145700629 DLSMS <0022> gsm0411_smc.c:467 SMC(12) message MNSMS-REL-REQ received in state MM_ESTABLISHED 20170505145700629 DLSMS <0022> gsm0411_smc.c:133 SMC(12) new CP state MM_ESTABLISHED -> IDLE 20170505145700629 DLSMS <0022> gsm_04_11.c:166 Got MMSMS_REL_REQ, destroying transaction. 20170505145700629 DLSMS <0022> gsm0411_smr.c:92 SMR(12) clearing SMR instance 20170505145700629 DLSMS <0022> gsm0411_smc.c:94 SMC(12) clearing instance 20170505145700652 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state ACTIVE -> RELEASE REQUESTED 20170505145700652 DRR <0003> gsm_04_08_utils.c:251 Sending Channel Release: Chan: Number: 1 Type: 1 20170505145700652 DRSL <0004> abis_rsl.c:768 (bts=0,trx=0,ts=0,ss=1) DEACTivate SACCH CMD 20170505145700659 DRSL <0004> abis_rsl.c:2027 (bts=0,trx=0,ts=0,ss=1) waiting for SAPI=0 to be released. 20170505145700825 DRSL <0004> abis_rsl.c:1718 (bts=0,trx=0,ts=0,ss=1) T3111 expired: releasing RF Channel 20170505145700825 DRSL <0004> abis_rsl.c:860 (bts=0,trx=0,ts=0,ss=1) RF Channel Release 20170505145700830 DRSL <0004> abis_rsl.c:931 (bts=0,trx=0,ts=0,ss=1) RF CHANNEL RELEASE ACK 20170505145700830 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state RELEASE REQUESTED -> NONE
Updated by neels almost 7 years ago
- Subject changed from ofono: successful SMS delivery is evaluated as not successful to ofono: Gobi modem: successful SMS delivery is evaluated as not successful
- Description updated (diff)
Updated by neels almost 7 years ago
- Related to Bug #2187: ofono: not all modems do what they should added
Updated by lynxis almost 7 years ago
- Status changed from New to In Progress
- Assignee changed from 118 to lynxis
Updated by lynxis almost 7 years ago
with modemmanager I received several (~30) unread messages and I can receive new messages.
I guess:
ofono is not processing unread or saved messages which resulted in having to many messages in the storage. But the error message of the modem is wrong, as it describes a protocol error.
TODO: check when a MS should sent Storage full indication to the Network
Updated by lynxis almost 7 years ago
AT+CPMS? +CPMS: "ME",23,23,"ME",23,23,"ME",23,23
storage,used,total
Updated by lynxis almost 7 years ago
In difference to the AT driver for sms, the qmi driver for sms doesn't read and clear the messages stored in the ME.
Updated by neels almost 7 years ago
- Related to Bug #2188: ofono: Gobi modem refuses to set Online=true added
Updated by lynxis almost 7 years ago
- Status changed from In Progress to Feedback
- Assignee changed from lynxis to pespin
From the ofono side, I would say it's working.
pespin: Does it also work with the gsm-tester?
Updated by pespin over 6 years ago
- Blocked by Bug #2421: ofono: Gobi modem: Refuses to Power on added
Updated by pespin over 6 years ago
- File nitb.log.txt nitb.log.txt added
- File ofono.log.txt ofono.log.txt added
- File gsmtap_rsl.pcapng gsmtap_rsl.pcapng added
- Status changed from Stalled to In Progress
- Assignee changed from pespin to lynxis
using latest sysmocom lynxis/master branch, the issue is still there with a gobi modem.
$ mdbus2 -s org.ofono /gobi_2 org.ofono.MessageManager.SendMessage 45599 "testing"
('/gobi_2/message_B8DCEC74837ADCE3C2334C138807CCB7B14AD39E',)
I receive the message 4 times in the other MS (a regular feature phone).
I attach logs for ofono -n -d during that time, as well as logs from nitb. I also attach a pcap file running on the IP of NITB, and GSMTAP is recorded there too.
Updated by pespin over 6 years ago
It fails in drivers/qmimodem/sms.c:raw_send_cb() due to failure in the following line:
if (!qmi_result_get_uint16(result, QMI_WMS_RESULT_MESSAGE_ID, &msgid)) {
Updated by pespin over 6 years ago
As far as I can see the "TP-MR" (message reference) is passed correctly between MS and NITB. The issue then looks more in QMI/modem side.
Updated by pespin over 6 years ago
- Status changed from In Progress to Feedback
- % Done changed from 0 to 50
Fix is provided in https://git.sysmocom.de/ofono/commit/?h=pespin/master&id=9cf8a8c3dec93d1800287a1d5c22331ef3d7b803
I tested it and I can send messages correctly now. Multipart messages also seem to be working. The pity is that if I understand correctly, status reports won't be available when using this modem.
Please have a look at it and decide whether it's good enough or there's a better way like to have QMI return the message id field. If there's no better way, we can merge it into branch osmo-gsm-tester and send it upstream for review.
Updated by lynxis almost 6 years ago
patch:
@@ -171,7 +171,8 @@ static void raw_send_cb(struct qmi_result *result, void *user_data)
}
if (!qmi_result_get_uint16(result, QMI_WMS_RESULT_MESSAGE_ID, &msgid)) {
- CALLBACK_WITH_FAILURE(cb, -1, cbd->data);
+ DBG("TP-MR field missing");
+ CALLBACK_WITH_SUCCESS(cb, -1, cbd->data);
return;
}
diff --git a/src/sms.c b/src/sms.c
index 17c5a9c94209..641e762f72e4 100644
--- a/src/sms.c
+++ b/src/sms.c
@@ -720,7 +720,7 @@ static void tx_finished(const struct ofono_error *error, int mr, void *data)
entry->cur_pdu += 1;
entry->retry = 0;
- if (entry->flags & OFONO_SMS_SUBMIT_FLAG_REQUEST_SR)
+ if (entry->flags & OFONO_SMS_SUBMIT_FLAG_REQUEST_SR && mr >= 0)
status_report_assembly_add_fragment(sms->sr_assembly,
entry->uuid.uuid,
&entry->receiver,
Next step:
a) send a mail to the ofono mailinglist with:
- what's the behaviour if only CALLBACK_WITH_SUCCESS implementet
- what's the behaviour without the whole patch
b) investigate if there is another solution to enable send reports
Actions
