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