通话故障总结

一般分析方法;

AT层需要搜下如下命令:

ATD+number

AT+CHUP

AT+ESRVCC

+ECPI

+ESIPCPI

AT+CLCC

Modem层的分析方法:

对于这种通话自动挂断问题,首先得确定CC流程是否完整。

如果CC流程不完整,就需要查看它的承载RR层

//这个流程就是通话的大致流程。setup就是发起通话.
OTA (PCORE)    1125225    738141903    11:20:39:844    CC    [NW->MS] CC__SETUP        
OTA (PCORE)    1125419    738142144    11:20:39:844    CC    [MS->NW] CC__CALL_CONFIRMED        
OTA (PCORE)    1125725    738153299    11:20:40:550    RRM_TDD    [MS->NW] RR__MEASUREMENT_REPORT        
OTA (PCORE)    1125765    738156615    11:20:40:786    RRM_TDD    [NW->MS] RR__ASSIGNMENT_COMMAND        
//到alerting,就是铃声开始响
OTA (PCORE)    1125854    738159798    11:20:40:990    CC    [MS->NW] CC__ALERTING        
OTA (PCORE)    1126976    738231482    11:20:45:513    RRM_TDD    [MS->NW] RR__MEASUREMENT_REPORT        
//这里connect接通
OTA (PCORE)    1127489    738270247    11:20:47:977    CC    [MS->NW] CC__CONNECT        
OTA (PCORE)    1127668    738277273    11:20:48:393    CC    [NW->MS] CC__CONNECT_ACKNOWLEDGE        
OTA (PCORE)    1137630    738313973    11:20:50:833    RRM_TDD    [MS->NW] RR__MEASUREMENT_REPORT    
//挂断,释放CC连接    
OTA (PCORE)    1139853    738331359    11:20:51:839    CC    [NW->MS] CC__DISCONNECT        
OTA (PCORE)    1139870    738331362    11:20:51:839    CC    [MS->NW] CC__RELEASE        
OTA (PCORE)    1140312    738335109    11:20:52:039    CC    [NW->MS] CC__RELEASE_COMPLETE        
//释放CC连接的承载RR连接
OTA (PCORE)    1140996    738336982    11:20:52:239    RRM_TDD    [NW->MS] RR__CHANNEL_RELEASE        

如果CC流程完整,但是报告是自动挂断,那么就看网络是否下发了 CC__DISCONNECT 或者RR__CHANNEL_RELEASE,如果有,就说明可能网络或者对端的问题。
如果CC流程不完整,没有下发CC__DISCONNECT 或者RR__CHANNEL_RELEASE,那么就说明是RR连接中断了,需要在通话中断的地方(RR__MEASUREMENT_REPORT不再出现的附近)
来查看RR层哪里出现了问题。
一般以下两种情况比较常见:
//N200 错误
PS    547587    839036    15:32:11:525    LISR2HISR_CTIRQ1 - RRM_2    MSG_ID_LAPDM_RR_REL_IND    N200 error    
//RLF 错误
PS    850942    752647    15:36:22:230    L1_2 - RRM_2    MSG_ID_LAPDM_RR_ERROR_IND    raido link failure    

这两种通常都是由信号质量差导致的,信号质量需要查看
547310, 917659, 838713, 15:32:09:725 2017/02/06, MOD_MPAL_2, MOD_RRM_2, RRM_MPAL_SAP, MSG_ID_MPAL_RR_SERV_DEDI_MEAS_IND

    Local_Parameter --> Len = 32, Addr = 0xF259BA8C
        mpal_rr_serv_dedi_meas_ind_struct = (struct)
            ref_count = 0x01
            lp_reserved = 0xf2
            msg_len = 0x0020
            rlac_full_in_quarter_dbm = 0xfe64
            rlac_sub_in_quarter_dbm = 0xfe65 //信号强度不应小于-105
            rxqual_full_avg = 0x07
            rxqual_sub_avg = 0x05 //信号质量不应小于-4
 

接通和挂断的时间点()

1、MO未接通自动挂掉

在modem log中看到

[MS->NW] MM__CM_SERVICE_REQUEST
[MS->NW] RR__CHANNEL_REQUEST
[MS->NW] RR__CHANNEL_REQUEST
[NW->MS] RR__SI_2TER (ARFCN[60], TC[5])
[NW->MS] RR__IMMEDIATE_ASSIGNMENT
[NW->MS] RR__SI_6 (ARFCN[60], TC[255])
[MS->NW] RR__CLASSMARK_CHANGE
[NW->MS] MM__ABORT
[MS->NW] RR__MEASUREMENT_REPORT
[NW->MS] RR__CHANNEL_RELEASE

MM_ABORT在协议TS 24.008 4.3.5中

2、接到来电,未接听自动挂断的

从log看测试机和配合机都是收到了网络发来的disconnect命令,挂断case都为为44 requested circuit/channel not available,未网络故障。
测试机:
398601, 0, 330658970, 14:47:47:752 2017/01/09, MOD_CC, , TRACE_PEER, [NW->MS] CC_DISCONNECT
398616, 0, 330658973, 14:47:47:752 2017/01/09, MOD_CC, , TRACE_PEER, [MS->NW] CC
RELEASE
398939, 0, 330662434, 14:47:47:960 2017/01/09, MOD_CC, , TRACE_PEER, [NW->MS] CC
RELEASE_COMPLETE
配合机:
374430, 0, 329598595, 14:47:48:782 2017/01/09, MOD_CC, , TRACE_PEER, [NW->MS] CC
DISCONNECT
374446, 0, 329598598, 14:47:48:782 2017/01/09, MOD_CC, , TRACE_PEER, [MS->NW] CC
RELEASE
374770, 0, 329605952, 14:47:49:386 2017/01/09, MOD
CC, , TRACE_PEER, [NW->MS] CC__RELEASE_COMPLETE

3、关于mtk平台SRVCC的log实例

Hi sir
从log看来,手机带的SRVCC的能力都是正常的,手机SRVCC 都是成功的,但是SRVCC 成功后网络每次都下发了CC disconnect,应该是网络问题,建议和对比机多做下对比测试,谢谢



Type    Index    Time    Local Time    Module    Message    Comment    Time Different
SYS    2241900    1942053    16:52:20:105    NIL    [AT_I p20, s10]ATD13903022925;
        
SYS    2765855    1950976    16:53:04:575    NIL    [AT_I p20, s10]ATD13903022925;
        
SYS    3095384    1954764    16:53:23:575    NIL    [IMSP_AT_I s21]AT+ESRVCCTFR=1,1,0,0,2,0,2,"13903022925",,        
SYS    3095418    1954764    16:53:23:575    NIL    [IMSP_AT_R s21]+ESRVCCTFR: 1, 1        
SYS    3240633    1972861    16:54:54:155    NIL    [AT_I p20, s10]ATD13903022925;
        
OTA    3491911    1976931    16:55:14:355    ERRC_CONN    [NW->MS] ERRC_MobilityFromEUTRACommand(CSFB:[0],purpose:[MobilityFromEUTRACommand_r8_IEs_purpose_handover_selected],targetRAT:[Handover_targetRAT_Type_geran])        
OTA    3492866    1976957    16:55:14:580    RRM    [NW->MS] RR__PHYSICAL_INFORMATION        
OTA    3492870    1976957    16:55:14:580    RRM    [MS->NW] RR__HANDOVER_COMPLETE        
SYS    3494267    1976983    16:55:14:780    NIL    [IMSP_AT_I s21]AT+ESRVCCTFR=1,1,0,0,3,0,2,"13903022925",,        
SYS    3494288    1976983    16:55:14:780    NIL    [IMSP_AT_R s21]+ESRVCCTFR: 1, 1        
OTA    3496629    1977026    16:55:14:980    CC    [NW->MS] CC__DISCONNECT        
OTA    3496642    1977026    16:55:14:980    CC    [MS->NW] CC__RELEASE        
OTA    3497024    1977105    16:55:15:380    CC    [NW->MS] CC__RELEASE_COMPLETE        
SYS    3605943    1979077    16:55:25:200    NIL    [AT_I p20, s10]ATD13903022925;
        
OTA    3609752    1979134    16:55:25:400    ESM    [NW->MS] ESM_MSG_ACTIVATE_DEDICATED_EPS_BEARER_CONTEXT_REQUEST (PTI:0, EBI:7)        
OTA    3609969    1979134    16:55:25:400    ESM    [MS->NW] ESM_MSG_ACTIVATE_DEDICATED_EPS_BEARER_CONTEXT_ACCEPT (PTI:0, EBI:7)        
OTA    3627337    1979420    16:55:26:800    ESM    [NW->MS] ESM_MSG_MODIFY_EPS_BEARER_CONTEXT_REQUEST (PTI:0, EBI:7)        
OTA    3627556    1979420    16:55:26:800    ESM    [MS->NW] ESM_MSG_MODIFY_EPS_BEARER_CONTEXT_ACCEPT (PTI:0, EBI:7)        
SYS    4177787    1996523    16:56:52:365    NIL    [AT_I p20, s10]ATD13903022925;
        
SIP    139        16:57:10:522        [MS->NW]INVITE sip:[2409:8019:8430:4500:0000:0000:0000:0008]:9900;Hpt=8fa2_16;CxtId=3;TRC=ffffffff-ffffffff SIP/2.0        
SIP    140        16:57:10:689        [NW->MS]SIP/2.0 100 Trying        
SIP    141        16:57:11:212        [NW->MS]SIP/2.0 200 OK        
SIP    142        16:57:11:245        [MS->NW]ACK sip:[2409:8019:8430:4500:0000:0000:0000:0008]:9900;Hpt=8fa2_16;CxtId=3;TRC=ffffffff-ffffffff SIP/2.0        
OTA    4547843    2000758    16:57:13:565    ERRC_CONN    [NW->MS] ERRC_MobilityFromEUTRACommand(CSFB:[0],purpose:[MobilityFromEUTRACommand_r8_IEs_purpose_handover_selected],targetRAT:[Handover_targetRAT_Type_geran])        
SYS    4550218    2000803    16:57:13:765    NIL    [IMSP_AT_I s21]AT+ESRVCCTFR=1,1,0,0,3,0,2,"13903022925",,        
SYS    4550239    2000803    16:57:13:765    NIL    [IMSP_AT_R s21]+ESRVCCTFR: 1, 1        
OTA    4552643    2000842    16:57:13:965    RRM    [MS->NW] RR__MEASUREMENT_REPORT        
OTA    4552688    2000845    16:57:13:965    CC    [NW->MS] CC__DISCONNECT        
SIP    143        16:57:17:039        [NW->MS]BYE sip:+8613903029925@[2409:8809:84F0:136D:CF50:041A:F6BE:D958]:50001 SIP/2.0        
SYS    4742879    2004164    16:57:30:570    NIL    [AT_I p20, s10]ATD13903022925;
        
OTA    5051207    2007543    16:57:47:570    ERRC_CONN    [NW->MS] ERRC_MobilityFromEUTRACommand(CSFB:[0],purpose:[MobilityFromEUTRACommand_r8_IEs_purpose_handover_selected],targetRAT:[Handover_targetRAT_Type_geran])        
OTA    5052151    2007569    16:57:47:570    RRM    [NW->MS] RR__PHYSICAL_INFORMATION        
OTA    5052155    2007569    16:57:47:570    RRM    [MS->NW] RR__HANDOVER_COMPLETE        
SYS    5053538    2007595    16:57:47:775    NIL    [IMSP_AT_I s21]AT+ESRVCCTFR=1,1,0,0,3,0,2,"13903022925",,        
SYS    5053559    2007595    16:57:47:775    NIL    [IMSP_AT_R s21]+ESRVCCTFR: 1, 1        
OTA    5056032    2007641    16:57:47:975    CC    [NW->MS] CC__DISCONNECT        
OTA    5056045    2007641    16:57:47:975    CC    [MS->NW] CC__RELEASE        

From: <sip:+8613903029925@gd.ims.mnc000.mcc460.3gppnetwork.org>;tag=qaeKX9Y5TSH813
To: <tel:13903022925;phone-context=ims.mnc000.mcc460.3gppnetwork.org>;tag=y2454z3k
CSeq: 44 INVITE
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,REFER,NOTIFY,MESSAGE,PRACK,OPTIONS
Contact: <sip:[2409:8019:8430:4500:0000:0000:0000:0008]:9900;Hpt=8fa2_16;CxtId=3;TRC=ffffffff-ffffffff>;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mmtel"
Require: precondition,100rel
User-Agent: VoLTE/WFC UA
RSeq: 1
P-Early-Media: gated
Feature-Caps: *;+g.3gpp.srvcc;+g.3gpp.mid-call;+g.3gpp.srvcc-alerting
Recv-Info: g.3gpp.state-and-event-info
Content-Length: 547
Content-Type: application/sdp

v=0

4、可以查看cs的连接状态

自动挂断是由于在手机发出[MS->NW] CC__CONNECT,网络还没有回应CC__CONNECT_ACKNOWLEDGE的情况下发生的,请问此问题的复现概率多大,请在同一地点同样的时刻做对比机测试,同时观察复现率
Type    Index    Time    Local Time    Module    Message    Comment    Time Different
OTA (PCORE)    221930    8071266    08:29:37:055    EMM_NASMSG    [NW->MS] EMM_CS_Service_Notification(paging identity="TMSI_PAGING_TYPE")        
OTA (PCORE)    225351    8082440    08:29:37:626    RRM_TDD    [MS->NW] RR__PAGING_RESPONSE        
OTA (PCORE)    228739    8118606    08:29:40:125    CC    [NW->MS] CC__SETUP        
OTA (PCORE)    228933    8118825    08:29:40:125    CC    [MS->NW] CC__CALL_CONFIRMED        
OTA (PCORE)    229300    8132778    08:29:41:032    CC    [MS->NW] CC__ALERTING        
OTA (PCORE)    230902    8261717    08:29:49:280    CC    [MS->NW] CC__CONNECT        
PS (PCORE)    232038    8349260    08:29:54:887    L1HISR - RRM_TDD    MSG_ID_LAPDM_RR_ERROR_IND
232038, 0, 8349260, 08:29:54:887 2017/01/22, MOD_L1HISR, MOD_RRM_TDD, L1HISR_GAS_SAP, MSG_ID_LAPDM_RR_ERROR_IND
...
            error_cause = ERROR_TIMER_EXPD_N200_ABNORMAL_REL (enum 2)
            channel_type = FACCH (enum 25)
...        
PS (PCORE)    232243    8350003    08:29:54:887    RATCM    [RATCM] cs_conn_state = RATCM_CS_IDLE, ps_conn_state = RATCM_PS_IDLE   

5.切换失败造成自动挂断

出现该问题的原因是UE切换失败造成的。


PS    547310    838713    15:32:09:725    MPAL_2 - RRM_2    MSG_ID_MPAL_RR_SERV_DEDI_MEAS_IND    rxqual_sub_avg = 0x05    
//网络要求UE进行切换
OTA    547379    838752    15:32:09:925    RRM_2    [NW->MS] RR__HANDOVER_COMMAND        
PS    547395    838764    15:32:10:125    RRM_2    [RMC] Target_arfcn = 656, F_O = 1169239, E_O = 7924        
PS    547449    838841    15:32:10:525    MPAL_2 - RRM_2    MSG_ID_MPAL_RR_HANDOVER_FAIL_IND        
PS    547460    838841    15:32:10:525    RRM_2 - LAPDM_2    MSG_ID_RR_LAPDM_RECON_REQ        
//切换失败,原因是T3124计时器超时,说明是网络没有回应造成的切换失败。
OTA    547461    838841    15:32:10:525    RRM_2    [MS->NW] RR__HANDOVER_FAILURE    Abnormal release, timer expired (3)    
//重新连接old channel,但old channel也没有回应,于是出现了N200 error,RR连接断开。
PS    547557    838998    15:32:11:325    MPAL_2 - RRM_2    MSG_ID_MPAL_RR_SERV_DEDI_MEAS_IND    rxqual_sub_avg = 0x07    
PS    547587    839036    15:32:11:525    LISR2HISR_CTIRQ1 - RRM_2    MSG_ID_LAPDM_RR_REL_IND    N200 error    

6、RLF发生后MS端发起重连的实例

第二组:
//同样是信号质量差,但第二组是由于RLF造成的通话中断。根据协议,RLF发生后会尝试进行call reestablishment,故耗费了几秒钟去找合适的小区重建call。
此题中未找到合适的小区,故上报ecpi 较晚。
Type    Index    Time    Local Time    Module    Message    Comment    Time Different
OTA    853907    376621    14:15:01:760    RRM    [MS->NW] RR__MEASUREMENT_REPORT        
//信号质量差导致Radio Link Failure错误
PS    853957    376629    14:15:01:760    LISR2HISR_CTIRQ1 - RRM    MSG_ID_LAPDM_RR_ERROR_IND        
//channel断开
PS    853973    376629    14:15:01:760    RRM - MPAL    MSG_ID_RR_MPAL_DEDICATED_CHANNEL_DISCONNECT_REQ        
PS    854034    376638    14:15:01:760    MPAL - RRM    MSG_ID_MPAL_RR_DEDICATED_CHANNEL_DISCONNECT_CNF        
PS    854042    376638    14:15:01:760    RRM - RATCM    MSG_ID_RATCM_GAS_CONN_LOSS_IND        
PS    854079    376638    14:15:01:760    RRM    [RMC] Radio Link Trigger reselection!        
PS    854161    376638    14:15:01:760    RATCM - MM    MSG_ID_MM_RATCM_CONN_LOSS_IND        
PS    854163    376638    14:15:01:760    MM    CM rej because RADIO LINK FAILURE        
//尝试重建call
PS    854165    376638    14:15:01:760    MM    MM new State: MM_WAIT_FOR_REESTABLISH        
PS    854180    376639    14:15:01:760    CC    ENTER RE-ESTABLISHMENT MODE        
OTA    854635    376696    14:15:01:960    RRM    [NW->MS] RR__SI_2 (ARFCN[123], TC[1])        
OTA    855148    376782    14:15:02:560    RRM    [NW->MS] RR__SI_2 (ARFCN[648], TC[1])        
OTA    855763    376884    14:15:02:960    RRM    [NW->MS] RR__SI_2TER (ARFCN[120], TC[5])        
OTA    856755    377047    14:15:03:760    RRM    [NW->MS] RR__SI_4 (ARFCN[118], TC[7])        
OTA    857287    377141    14:15:04:360    RRM    [NW->MS] RR__SI_2 (ARFCN[118], TC[1])        
PS    860562    377377    14:15:05:560    RRM    [RMC] RMC do reselection, num_of_top_six[6]!        
//没有合适小区进行重建call,放弃重建,报告通话中断。
PS    860588    377377    14:15:05:560    MM    MM new State: MM_IDLE_NO_CELL_AVAILABLE        
PS    860603    377377    14:15:05:560    CC - CSM    MSG_ID_MNCC_REL_CNF        
PS    860655    377377    14:15:05:560    L4C - CSM    MSG_ID_L4CCSM_CC_ABORT_CALL_REQ    
//ECPI上报通话中断    
SYS    860714    377377    14:15:05:560    NIL    [IMSP_U]+ECPI: 1,133,,,,,"",,"",2165        
OTA    861247    377422    14:15:05:760    RRM    [NW->MS] RR__SI_4 (ARFCN[115], TC[7])        
OTA    861293    377516    14:15:06:245    RRM    [NW->MS] RR__SI_2 (ARFCN[115], TC[1])        
OTA    861570    377659    14:15:06:955    MM    [MS->NW] MM__LOCATION_UPDATING_REQUEST (LU type: MM_NORMAL_LU)     

7、涉及call状态机,AP和Modem的同步(协议24.008)

发出connect或收到connect消息,mt或mo进入active状态

发出disconnect要等收到网络的cc_release才进入idle状态

主叫的响铃与被叫是否建立起连接无关,比如被叫没信号的时候,主叫听到"您拨打的号码无法接通",主叫就是在响铃状态。
被叫能否建立起连接只会影响主叫能不能进入cc_connect状态。即最终接通电话的状态。

8、关于paging类型(确认协议)

Spec25.331中有详细定义,RRC_PAGING_TYPE1/RRC_PAGING_TYPE2都可以用来传输paging,网络会根据当前UE 的状态选择使用:
8.1.2.1章节中:
RRC_PAGING_TYPE1 is used to transmit paging information to selected UEs in idle mode, CELL_PCH or URA_PCH state
using the paging control channel (PCCH).
8.1.11.1章节中:
RRC_PAGING_TYPE2 is used to transmit dedicated paging information to one UE in connected mode in CELL_DCH ,
CELL_FACH or CELL_PCH (FDD and 1.28 Mcps TDD only) state.
即:
RRC_PAGING_TYPE1用于idle态,CELL_PCH or URA_PCH 态,PCCH
RRC_PAGING_TYPE2用于CELL_DCH, CELL_FACH or CELL_PCH,DCCH

PAGING有很多的类型,分为CS域和PS域两大类,CS域包括被叫通话,短信,彩信等,PS域主要就是数据业务相关的:

OTA    1546750    487939    14:53:13:455    ERRC_CEL    [NW->MS] PAGING, PagingRecordList[KAL_TRUE], SIB Modification[KAL_FALSE], ETWS[KAL_FALSE], CMAS[KAL_FALSE]
这次收到的CS域的通话被叫:        
PS    1546760    487939    14:53:13:455    ERRC_CEL    [PAGING] Rx Paging for UE with S-TMSI: mmec[10100100b], m-tmsi:[11101100b 10001100b 00111101b 00000101b]        
PS    1546761    487939    14:53:13:455    ERRC_CEL    [PAGING] ueid matched?[KAL_TRUE]: sim_status[ENASAS_SIM_VALID], ueid sel[PagingUE_Identity_s_TMSI_selected], stmsi_valid in SIM[KAL_TRUE]        
PS    1546762    487939    14:53:13:455    ERRC_CEL    [CEL_DI/LV] send PAGING_IND to EMM on [ENASAS_CN_DOMAIN_CS] with STMSI(mmec/mtmsi)[164/236,140,61,5]        
PS    1546786    487939    14:53:13:455    EMM_ERRCIF    [EMM ERRCIF] Receive CS STMSI paging    
CSFB成功到2G:    
OTA    1548216    487953    14:53:13:455    EMM_NASMSG    [MS->NW] EMM_Extended_Service_Request(service type="MT_CSFB", CSFB response="CSFB_ACCEPTED_BY_UE")        
OTA    1551824    488129    14:53:14:255    RRM    [MS->NW] RR__PAGING_RESPONSE
OTA    1556048    489224    14:53:19:855    RRM    [NW->MS] RR__SI_6 (ARFCN[76], TC[255])                
OTA    1557308    490474    14:53:26:055    RRM    [MS->NW] RR__MEASUREMENT_REPORT        
临时发生了ERROR_TIMER_EXPD_N200_ABNORMAL_REL的RR连接错误,导致无法继续,失败,与后面的LU无关,此一般为临时网络问题:
PS    1557338    490537    14:53:26:455    LISR2HISR_CTIRQ1 - RRM    MSG_ID_LAPDM_RR_ERROR_IND
...
            error_cause = ERROR_TIMER_EXPD_N200_ABNORMAL_REL (enum 2)
            channel_type = SDCCH (enum 23)
...
        
PS    1602843    493569    14:53:41:615    ERRC_MOB    [MRM] store scell: earfcn[37900] pci[87] rsrp[-433] rsrq[-50] cell_off[0] cell_state[0]        
PS    1602991    493571    14:53:41:615    ERRC_MOB    [MRM] store scell: earfcn[37900] pci[87] rsrp[-433] rsrq[-49] cell_off[0] cell_state[0]    
第二次,这是是一个PS域属于业务相关的paging:
OTA    1603090    493571    14:53:41:615    ERRC_CEL    [NW->MS] PAGING, PagingRecordList[KAL_TRUE], SIB Modification[KAL_FALSE], ETWS[KAL_FALSE], CMAS[KAL_FALSE]        
PS    1603102    493571    14:53:41:615    ERRC_CEL    [PAGING] Rx Paging for UE with S-TMSI: mmec[10100100b], m-tmsi:[11101100b 10001110b 00111101b 00000101b]        
PS    1603103    493571    14:53:41:615    ERRC_CEL    [PAGING] ueid matched?[KAL_TRUE]: sim_status[ENASAS_SIM_VALID], ueid sel[PagingUE_Identity_s_TMSI_selected], stmsi_valid in SIM[KAL_TRUE]        
PS    1603104    493571    14:53:41:615    ERRC_CEL    [CEL_DI/LV] send PAGING_IND to EMM on [ENASAS_CN_DOMAIN_PS] with STMSI(mmec/mtmsi)[164/236,142,61,5]        
PS    1603105    493571    14:53:41:615    ERRC - EMM    MSG_ID_EMM_ERRC_PAGE_IND
建立起主要是完成PS域相关的网络需要:        
OTA    1603727    493576    14:53:41:615    ERRC_CONN    [MS->NW] ERRC_RRCConnectionRequest        
PS    1609305    493633    14:53:41:815    ERRC_MOB    [MRM] store scell: earfcn[37900] pci[87] rsrp[-438] rsrq[-52] cell_off[0] cell_state[0]        
本此时刻应该网络由于CS域的被叫的paging下来,但是网络没有发下来,此时手机驻网信号良好,且有其他paging下来,所以判断此为网络问题:

对比机:
一次在副卡上被叫,且是GSM网络,与测试机不同,没有对比的意义:
OTA    1530330    488178    14:53:12:480    RRM_2    [NW->MS] RR__SI_2QUATER (ARFCN[628], TC[5])        
OTA    1530437    488334    14:53:13:420    RRM_2    [NW->MS] RR__PAGING_REQUEST_TYPE_1        
OTA    1530440    488334    14:53:13:420    RRM_2    [MS->NW] RR__PAGING_RESPONSE        
OTA    1531692    488606    14:53:14:620    CC_2    [NW->MS] CC__SETUP        
OTA    1531801    488607    14:53:14:620    CC_2    [MS->NW] CC__CALL_CONFIRMED        
OTA    1532169    488795    14:53:15:620    CC_2    [MS->NW] CC__ALERTING        
OTA    1535911    493198    14:53:37:620    CC_2    [MS->NW] CC__CONNECT        
OTA    1536051    493276    14:53:38:020    CC_2    [NW->MS] CC__CONNECT_ACKNOWLEDGE        
OTA    1719339    521945    14:56:01:420    CC_2    [NW->MS] CC__DISCONNECT        
OTA    1719355    521945    14:56:01:420    CC_2    [MS->NW] CC__RELEASE        
OTA    1719671    521985    14:56:01:620    CC_2    [NW->MS] CC__RELEASE_COMPLETE    

9、测试机未收到paging

判断paging是否是自己的看ueid匹配

从log看被叫没收到寻呼是网络临时原因导致,且持续了两分钟左右,在16:43:45之后可以恢复。
这种网络问题表现为:当被叫与网络没同步上,网络端会在不通知手机的情况下分离手机的信息,导致网络不会给被叫发寻呼,而手机也不会知道自己被分离。直到手机重新同步到网络才能恢复。

此Log中被叫测试机行为符合这种情况,16:40:45到16:43:41之间手机正常执行收监听寻呼,测量邻区等操作。但就是收不到自己的寻呼。
而在16:43被叫测试机主动拨出电话,触发了重新同步到网络的动作,所以在此之后网络会认为手机注册正常,会为手机发送寻呼。

1. 被叫测试机一直在正常监听寻呼信道,并且能收到信道上的寻呼数据,只是没有收到发给自己的寻呼。如下:
1678231, 2446027, 5262103, 16:40:40:835 2017/03/02, MOD_EMAC, MOD_ERRC, ERRC_EMAC_SAP, MSG_ID_ERRC_EMAC_PAGING_IND //收到paging, 检查UEID后发现不是发给自己的paging
1678287, 2446027, 5262103, 16:40:40:835 2017/03/02, MOD_ERRC_CEL, , TRACE_GROUP_2, [PAGING] ueid matched?[KAL_FALSE]: sim_status[ENASAS_SIM_VALID], ueid sel[PagingUE_Identity_s_TMSI_selected],
1696178, 2451403, 5267479, 16:41:07:595 2017/03/02, MOD_EMAC, MOD_ERRC, ERRC_EMAC_SAP, MSG_ID_ERRC_EMAC_PAGING_IND //之后的两分钟也是这样
1722064, 2459339, 5275415, 16:41:47:395 2017/03/02, MOD_EMAC, MOD_ERRC, ERRC_EMAC_SAP, MSG_ID_ERRC_EMAC_PAGING_IND
1753709, 2470454, 5284887, 16:42:34:755 2017/03/02, MOD_EMAC, MOD_ERRC, ERRC_EMAC_SAP, MSG_ID_ERRC_EMAC_PAGING_IND
1794245, 2483254, 5296919, 16:43:34:915 2017/03/02, MOD_EMAC, MOD_ERRC, ERRC_EMAC_SAP, MSG_ID_ERRC_EMAC_PAGING_IND

2. 16:43:41测试机主动拨出电话,触发RA过程,手机会重新同步到网络。
1800054, 2485195, 5298179, 16:43:41:200 2017/03/02, MOD_ERRC_CONN, , TRACE_PEER, [MS->NW] ERRC_RRCConnectionRequest
1800586, 2485205, 5298188, 16:43:41:200 2017/03/02, MOD_ERRC_CONN, , TRACE_PEER, [NW->MS] ERRC_RRCConnectionSetup
1801119, 2485206, 5298189, 16:43:41:200 2017/03/02, MOD_EMM_NASMSG, , TRACE_PEER, [MS->NW] EMM_Extended_Service_Request(service type="MO_CSFB", CSFB response="CSFB_UNUSED")
1801141, 2485206, 5298189, 16:43:41:200 2017/03/02, MOD_ERRC_CONN, , TRACE_PEER, [MS->NW] ERRC_RRCConnectionSetupComplete
3. 之后手机可收到自己的paging,如下在16:44:00收到ps域的paging:
1854434, 1320223, 5302039, 16:44:00:330 2017/03/02, MOD_ERRC_CEL, , TRACE_PEER, [NW->MS] PAGING, PagingRecordList[KAL_TRUE], SIB Modification[KAL_FALSE], ETWS[KAL_FALSE], CMAS[KAL_FALSE]

我看对比机这个时间点好像也驻留了[37900/87]这个小区啊,具体驻留哪个小区怎么看?

可以搜索cell camp on as serving这条消息作为时间点参考,16:40:47对比机重选到了[37900/386],在这个小区收到的paging。如下:

//对比机本来在[37900/87]
1278684, 572987, 1534646, 16:40:47:550 2017/03/02, MOD_ERRC_MOB, , TRACE_GROUP_1, [MRM] Serv cell: earfcn[37900] pci[87] srxlev[101], squal[16], hps[0]
1278687, 572987, 1534646, 16:40:47:550 2017/03/02, MOD_ERRC_MOB, , TRACE_GROUP_1, [CJDG] SERV[37900/87] Srxlev[101] Squal[16] R[-367] qdb

//[37900/386]信号稍好了些,满足重选标准,选到了[37900/386]
1278692, 572987, 1534646, 16:40:47:550 2017/03/02, MOD_ERRC_MOB, , TRACE_GROUP_1, [CJDG] LCell[37900/386] Srx[124] Squ[36] R[-364] RESEL[P, State[ERRC_MOB_CJDG_CELL_STATUS_CND] Tresel_cnt[1235] S_Prio[R higher]]

所以对比机是在 [37900/386] 收到的paging:
1279156, 573022, 1534662, 16:40:47:550 2017/03/02, MOD_ERRC_SYS, , TRACE_PEER, [NW->MS] SystemInformationBlockType1 (EARFCN[37900], PCI[386])
1279361, 573022, 1534662, 16:40:47:550 2017/03/02, MOD_ERRC_CEL, , TRACE_GROUP_1, [CEL_DI/LV] cell camp on as serving: earfcn[37900]/pci[386], is_csg_cell[KAL_FALSE]
1283101, 573515, 1535151, 16:40:49:980 2017/03/02, MOD_ERRC_CEL, , TRACE_PEER, [NW->MS] PAGING, PagingRecordList[KAL_TRUE], SIB Modification[KAL_FALSE], ETWS[KAL_FALSE], CMAS[KAL_FALSE]

10、SAT命令失败导致打不出电话

SAT命令没被正常 fetch 导致的 拨号前modem下 call control 给卡时,卡返回 busy,最终导致无法打不出电话。
而fetch SAT命令涉及到开机部分。目前 log 不完善,无法定位问题。
请贵司抓取从开机到发生问题的完整 mtklog(必须包含开机部分)。

贵司要的分析log 和原因敝司都更新在下面了,贵司可以慢慢看。

//ATD因call control 下给卡时,卡返回 sat busy 而中止了:
SYS (PCORE)    85982    346462800    14:11:32:830    NIL    [AT_I p21, s10]ATD120;
        
PS (PCORE)    86240    346462817    14:11:32:830    ATCI    command: ATD120;

PS (PCORE)    86280    346462834    14:11:32:830    CSM - SIM    MSG_ID_SAT_CALL_CTRL_BY_SIM_REQ        
PS (PCORE)    86282    346462834    14:11:32:830    SIM    sim_al_envelope()        
PS (PCORE)    86283    346462834    14:11:32:830    SIM    SIM_ENVELOPE : length: 28        
PS (PCORE)    86284    346462834    14:11:32:830    SIM    APDU_tx 0: 80 C2 00 00 16 D4 14 82 02 82 81 86 03 81 21 F0        
PS (PCORE)    86285    346462834    14:11:32:830    SIM    APDU_tx 1: 13 09 64 F0 10 25 61 62 D3 60 2F 00 F2 F2 F2 F2        
PS (PCORE)    86431    346463127    14:11:32:830    SIM    SIM: SIM_SAT_CMD_BUSY        
PS (PCORE)    86432    346463127    14:11:32:830    SIM    ENVELOPE: send 22 bytes recv 0 bytes => 93 00                

PS (PCORE)    86435    346463127    14:11:32:830    CSM - L4C    MSG_ID_L4CCSM_CC_CALL_SETUP_CNF        
PS (PCORE)    86443    346463127    14:11:32:830    CSM - L4C    MSG_ID_L4CCSM_CC_CALL_INFO_IND        
PS (PCORE)    86449    346463127    14:11:32:830    L4C - CSM    MSG_ID_L4CCSM_CC_ABORT_CALL_REQ        
PS (PCORE)    86478    346463127    14:11:32:830    CSM - CC    MSG_ID_MNCC_ABORT_CALL_REQ

86433, 0, 346463127, 14:11:32:830 2017/02/27, MOD_SIM, MOD_CSM, PS_SIM_SAP, MSG_ID_SAT_CALL_CTRL_BY_SIM_CNF
    Local_Parameter --> Len = 84, Addr = 0xA577FC5C
        sat_call_ctrl_by_sim_cnf_struct = (struct)
            ref_count = 0x01
            lp_reserved = 0x30
            msg_len = 0x0054
            res = 0x03 //SAT_SIM_ERROR
            type = 0x06
            size_of_ccp1 = 0x00
            ccp1 = Array[15]
            .........

86435, 0, 346463127, 14:11:32:830 2017/02/27, MOD_CSM, MOD_L4C, CSM_L4C_SAP, MSG_ID_L4CCSM_CC_CALL_SETUP_CNF
    Local_Parameter --> Len = 20, Addr = 0xA576FAB4
        l4ccsm_cc_call_setup_cnf_struct = (struct)
            ref_count = 0x01
            lp_reserved = 0x00
            msg_len = 0x0014
            src_id = 0x17
            call_id_present = 0x00
            call_id = 0x00
            response = 0x01
            cause_present = 0x01
            cause = 0x030b //779, CSMCC_SAT_CALL_CTRL_REJECTED,如果cnf中包含这个 cause,modem就会终止拨号流程。
            call_type = 0x00
            ..........



2. 这个是要看fetch SAT命令初始化是否异常吗?具体在哪里初始化?
=>[MTK reply]
这是 modem 部分的,不是 fetch SAT命令的初始化。
fetch SAT命令不存在初始化的动作,只是个命令。
从现有modem log 中 check 到 modem 在这之前就没能正常 fetch SAT命令。而影响是否 fetch 的因素跟开机时候的modem 的一些 message 和变量有关。

11、移动3G的自动挂断问题

移动3G的信令消息

两次没接通的原因一样,都是在3G建立好RRC连接后网络发来了SIGNALLING_CONNECTION_RELEASE,释放了cs域连接,导致通话中断,且两次发生问题的3G小区相同。其他时间点在这个3G小区和其他3G小区没有发生此问题。这是网络原因导致,网络要主动发来消息断掉了电话。

第一通:
1249865, 266206, 243979, 09:53:07:975 2017/03/10, MOD_MM, , TRACE_PEER, [MS->NW] MM__PAGING_RESPONSE
1252847, 266219, 243992, 09:53:07:975 2017/03/10, MOD_ADR, , TRACE_PEER, [MS->NW] RRC__RRC_CONNECTION_REQUEST
1253103, 266266, 244032, 09:53:08:180 2017/03/10, MOD_ADR, , TRACE_PEER, [NW->MS] RRC__RRC_CONNECTION_SETUP
1253345, 266285, 244051, 09:53:08:180 2017/03/10, MOD_ADR, , TRACE_PEER, [MS->NW] RRC__RRC_CONNECTION_SETUP_COMPLETE % RRC连接建立成功
1254775, 266379, 244145, 09:53:08:785 2017/03/10, MOD_ADR, , TRACE_PEER, [NW->MS] RRC__SIGNALLING_CONNECTION_RELEASE % 网络发来信令释放消息,释放了CS域,CS服务中断
cn-DomainIdentity = cs-domain
第二通,原因相同:
314040, 312902, 287085, 09:56:43:530 2017/03/10, MOD_SIBE, , TRACE_PEER, [NW->MS] RRC_SI_SIB12 (UARFCN:[10713], PSC:[65])
317850, 312991, 287166, 09:56:43:930 2017/03/10, MOD_ADR, , TRACE_PEER, [MS->NW] RRC__RRC_CONNECTION_SETUP_COMPLETE
319189, 313083, 287258, 09:56:44:530 2017/03/10, MOD_ADR, , TRACE_PEER, [NW->MS] RRC__SIGNALLING_CONNECTION_RELEASE
cn-DomainIdentity = cs-domain

12、收到paging但是解码失败

对比机当时信号太差,一直解码寻呼消息失败。如下:
PS    582791    293339    09:57:06:240    ERRC_MOB    [MRM] store scell: earfcn[1650] pci[235] rsrp[-466] rsrq[-77] cell_off[0] cell_state[32]         % 信号质量-77太差
PS    583293    293594    09:57:07:520    EL1 - ERRC    MSG_ID_ERRC_EL1_PCH_CRCNG_IND        % decode paging一直失败,持续到 9:57:20
PS    583794    293850    09:57:08:620    EL1 - ERRC    MSG_ID_ERRC_EL1_PCH_CRCNG_IND        
PS    585382    294874    09:57:13:930    EL1 - ERRC    MSG_ID_ERRC_EL1_PCH_CRCNG_IND        
PS    587491    295641    09:57:17:755    EL1 - ERRC    MSG_ID_ERRC_EL1_PCH_CRCNG_IND        
PS    588489    296154    09:57:20:160    EL1 - ERRC    MSG_ID_ERRC_EL1_PCH_CRCNG_IND

如我上一条note所说,对比机是因为信号太差,连续多次解码PCH失败没能解出自己的paging。

1. 被叫对比机的TAU在9:57:01就完成了,而主叫在9:57:05才打出的电话,被叫对比机应该在9:57:08左右收到paging。所以应该不是TAU导致的。
569261, 322624, 292266, 09:57:00:880 2017/03/10, MOD_EMM_NASMSG, , TRACE_PEER, [MS->NW] EMM_Tracking_Area_Update_Request(EPS update type="EMM_UPDATE_TYPE_COMBINED_TAU", active flag="KAL_FALSE")
575648, 322748, 292380, 09:57:01:280 2017/03/10, MOD_EMM_NASMSG, , TRACE_PEER, [NW->MS] EMM_Tracking_Area_Update_Accept(EPS update result="EMM_UPDATE_RESULT_COMBINED_UPDATED")
575810, 322748, 292380, 09:57:01:280 2017/03/10, MOD_EMM_NASMSG, , TRACE_PEER, [MS->NW] EMM_Tracking_Area_Update_Complete

2. 当时对比机信号很差,在寻呼信道PCH上收到的paging都解码失败。即使网络正确下发了paging手机解码不出来也无法建成电话。
583293, 324061, 293594, 09:57:07:520 2017/03/10, MOD_EL1, MOD_ERRC, ERRC_EL1_SAP, MSG_ID_ERRC_EL1_PCH_CRCNG_IND %CRC NG: CRC校验not good,
result = EL1_RESULT_CRC_NG
583794, 324338, 293850, 09:57:08:620 2017/03/10, MOD_EL1, MOD_ERRC, ERRC_EL1_SAP, MSG_ID_ERRC_EL1_PCH_CRCNG_IND
585382, 325423, 294874, 09:57:13:930 2017/03/10, MOD_EL1, MOD_ERRC, ERRC_EL1_SAP, MSG_ID_ERRC_EL1_PCH_CRCNG_IND
587491, 326281, 295641, 09:57:17:755 2017/03/10, MOD_EL1, MOD_ERRC, ERRC_EL1_SAP, MSG_ID_ERRC_EL1_PCH_CRCNG_IND

13、MM层或AT命令查看是否注册上小区

GMM, MM 是2G 3G共用的,4G只看EMM即可。

GMM主要是23G的PS相关服务,比如路由区更新RAU,
MM主要负责23G的CS服务,比如打电话,位置更新LU。

当时对比机在4G,可以搜索EMM state。比如在9:57:01:280,EMM注册状态已经是EMMREG_STATE_TAU_COMPLETED。
575752, 322748, 292380, 09:57:01:280 2017/03/10, MOD_EMM, , TRACE_STATE, [EMM STATE] EMM_REG state from EMMREG_STATE_TAU_REQUESTED to EMMREG_STATE_TAU_COMPLETED

如果想看是否有注册上网,直接看AT命令会更准确。CREG是手机上报的注册状态,其中倒数第三个参数表示已经注册上的小区
567586, 322615, 292258, 09:57:00:680 2017/03/10, MOD_NIL, , TRACE_INFO, [AT_R p19, s9]+CREG: 3,1,"A561","01E2460B",2,0,0 %倒数第三个参数是2:3G
576344, 322751, 292383, 09:57:01:280 2017/03/10, MOD_NIL, , TRACE_INFO, [AT_U p18, s8]+CREG: 1,"2561","06C1D803",7,0,0 %倒数第三个参数是7:4G
578050, 322759, 292390, 09:57:01:480 2017/03/10, MOD_NIL, , TRACE_INFO, [AT_R p19, s9]+CREG: 3,1,"2561","06C1D803",7,0,0 %"2561"是LAC , "06C1D803"是小区id
579332, 322765, 292396, 09:57:01:480 2017/03/10, MOD_NIL, , TRACE_INFO, [AT_R p19, s9]+CREG: 3,1,"2561","06C1D803",7,0,0
580275, 322769, 292400, 09:57:01:480 2017/03/10, MOD_NIL, , TRACE_INFO, [AT_R p19, s9]+CREG: 3,1,"2561","06C1D803",7,0,0
倒数第三个参数取值如下:
0     GSM
2    UTRAN
3    GSM w/EGPRS
4    UTRAN w/HSDPA
5    UTRAN w/HSUPA
6    UTRAN w/HSDPA and HSUPA
7     E-UTRAN

14、查看终端接收paging的状态是否正常

2,F5 4#不通时间点: 15:39-15:45(10次连续来电提醒)
观察此时间区间内,手机驻留在4G小区earfcn[37900] pci[341],信号良好,且PCCH decode result from HW: [EL1_CH_PCH_RESULT_SUCCESS],像是网络没有下发paging给被叫导致连续10没有来电:
Type    Index    Time    Local Time    Module    Message    Comment    Time Different
OTA (PCORE)    1149624    387634034    15:39:46:004    ERRC_SYS    [NW->MS] MasterInformationBlock (EARFCN[37900], PCI[341])        
OTA (PCORE)    1149676    387634105    15:39:46:004    ERRC_SYS    [NW->MS] SystemInformationBlockType1 (EARFCN[37900], PCI[341])        
PS (L1CORE)    832284    387653268    15:39:46:701    LCEL    [LCEL][PAGING] PCCH decode result from HW: [EL1_CH_PCH_RESULT_SUCCESS]        
PS (L1CORE)    833333    387673251    15:39:47:981    LMOB    [MRM] store PCell: earfcn[37900] pci[341] rsrp[-467] rsrq[-54] sinr[-5] snr[-4] cell_off[0]        
PS (L1CORE)    835505    387733267    15:39:51:821    LCEL    [LCEL][PAGING] PCCH decode result from HW: [EL1_CH_PCH_RESULT_SUCCESS]        
PS (L1CORE)    836058    387753250    15:39:53:101    LMOB    [MRM] store PCell: earfcn[37900] pci[341] rsrp[-468] rsrq[-53] sinr[-11] snr[0] cell_off[0]        
PS (L1CORE)    840336    387873250    15:40:00:782    LMOB    [MRM] store PCell: earfcn[37900] pci[341] rsrp[-462] rsrq[-50] sinr[-7] snr[4] cell_off[0]        
PS (L1CORE)    840483    387873268    15:40:00:782    LCEL    [LCEL][PAGING] PCCH decode result from HW: [EL1_CH_PCH_RESULT_SUCCESS]        
PS (L1CORE)    852599    388233250    15:40:23:822    LMOB    [MRM] store PCell: earfcn[37900] pci[341] rsrp[-460] rsrq[-49] sinr[-6] snr[6] cell_off[0]        
PS (L1CORE)    852713    388233266    15:40:23:822    LCEL    [LCEL][PAGING] PCCH decode result from HW: [EL1_CH_PCH_RESULT_SUCCESS]        
PS (L1CORE)    877279    388933251    15:41:08:622    LMOB    [MRM] store PCell: earfcn[37900] pci[341] rsrp[-466] rsrq[-51] sinr[-2] snr[2] cell_off[0]        
PS (L1CORE)    877437    388933274    15:41:08:622    LCEL    [LCEL][PAGING] PCCH decode result from HW: [EL1_CH_PCH_RESULT_SUCCESS]        
PS (L1CORE)    914816    389993251    15:42:16:462    LMOB    [MRM] store PCell: earfcn[37900] pci[341] rsrp[-464] rsrq[-52] sinr[-5] snr[1] cell_off[0]        
PS (L1CORE)    914978    389993274    15:42:16:462    LCEL    [LCEL][PAGING] PCCH decode result from HW: [EL1_CH_PCH_RESULT_SUCCESS]        
PS (L1CORE)    934479    390513251    15:42:49:742    LMOB    [MRM] store PCell: earfcn[37900] pci[341] rsrp[-463] rsrq[-50] sinr[1] snr[3] cell_off[0]        
PS (L1CORE)    934599    390513268    15:42:49:742    LCEL    [LCEL][PAGING] PCCH decode result from HW: [EL1_CH_PCH_RESULT_SUCCESS]        
PS (L1CORE)    947185    390853252    15:43:11:502    LMOB    [MRM] store PCell: earfcn[37900] pci[341] rsrp[-460] rsrq[-47] sinr[2] snr[8] cell_off[0]        
PS (L1CORE)    947305    390853269    15:43:11:502    LCEL    [LCEL][PAGING] PCCH decode result from HW: [EL1_CH_PCH_RESULT_SUCCESS]        
PS (L1CORE)    957854    391133251    15:43:29:422    LMOB    [MRM] store PCell: earfcn[37900] pci[341] rsrp[-461] rsrq[-51] sinr[-3] snr[7] cell_off[0]        
PS (L1CORE)    958003    391133272    15:43:29:422    LCEL    [LCEL][PAGING] PCCH decode result from HW: [EL1_CH_PCH_RESULT_SUCCESS]        
PS (L1CORE)    977571    391653252    15:44:02:702    LMOB    [MRM] store PCell: earfcn[37900] pci[341] rsrp[-457] rsrq[-45] sinr[8] snr[13] cell_off[0]        
PS (L1CORE)    977693    391653269    15:44:02:702    LCEL    [LCEL][PAGING] PCCH decode result from HW: [EL1_CH_PCH_RESULT_SUCCESS]        
PS (L1CORE)    989907    391973251    15:44:23:182    LMOB    [MRM] store PCell: earfcn[37900] pci[341] rsrp[-463] rsrq[-49] sinr[1] snr[5] cell_off[0]        
PS (L1CORE)    990052    391973272    15:44:23:182    LCEL    [LCEL][PAGING] PCCH decode result from HW: [EL1_CH_PCH_RESULT_SUCCESS]        
PS (L1CORE)    1013473    392633252    15:45:05:422    LMOB    [MRM] store PCell: earfcn[37900] pci[341] rsrp[-464] rsrq[-51] sinr[1] snr[6] cell_off[0]        
PS (L1CORE)    1013593    392633268    15:45:05:422    LCEL    [LCEL][PAGING] PCCH decode result from HW: [EL1_CH_PCH_RESULT_SUCCESS]        
对比信号不好不能正确解码的实例:

这里是正好在服务4G小区的的信号不好,导致的PCCH decode result from HW: [EL1_CH_PCH_RESULT_PDSCH_CRCNG]底层不能正确解码,为弱信号问题:
PS (L1CORE)    187344    1374794020    15:23:03:102    LMOB    [MRM] store PCell: earfcn[38400] pci[336] rsrp[-396] rsrq[-41] sinr[3] snr[3] cell_off[0]        
PS (L1CORE)    187865    1374814034    15:23:04:384    LCEL    [LCEL][PAGING] PCCH decode result from HW: [EL1_CH_PCH_RESULT_SUCCESS]        
PS (L1CORE)    188796    1374834046    15:23:05:663    LCEL    [LCEL][PAGING] PCCH decode result from HW: [EL1_CH_PCH_RESULT_PDSCH_CRCNG]        
PS (L1CORE)    189645    1374854030    15:23:06:943    LMOB    [MRM] store PCell: earfcn[37900] pci[66] rsrp[-471] rsrq[-60] sinr[-5] snr[-5] cell_off[0]        
PS (L1CORE)    189744    1374854046    15:23:06:943    LCEL    [LCEL][PAGING] PCCH decode result from HW: [EL1_CH_PCH_RESULT_PDSCH_CRCNG]        
PS (L1CORE)    190324    1374874014    15:23:08:223    LCEL    [LCEL][PAGING] PCCH decode result from HW: [EL1_CH_PCH_RESULT_NO_PDCCH]        
PS (L1CORE)    191199    1374894050    15:23:09:503    LCEL    [LCEL][PAGING] PCCH decode result from HW: [EL1_CH_PCH_RESULT_PDSCH_CRCNG]        
PS (L1CORE)    191903    1374914047    15:23:10:783    LCEL    [LCEL][PAGING] PCCH decode result from HW: [EL1_CH_PCH_RESULT_SUCCESS]        
PS (L1CORE)    192464    1374934030    15:23:12:063    LMOB    [MRM] store PCell: earfcn[37900] pci[66] rsrp[-472] rsrq[-61] sinr[-14] snr[-14] cell_off[0]        
PS (L1CORE)    192581    1374934047    15:23:12:063    LCEL    [LCEL][PAGING] PCCH decode result from HW: [EL1_CH_PCH_RESULT_PDSCH_CRCNG]        
PS (L1CORE)    199869    1375134032    15:23:24:863    LMOB    [MRM] store PCell: earfcn[37900] pci[66] rsrp[-487] rsrq[-73] sinr[-27] snr[-27] cell_off[0]

15、CSFB以后建立RR连接失败,RR_DATA中出现大量bad_block

被叫收到paging后CSFB 到 2G ARFCN[64]小区后    
OTA (PCORE)    564948    1378894057    15:27:25:514    ERRC_CEL    [NW->MS] PAGING, PagingRecordList[KAL_TRUE], SIB Modification[KAL_FALSE], ETWS[KAL_FALSE], CMAS[KAL_FALSE], EAB[KAL_FALSE]        
OTA (PCORE)    566164    1378895065    15:27:25:514    EMM_NASMSG    [MS->NW] EMM_Extended_Service_Request(service type="MT_CSFB", CSFB response="CSFB_ACCEPTED_BY_UE")        
OTA (PCORE)    567838    1378898163    15:27:25:714    ERRC_CONN    [NW->MS] ERRC_RRCConnectionRelease(cause:[ReleaseCause_other], redirectInfo:[1])        
PS (PCORE)    569364    1378907846    15:27:26:398    RRM_TDD    [RCS] There are [21] ARFCNs to try        
PS (PCORE)    569365    1378907846    15:27:26:398    RRM_TDD    [RCS] Sorted power scan list: Index:0 ARFCN:61 POWER:-352        
PS (PCORE)    569366    1378907846    15:27:26:398    RRM_TDD    [RCS] Sorted power scan list: Index:1 ARFCN:77 POWER:-354        
PS (PCORE)    569367    1378907846    15:27:26:398    RRM_TDD    [RCS] Sorted power scan list: Index:2 ARFCN:64 POWER:-356        
PS (L1CORE)    306715    1378928421    15:27:27:619    L1 - GISE_TDD    MSG_ID_MPHC_BLOCK_QUALITY_IND        
OTA (PCORE)    569750    1378927875    15:27:27:620    RRM_TDD    [NW->MS] RR__SI_1 (ARFCN[64], TC[255])        
OTA (PCORE)    569791    1378927878    15:27:27:620    RRM_TDD    [NW->MS] RR__SI_3 (ARFCN[64], TC[255])
由于信号质量不佳RR_BAD_BLOCK,导致无法建立起RR channel,可能为临时网络干扰导致的:    
OTA (PCORE)    570315    1378927941    15:27:27:620    RRM_TDD    [MS->NW] RR__PAGING_RESPONSE        
OTA (PCORE)    572896    1378928785    15:27:27:620    RRM_TDD    [MS->NW] RR__CHANNEL_REQUEST    block_ind = RR_BAD_BLOCK (enum 1)    
OTA (PCORE)    574209    1378933543    15:27:28:029    RRM_TDD    [MS->NW] RR__CHANNEL_REQUEST        
OTA (PCORE)    574312    1378937665    15:27:28:232    RRM_TDD    [MS->NW] RR__CHANNEL_REQUEST        
OTA (PCORE)    574406    1378943581    15:27:28:657    RRM_TDD    [MS->NW] RR__CHANNEL_REQUEST        
PS (PCORE)    574412    1378943866    15:27:28:657    MPAL_TDD - RRM_TDD    MSG_ID_MPAL_RR_DATA_IND    block_ind = RR_BAD_BLOCK (enum 1)   

16、关于2G立即指配程序失败发生重连的实例(关于网络系统消息的确认)

更新:
OTA (PCORE)    2204618    41698342    14:45:07:289    RRM_TDD_2    [NW->MS] RR__SI_5 (ARFCN[656], TC[255])        
OTA (PCORE)    2204767    41703189    14:45:07:689    RRM_TDD_2    [MS->NW] RR__MEASUREMENT_REPORT        
OTA (PCORE)    2204799    41703397    14:45:07:689    RRM_TDD_2    [NW->MS] RR__ASSIGNMENT_COMMAND        
OTA (PCORE)    2204847    41704331    14:45:07:689    RRM_TDD_2    [MS->NW] RR__ASSIGNMENT_COMPLETE
重新指配完成后,发生ERROR_TIMER_EXPD_N200_ABNORMAL_REL的底层失败,        
PS (PCORE)    2205367    41719561    14:45:08:709    L1HISR - RRM_TDD_2    MSG_ID_LAPDM_RR_REL_IND    
...
            error_cause = ERROR_TIMER_EXPD_N200_ABNORMAL_REL (enum 2)
            channel_type = FACCH (enum 25)
...            
重新在2G ARFCN[656]小区建立起连接:
PS (PCORE)    2205371    41719563    14:45:08:709    RRM_TDD_2 - MPAL_TDD_2    MSG_ID_RR_MPAL_DEDICATED_CHANNEL_RECONNECT_REQ        
PS (PCORE)    2205394    41719779    14:45:08:709    MPAL_TDD_2 - RRM_TDD_2    MSG_ID_MPAL_RR_DEDICATED_CHANNEL_RECONNECT_CNF
并且给网络报告说底层发生了一次错误,    
OTA (PCORE)    2205398    41719780    14:45:08:709    RRM_TDD_2    [MS->NW] RR__ASSIGNMENT_FAILURE
...
RR Cause
RR cause value: Protocol error unspecified (111)
...
PS (PCORE)    2205399    41719780    14:45:08:709    RRM_TDD_2    RRM_SUBSTATE = RRM_DEDICATED_RECON_L2_SUBSTATE    
            
PS (PCORE)    2205795    41732610    14:45:09:528    MPAL_TDD_2 - RRM_TDD_2    MSG_ID_MPAL_RR_SERV_DEDI_MEAS_IND        
OTA (PCORE)    2206372    41749843    14:45:10:528    RRM_TDD_2    [NW->MS] RR__SI_5TER (ARFCN[656], TC[255])    
所以此问题的还是后面CC DISCONNECT,casue No circuit/channel available,与前面的RR__ASSIGNMENT_FAILURE没有关系,RR__ASSIGNMENT_FAILURE只是发生了底层错误恢复连接后给网络报告Protocol error unspecified (111)情况,后面又正常恢复在ARFCN[656]小区:
CC DISCONNECT,casue No circuit/channel available一般为网络资源调配的问题,判断为网络原因    
OTA (PCORE)    2206533    41754893    14:45:10:944    CC_2    [NW->MS] CC__DISCONNECT    
...
Cause - (34) No circuit/channel available
...        

17、随机接入失败案例

哪里标志着随机接入失败?
OTA 2315394 820798 11:14:53:195 RRM_2 [NW->MS] RR__PAGING_REQUEST_TYPE_1
OTA 2315397 820798 11:14:53:195 RRM_2 [MS->NW] RR__PAGING_RESPONSE
OTA 2315793 820799 11:14:53:195 RRM_2 [MS->NW] RR__CHANNEL_REQUEST
OTA 2316903 821465 11:14:56:595 RRM_2 [MS->NW] RR__CHANNEL_REQUEST
PS 2317687 822080 11:14:59:595 RRM_2 [RMC] T3126 timeout in RRM_ACCESS_STATE state.

A:T3126是UE侧随机接入的计时器,如果超时,就代表随机接入失败。

关于11:06和11:14这两通通话,我这边只能分析到都是RR__CHANNEL_REQUEST 后没有得到网络端的RR__IMMEDIATE_ASSIGNMENT ,
那如何去确认两个原因不同呢?或是这种情况如何搜索关键字呢?

A: 11:06是有得到网络端的RR__IMMEDIATE_ASSIGNMENT,可能是您没注意到。这种情况可以看MSG_ID_LAPDM_RR_REL_IND,看error_cause的原因,一般要么是N200要么是RLF。
Type    Index    Time    Local Time    Module    Message    Comment    Time Different
OTA    1881851    724814    11:06:53:335    RRM_2    [NW->MS] RR__PAGING_REQUEST_TYPE_2        
OTA    1881854    724814    11:06:53:335    RRM_2    [MS->NW] RR__PAGING_RESPONSE        
OTA    1882558    724874    11:06:53:535    RRM_2    [NW->MS] RR__IMMEDIATE_ASSIGNMENT       


11:14这通通话因为没有得到网络端的RR__IMMEDIATE_ASSIGNMENT,还没成功建立起RR连接,所以就不能看MSG_ID_LAPDM_RR_REL_IND这个消息。要看为何没有成功建立起连接,一般情况都是由于T3126超时导致的。关键字搜索“T3126 timeout”
18、对于网络下发RR_CHANNEL_RELEASE原因的一些探讨

CSFB后什么情况需要位置更新

1,LU相关信息如下:
与位置相关的ID 有LAC(Location Area Code)(2G:SI_3/3G:SIB1)和TAC(Tracking Area Code)(4G:SIB1)
当小区重选伴随LAC或TAC发生改变时会引起做LU(LOCATION_UPDATING)

MTK 平台RR层连接断开的check
2,RR断开连接可以通过RR_ERROR_IND和RR_REL_CONF两条trace进行check

3,随机接入失败和网络下发RR_release属于网络行为,从UE端不得而知,确保后续的UE行为无异常即可。

19、手机handover以后,由于小区信号质量差发生RLF(切换时是好的,切换后变差)

1,你说的小区切换的时候只看信号强度,不看信号质量应该是指手机空闲态时小区重选是看信号强度的,但是这里是通话过程中,属于网络控制的范畴,手机在哪个小区,切到哪个网络没有自主权,只会根据网络指导的测量报告发送给网络,网络根据这些报告,是看信号强度或质量,或吞吐量等参数由网络决定,手机没有办法主导,所以这里要区分好小区重选和切换的概念
2,切换三秒时间足以导致底层断开

这样因为手机上报了当前arfcn的测量信号情况给网络:如服务小区信号质量等: .111 .... = RXQUAL-FULL-SERVING-CELL: BER > 12.8%, Mean value 18.10% (7)
OTA    300000    4081861    16:16:24:770    RRM    [MS->NW] RR__MEASUREMENT_REPORT    
DTAP Radio Resources Management Message Type: Measurement Report (0x15)

Measurement Results

0... .... = BA-USED: 0

.1.. .... = DTX-USED: DTX was used

..00 1100 = RXLEV-FULL-SERVING-CELL: -99 <= x < -98 dBm (12)

0... .... = 3G-BA-USED: 0

.0.. .... = MEAS-VALID: The measurement results are valid

RXLEV-SUB-SERVING-CELL: -89 <= x < -88 dBm (22)

.111 .... = RXQUAL-FULL-SERVING-CELL: BER > 12.8%, Mean value 18.10% (7)

.... 001. = RXQUAL-SUB-SERVING-CELL: 0.2% <= BER < 0.4%, Mean value 0.28% (1)

.... ...1 10.. .... = NO-NCELL-M: 6 neighbour cell measurement result (6)

..00 1111 = RXLEV-NCELL: 15

1011 1... = BCCH-FREQ-NCELL: 23

.... .001 000. .... = BSIC-NCELL: 8

...0 0101 1... .... = RXLEV-NCELL: 11

.100 10.. = BCCH-FREQ-NCELL: 18

.... ..10 1000 .... = BSIC-NCELL: 40

.... 0101 11.. .... = RXLEV-NCELL: 23

..01 001. = BCCH-FREQ-NCELL: 9

.... ...0 1111 0... = BSIC-NCELL: 30

.... .010 101. .... = RXLEV-NCELL: 21

...0 1010 = BCCH-FREQ-NCELL: 10

0000 00.. = BSIC-NCELL: 0

.... ..01 0011 .... = RXLEV-NCELL: 19

.... 0010 1... .... = BCCH-FREQ-NCELL: 5

.000 001. = BSIC-NCELL: 1

.... ...0 0110 1... = RXLEV-NCELL: 13

.... .000 01.. .... = BCCH-FREQ-NCELL: 1

..00 0101 = BSIC-NCELL: 5    
PS    300124    4081957    16:16:25:170    MPAL - RRM    MSG_ID_MPAL_RR_SERV_DEDI_MEAS_IND        
OTA    300260    4082040    16:16:25:570    RRM    [NW->MS] RR__SI_6 (ARFCN[62], TC[255])
所以网络根据当前手机上报的服务小区和邻小区的信号值与当前网络资源作出了切换ARFCN[71]的指令:        
OTA    300283    4082047    16:16:25:570    RRM    [NW->MS] RR__HANDOVER_COMMAND        
OTA    300397    4082087    16:16:25:770    RRM    [MS->NW] RR__HANDOVER_COMPLETE        
OTA    305526    4085468    16:16:42:770    RRM    [NW->MS] RR__SI_5 (ARFCN[71], TC[255])        
但是后面由于信号质量不佳就出现了底层链路失败:
PS    306265    4085962    16:16:45:170    MPAL - RRM    MSG_ID_MPAL_RR_SERV_DEDI_MEAS_IND        
PS    306397    4086044    16:16:45:570    LAPDM    radio link failure        
PS    306398    4086044    16:16:45:570    L1 - RRM    MSG_ID_LAPDM_RR_ERROR_IND        

20、主卡与副卡资源冲突

经重新check,贵司所提到的该两通paging,同样因为与卡2发生冲突导致失败;
另,上层消息MM__PAGING_RESPONSE需要在RRC连接建立后,方可通过[MS->NW] FDD_RRC__INITIAL_DIRECT_TRANSFER向网络传输
该时间点RRC连接没有建立成功,于是该response也是没有搜到的,请知悉

如沟通,还请交换卡之后进行复测,

Type    Index    Time    Local Time    Module    Message    Comment    Time Different
OTA    965158    165697    17:16:26:215    ADR    [NW->MS] RRC__PAGING_TYPE1        
OTA    965176    165697    17:16:26:215    MM    [MS->NW] MM__PAGING_RESPONSE        
PS    965182    165697    17:16:26:215    RATCM - RRCE    MSG_ID_RATCM_RRCE_CONN_EST_REQ        
PS    965192    165697    17:16:26:215    RRCE - CSCE    MSG_ID_CSCE_RRCE_RRC_CONNECTION_ESTABLISHMENT_IND        
PS    965213    165748    17:16:26:620    MPAL_2 - RRM_2    MSG_ID_MPAL_RR_DATA_IND    block_ind = RR_BAD_BLOCK (enum 1)    
PS    965217    165757    17:16:26:620    MPAL_2 - RRM_2    MSG_ID_MPAL_RR_DATA_IND    block_ind = RR_CONFLICT_WITH_PEER_GSM_OTHERS (enum 8)    
PS    965257    165937    17:16:27:560    MPAL_2 - RRM_2    MSG_ID_MPAL_RR_DATA_IND    block_ind = RR_BAD_BLOCK (enum 1)    
PS    965402    166205    17:16:28:900    MEME    MEME: PSC 307, RSCP -105, EcN0 -19, RRC_DB_CellType_detected, SyncInfo(0), TM(-28416), OFF(4), CIO 0, dbIdx 46, active 0        
PS    965502    166321    17:16:29:500    MPAL_2 - RRM_2    MSG_ID_MPAL_RR_DATA_IND    block_ind = RR_CONFLICT_WITH_PEER_GSM_OTHERS (enum 8)    
PS    965663    166459    17:16:30:190    MEME    MEME: PSC 307, RSCP -105, EcN0 -18, RRC_DB_CellType_detected, SyncInfo(0), TM(-28416), OFF(4), CIO 0, dbIdx 46, active 0        
OTA    965707    166465    17:16:30:190    ADR    [NW->MS] RRC__PAGING_TYPE1        paging
PS    965714    166465    17:16:30:190    RRCE    CN Paging: CS_DOMAIN, IMSI_TYPE, RRC_PagingCause_terminatingConversationalCall        
PS    965728    166512    17:16:30:455    MPAL_2 - RRM_2    MSG_ID_MPAL_RR_DATA_IND        
PS    965877    166697    17:16:31:220    MPAL_2 - RRM_2    MSG_ID_MPAL_RR_DATA_IND    block_ind = RR_CONFLICT_WITH_PEER_GSM_OTHERS (enum 8)    
PS    966223    166972    17:16:32:660    MEME    MEME: PSC 307, RSCP -104, EcN0 -18, RRC_DB_CellType_detected, SyncInfo(0), TM(-28416), OFF(4), CIO 0, dbIdx 46, active 0        
OTA    966269    166977    17:16:32:660    ADR    [NW->MS] RRC__PAGING_TYPE1        paging
PS    966276    166977    17:16:32:660    RRCE    CN Paging: CS_DOMAIN, IMSI_TYPE, RRC_PagingCause_terminatingConversationalCall        
PS    966278    166977    17:16:32:660    RRCE - RATCM    MSG_ID_RATCM_RRCE_PAGE_IND        
PS    966287    166982    17:16:32:660    MPAL_2 - RRM_2    MSG_ID_MPAL_RR_DATA_IND        
PS    966311    167074    17:16:33:265    MPAL_2 - RRM_2    MSG_ID_MPAL_RR_DATA_IND    block_ind = RR_CONFLICT_WITH_PEER_GSM_OTHERS (enum 8)    
PS    967823    167997    17:16:37:875    MEME    MEME: PSC 307, RSCP -106, EcN0 -20, RRC_DB_CellType_detected, SyncInfo(0), TM(-28416), OFF(4), CIO 0, dbIdx 46, active 0        
可以看到,发起后,是有发送RRCE_CONN_EST_REQ进行连接建立的,
但随后因信道资源与卡2发生冲突,导致该消息未能发送给网络。
Type    Index    Time    Local Time    Module    Message    Comment    Time Different
OTA    964658    165177    17:16:23:780    SIBE    [NW->MS] RRC_SI_MIB (UARFCN:[10713], PSC:[307])        
PS    965119    165691    17:16:26:215    MEME    MEME: PSC 307, RSCP -105, EcN0 -19, RRC_DB_CellType_detected, SyncInfo(0), TM(-28416), OFF(4), CIO 0, dbIdx 46, active 0        
OTA    965158    165697    17:16:26:215    ADR    [NW->MS] RRC__PAGING_TYPE1        
OTA    965176    165697    17:16:26:215    MM    [MS->NW] MM__PAGING_RESPONSE        
PS    965182    165697    17:16:26:215    RATCM - RRCE    MSG_ID_RATCM_RRCE_CONN_EST_REQ        
PS    965192    165697    17:16:26:215    RRCE - CSCE    MSG_ID_CSCE_RRCE_RRC_CONNECTION_ESTABLISHMENT_IND        
PS    965213    165748    17:16:26:620    MPAL_2 - RRM_2    MSG_ID_MPAL_RR_DATA_IND    block_ind = RR_BAD_BLOCK (enum 1)    
PS    965217    165757    17:16:26:620    MPAL_2 - RRM_2    MSG_ID_MPAL_RR_DATA_IND    block_ind = RR_CONFLICT_WITH_PEER_GSM_OTHERS (enum 8)    
PS    965257    165937    17:16:27:560    MPAL_2 - RRM_2    MSG_ID_MPAL_RR_DATA_IND    block_ind = RR_BAD_BLOCK (enum 1)    
PS    965402    166205    17:16:28:900    MEME    MEME: PSC 307, RSCP -105, EcN0 -19, RRC_DB_CellType_detected, SyncInfo(0), TM(-28416), OFF(4), CIO 0, dbIdx 46, active 0        
PS    965502    166321    17:16:29:500    MPAL_2 - RRM_2    MSG_ID_MPAL_RR_DATA_IND    block_ind = RR_CONFLICT_WITH_PEER_GSM_OTHERS (enum 8)    
PS    965663    166459    17:16:30:190    MEME    MEME: PSC 307, RSCP -105, EcN0 -18, RRC_DB_CellType_detected, SyncInfo(0), TM(-28416), OFF(4), CIO 0, dbIdx 46, active 0        

Log最后的两通MT被网络release,经检查发现该两通paging携带的ID为IMSI,2#和对比机8#中接收到的ID都为TMSI,
这与之前贵司提的一笔问题类似, 同样请交换SIM卡后,进行复测。
Type    Index    Time    Local Time    Module    Message    Comment    Time Different
OTA    1480308    239650    17:22:36:075    ADR    [NW->MS] RRC__PAGING_TYPE1    Mobile Identity Type: IMSI     
OTA    1480326    239650    17:22:36:075    MM    [MS->NW] MM__PAGING_RESPONSE        
OTA    1482155    239827    17:22:36:885    ADR    [NW->MS] RRC__RRC_CONNECTION_RELEASE_DCCH        
OTA    1482167    239827    17:22:36:885    ADR    [MS->NW] RRC__RRC_CONNECTION_RELEASE_COMPLETE        
OTA    1483590    239906    17:22:37:285    ADR    [NW->MS] RRC__PAGING_TYPE1    Mobile Identity Type: IMSI     
OTA    1483608    239906    17:22:37:285    MM    [MS->NW] MM__PAGING_RESPONSE        
OTA    1485855    240083    17:22:38:285    ADR    [NW->MS] RRC__RRC_CONNECTION_RELEASE_DCCH        
OTA    1485920    240092    17:22:38:285    ADR    [MS->NW] RRC__RRC_CONNECTION_RELEASE_COMPLETE    

21、关于当前驻留小区的查看

OTA (PCORE) 2206372 41749843 14:45:10:528 RRM_TDD_2 [NW->MS] RR__SI_5TER (ARFCN[656], TC[255])
//log中有这个网络发给终端的系统消息收到就说明终端已经驻留到这个小区了吗还是别的意思
====================
一般来说是驻留在此小区,但是在还没有驻留此小区搜网络的时候也会搜集系统消息的显示此信令

更新:
OTA (PCORE)    2204618    41698342    14:45:07:289    RRM_TDD_2    [NW->MS] RR__SI_5 (ARFCN[656], TC[255])        
OTA (PCORE)    2204767    41703189    14:45:07:689    RRM_TDD_2    [MS->NW] RR__MEASUREMENT_REPORT        
OTA (PCORE)    2204799    41703397    14:45:07:689    RRM_TDD_2    [NW->MS] RR__ASSIGNMENT_COMMAND        
OTA (PCORE)    2204847    41704331    14:45:07:689    RRM_TDD_2    [MS->NW] RR__ASSIGNMENT_COMPLETE
重新指配完成后,发生ERROR_TIMER_EXPD_N200_ABNORMAL_REL的底层失败,        
PS (PCORE)    2205367    41719561    14:45:08:709    L1HISR - RRM_TDD_2    MSG_ID_LAPDM_RR_REL_IND    
...
            error_cause = ERROR_TIMER_EXPD_N200_ABNORMAL_REL (enum 2)
            channel_type = FACCH (enum 25)
...            
重新在2G ARFCN[656]小区建立起连接:
PS (PCORE)    2205371    41719563    14:45:08:709    RRM_TDD_2 - MPAL_TDD_2    MSG_ID_RR_MPAL_DEDICATED_CHANNEL_RECONNECT_REQ        
PS (PCORE)    2205394    41719779    14:45:08:709    MPAL_TDD_2 - RRM_TDD_2    MSG_ID_MPAL_RR_DEDICATED_CHANNEL_RECONNECT_CNF
并且给网络报告说底层发生了一次错误,    
OTA (PCORE)    2205398    41719780    14:45:08:709    RRM_TDD_2    [MS->NW] RR__ASSIGNMENT_FAILURE
...
RR Cause
RR cause value: Protocol error unspecified (111)
...
PS (PCORE)    2205399    41719780    14:45:08:709    RRM_TDD_2    RRM_SUBSTATE = RRM_DEDICATED_RECON_L2_SUBSTATE    
            
PS (PCORE)    2205795    41732610    14:45:09:528    MPAL_TDD_2 - RRM_TDD_2    MSG_ID_MPAL_RR_SERV_DEDI_MEAS_IND        
OTA (PCORE)    2206372    41749843    14:45:10:528    RRM_TDD_2    [NW->MS] RR__SI_5TER (ARFCN[656], TC[255])    
所以此问题的还是后面CC DISCONNECT,casue No circuit/channel available,与前面的RR__ASSIGNMENT_FAILURE没有关系,RR__ASSIGNMENT_FAILURE只是发生了底层错误恢复连接后给网络报告Protocol error unspecified (111)情况,后面又正常恢复在ARFCN[656]小区:
CC DISCONNECT,casue No circuit/channel available一般为网络资源调配的问题,判断为网络原因    
OTA (PCORE)    2206533    41754893    14:45:10:944    CC_2    [NW->MS] CC__DISCONNECT    
...
Cause - (34) No circuit/channel available
...        

22.4G下TAU异常导致无法接收paging

主叫端无异常:
Type    Index    Time    Local Time    Module    Message    Comment    Time Different
SYS (PCORE)    798859    1619414071    14:57:48:396    NIL    [AT_I p21, s10]ATD18576395029;        
SYS (PCORE)    799090    1619414101    14:57:48:396    NIL    [AT_U p19, s8]+ECPI: 1,130,0,0,0,0,"18576395029",129,""    
SYS (PCORE)    861706    1619620021    14:58:01:396    NIL    [AT_U p19, s8]+ECPI: 1,2,1,1,0,20,"18576395029",129,""    
SYS (PCORE)    998804    1619863549    14:58:16:998    NIL    [AT_I p19, s8]AT+CHLD=11        

经查看被叫端log,在14:57:40前一通CC释放之后,UE 回到4G,做TAU
但是发出EMM_Tracking_Area_Update_Request一直没有收到网络回复,直到EMM_T3430 is expired超时
于是UE侧将连接释放,14:57:55:916重新选择小区,建立连接
再次发起做TAU,但网络将之拒绝:EMM_Tracking_Area_Update_Reject,cause为UE identity cannot be derived by the network(9)
Spec24.301有对该cause进行描述If the rejected request was not for initiating a PDN connection for emergency bearer services, the UE shall subsequently, automatically initiate the attach procedure.
随后UE重新发起attach成功驻网,UE行为符合SPEC规定,并无异常
【导致该通失败的原因主要是】:在这接近半分钟左右的时间里,做TAU时网络端出现异常导致的
至于网络端为何会出现该异常,从UE侧无法获知,请知悉。

以下为具体发生TAU异常的trace:
Type    Index    Time    Local Time    Module    Message    Comment    Time Different
OTA (PCORE)    842370    1686986316    14:57:40:755    ERRC_SYS    [NW->MS] SystemInformationBlockType1 (EARFCN[451], PCI[397])        
PS (PCORE)    843178    1686986522    14:57:40:755    ERRC_MOB    [MRM] store PCell: earfcn[451] pci[397] rsrp[-350] rsrq[-19] sinr[125] snr[125] cell_off[0]        
OTA (PCORE)    847251    1686987705    14:57:40:755    EMM_NASMSG    [MS->NW] EMM_Tracking_Area_Update_Request(EPS update type="EMM_UPDATE_TYPE_COMBINED_TAU", active flag="KAL_FALSE")        //第一次发起TAU,但一直没收到网络响应,直到超时
PS (PCORE)    858180    1687221829    14:57:55:916    ERRC_MOB    [MRM] store PCell: earfcn[451] pci[397] rsrp[-364] rsrq[-13] sinr[128] snr[128] cell_off[0]        
PS (PCORE)    858201    1687222080    14:57:55:916    EMM    [EMM TIMER] TIMER ID: EMM_T3430 is expired        
PS (PCORE)    858280    1687222084    14:57:55:916    EMM - ERRC    MSG_ID_EMM_ERRC_RELEASE_REQ    cause = ENASAS_LOCAL_REL    //超时后,UE侧将连接释放掉
OTA (PCORE)    859370    1687222567    14:57:55:916    ERRC_SYS    [NW->MS] SystemInformationBlockType1 (EARFCN[451], PCI[397])        
PS (PCORE)    859941    1687222737    14:57:55:916    ERRC - EMM    MSG_ID_EMM_ERRC_CELLSELECT_IND        
OTA (PCORE)    861773    1687379718    14:58:05:952    EMM_NASMSG    [MS->NW] EMM_Tracking_Area_Update_Request(EPS update type="EMM_UPDATE_TYPE_COMBINED_TAU", active flag="KAL_FALSE")        //重新建立连接,再次发起TAU
OTA (PCORE)    861979    1687380504    14:58:05:952    EMM_NASMSG    [NW->MS] EMM_Tracking_Area_Update_Reject(EMM cause="EMM_CAUSE_UE_ID_NOT_DERIVED_BY_NW")     Cause: UE identity cannot be derived by the network (9)    //网络将之拒绝
OTA (PCORE)    870020    1687382653    14:58:06:152    EMM_NASMSG    [MS->NW] EMM_Attach_Request(EPS attach type="EMM_ATTACH_TYPE_COMBINED_ATTACH")        //随后UE发起attach并成功驻网
OTA (PCORE)    872281    1687390274    14:58:06:556    EMM_NASMSG    [NW->MS] EMM_Attach_Accept(EPS attach result="EMM_ATTACH_RESULT_COMBINED_ATTACHED")        
OTA (PCORE)    892158    1687595157    14:58:19:736    ERRC_CONN    [NW->MS] ERRC_RRCConnectionRelease(cause:[ReleaseCause_other], redirectInfo:[0])        
OTA (PCORE)    894782    1687919692    14:58:40:579    ERRC_CEL    [NW->MS] PAGING, PagingRecordList[KAL_TRUE], SIB Modification[KAL_FALSE], ETWS[KAL_FALSE], CMAS[KAL_FALSE], EAB[KAL_FALSE]        
OTA (PCORE)    896053    1687920962    14:58:40:579    EMM_NASMSG    [MS->NW] EMM_Extended_Service_Request(service type="MT_CSFB", CSFB response="CSFB_ACCEPTED_BY_UE")        

23、移动3G下由于RLF而断开连接(区分网络主动release的情况)

在spec25.331中8.5.6节对RLF处理有如下描述:
For FDD in CELL_DCH state and in TDD when a radio link failure occurs, the UE shall:
1> clear the dedicated physical channel configuration;
1> perform actions as specified for the ongoing procedure;
1> if no procedure is ongoing or no actions are specified for the ongoing procedure:
2> perform a cell update procedure according to subclause 8.3.1 using the cause "radio link failure".
通话断开是因为RLF,发生RLF之后会发起cell update,并 有计数器V302进行数,多次发送,直到达到最大计数或收到网络响应后,释放连接。

OTA (PCORE) 6759419 1715254669 15:17:23:179 ADR_TDD [NW->MS] TDD_RRC__RRC_CONNECTION_RELEASE_CCCH //log

可查看log中RRC_CONNECTION_RELEASE的release cause,
如果是网络正常主动释放连接,会携带releaseCause: normalEvent (0)
在发生Cell update上报RLF后,网络释放连接的releaseCause: unspecified

24、手机在空闲态也会读取其他小区的系统消息,查看当前服务小区

手机在空闲态时会去读邻区的系统消息,这个是正常的。手机在这段时间内并没有进行过重选,一直在519小区。


Type    Index    Time    Local Time    Module    Message    Comment    Time Different
OTA    114847    18941871    11:13:20:700    CC    [NW->MS] CC__DISCONNECT        
OTA    114863    18941871    11:13:20:700    CC    [MS->NW] CC__RELEASE        
OTA    115269    18941919    11:13:21:100    CC    [NW->MS] CC__RELEASE_COMPLETE        
PS    119431    18942345    11:13:23:220    MPAL - RRM    MSG_ID_MPAL_RR_DATA_IND        
PS    119725    18942415    11:13:23:420    RRM    [RMC] Serv arfcn[519]: RAC[3], C1[142], C2[582]        
PS    120462    18942533    11:13:24:020    MPAL - RRM    MSG_ID_MPAL_RR_DATA_IND        
PS    120723    18942607    11:13:24:420    RRM    [RMC] Serv arfcn[519]: RAC[3], C1[142], C2[582]        
PS    121087    18942721    11:13:25:020    MPAL - RRM    MSG_ID_MPAL_RR_DATA_IND        
PS    121224    18942799    11:13:25:420    RRM    [RMC] Serv arfcn[519]: RAC[3], C1[143], C2[583]        
PS    121407    18942910    11:13:26:020    MPAL - RRM    MSG_ID_MPAL_RR_DATA_IND        
PS    121477    18942955    11:13:26:295    MPAL - RRM    MSG_ID_MPAL_RR_DATA_IND        
PS    121610    18943106    11:13:26:965    MPAL - RRM    MSG_ID_MPAL_RR_DATA_IND        
PS    121700    18943332    11:13:27:985    MPAL - RRM    MSG_ID_MPAL_RR_DATA_IND        
PS    121917    18943520    11:13:29:120    MPAL - RRM    MSG_ID_MPAL_RR_DATA_IND        
PS    121952    18943708    11:13:29:870    MPAL - RRM    MSG_ID_MPAL_RR_DATA_IND        
//serv arfcn 表示当前驻留小区,可以看到,一直没有变过。
PS    121990    18943708    11:13:29:870    RRM    [RMC] Serv arfcn[519]: RAC[3], C1[139], C2[579]        
//这里就是读邻小区信息,目的是重选时可以更快驻留到目标小区,节约时间。
PS    122076    18943749    11:13:30:115    RRM - MPAL    MSG_ID_RR_MPAL_NEIGHBOR_SYS_INFO_READ_REQ        
OTA    122082    18943760    11:13:30:320    RRM    [NW->MS] RR__SI_3 (ARFCN[78], TC[6])        
PS    122083    18943760    11:13:30:320    RRM - MPAL    MSG_ID_RR_MPAL_NEIGHBOR_SYS_INFO_STOP_REQ        
PS    122240    18943860    11:13:30:730    MPAL - RRM    MSG_ID_MPAL_RR_DATA_IND        
PS    122366    18944049    11:13:31:745    MPAL - RRM    MSG_ID_MPAL_RR_DATA_IND        
PS    122613    18944236    11:13:32:615    MPAL - RRM    MSG_ID_MPAL_RR_DATA_IND        
PS    122767    18944425    11:13:33:630    MPAL - RRM    MSG_ID_MPAL_RR_DATA_IND        
PS    122993    18944650    11:13:34:580    MPAL - RRM    MSG_ID_MPAL_RR_DATA_IND        
PS    123062    18944650    11:13:34:580    RRM    [RMC] Serv arfcn[519]: RAC[3], C1[143], C2[583]        
PS    123104    18944838    11:13:35:520    MPAL - RRM    MSG_ID_MPAL_RR_DATA_IND        
PS    123249    18945026    11:13:36:465    MPAL - RRM    MSG_ID_MPAL_RR_DATA_IND        
PS    123293    18945215    11:13:37:405    MPAL - RRM    MSG_ID_MPAL_RR_DATA_IND        
PS    123328    18945403    11:13:38:345    MPAL - RRM    MSG_ID_MPAL_RR_DATA_IND        
PS    123477    18945591    11:13:39:285    MPAL - RRM    MSG_ID_MPAL_RR_DATA_IND        
PS    123541    18945591    11:13:39:285    RRM    [RMC] Serv arfcn[519]: RAC[3], C1[142], C2[582]        
PS    123603    18945780    11:13:40:230    MPAL - RRM    MSG_ID_MPAL_RR_DATA_IND        

25、N200的底层确认

1.At time 27896673; N200 abnormal expiry observed (MSG_ID_LAPDM_RR_ERROR_IND, channel_type= SDCCH). UE failed to receive L2 ack for MM__AUTHENTICATION_RESPONSE msg.
2. Checked Downlink status and it has been observed that on serving arfcn 70 antenna power in range of ~-7x dbm to ~-9xdbm. SNR conditions are good and UE is able to decode all the sdcch blocks successfully so there is no issue at Rx.
3.At uplink side; UE is transmitting with 33 dBm, NB and TA= 4Qb which indicates that UE is little far from Network and NW could miss MM__AUTHENTICATION_RESPONSE because of this therefore it didn't respond with L2ack which leads to expiry of N200 timer.
4.Due to bad TX status, N200 timeout happened. It seems to be temporary network issue.

26、一张卡做业务,另一张卡被suspend的实例

我一般习惯搜索suspend和resume,可以看到这段时间有如下经历
Type    Index    Time    Local Time    Module    Message    Comment    Time Different
PS (PCORE)    470370    154694385    11:30:01:185    RSVAS - RRM_FDD_2    MSG_ID_RSVAS_GAS_SUSPEND_SERVICE_REQ        //卡1要LU,卡2被suspend
PS (PCORE)    470541    154694404    11:30:01:185    RRM_FDD_2 - MPAL_FDD_2    MSG_ID_RR_MPAL_SUSPEND_REQ        
PS (PCORE)    470542    154694404    11:30:01:185    RRM_FDD_2 - RSVAS    MSG_ID_RSVAS_GAS_SUSPEND_SERVICE_CNF        
PS (PCORE)    470591    154694408    11:30:01:185    RRM_FDD_2 - RATCM_2    MSG_ID_RATCM_GAS_SUSPEND_IND        
PS (PCORE)    480699    154725849    11:30:03:199    RSVAS - RRM_FDD_2    MSG_ID_RSVAS_GAS_VIRTUAL_RESUME_SERVICE_REQ        //卡1的LU结束CS连接断开,但RRC连接还没有释放,所以卡2进入virtual状态
PS (PCORE)    480773    154725858    11:30:03:199    RRM_FDD_2 - MPAL_FDD_2    MSG_ID_RR_MPAL_VIRTUAL_RESUME_REQ        
PS (PCORE)    480774    154725858    11:30:03:199    RRM_FDD_2 - RATCM_2    MSG_ID_RATCM_GAS_RESUME_IND        
PS (PCORE)    491223    154774778    11:30:06:209    RSVAS - RRM_FDD_2    MSG_ID_RSVAS_GAS_RESUME_SERVICE_REQ        //RRC连接断开,卡2彻底resume
PS (PCORE)    491619    154774806    11:30:06:209    RRM_FDD_2 - MPAL_FDD_2    MSG_ID_RR_MPAL_RESUME_REQ        
PS (PCORE)    500404    154843538    11:30:10:676    RSVAS - RRM_FDD_2    MSG_ID_RSVAS_GAS_SUSPEND_SERVICE_REQ        //卡1要LU,卡2被suspend
PS (PCORE)    500590    154843562    11:30:10:676    RRM_FDD_2 - MPAL_FDD_2    MSG_ID_RR_MPAL_SUSPEND_REQ        
PS (PCORE)    500591    154843562    11:30:10:676    RRM_FDD_2 - RSVAS    MSG_ID_RSVAS_GAS_SUSPEND_SERVICE_CNF        
PS (PCORE)    500621    154843564    11:30:10:676    RRM_FDD_2 - RATCM_2    MSG_ID_RATCM_GAS_SUSPEND_IND        
PS (PCORE)    508392    154875355    11:30:12:688    RSVAS - RRM_FDD_2    MSG_ID_RSVAS_GAS_VIRTUAL_RESUME_SERVICE_REQ        //卡1的LU结束CS连接断开,但RRC连接还没有释放,所以卡2进入virtual状态
PS (PCORE)    508466    154875365    11:30:12:688    RRM_FDD_2 - MPAL_FDD_2    MSG_ID_RR_MPAL_VIRTUAL_RESUME_REQ        
PS (PCORE)    508467    154875365    11:30:12:688    RRM_FDD_2 - RATCM_2    MSG_ID_RATCM_GAS_RESUME_IND        
PS (PCORE)    516908    154908657    11:30:14:897    RSVAS - RRM_FDD_2    MSG_ID_RSVAS_GAS_RESUME_SERVICE_REQ        //RRC连接断开,卡2彻底resume
PS (PCORE)    517126    154908679    11:30:14:897    RRM_FDD_2 - MPAL_FDD_2    MSG_ID_RR_MPAL_RESUME_REQ        

27、通话的下发流程

csm cc mm

从log中看,这通call最终没有拨打成功。直接原因是上一通电话挂断后,网络没有释放RRC连接,同时之后手机发送消息都无法得到网络的回复。
具体log如下:
Type    Index    Time    Local Time    Module    Message    Comment    Time Different
OTA    220801    515938    09:45:22:410    CC    [MS->NW] CC__RELEASE_COMPLETE        //上一通电话结束
PS    220824    515938    09:45:22:410    MM    MM_T3240_TIMER_ID Timer starts, period = 2000        //启动T3240,等网络下发消息
SYS    233838    516875    09:45:27:010    NIL    [AT_I p20, s10]ATD13509237401;
SYS    234100    516876    09:45:27:010    NIL    [IMSP_AT_I s21]ATD13509237401;        //拨打电话(三次尝试建立连接)
PS    234356    516877    09:45:27:210    CC - MM    MSG_ID_MMCC_EST_REQ        //第一次尝试 携带speech call emergency call 附加csmt等原因
PS    234357    516877    09:45:27:210    MM    CM service request is pended because of MM in state MM_WAIT_FOR_NETWORK_COMMAND        //此时T3240在run,手机需要等网络的消息
OTA    257559    517938    09:45:32:410    MM    [MS->NW] MM__LOCATION_UPDATING_REQUEST (LU type: MM_NORMAL_LU)        //T3240结束后,需要进行LU
PS    347027    521938    09:45:52:410    MM    MM_T3210_TIMER_ID Timer expires in state MM_LOCATION_UPDATING_INITIATED        //LU没有得到网络的任何回复,导致T3210超时
PS    347080    521938    09:45:52:410    MM - CC    MSG_ID_MMCC_EST_REJ        //LU没有成功,导致第一次尝试失败
PS    384697    523639    09:46:01:010    CC - MM    MSG_ID_MMCC_EST_REQ        //第二次尝试
OTA    384701    523639    09:46:01:010    MM    [MS->NW] MM__CM_SERVICE_REQUEST        
PS    384834    523639    09:46:01:010    MM    MM_T3230_TIMER_ID Timer starts, period = 3000        
PS    451774    526641    09:46:16:010    MM    CM service rejected because T3230 expiry        //发送CM service request网络没有回应,T3230超时
PS    451775    526641    09:46:16:010    MM - CC    MSG_ID_MMCC_EST_REJ        //第二次尝试失败
PS    451780    526641    09:46:16:010    MM    MM_T3240_TIMER_ID Timer starts, period = 2000        //尝试失败后,需等网络下发消息
PS    489859    528343    09:46:24:410    CC - MM    MSG_ID_MMCC_EST_REQ        //第三次尝试(此时T3240还在run)
PS    496418    528641    09:46:26:010    MM    MM_T3240_TIMER_ID Timer expires in state MM_WAIT_FOR_NETWORK_COMMAND        //T3240超时
OTA    496475    528641    09:46:26:010    MM    [MS->NW] MM__LOCATION_UPDATING_REQUEST (LU type: MM_NORMAL_LU)        //需要LU
PS    496614    528641    09:46:26:010    MM    MM_T3210_TIMER_ID Timer starts, period = 4000        
PS    585471    532641    09:46:46:010    MM    MM_T3210_TIMER_ID Timer expires in state MM_LOCATION_UPDATING_INITIATED        //LU没有得到网络的任何回复,导致T3210超时
PS    585522    532641    09:46:46:010    MM    CM rej because LU is rejected        //LU没有成功,导致第三次尝试失败
PS    585524    532641    09:46:46:010    MM - CC    MSG_ID_MMCC_EST_REJ        
28、3G下的RLF底层确认

底层RD分析如下:
The reason for not receiving any thing in DL and RLF is sudden drop of DL DPCH power even though CPICH quality is good.
This has decreased drastically from 3000 to -2000 in one frame at 09:45:23:805.
Generally we see this behavior when NW releases the connection. NW may release connection when some old Procedure is pending or some issue from NW side itself.

From the logs I see UE got RLC ACK for all the packets sent till 09:45:22:410 (CC_RELEASE_COMPLETE) on RB3 and ACTIVE_SET_UPDATE_COMPLETE on RB2. So there is no pending procedure which can cause the NW to release the connection abruptly.
So this looks to be NW issue.

29、WCDMA的激活集

PS    1431826    297842    09:12:04:200    MEME    MEME: PSC 260, RSCP -102 (-105 ,-104), EcN0 -18 (-20 ,-19), RRC_DB_CellType_monitored, SyncInfo(1), TM(24320), OFF(124), CIO 0, dbIdx 5, active 1
测量的结果后面打印active 1证明该小区是在激活集内。active 0表示不是激活集内的小区。
激活集是指与UE有无线链路RL连接的小区的集合,可以有1个,2个,3个。这个是WCDMA软切换的需求。

当前激活集一开始只有PSC260,如果当前激活集中只有一个小区,那么这个小区就是服务小区。
后面上报E1A加入168和81,这种情况下只有260还是处于激活集当中就还是服务小区。
当然驻留的小区的判断可以有其他,从LOG中可以看他在哪个小区发起LAU,或者有服务小区改变的trace.也可以从手机工模里面看当前服务小区的ARFCN和PSC。
小区改变的trace:
Type    Index    Time    Local Time    Module    Message    Comment    Time Different
PS    391705    270136    09:09:45:800    MEME    MEME: Serving cell changed from uarfcn 10713 PSC 81 (Idx 23) to uarfcn 10713 PSC 260 (Idx 48)        
激活集变化情况:
Type    Index    Time    Local Time    Module    Message    Comment    Time Different
PS    1431030    297822    09:12:04:200    MEME    MEME: PSC 260, RSCP -106 (-106 ,-106), EcN0 -22 (-22 ,-22), RRC_DB_CellType_monitored, SyncInfo(1), TM(24320), OFF(124), CIO 0, dbIdx 5, active 1    //当前激活集只有一个,260    
OTA    1431212    297826    09:12:04:200    ADR    [NW->MS] RRC__ADD PSC [168] - RRC__ACTIVESET_UPDATE    //网络下发ACTIVESET_UPDATE+168    
PS    1431826    297842    09:12:04:200    MEME    MEME: PSC 260, RSCP -102 (-105 ,-104), EcN0 -18 (-20 ,-19), RRC_DB_CellType_monitored, SyncInfo(1), TM(24320), OFF(124), CIO 0, dbIdx 5, active 1    //当前激活集 260、168    
PS    1431827    297842    09:12:04:200    MEME    MEME: PSC 168, RSCP -110 (-110 ,-110), EcN0 -25 (-24 ,-24), RRC_DB_CellType_monitored, SyncInfo(1), TM(20669), OFF(118), CIO 0, dbIdx 20, active 1        
OTA    1434866    297930    09:12:04:600    ADR    [NW->MS] RRC__ADD PSC [81] - RRC__ACTIVESET_UPDATE    //网络下发ACTIVESET_UPDATE+81    
PS    1437851    298000    09:12:05:000    MEME    MEME: PSC 168, RSCP -100 (-102 ,-101), EcN0 -25 (-24 ,-24), RRC_DB_CellType_monitored, SyncInfo(1), TM(20669), OFF(118), CIO 0, dbIdx 20, active 1    //当前激活集260.168.81    
PS    1437852    298000    09:12:05:000    MEME    MEME: PSC 260, RSCP -99 (-101 ,-100), EcN0 -25 (-24 ,-24), RRC_DB_CellType_monitored, SyncInfo(1), TM(24320), OFF(124), CIO 0, dbIdx 5, active 1        
PS    1437853    298000    09:12:05:000    MEME    MEME: PSC 81, RSCP -99 (-102 ,-101), EcN0 -25 (-24 ,-24), RRC_DB_CellType_monitored, SyncInfo(1), TM(17517), OFF(35), CIO 0, dbIdx 23, active 1    
-------------------------------------------------------------------------------------------------------------
不好意思之前说错,是E1C事件,上报E1C,表明测量到有小区比激活集小区信号好,网络收到E1C事件应该替换该小区进入到激活集中。
OTA    1437946    298000    09:12:05:000    ADR    [MS->NW] RRC__INTRA_e1C [276] [278] [178] [81] [168] [260] - MEASUREMENT_REPORT  

第一次log分析:  

测试机MO端:EcN0 -25非常差,导致发送RLF,通话掉话。之间激活集有3个cell,上报了E3C事,并没有ACTIVESET_UPDATE的动作。

Type    Index    Time    Local Time    Module    Message    Comment    Time Different
OTA    1431212    297826    09:12:04:200    ADR    [NW->MS] RRC__ADD PSC [168] - RRC__ACTIVESET_UPDATE    //+cell 168    
PS    1431824    297842    09:12:04:200    MEME    MEME: PSC 276, RSCP -88 (-88 ,-88), EcN0 -4 (-4 ,-4), RRC_DB_CellType_detected, SyncInfo(1), TM(22901), OFF(18), CIO 0, dbIdx 64, active 0        
PS    1431825    297842    09:12:04:200    MEME    MEME: PSC 278, RSCP -93 (-94 ,-94), EcN0 -9 (-10 ,-10), RRC_DB_CellType_detected, SyncInfo(1), TM(21877), OFF(18), CIO 0, dbIdx 94, active 0        
PS    1431826    297842    09:12:04:200    MEME    MEME: PSC 260, RSCP -102 (-105 ,-104), EcN0 -18 (-20 ,-19), RRC_DB_CellType_monitored, SyncInfo(1), TM(24320), OFF(124), CIO 0, dbIdx 5, active 1    //当前激活集 260、168    
PS    1431827    297842    09:12:04:200    MEME    MEME: PSC 168, RSCP -110 (-110 ,-110), EcN0 -25 (-24 ,-24), RRC_DB_CellType_monitored, SyncInfo(1), TM(20669), OFF(118), CIO 0, dbIdx 20, active 1        
OTA    1434866    297930    09:12:04:600    ADR    [NW->MS] RRC__ADD PSC [81] - RRC__ACTIVESET_UPDATE    //+cell 81    
PS    1437851    298000    09:12:05:000    MEME    MEME: PSC 168, RSCP -100 (-102 ,-101), EcN0 -25 (-24 ,-24), RRC_DB_CellType_monitored, SyncInfo(1), TM(20669), OFF(118), CIO 0, dbIdx 20, active 1    //当前激活集260.168.81    
PS    1437852    298000    09:12:05:000    MEME    MEME: PSC 260, RSCP -99 (-101 ,-100), EcN0 -25 (-24 ,-24), RRC_DB_CellType_monitored, SyncInfo(1), TM(24320), OFF(124), CIO 0, dbIdx 5, active 1        
PS    1437853    298000    09:12:05:000    MEME    MEME: PSC 81, RSCP -99 (-102 ,-101), EcN0 -25 (-24 ,-24), RRC_DB_CellType_monitored, SyncInfo(1), TM(17517), OFF(35), CIO 0, dbIdx 23, active 1        
OTA    1437946    298000    09:12:05:000    ADR    [MS->NW] RRC__INTRA_e1C [276] [278] [178] [81] [168] [260] - MEASUREMENT_REPORT    //上报E1C,表明测量到有小区比激活集小区信号好    
PS    1437947    298000    09:12:05:000    MEME - DRLC    MSG_ID_RLC_AM_DATA_REQ    MUI =1952    
PS    1441389    298082    09:12:05:400    URLC - ADR    MSG_ID_RLC_AM_DATA_CNF    MUI[0] = 1952    
PS    1462458    298510    09:12:07:600    MEME    MEME: PSC 260, RSCP -105 (-105 ,-105), EcN0 -25 (-24 ,-24), RRC_DB_CellType_monitored, SyncInfo(1), TM(24320), OFF(124), CIO 0, dbIdx 5, active 1        
PS    1462459    298510    09:12:07:600    MEME    MEME: PSC 81, RSCP -105 (-105 ,-105), EcN0 -25 (-24 ,-24), RRC_DB_CellType_monitored, SyncInfo(1), TM(17517), OFF(35), CIO 0, dbIdx 23, active 1        
PS    1462878    298520    09:12:07:600    MEME    MEME: PSC 168, RSCP -105 (-105 ,-105), EcN0 -25 (-24 ,-24), RRC_DB_CellType_monitored, SyncInfo(1), TM(20669), OFF(118), CIO 0, dbIdx 20, active 1        
PS    1471405    298750    09:12:08:800    MEME    MEME: PSC 168, RSCP -105 (-105 ,-105), EcN0 -25 (-24 ,-24), RRC_DB_CellType_monitored, SyncInfo(1), TM(20669), OFF(118), CIO 0, dbIdx 20, active 1        
PS    1471407    298750    09:12:08:800    MEME    MEME: PSC 81, RSCP -105 (-105 ,-105), EcN0 -25 (-24 ,-24), RRC_DB_CellType_monitored, SyncInfo(1), TM(17517), OFF(35), CIO 0, dbIdx 23, active 1        
PS    1471743    298760    09:12:08:800    MEME    MEME: PSC 260, RSCP -105 (-105 ,-105), EcN0 -24 (-24 ,-24), RRC_DB_CellType_monitored, SyncInfo(1), TM(24320), OFF(124), CIO 0, dbIdx 5, active 1        
PS    1473355    298810    09:12:09:000    MEME    MEME: PSC 260, RSCP -104 (-104 ,-104), EcN0 -24 (-24 ,-24), RRC_DB_CellType_monitored, SyncInfo(1), TM(24320), OFF(124), CIO 0, dbIdx 5, active 1        
PS    1473356    298810    09:12:09:000    MEME    MEME: PSC 168, RSCP -104 (-105 ,-104), EcN0 -25 (-24 ,-24), RRC_DB_CellType_monitored, SyncInfo(1), TM(20669), OFF(118), CIO 0, dbIdx 20, active 1        
PS    1473357    298810    09:12:09:000    MEME    MEME: PSC 81, RSCP -105 (-105 ,-105), EcN0 -25 (-24 ,-24), RRC_DB_CellType_monitored, SyncInfo(1), TM(17517), OFF(35), CIO 0, dbIdx 23, active 1        
PS    1473582    298816    09:12:09:200    UL1 - RRCE    MSG_ID_CPHY_RL_FAILURE_IND        //底层发生RLF
OTA    1477984    299009    09:12:10:000    ADR    [MS->NW] RRC__CELL_UPDATE    cellUpdateCause = radiolinkFailure    
OTA    1484761    299241    09:12:11:200    ADR    [MS->NW] RRC__CELL_UPDATE    cellUpdateCause = radiolinkFailure    
OTA    1490380    299457    09:12:12:400    ADR    [MS->NW] RRC__CELL_UPDATE    cellUpdateCause = radiolinkFailur

30、查看ERRC层的状态

网络下发这一条的时候UE已经处于connected mode网络是不会通过paging来通知UE的而是直接发送。
另外debug paging这部分log是属于底层log按照公司的规定是不可以贴出来的请见谅。
Type    Index    Time    Local Time    Module    Message    Comment    Time Different
PS (PCORE)    167890    1196651731    08:32:21:744    ERRC_CONN    [CONN]state trasition: current=CONN_RECONF ---> next=CONN_CONNECTED        
PS (PCORE)    169489    1196653094    08:32:21:946    ERRC_CONN    [CONN]state trasition: current=CONN_CONNECTED ---> next=CONN_RECONF        
PS (PCORE)    170203    1196653242    08:32:21:946    ERRC_CONN    [CONN]state trasition: current=CONN_RECONF ---> next=CONN_CONNECTED        
PS (PCORE)    171643    1196658874    08:32:22:168    ERRC_CONN    [CONN]state trasition: current=CONN_CONNECTED ---> next=CONN_RECONF        
PS (PCORE)    172254    1196659041    08:32:22:369    ERRC_CONN    [CONN]state trasition: current=CONN_RECONF ---> next=CONN_CONNECTED     

31、GSM空闲态查看服务小区

针对acc 手机刚好被限制的case, 2G 底层分析如下:

7513, 2143057, 10684298, 22:51:26:260 2017/06/08, MOD_RRM_2, , TRACE_PEER, [NW->MS] RR__SI_13 (ARFCN[660], TC[4])

5658, 2141012, 10682454, 22:51:17:050 2017/06/08, MOD_RRM_2, , TRACE_GROUP_1, [RMC] Serv arfcn[660]: RAC[0], C1[115], C2[171]
6380, 2141953, 10683301, 22:51:21:285 2017/06/08, MOD_RRM_2, , TRACE_GROUP_1, [RMC] Serv arfcn[660]: RAC[0], C1[116], C2[172]
7183, 2142680, 10683950, 22:51:24:520 2017/06/08, MOD_RRM_2, , TRACE_GROUP_1, [RMC] Serv arfcn[660]: RAC[0], C1[124], C2[180]
8271, 2143766, 10684996, 22:51:29:760 2017/06/08, MOD_RRM_2, , TRACE_GROUP_1, [RMC] Serv arfcn[660]: RAC[0], C1[116], C2[172]
27497, 2154170, 10694600, 22:52:17:780 2017/06/08, MOD_RRM_2, , TRACE_GROUP_1, [RMC] Serv arfcn[660]: RAC[0], C1[93], C2[149]
28236, 2154919, 10695248, 22:52:21:010 2017/06/08, MOD_RRM_2, , TRACE_GROUP_1, [RMC] Serv arfcn[660]: RAC[0], C1[76], C2[132]
30424, 2156948, 10697142, 22:52:30:490 2017/06/08, MOD_RRM_2, , TRACE_GROUP_1, [RMC] Serv arfcn[660]: RAC[0], C1[100], C2[156]
32284, 2157865, 10697989, 22:52:34:725 2017/06/08, MOD_RRM_2, , TRACE_GROUP_1, [RMC] Serv arfcn[660]: RAC[0], C1[109], C2[165]
38637, 2159724, 10699684, 22:52:43:185 2017/06/08, MOD_RRM_2, , TRACE_GROUP_1, [RMC] Serv arfcn[660]: RAC[0], C1[99], C2[155]

整个过程中的服务小区是 频点660,此小区比周边的相邻小区信号质量好 属于是正常驻留在此
由于贵司没有提供完整的开机log 产生这个问题的时候 已经是看不到服务小区最开始收系统消息1 2 3 4 的情况,
当手机支持GPRS ,也就是携带SI13 的时候,服务小区只会周期性收SI13 ,来确定系统消息是否改变

32、2G小区不满足搜3G

搜完2G找不到合适的小区会全频扫2G尝试找2G小区,如果还是没有会尝试去搜3G小区;
该题2G一开始没有找到就去全频扫,找到其他小区但是要不就C1不满足要不basic解不出要不plmn不匹配的小区。
然后找2G,找到10071/29,搜系统消息,但是后面S值不满足就没有接入。

Type    Index    Time    Local Time    Module    Message    Comment    Time Different
OTA (PCORE)    1423422    34733524    14:49:22:913    EMM_NASMSG    [NW->MS] EMM_CS_Service_Notification(paging identity="TMSI_PAGING_TYPE")        
OTA (PCORE)    1423612    34733542    14:49:22:913    EMM_NASMSG    [MS->NW] EMM_Extended_Service_Request(service type="MT_CSFB", CSFB response="CSFB_ACCEPTED_BY_UE")        
OTA (PCORE)    1423874    34733910    14:49:22:913    ERRC_CONN    [NW->MS] ERRC_RRCConnectionRelease(cause:[ReleaseCause_other], redirectInfo:[1])        
PS (PCORE)    1425410    34734595    14:49:23:113    RRM_TDD - MPAL_TDD    MSG_ID_RR_MPAL_SEARCH_RF_REQ        
PS (PCORE)    1425436    34743821    14:49:23:703    MPAL_TDD - RRM_TDD    MSG_ID_MPAL_RR_SEARCH_RF_CNF        
PS (PCORE)    1425439    34743822    14:49:23:703    RRM_TDD    [RCS] There are [0] ARFCNs to sort or sorted        
PS (PCORE)    1425481    34743827    14:49:23:703    RRM_TDD - MPAL_TDD    MSG_ID_RR_MPAL_SEARCH_RF_REQ        
PS (PCORE)    1425503    34789759    14:49:26:643    MPAL_TDD - RRM_TDD    MSG_ID_MPAL_RR_SEARCH_RF_CNF        
PS (PCORE)    1425658    34789769    14:49:26:643    RRM_TDD    [RCS] There are [100] ARFCNs to try        
PS (PCORE)    1425659    34789769    14:49:26:643    RRM_TDD    [RCS] Sorted power scan list: Index:0 ARFCN:4 POWER:-410        
PS (PCORE)    1425660    34789769    14:49:26:643    RRM_TDD    [RCS] Sorted power scan list: Index:1 ARFCN:5 POWER:-431        
PS (PCORE)    1425661    34789769    14:49:26:643    RRM_TDD    [RCS] Sorted power scan list: Index:2 ARFCN:15 POWER:-431        
PS (PCORE)    1425662    34789769    14:49:26:643    RRM_TDD    [RCS] Sorted power scan list: Index:3 ARFCN:109 POWER:-432        
PS (PCORE)    1425663    34789769    14:49:26:643    RRM_TDD    [RCS] Sorted power scan list: Index:4 ARFCN:825 POWER:-374        
PS (PCORE)    1425664    34789769    14:49:26:643    RRM_TDD    [RCS] Sorted power scan list: Index:5 ARFCN:822 POWER:-375        
PS (PCORE)    1425665    34789769    14:49:26:643    RRM_TDD    [RCS] Sorted power scan list: Index:6 ARFCN:820 POWER:-381        
PS (PCORE)    1425666    34789769    14:49:26:643    RRM_TDD    [RCS] Sorted power scan list: Index:7 ARFCN:821 POWER:-382        
PS (PCORE)    1425667    34789769    14:49:26:643    RRM_TDD    [RCS] Sorted power scan list: Index:8 ARFCN:828 POWER:-382        
OTA (PCORE)    1425873    34799995    14:49:27:234    RRM_TDD    [NW->MS] RR__SI_3 (ARFCN[109], TC[6])         /46011
PS (PCORE)    1428863    35027431    14:49:41:804    RSVAU - TL1    MSG_ID_TDD_CPHY_FREQUENCY_SCAN_REQ        
PS (PCORE)    1428882    35027446    14:49:41:804    TL1 - RSVAU    MSG_ID_TDD_CPHY_FREQUENCY_SCAN_CNF        
PS (PCORE)    1428934    35034777    14:49:42:325    TL1 - MEME_TDD    MSG_ID_TDD_CPHY_MEASUREMENT_CELL_IND        
PS (PCORE)    1428937    35034780    14:49:42:325    MEME_TDD - CSE_TDD    MSG_ID_TDD_CSE_MEME_CELL_MEASUREMENT_RESULT_IND    rscp = -435    
PS (PCORE)    1428945    35034783    14:49:42:325    CSE_TDD - SIBE_TDD    MSG_ID_TDD_SIBE_SIB_COLLECTION_REQ        
OTA (PCORE)    1429025    35036498    14:49:42:325    SIBE_TDD    [NW->MS] TDD_RRC_SI_MIB (TDD_UARFCN:[10071], PSC:[29])        
OTA (PCORE)    1429134    35038064    14:49:42:535    SIBE_TDD    [NW->MS] TDD_RRC_SI_SB1 (TDD_UARFCN:[10071], PSC:[29])        
PS (PCORE)    1429686    35047127    14:49:42:975    SIBE_TDD - CSE_TDD    MSG_ID_TDD_SIBE_SIB_COLLECTION_CNF    success = KAL_TRUE (enum 1)    
PS (PCORE)    1429701    35047136    14:49:42:975    CSE_TDD    TDD_DB_CELL [TDD_UARFCN = 10071, PHYSCELLID = 29, index = 24] does not fulfill Cell Selection criteria even though SIB Collection procedure was successful         //S值不满足就没有接入
PS (PCORE)    1429703    35047137    14:49:42:975    CSCE_TDD    Designated cell [TDD_UARFCN = 10071, PHYSCELLID = 29] S criteria NOT satisfied [Squal = 1, Srxlev = -39936]

转载于:https://my.oschina.net/u/2829875/blog/822411

  • 3
    点赞
  • 12
    收藏
    觉得还不错? 一键收藏
  • 0
    评论

“相关推荐”对你有帮助么?

  • 非常没帮助
  • 没帮助
  • 一般
  • 有帮助
  • 非常有帮助
提交
评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值