Cellular Network Infrastructure » OsmoGSMTester

root@osmo-gsm-tester-rnd:~# mdbus2 -s org.ofono /sierra_1 org.ofono.MessageManager.SendMessage 1009 "test sms to gobi 3" 
('/sierra_1/message_CCD3AC8CFFBDCC9135B1E631BCCA872AAB3B476A',)

[SIGNAL] org.ofono.MessageManager.MessageAdded  /sierra_1  :1.873
('/sierra_1/message_CCD3AC8CFFBDCC9135B1E631BCCA872AAB3B476A', {'State': <'pending'>})
[SIGNAL] org.ofono.Message.PropertyChanged  /sierra_1/message_CCD3AC8CFFBDCC9135B1E631BCCA872AAB3B476A  :1.873
('State', <'sent'>)
[SIGNAL] org.ofono.MessageManager.MessageRemoved  /sierra_1  :1.873
('/sierra_1/message_CCD3AC8CFFBDCC9135B1E631BCCA872AAB3B476A',)

20170505150616847 DRSL <0004> abis_rsl.c:1867 (bts=0,trx=0,ts=0,ss=1) Activating ARFCN(868) SS(1) lctype SDCCH r=OTHER ra=0x1f ta=0
20170505150616847 DRSL <0004> abis_rsl.c:586 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) Tx RSL Channel Activate with act_type=INITIAL             
20170505150616847 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state NONE -> ACTIVATION REQUESTED                       
20170505150616855 DRSL <0004> abis_rsl.c:1590 (bts=0,trx=0,ts=0,ss=1) CHANNEL ACTIVATE ACK              
20170505150616855 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state ACTIVATION REQUESTED -> ACTIVE
20170505150617203 DMM <0002> gsm_04_08.c:1016 <- CM SERVICE REQUEST serv_type=0x04 MI(TMSI)=3660505949    
20170505150617226 DMM <0002> gsm_04_08_utils.c:662 -> CM SERVICE ACK                                  
20170505150618380 DLSMS <0022> gsm_04_11.c:805 receiving data (trans_id=d)
20170505150618380 DLSMS <0022> gsm_04_11.c:820  -> (new transaction)      
20170505150618380 DLSMS <0022> gsm0411_smc.c:87 SMC(0) instance created for network
20170505150618380 DLSMS <0022> gsm0411_smr.c:85 SMR(0) instance created for network.
20170505150618381 DLSMS <0022> gsm0411_smc.c:567 SMC(0) message MMSMS-EST-IND (CP DATA) received in state IDLE
20170505150618381 DLSMS <0022> gsm0411_smc.c:284 SMC(0) received CP-DATA                                      
20170505150618381 DLSMS <0022> gsm0411_smc.c:133 SMC(0) new CP state IDLE -> MM_ESTABLISHED
20170505150618381 DLSMS <0022> gsm_04_11.c:143 sending CP message (trans=d)                
20170505150618381 DLSMS <0022> gsm_04_11.c:127 GSM4.11 TX d9 04            
20170505150618381 DLSMS <0022> gsm_04_11.c:769 MNSMS-DATA/EST-IND
20170505150618381 DLSMS <0022> gsm0411_smr.c:483 SMR(0) message MNSMS-EST-IND received in state IDLE
20170505150618381 DLSMS <0022> gsm0411_smr.c:257 SMR(0) RX SMS RP-DATA                              
20170505150618381 DLSMS <0022> gsm0411_smr.c:139 SMR(0) new RP state IDLE -> WAIT_TO_TX_RP_ACK
20170505150618381 DLSMS <0022> gsm_04_11.c:686 RX SMS RP-DATA (MO)                            
20170505150618381 DLSMS <0022> gsm_04_11.c:586 RX_RP-DATA: src_len=0, dst_len=2 ud_len=26
20170505150618381 DLSMS <0022> gsm_04_11.c:554 DST(2,91 f7 )                             
20170505150618381 DLSMS <0022> gsm_04_11.c:478 RX SMS: Sender: 901700000009031, MTI: 0x01, VPF: 0x02, MR: 0x39 PID: 0x00, DCS: 0x00, DA: 1009, UserDataLength: 0x12, UserData: "test sms to gobi 3" 
20170505150618381 DLSMS <0022> sms_queue.c:333 Triggering SMS queue                                                                                                                                
20170505150618406 DLSMS <0022> sms_queue.c:333 Triggering SMS queue
20170505150618406 DLSMS <0022> gsm_04_11.c:513 TX: SMS RP ACK      
20170505150618406 DLSMS <0022> gsm0411_smr.c:416 SMR(0) message SM-RL-REPORT_REQ received in state WAIT_TO_TX_RP_ACK
20170505150618406 DLSMS <0022> gsm0411_smr.c:226 SMR(0) TX SMS REPORT                                               
20170505150618406 DLSMS <0022> gsm0411_smr.c:139 SMR(0) new RP state WAIT_TO_TX_RP_ACK -> IDLE
20170505150618407 DLSMS <0022> gsm0411_smc.c:467 SMC(0) message MNSMS-DATA-REQ received in state MM_ESTABLISHED
20170505150618407 DLSMS <0022> gsm0411_smc.c:180 SMC(0) send CP data                                           
20170505150618407 DLSMS <0022> gsm0411_smc.c:133 SMC(0) new CP state MM_ESTABLISHED -> WAIT_CP_ACK
20170505150618407 DLSMS <0022> gsm_04_11.c:143 sending CP message (trans=d)                       
20170505150618407 DLSMS <0022> gsm_04_11.c:127 GSM4.11 TX d9 01 02 03 0d   
20170505150618407 DLSMS <0022> gsm0411_smr.c:185 SMR(0) TX: MNSMS-REL-REQ
20170505150618407 DLSMS <0022> gsm0411_smc.c:467 SMC(0) message MNSMS-REL-REQ received in state WAIT_CP_ACK
20170505150618407 DLSMS <0022> gsm0411_smc.c:332 SMC(0) cannot release yet current state: WAIT_CP_ACK      
20170505150619088 DLSMS <0022> gsm_04_11.c:805 receiving data (trans_id=d)                           
20170505150619088 DLSMS <0022> gsm0411_smc.c:567 SMC(0) message MMSMS-DATA-IND (CP ACK) received in state WAIT_CP_ACK
20170505150619088 DLSMS <0022> gsm0411_smc.c:256 SMC(0) received CP-ACK                                              
20170505150619088 DLSMS <0022> gsm0411_smc.c:133 SMC(0) new CP state WAIT_CP_ACK -> MM_ESTABLISHED
20170505150619088 DLSMS <0022> gsm0411_smc.c:268 SMC(0) we have pending release.                  
20170505150619088 DLSMS <0022> gsm0411_smc.c:133 SMC(0) new CP state MM_ESTABLISHED -> IDLE
20170505150619088 DLSMS <0022> gsm_04_11.c:166 Got MMSMS_REL_REQ, destroying transaction.  
20170505150619088 DLSMS <0022> gsm0411_smr.c:92 SMR(0) clearing SMR instance             
20170505150619088 DLSMS <0022> gsm0411_smc.c:94 SMC(0) clearing instance    
20170505150619110 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state ACTIVE -> RELEASE REQUESTED
20170505150619110 DRR <0003> gsm_04_08_utils.c:251 Sending Channel Release: Chan: Number: 1 Type: 1    
20170505150619110 DRSL <0004> abis_rsl.c:768 (bts=0,trx=0,ts=0,ss=1) DEACTivate SACCH CMD          
20170505150619116 DRSL <0004> abis_rsl.c:2027 (bts=0,trx=0,ts=0,ss=1) waiting for SAPI=0 to be released.
20170505150619322 DRSL <0004> abis_rsl.c:1718 (bts=0,trx=0,ts=0,ss=1) T3111 expired: releasing RF Channel
20170505150619322 DRSL <0004> abis_rsl.c:860 (bts=0,trx=0,ts=0,ss=1) RF Channel Release                  
20170505150619327 DRSL <0004> abis_rsl.c:931 (bts=0,trx=0,ts=0,ss=1) RF CHANNEL RELEASE ACK
20170505150619327 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state RELEASE REQUESTED -> NONE
20170505150619381 DLSMS <0022> sms_queue.c:220 Attempting to send 20 SMS                             
20170505150619394 DLSMS <0022> sms_queue.c:235 Sending SMS round 1      
20170505150619394 DLSMS <0022> gsm_04_11.c:1008 Sending SMS: no connection open, start paging 901700000009032
20170505150619394 DMM <0002> gsm_subscriber.c:190 Subscriber 901700000009032 not paged yet.                  
20170505150619405 DLSMS <0022> sms_queue.c:235 Sending SMS round 2                         
20170505150619405 DLSMS <0022> sms_queue.c:251 Sending SMS done (loop) (1 attempted)
20170505150619405 DLSMS <0022> sms_queue.c:286 SMSqueue added 1 messages in 2 rounds
20170505150621125 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
20170505150621125 DRSL <0004> abis_rsl.c:586 (bts=0,trx=0,ts=0,pchan=CCCH+SDCCH4) Tx RSL Channel Activate with act_type=INITIAL    
20170505150621125 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state NONE -> ACTIVATION REQUESTED                       
20170505150621133 DRSL <0004> abis_rsl.c:1590 (bts=0,trx=0,ts=0,ss=1) CHANNEL ACTIVATE ACK              
20170505150621133 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state ACTIVATION REQUESTED -> ACTIVE
20170505150621440 DRR <0003> gsm_04_08.c:1462 PAGING RESPONSE: MI(TMSI)=737688935                         
20170505150621440 DRR <0003> gsm_04_08.c:1495 <- Channel was requested by 901700000009032
20170505150621461 DLSMS <0022> gsm_04_11.c:965 paging_cb_send_sms(hooknum=1, event=0, msg=(nil),conn=0xe60c70, sms=0xe8dfc0/id: 16)
20170505150621461 DLSMS <0022> gsm_04_11.c:893 gsm411_send_sms()                                                                   
20170505150621461 DLSMS <0022> gsm0411_smc.c:87 SMC(16) instance created for network
20170505150621461 DLSMS <0022> gsm0411_smr.c:85 SMR(16) instance created for network.
20170505150621461 DLSMS <0022> gsm_04_11.c:946 TX: SMS DELIVER                       
20170505150621477 DLSMS <0022> gsm0411_smr.c:416 SMR(16) message SM-RL-DATA_REQ received in state IDLE
20170505150621477 DLSMS <0022> gsm0411_smr.c:215 SMR(16) TX SMS RP-DATA                               
20170505150621477 DLSMS <0022> gsm0411_smr.c:139 SMR(16) new RP state IDLE -> WAIT_FOR_RP_ACK
20170505150621477 DLSMS <0022> gsm0411_smc.c:467 SMC(16) message MNSMS-EST-REQ received in state IDLE
20170505150621477 DLSMS <0022> gsm0411_smc.c:133 SMC(16) new CP state IDLE -> MM_CONN_PENDING        
20170505150621477 DLSMS <0022> gsm0411_smc.c:567 SMC(16) message MMSMS-EST-CNF received in state MM_CONN_PENDING
20170505150621477 DLSMS <0022> gsm0411_smc.c:180 SMC(16) send CP data                                           
20170505150621477 DLSMS <0022> gsm0411_smc.c:133 SMC(16) new CP state MM_CONN_PENDING -> WAIT_CP_ACK
20170505150621477 DLSMS <0022> gsm_04_11.c:143 sending CP message (trans=0)                         
20170505150621477 DLSMS <0022> gsm_04_11.c:127 GSM4.11 TX 09 01 2b 01 00 07 91 44 77 58 10 06 50 00 1f 00 04 80 01 01 00 00 71 50 50 31 60 12 00 12 f4 f2 9c 0e 9a b7 e7 20 fa 1b 74 7e 8b d3 a0 19 
20170505150622852 DLSMS <0022> gsm_04_11.c:805 receiving data (trans_id=0)                                                                                                                          
20170505150622853 DLSMS <0022> gsm0411_smc.c:567 SMC(16) message MMSMS-DATA-IND (CP ACK) received in state WAIT_CP_ACK
20170505150622853 DLSMS <0022> gsm0411_smc.c:256 SMC(16) received CP-ACK                                              
20170505150622853 DLSMS <0022> gsm0411_smc.c:133 SMC(16) new CP state WAIT_CP_ACK -> MM_ESTABLISHED
20170505150623088 DLSMS <0022> gsm_04_11.c:805 receiving data (trans_id=0)                         
20170505150623088 DLSMS <0022> gsm0411_smc.c:567 SMC(16) message MMSMS-DATA-IND (CP DATA) received in state MM_ESTABLISHED
20170505150623088 DLSMS <0022> gsm0411_smc.c:284 SMC(16) received CP-DATA                                                 
20170505150623088 DLSMS <0022> gsm_04_11.c:143 sending CP message (trans=0)
20170505150623088 DLSMS <0022> gsm_04_11.c:127 GSM4.11 TX 09 04            
20170505150623088 DLSMS <0022> gsm_04_11.c:769 MNSMS-DATA/EST-IND
20170505150623088 DLSMS <0022> gsm0411_smr.c:483 SMR(16) message MNSMS-DATA-IND received in state WAIT_FOR_RP_ACK
20170505150623088 DLSMS <0022> gsm0411_smr.c:309 SMR(16) RX SMS RP-ACK                                           
20170505150623088 DLSMS <0022> gsm0411_smr.c:139 SMR(16) new RP state WAIT_FOR_RP_ACK -> IDLE
20170505150623088 DLSMS <0022> gsm_04_11.c:712 RX SMS RP-ACK (MO)                            
20170505150623114 DLSMS <0022> sms_queue.c:220 Attempting to send 20 SMS
20170505150623127 DLSMS <0022> sms_queue.c:230 Sending SMS done (0 attempted)
20170505150623127 DLSMS <0022> sms_queue.c:286 SMSqueue added 0 messages in 0 rounds
20170505150623127 DLSMS <0022> gsm0411_smr.c:185 SMR(16) TX: MNSMS-REL-REQ          
20170505150623127 DLSMS <0022> gsm0411_smc.c:467 SMC(16) message MNSMS-REL-REQ received in state MM_ESTABLISHED
20170505150623127 DLSMS <0022> gsm0411_smc.c:133 SMC(16) new CP state MM_ESTABLISHED -> IDLE                   
20170505150623127 DLSMS <0022> gsm_04_11.c:166 Got MMSMS_REL_REQ, destroying transaction.   
20170505150623127 DLSMS <0022> gsm0411_smr.c:92 SMR(16) clearing SMR instance            
20170505150623128 DLSMS <0022> gsm0411_smc.c:94 SMC(16) clearing instance    
20170505150623147 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state ACTIVE -> RELEASE REQUESTED
20170505150623147 DRR <0003> gsm_04_08_utils.c:251 Sending Channel Release: Chan: Number: 1 Type: 1    
20170505150623147 DRSL <0004> abis_rsl.c:768 (bts=0,trx=0,ts=0,ss=1) DEACTivate SACCH CMD          
20170505150623154 DRSL <0004> abis_rsl.c:2027 (bts=0,trx=0,ts=0,ss=1) waiting for SAPI=0 to be released.
20170505150623323 DRSL <0004> abis_rsl.c:1718 (bts=0,trx=0,ts=0,ss=1) T3111 expired: releasing RF Channel
20170505150623323 DRSL <0004> abis_rsl.c:860 (bts=0,trx=0,ts=0,ss=1) RF Channel Release                  
20170505150623328 DRSL <0004> abis_rsl.c:931 (bts=0,trx=0,ts=0,ss=1) RF CHANNEL RELEASE ACK
20170505150623328 DRSL <0004> abis_rsl.c:1224 (bts=0,trx=0,ts=0,ss=1) state RELEASE REQUESTED -> NONE

neels: can you please try: https://code.fe80.eu/lynxis/ofono/tree/lynxis_sms_storage

also sent upstream.

• neels redirects request to pespin

lynxis, what's the status of the following branch you proposed? Is it already merged upstream? merged in osmo-gsm-tester sysmocom branch? Please update ofono in the main unit as you see is needed.

Anyway I could not test this due to issue #2421

There is already a fix upstream and in our repo. It fixes the `Can not receive part` of the problem.
But there are still SMS in the ME storage we do not receive atm.

Using latest ofono sysmocom:lynxis/master There are still issues. Ofono doesn't send a signal when a message is received in a gobi modem.

I added the print log below to ofono:

$ git diff
diff --git a/drivers/qmimodem/sms.c b/drivers/qmimodem/sms.c
index 79ea042e..72cba557 100644
--- a/drivers/qmimodem/sms.c
+++ b/drivers/qmimodem/sms.c
@@ -361,6 +361,8 @@ static void event_notify(struct qmi_result *result, void *user_data)
                DBG("msg format %d PDU length %d", message->msg_format, plen);

                ofono_sms_deliver_notify(sms, message->msg_data, plen, plen);
+       } else {
+               DBG("empty message!");
        }
 }

Looking at ofono -n -d log, this is printed when an sms is received:

ofonod[19751]: drivers/qmimodem/qmibridge.c:ask_qmi() READ: QMI QMUX:
QMI   length  = 20
QMI   flags   = 0x80
QMI   service = "wms" 
QMI   client  = 4
QMI QMI:
QMI   flags       = "indication" 
QMI   transaction = 0
QMI   tlv_length  = 8
QMI   message     = "Event Report" (0x0001)
QMI TLV:
QMI   type       = "MT Message" (0x10)
QMI   length     = 5
QMI   value      = 01:03:00:00:00
QMI   translated = [ storage_type = 'nv' memory_index = '3' ]
ofonod[19751]: drivers/qmimodem/sms.c:event_notify()
ofonod[19751]: drivers/qmimodem/sms.c:event_notify() storage type 1 index 3
ofonod[19751]: drivers/qmimodem/sms.c:event_notify() empty message!

Which means following line is failing, because the TLV doesn't seem to be there:

message = qmi_result_get(result, QMI_WMS_RESULT_MESSAGE, &len);

As a result, the sms is not notified.
Is it possible to read the SMS from other place? (ie internal storage of the modem). We can perhaps get it from there?

Yes, it's possible to implement this case.

laforge: Should I continue to work on this? Because it's only an issue on the gobi2000.

It seems a patch which may fix the issue was submitted today to ofono ml. Name of the topic: "qmi: support SMS receive on Quectel EC21".