關於MTK平臺的短信故障分析

主要是log分析

關鍵字的搜索：

cmt

eimscmt

一些解惑

Dear sir
一、這個retry的機制是modem側實現的嗎？怎麼觸發這個機制，是在收不到網絡發來的RP_ACK嗎？
->modem實現的。12s內沒有收到網絡RP-ACK就會觸發這個機制。 
二、從log如何判斷設備進行這個retry機制，是看發送SMS__RP_DATA嗎？若是是，那又如何
判斷這個SMS__RP_DATA是此次發送失敗的retry而不是又發起了一次新的發送短信呢？
->簡單的判斷能夠看以下例子，若是RP-DATA是由AT+CMGS發起的是屬於首次發起的，若是RP-DATA前面的log並無AT+CMGS則屬於modem重傳的
Type    Index    Time    Local Time    Module    Message    Comment    Time Different
SYS    45833    34146    17:25:59:985    NIL    [AT_I p21, s11]AT+CMGS=92, "00210006816650910008525230592753856253542c6253542c6253542c76845b5850a88fc77a0b67516751901a4f207edf6eda6eda6eda6eda6eda6eda6eda560e560e560e560e70e670e670e670e670e670e653065306530653065306"
        
OTA    45910    34156    17:25:59:985    SMS    [MS->NW]: SMS__RP_DATA (smi=0)        
OTA    48452    34185    17:26:00:185    SMS    [MS->NW]: SMS__CP_DATA (smi=0)        
OTA    49685    34200    17:26:00:185    SMS    [NW->MS]: SMS__CP_ACK (smi=0)        
OTA    68268    36794    17:26:13:185    SMS    [MS->NW]: SMS__RP_DATA (smi=0)        
三、log中哪裏顯示 2G尚未建好connection？
->查看modem log中PS TRACE Peer窗口的OTA信令，若是在2G時沒有發起Channel Reques的則表明當前沒有建好鏈接，沒法提供SMS服務。

以前的分析結果

Dear sir
在4G發送短信的期間進行CSFB call是會打斷SMS的流程，UE切到2G後沒有收到網絡的CP-DATA，就會認爲發送失敗而且進行重選，而重傳的時候因爲2G尚未建好connection也就被直接reject掉，因此最後上報MO SMS fail，但網絡可能會仍然把異常的SMS發送給對端，這屬於網絡問題，手機的處理流程是正常的。
Type    Index    Time    Local Time    Module    Message    Comment    Time Different
PS    752915    82237    17:30:00:470    SMSAL - SMS    MSG_ID_SMS_SUBMIT        
OTA    752919    82237    17:30:00:470    SMS    [MS->NW]: SMS__RP_DATA (smi=0)        
OTA    756005    82278    17:30:00:670    SMS    [MS->NW]: SMS__CP_DATA (smi=0)        
OTA    757920    82293    17:30:00:670    EMM_NASMSG    [MS->NW] EMM_Extended_Service_Request(service type="MO_CSFB", CSFB response="CSFB_UNUSED")        
OTA    758401    82298    17:30:00:670    SMS    [NW->MS]: SMS__CP_ACK (smi=0)        
OTA    758709    82300    17:30:00:670    ERRC_CONN    [NW->MS] ERRC_RRCConnectionRelease(cause:[ReleaseCause_other], redirectInfo:[1])        
OTA    762762    82549    17:30:02:070    SMS    [MS->NW]: SMS__RP_DATA (smi=0)    retry    
PS    762764    82549    17:30:02:070    SMS - MM    MSG_ID_MMSMS_EST_REQ        
PS    762768    82549    17:30:02:070    MM - SMS    MSG_ID_MMSMS_EST_REJ    CM_MM_RR_NO_SERVICE    
PS    762772    82549    17:30:02:070    SMS - SMSAL    MSG_ID_SMS_SUBMIT_REPORT_NACK

2、判斷手機狀態是否可收到短信

二、RRC三個步驟創建正常
[MS->NW] ERRC_RRCConnectionRequest
[NW->MS] ERRC_RRCConnectionSetup
[MS->NW] ERRC_RRCConnectionSetupComplete

三、這份log沒有副卡，全部不會有該問題
假設有副卡也就是看OTA沒有進行CS業務
四、沒有作Attach和TAU，因此沒有該問題
至於流程是否完整請查看24.301裏面5.5章節關於Attach和TAU的流程圖介紹

3、信號質量很差網絡未回覆cp_ack

發送此現象的緣由是手機已將CP_DATA（包含短信內容）發送給網絡，網絡未回覆CP_DATA,重發,網絡未回覆CP_ACK,致使短信發送失敗，網絡已收到CP_DATA,有可能將CP_DATA轉發給接收端，因此接收端能收到短信。手機端流程處理正常，網絡緣由，請知悉!

435101, 0, 93784728, 16:48:48:201 2016/12/30, MOD_SMSAL, MOD_SMS, MNSMS_SAP, MSG_ID_SMS_SUBMIT
437320, 0, 93786994, 16:48:48:201 2016/12/30, MOD_SMS, , TRACE_PEER, [MS->NW] [MO] SMS__CP_DATA (ti=1)
438160, 0, 93788190, 16:48:48:401 2016/12/30, MOD_SMS, , TRACE_PEER, [NW->MS] [MO] SMS__CP_ACK (ti=1)
438160, 0, 93788190, 16:48:48:401 2016/12/30, MOD_SMS, , TRACE_PEER, [NW->MS] [MO] SMS__CP_ACK (ti=1)
458528, 0, 93864754, 16:48:53:252 2016/12/30, MOD_SMS, , TRACE_PEER, [MS->NW] [MO] SMS__RP_DATA (rl_id=0)
460851, 0, 93867259, 16:48:53:452 2016/12/30, MOD_SMS, , TRACE_PEER, [MS->NW] [MO] SMS__CP_DATA (ti=2)
479798, 0, 93944285, 16:48:58:406 2016/12/30, MOD_SMS, MOD_SMSAL, MNSMS_SAP, MSG_ID_SMS_SUBMIT_REPORT_NACK
 

ECSQ: 15,25,1,1,1,-49,-464,7,17,38 看第1個參數和第7個參數。 第一個參數asu>20表示信號質量比較好。 第7個參數-464= -116<-95 強度也不是很好。
當前信號質量不是很好。
434921, 0, 93722645, 16:48:44:262 2016/12/30, MOD_NIL, , TRACE_INFO, [AT_R p20, s9]+ECSQ: 16,24,1,1,1,-47,-467,7,15,38
461837, 0, 93869352, 16:48:53:652 2016/12/30, MOD_NIL, , TRACE_INFO, [AT_U p19, s8]+ECSQ: 18,24,1,1,1,-44,-466,7,21,38

3、TIO不一致的問題

網絡有點異常，@10:43:17發送的SMS沒有收到網絡的RP-ACK，以後UE進行重傳可是網絡返回的RP-ACK帶的TIO和UE發送不同，也就是TIO unsync，這種狀況是把它丟棄掉因此UE會上報SMS fail，而網絡沒有處理好這種異常的SMS流程仍然把SMS發送給對端。
這屬於網絡臨時問題，手機處理流程正常。
Type    Index    Time    Local Time    Module    Message    Comment    Time Different
SYS (PCORE)    618494    4619233    10:43:17:075    NIL    [AT_I p22, s11]AT+CMGS=16, "0001000681665048000806540c8c0b4e86"
PS (PCORE)    618736    4619782    10:43:17:275    SMSAL - SMS    MSG_ID_SMS_SUBMIT
OTA (PCORE)    618738    4619784    10:43:17:275    SMS    [MS->NW] [MO] SMS__RP_DATA (rl_id=1)
OTA (PCORE)    618760    4619788    10:43:17:275    SMS    [MS->NW] [MO] SMS__CP_DATA (ti=1)    .001 .... = TIO: 1
OTA (PCORE)    619101    4620889    10:43:17:275    SMS    [NW->MS] [MO] SMS__CP_ACK (ti=1)
OTA (PCORE)    645114    4707446    10:43:22:755    ERRC_CONN    [NW->MS] ERRC_RRCConnectionRelease(cause:[ReleaseCause_other], redirectInfo:[0])
OTA (PCORE)    647395    4708551    10:43:22:955    SMS    [MS->NW] [MO] SMS__RP_DATA (rl_id=0)
OTA (PCORE)    649748    4710804    10:43:22:955    SMS    [MS->NW] [MO] SMS__CP_DATA (ti=2)
OTA (PCORE)    649785    4710808    10:43:22:955    EMM_NASMSG    [MS->NW] EMM_Uplink_NAS_Transport    .010 .... = TIO: 2
OTA (PCORE)    650491    4711746    10:43:23:155    EMM_NASMSG    [NW->MS] EMM_Downlink_NAS_Transport    .001 .... = TIO: 1
PS (PCORE)    650501    4711748    10:43:23:155    SMS    SMS: sms_find_cm_id_by_ti error: ti=1
OTA (PCORE)    652168    4717669    10:43:23:387    EMM_NASMSG    [NW->MS] EMM_Downlink_NAS_Transport    .001 .... = TIO: 1
PS (PCORE)    652178    4717670    10:43:23:387    SMS    SMS: sms_find_cm_id_by_ti error: ti=1
OTA (PCORE)    670222    4787696    10:43:27:875    ERRC_CONN    [NW->MS] ERRC_RRCConnectionRelease(cause:[ReleaseCause_other], redirectInfo:[0])
PS (PCORE)    670750    4787923    10:43:27:875    SMS    SMS:[RL_FSM]rl_id=0 , RL_FSM_SMCP_ERR_IND
PS (PCORE)    670754    4787924    10:43:27:875    SMS - SMSAL    MSG_ID_SMS_SUBMIT_REPORT_NACK
PS (PCORE)    793499    5614474    10:44:20:903    SMSAL - SMS    MSG_ID_SMS_SUBMIT
OTA (PCORE)    793501    5614476    10:44:20:903    SMS    [MS->NW] [MO] SMS__RP_DATA (rl_id=0)
OTA (PCORE)    795738    5616646    10:44:20:903    SMS    [MS->NW] [MO] SMS__CP_DATA (ti=3)
OTA (PCORE)    796518    5618041    10:44:21:111    SMS    [NW->MS] [MO] SMS__CP_ACK (ti=3)
OTA (PCORE)    815837    5693644    10:44:25:859    ERRC_CONN    [NW->MS] ERRC_RRCConnectionRelease(cause:[ReleaseCause_other], redirectInfo:[0])
OTA (PCORE)    818201    5694802    10:44:26:059    SMS    [MS->NW] [MO] SMS__RP_DATA (rl_id=0)
OTA (PCORE)    820547    5697863    10:44:26:264    SMS    [MS->NW] [MO] SMS__CP_DATA (ti=4)
OTA (PCORE)    820584    5697866    10:44:26:264    EMM_NASMSG    [MS->NW] EMM_Uplink_NAS_Transport    .100 .... = TIO: 4
OTA (PCORE)    821289    5698587    10:44:26:264    EMM_NASMSG    [NW->MS] EMM_Downlink_NAS_Transport    .011 .... = TIO: 3
OTA (PCORE)    821541    5700039    10:44:26:264    EMM_NASMSG    [NW->MS] EMM_Downlink_NAS_Transport    .011 .... = TIO: 3
PS (PCORE)    840471    5774885    10:44:31:176    SMS - SMSAL    MSG_ID_SMS_SUBMIT_REPORT_NACK
PS (PCORE)    874563    6065388    10:44:49:749    SMSAL - SMS    MSG_ID_SMS_SUBMIT
PS (PCORE)    922668    6235199    10:45:00:502    SMS - SMSAL    MSG_ID_SMS_SUBMIT_REPORT_NACK

4、4G小區切換的狀況下很容易收不到網絡端的RP_ACK

在關機前REF收到的5頁長短信是連續發送過來，而DUT只收到其中兩條，@10:13:07:800網絡讓DUT作切換，以後新的cell並無給發送剩餘的SMS，這是網絡問題，應該是基站並無很好處理好收短信遇到切換的場景。
DUT:
Type    Index    Time    Local Time    Module    Message    Comment    Time Different
OTA (PCORE)    37469    938890    10:13:06:577    SMS    [NW->MS] [MT] SMS__CP_DATA (ti=14)    Message part number: 3    
OTA (PCORE)    37470    938890    10:13:06:577    SMS    [MS->NW] [MT] SMS__CP_ACK (ti=14)        
PS (PCORE)    37539    938899    10:13:06:577    SMS - SMSAL    MSG_ID_SMS_DELIVER        
PS (PCORE)    37889    940294    10:13:06:577    SMSAL - SMS    MSG_ID_SMS_DELIVER_REPORT_ACK        
OTA (PCORE)    37893    940295    10:13:06:577    SMS    [MS->NW] [MT] SMS__CP_DATA (ti=14)        
OTA (PCORE)    38316    941463    10:13:06:798    SMS    [NW->MS] [MT] SMS__CP_ACK (ti=14)        
OTA (PCORE)    41349    953511    10:13:07:600    SMS    [NW->MS] [MT] SMS__CP_DATA (ti=14)    Message part number: 1    
PS (PCORE)    41419    953520    10:13:07:600    SMS - SMSAL    MSG_ID_SMS_DELIVER        
PS (PCORE)    41676    954451    10:13:07:600    SMSAL - SMS    MSG_ID_SMS_DELIVER_REPORT_ACK        
PS (PCORE)    42645    957993    10:13:07:800    ERRC_MOB    [RPT] A4 enter condition pci[395] (mn[-390]+ofn[0]+ocn[0]-hys[4])=-394 > thresh[-404] rslt=1        
OTA (PCORE)    42656    957994    10:13:07:800    ERRC_MOB    [MS->NW] ERRC_MeasurementReport[9] eventA4 ncell[38400/395] rslt[-390][-17]        
OTA (PCORE)    42914    958943    10:13:07:800    ERRC_CONN    [NW->MS] ERRC_RRCConnectionReconfiguration(measCfg:[0],mobCtrlInfo:[1],dedInfoNASList:[0],radioresCfgDed:[1],secCfgHO:[1])        
OTA (PCORE)    48374    966699    10:13:08:420    ERRC_MOB    [MS->NW] ERRC_MeasurementReport[18] eventA2 pcell[38400/395] rslt[-393][-26]        
OTA (PCORE)    59148    1037165    10:13:12:900    ERRC_CONN    [NW->MS] ERRC_RRCConnectionRelease(cause:[ReleaseCause_other], redirectInfo:[0])        

如何從mdlog看出來接收的信息對應哪張SIM卡。 打開mdlog以後，搜索SMSAL，能夠找到MSG_ID_SMS_DELIVER 這樣的數據（這是接收短信） Source和Destination列就是module名稱。好比：SMS、SMSAL 這樣指的就是卡1 SMS_2, SMSAL_2 指的就是卡2 例如這份log:中批-1-600-w29-log3-10.14@mdlog1@MDLog1_2017_0507_101802 看到的 5488, 0, 1239252, 10:18:40:667 2017/05/07, MOD_SMS, MOD_SMSAL, MNSMS_SAP, MSG_ID_SMS_DELIVER 這就能夠看出來是卡1接收了短信。