MTK平臺sip信令的查看和volte的故障

關鍵字搜索：

siptx-io

volte_auto_testing

AT命令：

CIREGU

CGACT

volte基本流程場景：

參考博客：http://www.cnblogs.com/gnuhpc/archive/2012/12/10/2812095.html

sip hold:

http://blog.csdn.net/blade2001/article/details/9163205

sip協議詳解:

https://wenku.baidu.com/view/9069e37569eae009581bec9d.html

https://wenku.baidu.com/view/d2e34ad484254b35eefd34f7.html?re=view

1、SDP/Bearer match失敗

tft packet filter這塊24.008 10.5.6.12 Traffic Flow Template有講到，UE的資源預留在RFC 3313有提到，具體行爲可能並無細說，是經過日常看log和workshop所知的。關於此類問題首先看到VoLTE_Auto_Testing: [0][call] event/recv/0/2/bw_cnf/0這一塊能判斷是資源預留失敗，接着能夠經過查看tft的行爲來進一步判斷

在call進行的過程當中手機會跟網絡進行SDP/Bearer match，若是匹配失敗，IMCB向call UA發送bw_cnf=0，這樣會致使UA發cancel來斷cal，經常會有網絡問題致使的bearer匹配失敗

K4添加通話失敗是由於BW Reserve Failure致使UA發Cancel斷call
02-17 15:02:24.236500 1849 1880 I VoLTE_Auto_Testing: [0][call] event/recv/0/2/bw_cnf/0
02-17 15:02:24.240988 1848 1861 D VoLTE SIPTX: [SIPTX-IO] Send SIP (2409:8019:8630:1900:8::: 9900 )[131073:1638420] ==> { CANCEL tel:668189;phone-context=ims.mnc002.mcc460.3gppnetwork.org SIP/2.0 }
02-17 15:02:24.242998 1849 1880 I VoLTE_Auto_Testing: [0][call] state_change/0/2/DISC_IND

k4呼出失敗是由於以前所說的BW Reserve Failure致使UA發Cancel斷call，而failure是由於在第二通cal創建的過程當中網絡錯誤的刪除了pf=2的上行RTP packet filter，這樣致使了後續qos和tft都match failed，而對比機log則不存在這樣的狀況，由於網絡沒有錯誤刪除任何pf，這是網絡問題形成的，請您知悉！

Type    Index    Time    Local Time    Module    Message    Comment    Time Different
OTA    610411    491332    17:27:57:305    ESM    [NW->MS] ESM_MSG_MODIFY_EPS_BEARER_CONTEXT_REQUEST (PTI:0, EBI:7)    //消息體中能夠看到pf
101. .... = TFT operation code: Delete packet filters from existing TFT (5)
.... 0001 = Packet filter identifier: 2 (1)
03-04 17:27:58.151558 4436 4436 I VoLTE IMCB: tft_mod (1) qos_mod(1) imcb_bearer_msg_media_add_req_chk (vendor/mediatek/proprietary/frameworks/opt/volte/volte_imcb/sub_imcb/bearer/src/imcb_bearer_media_chk.c, 211)
03-04 17:28:04.082754 4434 4470 I VoLTE_Auto_Testing: [0][call] event/recv/0/2/bw_cnf/0
03-04 17:28:04.088060 4433 4453 D VoLTE SIPTX: [SIPTX-IO] Send SIP (2409:8019:8630:1900:8::: 9900 )[524292:2228254] ==> { CANCEL tel:664253;phone-context=ims.mnc002.mcc460.3gppnetwork.org SIP/2.0 }

2、呼叫轉移的問題（待確認）

分析從log中看UE這邊收到181以後就有收到網絡很快下發的487從而通話只能被斷開，這個是網絡行爲決定的，因爲貴司是用聯通卡設置了呼叫轉移，懷疑的跨運營商之間網絡仍是有問題，以前其餘客戶也有碰到相似的問題，還請貴司用相同的卡在相同地點多對比測試，請知悉！

16569: 02-23 14:06:19.919106 1762 1782 D VoLTE SIPTX: [SIPTX-IO] Recv SIP (2409:8019:8630:1900:8::: 9900 )[131073:262147] <== { SIP/2.0 181 Call Is Being Forwarded }
16652: 02-23 14:06:19.922044 1763 3097 I VoLTE_Auto_Testing: [0][call] msg/recv/resp/0/-1/181
16682: 02-23 14:06:19.923350 1763 3097 I VoLTE_Auto_Testing: [0][call] event/send/0/1/ecpi/2/0/0/3/0
16689: 02-23 14:06:19.923617 1763 3097 I VoLTE_Auto_Testing: [0][call] event/send/0/1/notify/2
17943: 02-23 14:06:21.459108 1762 1782 D VoLTE SIPTX: [SIPTX-IO] Recv SIP (2409:8019:8630:1900:8::: 9900 )[131073:262147] <== { SIP/2.0 487 Request Terminated }
18018: 02-23 14:06:21.489841 1763 3097 I VoLTE_Auto_Testing: [0][call] msg/recv/resp/0/-1/487
18035: 02-23 14:06:21.490466 1763 3097 I VoLTE_Auto_Testing: [0][call] event/send/0/1/bw_rel
18043: 02-23 14:06:21.490808 1763 3097 I VoLTE_Auto_Testing: [0][call] event/send/0/1/ecpi/133/0/0/3/31
3、4G鏈接斷開致使volte通話中斷

主叫端在收到SIP/2.0 180 Ringing因爲信號比較弱 rsrp[-486] rsrq[-60] ，致使網絡下發了ERRC_RRCConnectionRelease
Type    Index    Time    Local Time    Module    Message    Comment    Time Different
SYS    290269    160840    14:51:13:400    NIL    [AT_I p20, s10]ATD664253;
        
OTA    293869    160888    14:51:13:600    ESM    [NW->MS] ESM_MSG_ACTIVATE_DEDICATED_EPS_BEARER_CONTEXT_REQUEST (PTI:0, EBI:7)        
OTA    294085    160888    14:51:13:600    ESM    [MS->NW] ESM_MSG_ACTIVATE_DEDICATED_EPS_BEARER_CONTEXT_ACCEPT (PTI:0, EBI:7)        
SIP    0        14:51:13:788        [MS->NW]INVITE tel:664253;phone-context=ims.mnc007.mcc460.3gppnetwork.org SIP/2.0        
SIP    1        14:51:13:922        [NW->MS]SIP/2.0 100 Trying        
OTA    307739    161099    14:51:14:800    ESM    [NW->MS] ESM_MSG_MODIFY_EPS_BEARER_CONTEXT_REQUEST (PTI:0, EBI:7)        
OTA    307951    161099    14:51:14:800    ESM    [MS->NW] ESM_MSG_MODIFY_EPS_BEARER_CONTEXT_ACCEPT (PTI:0, EBI:7)        
SIP    2        14:51:15:017        [NW->MS]SIP/2.0 183 Session Progress        
SIP    3        14:51:15:052        [MS->NW]PRACK sip:[2409:8019:8630:2100:0008:0000:0000:0000]:9900;Hpt=8f32_16;CxtId=3;TRC=ffffffff-ffffffff SIP/2.0        
SIP    4        14:51:15:404        [NW->MS]SIP/2.0 200 OK        
SIP    5        14:51:15:432        [MS->NW]UPDATE sip:[2409:8019:8630:2100:0008:0000:0000:0000]:9900;Hpt=8f32_16;CxtId=3;TRC=ffffffff-ffffffff SIP/2.0        
SIP    6        14:51:16:198        [NW->MS]SIP/2.0 200 OK        
SIP    7        14:51:16:207        [NW->MS]SIP/2.0 180 Ringing        
PS    334007    161463    14:51:16:600    ERRC_MOB    [MRM] store scell: earfcn[37900] pci[87] rsrp2[-464] rssnr[6]        
PS    334008    161463    14:51:16:600    ERRC_MOB    [MRM] store scell: earfcn[37900] pci[87] rsrp[-486] rsrq[-60] cell_off[0] cell_state[0]        
PS    334037    161463    14:51:16:600    ERRC_MOB    [RPT] earfcn[38098] pci[320] cell_state[1] rsrp[-520] rsrq[-83] is skipped due to cell state.        
PS    334040    161463    14:51:16:600    ERRC_MOB    [RPT] earfcn[40936] pci[90] cell_state[1] rsrp[-484] rsrq[-88] is skipped due to cell state.        
PS    334046    161463    14:51:16:600    ERRC_MOB    [RPT] earfcn[38950] pci[248] cell_state[1] rsrp[-493] rsrq[-64] is skipped due to cell state.        
PS    334047    161463    14:51:16:600    ERRC_MOB    [RPT] earfcn[38950] pci[289] cell_state[1] rsrp[-488] rsrq[-74] is skipped due to cell state.        
OTA    334455    161468    14:51:16:600    ERRC_CONN    [NW->MS] ERRC_RRCConnectionRelease(cause:[ReleaseCause_other], redirectInfo:[1])    

被叫端，收到180 後回覆200 OK, CALL 已經接通了，過了30s 才收到網絡的BYE，應該是網絡問題
Type    Index    Time    Local Time    Module    Message    Comment    Time Different
SYS    92076    141376    14:49:37:000    NIL    [AT_U p18, s8]+ECPI: 1,6,0,1,1,20,"660623",129,"<sip:660623@gd.ims.mnc000.mcc460.3gppnetwork.org;noa=subscriber;srvattri=national;phone-context=+86>"        
SYS    387497    144878    14:49:54:600    NIL    [AT_U p18, s8]+ECPI: 1,133,0,1,1,20,"660623",129,"<sip:660623@gd.ims.mnc000.mcc460.3gppnetwork.org;noa=subscriber;srvattri=national;phone-context=+86>",16        
SYS    1057865    160785    14:51:14:090    NIL    [AT_U p18, s8]+ECPI: 1,0,0,1,1,20,"660623",129,"<sip:660623@gd.ims.mnc000.mcc460.3gppnetwork.org;noa=subscriber;srvattri=national;phone-context=+86>"        
OTA    1064576    160869    14:51:14:490    ERRC_CONN    [NW->MS] ERRC_RRCConnectionReconfiguration(measCfg:[1],mobCtrlInfo:[0],dedInfoNASList:[0],radioresCfgDed:[0],secCfgHO:[0])        
OTA    1065031    160870    14:51:14:490    ERRC_CONN    [MS->NW] ERRC_RRCConnectionReconfigurationComplete        
SIP    32        14:51:14:624        [NW->MS]INVITE sip:[2409:8809:8691:50F5:0001:0001:1C7F:9255]:50001 SIP/2.0        
SIP    34        14:51:14:702        [MS->NW]SIP/2.0 183 Session Progress        
SIP    35        14:51:15:450        [NW->MS]PRACK sip:+8618825894253@[2409:8809:8691:50F5:0001:0001:1C7F:9255]:50001 SIP/2.0        
SIP    36        14:51:15:459        [MS->NW]SIP/2.0 200 OK        
SIP    37        14:51:15:854        [NW->MS]UPDATE sip:+8618825894253@[2409:8809:8691:50F5:0001:0001:1C7F:9255]:50001 SIP/2.0        
SIP    39        14:51:15:892        [MS->NW]SIP/2.0 180 Ringing        
SYS    1219987    163778    14:51:29:090    NIL    [AT_U p18, s8]+ECPI: 1,132,0,1,1,20,"660623",129,"<sip:660623@gd.ims.mnc000.mcc460.3gppnetwork.org;noa=subscriber;srvattri=national;phone-context=+86>"        
SYS    1220123    163778    14:51:29:090    NIL    [AT_U p18, s8]+ECPI: 1,6,0,1,1,20,"660623",129,"<sip:660623@gd.ims.mnc000.mcc460.3gppnetwork.org;noa=subscriber;srvattri=national;phone-context=+86>"        
SIP    40        14:51:29:666        [MS->NW]SIP/2.0 200 OK        
SYS    1688380    170196    14:52:01:090    NIL    [AT_U p18, s8]+ECPI: 1,133,0,1,1,20,"660623",129,"<sip:660623@gd.ims.mnc000.mcc460.3gppnetwork.org;noa=subscriber;srvattri=national;phone-context=+86>",16        
OTA    1690047    170220    14:52:01:290    ESM    [NW->MS] ESM_MSG_DEACTIVATE_EPS_BEARER_CONTEXT_REQUEST (PTI:0, EBI:7)        
OTA    1690059    170220    14:52:01:290    ESM    [MS->NW] ESM_MSG_DEACTIVATE_EPS_BEARER_CONTEXT_ACCEPT (PTI:0, EBI:7)        
SIP    41        14:52:01:718        [NW->MS]ACK sip:+8618825894253@[2409:8809:8691:50F5:0001:0001:1C7F:9255]:50001 SIP/2.0        
SIP    42        14:52:01:726        [NW->MS]BYE sip:+8618825894253@[2409:8809:8691:50F5:0001:0001:1C7F:9255]:50001 SIP/2.0        
SIP    43        14:52:01:759        [MS->NW]SIP/2.0 200 OK        

4、4G鏈接斷開致使volte信令不完整

此問題發生的緣由是出在MO這邊，當MT端接聽的那個時間段MO這邊有收到網絡的RRCConnectionRelease從而致使的掉話，從log中看測試過程當中B2測量也始終未有知足故沒法進行SRVCC切換，整體來看應該是NW issue，請知悉！
Type    Index    Time    Local Time    Module    Message    Comment    Time Different
SYS (PCORE)    530927    157841739    19:43:29:040    NIL    [AT_I p21, s10]ATD666160;
        
SYS (PCORE)    531136    157841760    19:43:29:040    NIL    [AT_U p19, s8]+ECPI: 1,130,0,0,0,0,"666160",129,""        
SYS (PCORE)    606692    158043375    19:43:42:046    NIL    [AT_U p19, s8]+ECPI: 1,2,1,1,0,20,"666160",129,""        
PS (PCORE)    726392    158218620    19:43:53:246    ERRC_MOB    [RPT] B2 enter cond2 cell_id[78] (mn[-417]+ofn[0]-hys[4])=-421 > thresh2[-380]) rslt=0        
PS (PCORE)    726394    158218620    19:43:53:246    ERRC_MOB    [RPT] B2 enter cond2 cell_id[630] (mn[-422]+ofn[0]-hys[4])=-426 > thresh2[-380]) rslt=0        
PS (PCORE)    726396    158218620    19:43:53:246    ERRC_MOB    [RPT] B2 enter cond2 cell_id[71] (mn[-435]+ofn[0]-hys[4])=-439 > thresh2[-380]) rslt=0        
PS (PCORE)    726398    158218620    19:43:53:246    ERRC_MOB    [RPT] B2 enter cond2 cell_id[632] (mn[-417]+ofn[0]-hys[4])=-421 > thresh2[-380]) rslt=0        
PS (PCORE)    726399    158218620    19:43:53:246    ERRC_MOB    [RPT] B2 enter cond1 (ms[-483]+hys[4])=-479 < thresh1[-472]) rslt=1        
PS (PCORE)    726400    158218620    19:43:53:246    ERRC_MOB    [RPT] B2 enter cond2 cell_id[60] (mn[-404]+ofn[0]-hys[4])=-408 > thresh2[-380]) rslt=0        
OTA (PCORE)    735955    158232242    19:43:54:046    ERRC_CONN    [NW->MS] ERRC_RRCConnectionRelease(cause:[ReleaseCause_other], redirectInfo:[1])        
OTA (PCORE)    767951    158372033    19:44:03:046    MM    [MS->NW] MM__LOCATION_UPDATING_REQUEST (LU type: MM_NORMAL_LU)        
PS (PCORE)    769070    158372172    19:44:03:046    IMSP - IMC    MSG_ID_IMSP_IMC_CELL_INFO_UPDATE_REQ        
PS (PCORE)    769198    158372200    19:44:03:046    IMC    [IMC-REG]RAT is 23G, trigger IMS DEREG to IMCB)        
PS (PCORE)    769200    158372201    19:44:03:046    IMC - IMCB    MSG_ID_IMCB_IMC_IMS_DEREG_IND        
SYS (PCORE)    771465    158372695    19:44:03:046    NIL    [AT_U p19, s8]+ECPI: 1,133,0,0,0,20,"666160",129,"",31        

5、IMS註冊過程當中關ims開關問題

//Device was trying to get IMS registered
PS    98552    293278    13:20:56:690    IMC    [IMC-REG] ims_support:1        
PS    98562    293278    13:20:56:690    IMC    [IMC-REG] Normal REG condition check result: (1)
//User made IMS/VoLTE off        
SYS    98660    293282    13:20:56:690    NIL    [AT_I p21, s11]AT+EIMS=0
        
PS    98710    293282    13:20:56:690    IMC    [IMC-REG] Normal REG condition check result: (2)        
PS    98962    293284    13:20:56:690    IMC    [IMC-REG] ims_support check failed
// User gave Airplane Off/ON
Line 34609: 04-24 13:22:02.216262 13338 13338 I PhoneApp: Turning radio off - airplane
Line 39656: 04-24 13:22:28.298953 13338 13338 I PhoneApp: Turning radio on - airplane    

6、volte會議通話失敗

從log來看在合併電話會議時，將第一路通話加入電話會議收到網絡的Notify有報錯，有比較成功加入的消息和這次消息，並無什麼異常，懷疑是網絡低機率異常形成的：
Type    Index    Time    Local Time    Module    Message    Comment    Time Different
SYS    715276    757167    11:44:02:680    NIL    [AT_I p18, s8]AT+CHLD=3        
SYS    715349    757167    11:44:02:680    NIL    [AT_U p18, s8]+ECPI: 3,130,0,0,0,22,"",129,""        
SYS    727209    757290    11:44:03:280    NIL    [AT_U p18, s8]+ECPI: 3,2,0,1,1,22,"",129,""        
SYS    728075    757300    11:44:03:280    NIL    [AT_U p18, s8]+ECPI: 3,132,0,1,1,22,"",129,""        
SYS    728210    757300    11:44:03:280    NIL    [AT_U p18, s8]+ECPI: 3,6,0,1,1,22,"",129,""        
SYS    732598    757348    11:44:03:480    NIL    [AT_U p18, s8]+ECONF: 3,0,"",1,0,1        
SYS    742891    757438    11:44:04:080    NIL    [AT_U p18, s8]+ECONF: 3,0,"",0,0,2        
05-11 11:44:04.658148 6212 6227 I VoLTE SIPTX: [SIPTX-IO] Recv SIP (2405:200:330:1581::21: 32920 )[65536:458758] <== { NOTIFY sip:+917011714993@[2405:204:188d:4d3b:0:0:b32:98ad]:50045 SIP/2.0 }
SIP/2.0 480 Temporarily not available
Reason:X.int ;reasoncode=0x00000A03;add-info=0B0A.0005.0003
Reason:Q.850 ;cause=127
7、掉volte的問題

In logs we observed in logs that serving cell power was not good and A2 & A3 events were triggered but after it device moves to IDLE mode.
NW releases the RRC Connection with "idleModeMobilityControlInfo" means NW provides cells for the device to move to Idle mode and cells with carrier frequency(carrierFreq: 39325) were given highest priority.
Device finds EARFCN 39325 in B40 but cell condition were too poor that device could not select this cell, RSRP & RSRQ levels reported by the device are default values(1 & 1) and hence UI shows device in no service.

Device starts searching for other cells to get in service but could not get any cell till 16:16 PM.

So device goes to No service because of poor radio conditions and comes again in service around after 1 min once get the good cell.
This is not an issue, this is caused due to temporary NW conditions.

Please check below analysis, if any concern then let us know otherwise we shall close this issue.

//Measurement Events A2/A3 triggered but after this device moves to Idle mode
OTA    6596052    3706308    16:15:19:025    ERRC_MOB    [MS->NW] MEASUREMENT REPORT (measId[2] ERRC_MOB_RPT_TYPE_EVT_A2 scell[39325][194] rslt[-455][-78])        
OTA    6596072    3706308    16:15:19:025    ERRC_MOB    [MS->NW] MEASUREMENT REPORT (measId[1] ERRC_MOB_RPT_TYPE_EVT_A3 ERRC_MOB_OBJ_EUTRA scell[39325][194] rslt[-455][-78] ncell[39325][99] rslt[-435][-58])        
//Serving Cell power are RSRP -115 and RSRQ -20
PS    6596828    3706320    16:15:19:025    ERRC - EVAL    MSG_ID_EVAL_ERRC_CELL_POWER_LEVEL_IND        
//Still device is showing registration         
PS    6607604    3706450    16:15:19:825    VDM_ADS    [VDM ADS] Service status: CS domain NAS registration status = NAS_REG_STATUS_REGISTERED_ROAMING        
PS    6607610    3706450    16:15:19:825    VDM_ADS    [VDM ADS] Service status: PS domain NAS registration status = NAS_REG_STATUS_REGISTERED_ROAMING        
PS    6607620    3706450    16:15:19:825    VDM_ADS    [VDM ADS] Service status: cell id = 926480        
// RRC connection released by the NW device moves to Idle mode and NW send carrier freq 39325 as higest priority for reselection
OTA    6643263    3708566    16:15:30:405    ERRC_CONN    [NW->MS] ERRC_RRCConnectionRelease(cause:[ReleaseCause_other], redirectInfo:[0])    
carrierFreq: 39325

cellReselectionPriority: 7    
PS    6643478    3708569    16:15:30:405    ERRC_SPV    [SPV]ERRC state transition: current[ERRC_STS_CONNECTED]->next[ERRC_STS_IDLE]    
PS    6648384    3709151    16:15:33:205    EVAL - L4C    MSG_ID_L4C_EVAL_CELL_POWER_LEVEL_IND    -463, -64        
//Device finds     earfcn 39325 in band 40 but device could not find this cell and reporting default values of RSRP and RSRQ and device goes in NO services    
PS    6650114    3709180    16:15:33:405    MRS    [MRS_EAS] earfcn 39325 is in band 40        
PS    6650115    3709180    16:15:33:405    ERRC - EVAL    MSG_ID_EVAL_ERRC_CELL_POWER_LEVEL_IND    RSRP=1, RSRQ=1    

//Device starts searching new cells for registration    
PS    6650293    3709180    16:15:33:405    VDM_ADS    [VDM ADS] Service status: CS domain NAS registration status = NAS_REG_STATUS_NOT_REGISTERED_SEARCHING        
PS    6650299    3709180    16:15:33:405    VDM_ADS    [VDM ADS] Service status: PS domain NAS registration status = NAS_REG_STATUS_NOT_REGISTERED_SEARCHING        
// Both cells of freq 39325 were failed in selection        
PS    6698174    3713069    16:15:52:805    ERRC_CEL    [CEL_DI/LV] cell failed: earfcn[39325]/pci[294], fail[ERRC_CEL_TRACE_DI_JUDGE]        
PS    6699732    3713109    16:15:53:005    ERRC_CEL    [CEL_DI/LV] cell failed: earfcn[39325]/pci[99], fail[ERRC_CEL_TRACE_DI_JUDGE]        
PS    6699859    3713109    16:15:53:005    EVAL - L4C    MSG_ID_L4C_EVAL_CELL_POWER_LEVEL_IND    RSRP =1, RSRQ =1
//finally device gets a cell and registers and comes in service    
OTA    6732581    3718840    16:16:21:805    ERRC_SYS    [NW->MS] MasterInformationBlock (EARFCN[1490], PCI[238])        
OTA    6732668    3718841    16:16:21:805    ERRC_SYS    [NW->MS] SystemInformationBlockType1 (EARFCN[1490], PCI[238])        
PS    6734037    3718866    16:16:21:805    VDM_ADS    [VDM ADS] Service status: CS domain NAS registration status = NAS_REG_STATUS_REGISTERED_ROAMING        
PS    6734043    3718866    16:16:21:805    VDM_ADS    [VDM ADS] Service status: PS domain NAS registration status = NAS_REG_STATUS_REGISTERED_ROAMING    

AP LOG:

We can see registration states. device goes unregistered during this time and again registered at 16:16.

Also see that VoLTE icon was off at 16:15:49 and made on again at 16:16:02.

Hopefully it clears now, can we close this issue?

// Device goes unregistered and registered again.
Line 76577: 05-19 16:15:48.981 2535 2549 I VoLTE REG: *Reg[0] = OOS --> Registered , cause = 0, owner = 2 (vendor/mediatek/proprietary/protect-app/external/volte/volte_stack/src/reg/reg.c:3357) (vendor/mediatek/proprietary/protect-app/external/volte/volte_stack/src/reg/reg.c:732)
Line 78815: 05-19 16:15:50.712 2535 2549 I VoLTE REG: *Reg[0] = unknown --> Disconnect , cause = 0, owner = 2 (vendor/mediatek/proprietary/protect-app/external/volte/volte_stack/src/reg/reg.c:1274) (vendor/mediatek/proprietary/protect-app/external/volte/volte_stack/src/reg/reg.c:732)
Line 84067: 05-19 16:15:59.781 2535 2549 I VoLTE REG: **Reg[0] = Disconnect --> Connecting , cause = 0, owner = 2 (vendor/mediatek/proprietary/protect-app/external/volte/volte_stack/src/reg/reg.c:3263) (vendor/mediatek/proprietary/protect-app/external/volte/volte_stack/src/reg/reg.c:751)
Line 84206: 05-19 16:15:59.785 2535 2549 I VoLTE REG: *Reg[0] = Connecting --> Unregistered , cause = 0, owner = 2 (vendor/mediatek/proprietary/protect-app/external/volte/volte_stack/src/reg/reg.c:3196) (vendor/mediatek/proprietary/protect-app/external/volte/volte_stack/src/reg/reg.c:732)
Line 84329: 05-19 16:15:59.792 2535 2549 I VoLTE REG: *Reg[0] = Unregistered --> Registering , cause = 0, owner = 2 (vendor/mediatek/proprietary/protect-app/external/volte/volte_stack/src/reg/reg.c:2058) (vendor/mediatek/proprietary/protect-app/external/volte/volte_stack/src/reg/reg.c:732)
Line 84954: 05-19 16:16:00.272 2535 21797 I VoLTE REG: *Reg[0] = Registering --> Authenticating , cause = 0, owner = 2 (vendor/mediatek/proprietary/protect-app/external/volte/volte_stack/src/reg/reg.c:4629) (vendor/mediatek/proprietary/protect-app/external/volte/volte_stack/src/reg/reg.c:732)
Line 86132: 05-19 16:16:02.375 2535 21797 I VoLTE REG: *Reg[0] = Authenticating --> Registered , cause = 0, owner = 2 (vendor/mediatek/proprietary/protect-app/external/volte/volte_stack/src/reg/reg.c:4339) (vendor/mediatek/proprietary/protect-app/external/volte/volte_stack/src/reg/reg.c:732)


//VoLTE icon on/off at Ap
Line 77876: 05-19 16:15:49.314 1103 1103 D SignalClusterView: set VoLTE Icon off
Line 86593: 05-19 16:16:02.404 1103 1103 D SignalClusterView: set VoLTE Icon on

8、volte註冊失敗，pdn鏈接請求被拒

此問題從log中看極可能是機率性的這個應該是timing處理的case，大體緣由是這樣，UE這邊發第一次IMS PDN創建請求時在發送最後的accept消息時恰好很短期後副卡恰好要作LU佔用底層資源這時候可能就是當底層在data發送出去等網絡回覆ACK的過程（其實網絡已經有收到UE發送的這個消息可是UE沒有收到網絡回覆的ACK），這樣因爲副卡資源佔用致使底層回報發送failure由於底層必需要等到ACK纔算成功，故AP後續就再次發送IMS PDN創建請求給NW，但NW由於已經收到Accept致使不接受重複的PDN創建請求從而致使了此次註冊的失敗，具體log流程以下：
Type    Index    Time    Local Time    Module    Message    Comment    Time Different
OTA    173744    4903    15:14:24:130    ESM    [MS->NW] ESM_MSG_PDN_CONNECTIVITY_REQUEST (PTI:2, EBI:0)        
OTA    175162    4925    15:14:24:130    ESM    [NW->MS] ESM_MSG_ACTIVATE_DEFAULT_EPS_BEARER_CONTEXT_REQUEST (PTI:2, EBI:6)        
OTA    175198    4925    15:14:24:130    ESM    [MS->NW] ESM_MSG_ACTIVATE_DEFAULT_EPS_BEARER_CONTEXT_ACCEPT (PTI:0, EBI:6)        
PS    175199    4925    15:14:24:130    ESM - EMM    MSG_ID_ESM_EMM_DATA_REQ        
PS    175244    4925    15:14:24:130    EMM - ESM    MSG_ID_ESM_EMM_DATA_SEND_IND        
PS    175253    4925    15:14:24:130    EMM - ERRC    MSG_ID_EMM_ERRC_DATA_REQ        
PS    175265    4925    15:14:24:130    ERRC - EPDCP    MSG_ID_ERRC_EPDCP_DCCH_DATA_REQ        
OTA    176240    4944    15:14:24:330    MM_2    [MS->NW] MM__LOCATION_UPDATING_REQUEST (LU type: MM_IMSI_ATTACH_LU)        
PS    176251    4944    15:14:24:330    RSVAS - ERRC    MSG_ID_RSVAS_EAS_ABORT_SERVICE_REQ        
PS    176318    4944    15:14:24:330    ERRC - EMM    MSG_ID_EMM_ERRC_RELEASE_IND        
PS    176391    4944    15:14:24:330    EMM - ESM    MSG_ID_ESM_EMM_CONN_RELEASE_IND        
PS    176485    4944    15:14:24:330    EMM - EVAL    MSG_ID_EVAL_EMM_REL_IND        
PS    176494    4944    15:14:24:330    EMM - ERRC    MSG_ID_EMM_ERRC_RELEASE_RSP        
PS    176698    4945    15:14:24:330    EMM - ESM    MSG_ID_ESM_EMM_DATA_CNF        
OTA    176746    4945    15:14:24:330    ESM    [MS->NW] ESM_MSG_PDN_CONNECTIVITY_REQUEST (PTI:2, EBI:0)        
PS    176747    4945    15:14:24:330    ESM - EMM    MSG_ID_ESM_EMM_DATA_REQ        
PS    177219    4946    15:14:24:330    EPDCP - ERRC    MSG_ID_ERRC_EPDCP_DCCH_DATA_CNF        
PS    177221    4946    15:14:24:330    EPDCP - ERRC    MSG_ID_ERRC_EPDCP_DCCH_DATA_CNF        
OTA    230424    6547    15:14:32:345    ESM    [MS->NW] ESM_MSG_PDN_CONNECTIVITY_REQUEST (PTI:2, EBI:0)        
OTA    230960    6555    15:14:32:345    ESM    [NW->MS] ESM_MSG_PDN_CONNECTIVITY_REJECT (PTI:2, EBI:0, ESM cause:"ESM_CAUSE_MULTIPLE_PDN_APN_NOT_ALLOWED")        
SYS    231107    6555    15:14:32:345    NIL    [AT_R p17, s5]+CME ERROR: 3383        

9、副卡佔用資源致使PDN鏈接請求收不到再次發送被網絡拒絕從而註冊部上volte

此問題從log中看極可能是機率性的這個應該是timing處理的case，大體緣由是這樣，UE這邊發第一次IMS PDN創建請求時在發送最後的accept消息時恰好很短期後副卡恰好要作LU佔用底層資源這時候可能就是當底層在data發送出去等網絡回覆ACK的過程（其實網絡已經有收到UE發送的這個消息可是UE沒有收到網絡回覆的ACK），這樣因爲副卡資源佔用致使底層回報發送failure由於底層必需要等到ACK纔算成功，故AP後續就再次發送IMS PDN創建請求給NW，但NW由於已經收到Accept致使不接受重複的PDN創建請求從而致使了此次註冊的失敗，具體log流程以下： Type    Index    Time    Local Time    Module    Message    Comment    Time Different OTA    173744    4903    15:14:24:130    ESM    [MS->NW] ESM_MSG_PDN_CONNECTIVITY_REQUEST (PTI:2, EBI:0)         OTA    175162    4925    15:14:24:130    ESM    [NW->MS] ESM_MSG_ACTIVATE_DEFAULT_EPS_BEARER_CONTEXT_REQUEST (PTI:2, EBI:6)         OTA    175198    4925    15:14:24:130    ESM    [MS->NW] ESM_MSG_ACTIVATE_DEFAULT_EPS_BEARER_CONTEXT_ACCEPT (PTI:0, EBI:6)         PS    175199    4925    15:14:24:130    ESM - EMM    MSG_ID_ESM_EMM_DATA_REQ         PS    175244    4925    15:14:24:130    EMM - ESM    MSG_ID_ESM_EMM_DATA_SEND_IND         PS    175253    4925    15:14:24:130    EMM - ERRC    MSG_ID_EMM_ERRC_DATA_REQ         PS    175265    4925    15:14:24:130    ERRC - EPDCP    MSG_ID_ERRC_EPDCP_DCCH_DATA_REQ         OTA    176240    4944    15:14:24:330    MM_2    [MS->NW] MM__LOCATION_UPDATING_REQUEST (LU type: MM_IMSI_ATTACH_LU)         PS    176251    4944    15:14:24:330    RSVAS - ERRC    MSG_ID_RSVAS_EAS_ABORT_SERVICE_REQ         PS    176318    4944    15:14:24:330    ERRC - EMM    MSG_ID_EMM_ERRC_RELEASE_IND         PS    176391    4944    15:14:24:330    EMM - ESM    MSG_ID_ESM_EMM_CONN_RELEASE_IND         PS    176485    4944    15:14:24:330    EMM - EVAL    MSG_ID_EVAL_EMM_REL_IND         PS    176494    4944    15:14:24:330    EMM - ERRC    MSG_ID_EMM_ERRC_RELEASE_RSP         PS    176698    4945    15:14:24:330    EMM - ESM    MSG_ID_ESM_EMM_DATA_CNF         OTA    176746    4945    15:14:24:330    ESM    [MS->NW] ESM_MSG_PDN_CONNECTIVITY_REQUEST (PTI:2, EBI:0)         PS    176747    4945    15:14:24:330    ESM - EMM    MSG_ID_ESM_EMM_DATA_REQ         PS    177219    4946    15:14:24:330    EPDCP - ERRC    MSG_ID_ERRC_EPDCP_DCCH_DATA_CNF         PS    177221    4946    15:14:24:330    EPDCP - ERRC    MSG_ID_ERRC_EPDCP_DCCH_DATA_CNF         OTA    230424    6547    15:14:32:345    ESM    [MS->NW] ESM_MSG_PDN_CONNECTIVITY_REQUEST (PTI:2, EBI:0)         OTA    230960    6555    15:14:32:345    ESM    [NW->MS] ESM_MSG_PDN_CONNECTIVITY_REJECT (PTI:2, EBI:0, ESM cause:"ESM_CAUSE_MULTIPLE_PDN_APN_NOT_ALLOWED")         SYS    231107    6555    15:14:32:345    NIL    [AT_R p17, s5]+CME ERROR: 3383