目录
1、从日志可以看到刚搜网就收到了STOP_MODE_REQ,需要查看STOP_MODE_REQ的原因:
4、为什么会读取卡文件EFEPSNSC (EPS NAS Security Context)失败,是SIM卡协议问题,这里不再累述。
一、问题描述:
在英国调用 three的卡,大概率不搜网。
二、问题分析:
1、从日志可以看到刚搜网就收到了STOP_MODE_REQ,需要查看STOP_MODE_REQ的原因:
[3010/ 2/ 3/ 4] MSG 15:39:33.795990 NAS REG/High [ reg_state.c 9976] DS: SUB 1 =REG= CM_SIM_AVAILABLE_REQ mode_pref:-1, session_type:0 nv_index:0
[3010/ 3/ 4] MSG 15:39:33.797005 NAS REG/Error [ reg_sim.c 9556] DS: SUB 1 =REG= Read EF EHPLMN attributes list failed or OEM EHPLMN undefined or USIM compliant, use EFS
[3010/ 2/ 3/ 4] MSG 15:39:33.798047 NAS REG/High [ reg_sim.c 9591] DS: SUB 1 =REG= EHPLMN list (length = 1)
[3010/ 2/ 3/ 4] MSG 15:39:33.798047 NAS REG/High [ reg_sim.c 9613] DS: SUB 1 =REG= 0 234- 20
[3010/ 2/ 3/ 4] MSG 15:39:33.817995 NAS REG/High [ reg_send.c 880] DS: SUB 1 =REG= CM_SIM_AVAILABLE_CNF
[3010/ 2/ 3/ 4] MSG 15:39:33.826016 NAS REG/High [ reg_state.c 2083] DS: SUB 1 =REG= NEW RAT priority list num_items = 2 Scan Scope type = 1, additional_info in CM_SERVICE_REQ = 0
[3010/ 2/ 3/ 4] MSG 15:39:33.826016 NAS REG/High [ reg_state.c 2097] DS: SUB 1 =REG= sys_mode = 9 bst_rat_acq_required = 1
[3010/ 2/ 3/ 4] MSG 15:39:33.826016 NAS REG/High [ reg_state.c 2139] DS: SUB 1 =REG= sys_mode = 5 bst_rat_acq_required = 1 band_cap = 0x10060000 0ec00000 bst_band_cap = 0x10060000 0ec00000
[3010/ 2/ 3/ 4] MSG 15:39:33.827031 NAS REG/High [ reg_state.c 3267] DS: SUB 1 =REG= CM_SERVICE_REQ - AUTOMATIC type=2
//搜网:
[3010/ 2/ 3/ 4] MSG 15:39:33.829011 NAS REG/High [ reg_send.c 1992] DS: SUB 1 =REG= MMR_REG_REQ PLMN(234-20) RAT(0-GSM,1-W,2-LTE,3-TDS) = 2 netsel 0, type 2 grat_scan_done 0 trans_id 2 trm_timeout -1
//STOP_MODE_REQ
[ 5/ 2] MSG 15:39:33.840026 Call Manager/High [ cmregprx.c 4515] =CMREGPRX= CMREG->NAS: sub 0 stk 0, Send STOP_MODE_REQ, reason=0 1
[ 5/ 2] MSG 15:39:33.861016 Call Manager/High [ cmregprx.c 13304] =CMREGPRX= NAS->CMREG: sub 0 stk 0, STOP_MODE_CNF, tran-id=5, state=1, sub_state=2, stop reas: 0
[ 5/ 2] MSG 15:39:33.862031 Call Manager/High [ cmregprx.c 4768] =CMREGPRX= CMREG->NAS: sub 0, Send SIM_NOT_AVAILABLE_REQ
[3010/ 2/ 3/ 4] MSG 15:39:33.862031 NAS REG/High [ reg_send.c 2080] DS: SUB 1 =REG= MMR_SIM_NOT_AVAILABLE_REQ
[3007/ 2/ 3/ 4] MSG 15:39:33.862031 NAS MM/High [ mmcoord.c 2271] DS: SUB 1 =MM= MM received MMR_SIM_NOT_AVAILABLE_REQ
2、再向前找日志发现STOP_MODE_REQ的原因应该是MMGSDI_SESSION_ILLEGAL_SUBSCRIPTION_EVT导致,需要继续查看为什么会MMGSDI_SESSION_ILLEGAL_SUBSCRIPTION_EVT
[ 5/ 2] MSG 15:39:33.834011 Call Manager/High [ cmmmgsdi.c 5654] =CM= <<CM mmgsdievt 20, session_id 93
[ 5/ 2] MSG 15:39:33.834011 Call Manager/High [ cmmmgsdi.c 5820] =CM= UIM->CM: MMGSDI_SESSION_ILLEGAL_SUBSCRIPTION_EVT, session-id 93
[ 5/ 2] MSG 15:39:33.834011 Call Manager/High [ cmmmgsdi.c 5831] =CM= UIM->CM: MMGSDI_SESSION_ILLEGAL_SUBSCRIPTION_EVT send to CMRPM_TDS
[ 5/ 2] MSG 15:39:33.834011 Call Manager/High [ cm.c 11234] =CM= CM_PH_CMD_SUBSCRIPTION_NOT_AVAILABLE, cdma=1, gwl=0, asubs_id=0 cause=0
[ 5/ 2] MSG 15:39:33.834011 Call Manager/High [ cmph.c 38859] =CM= AS_ID 0, subs na CDMA 1, GW 0
[ 5/ 2] MSG 15:39:33.835000 Call Manager/High [ cmph.c 20179] =CM= PH_PROC: sub 0, CM_PH_CMD_SUBSCRIPTION_NOT_AVAILABLE is being processed cause:0, 1 1 0 0
[ 5/ 2] MSG 15:39:33.835000 Call Manager/High [ cmph.c 20189] =CM= SUBSCRIPTION_NOT_AVAILABLE sub_asub_id 0 1x_sub 0
[ 5/ 2] MSG 15:39:33.836016 Call Manager/High [ cmregprx.c 16765] =CMREGPRX= CMREG->NAS: sub 0, Send ABORT_CC_REQ and ABORT_SS_REQ reason=0
[ 5/ 2] MSG 15:39:33.836016 Call Manager/High [ cmph.c 2884] =CM= PH_PROC: wait for ABORT_CNF: cmd 8, abort_sub_bitmask=0x0, as_id=0
[ 5/ 2] MSG 15:39:33.837005 Call Manager/High [ cmph.c 20179] =CM= PH_PROC: sub 0, CM_PH_CMD_SUBSCRIPTION_NOT_AVAILABLE is being processed cause:0, 1 1 0 0
[ 5/ 2] MSG 15:39:33.837005 Call Manager/High [ cmph.c 20189] =CM= SUBSCRIPTION_NOT_AVAILABLE sub_asub_id 0 1x_sub 0
[ 5/ 2] MSG 15:39:33.837005 Call Manager/High [ cmclnup.c 571] =CM= NO_CLNUP: illegal sub
[ 5/ 2] MSG 15:39:33.837005 Call Manager/High [ cmph.c 20270] =CM= SUBSC_NOT_AVAIL: sess_type 0 app_type 3
[ 5/ 2] MSG 15:39:33.837005 Call Manager/High [ cmpmprx.c 2495] =CM= AS_ID 0, not_ok_to_enforce: due to Subsc not avail or No policy changed, device_policy_changes 0x0, policy_changes 0x0
[ 5/ 2] MSG 15:39:33.839063 Call Manager/High [ cmdbg.c 3897] =CM= <<CM1 phevt=16
3、MMGSDI_SESSION_ILLEGAL_SUBSCRIPTION_EVT肯定是UIM模块发出来的,但没有UIM模块的log,要找出哪里导致的MMGSDI_SESSION_ILLEGAL_SUBSCRIPTION_EVT会增加一定的困难。
结合日志和代码继续向前找原因,发现是卡ready后EMM读取卡文件EFEPSNSC (EPS NAS Security Context)失败,把卡设为了SYS_SIM_STATE_CS_PS_INVALID而导致的MMGSDI_SESSION_ILLEGAL_SUBSCRIPTION_EVT。
日志:
[3007/ 2/ 3/ 4] MSG 15:39:33.804011 NAS MM/High [ mmsim.c 1564] DS: SUB 1 =MM= mm_load_sim_data called
[3007/ 2/ 3/ 4] MSG 15:39:33.807005 NAS MM/High [ mmsim.c 1952] DS: SUB 1 =EMM= Deleting EPSNSC and EPSLOCI from EFS
[3007/ 2/ 3/ 4] MSG 15:39:33.807005 NAS MM/High [ emm_sim_handler.c 620] DS: SUB 1 =EMM= LAST_REGISTERED_TAI valid = 0
[3007/ 3/ 4] MSG 15:39:33.807005 NAS MM/Error [ emm_sim_handler.c 625] DS: SUB 1 =EMM= SIM read failed, this must not happen in this stage because we end up writing incorrect values in LAST_REG_PLMN
[3007/ 2/ 3/ 4] MSG 15:39:33.807995 NAS MM/High [ emm_security.c 2615] DS: SUB 1 =EMM= based on eps_storage_supported supported , update context in USIM(1) / EFS(0) = 1
[3007/ 3/ 4] MSG 15:39:33.809011 NAS MM/Error [ mmsim.c 2220] ds1=MM= Unable to write to EF 16469 (MMGSDI err = 4)
[3007/ 3/ 4] MSG 15:39:33.809011 NAS MM/Error [ emm_security.c 2880] DS: SUB 1 =EMM= Cannot update EF EPS NSC 0
[3007/ 2/ 3/ 4] MSG 15:39:33.809011 NAS MM/High [ emm_rrc_if.c 1892] DS: SUB 1 =EMM= Sent LTE_RRC_SIM_UPDATE_REQ
[3007/ 2/ 3/ 4] MSG 15:39:33.810026 NAS MM/High [ emm_utility.c 6579] DS: SUB 1 =EMM= Setting RPLMN - Sim state 0, EMM state 1, Last RTAI 0
[3007/ 3/ 4] MSG 15:39:33.815000 NAS MM/Error [ mmsim.c 2193] ds1=MM= Unable to read from EF 16469 (MMGSDI err = 4)
[3007/ 3/ 4] MSG 15:39:33.815000 NAS MM/Error [ emm_security.c 2183] DS: SUB 1 =EMM= EPS NSC file read error
[3007/ 2/ 3/ 4] MSG 15:39:33.815000 NAS MM/High [ emm_sim_handler.c 620] DS: SUB 1 =EMM= LAST_REGISTERED_TAI valid = 0
[3007/ 3/ 4] MSG 15:39:33.815990 NAS MM/Error [ emm_sim_handler.c 625] DS: SUB 1 =EMM= SIM read failed, this must not happen in this stage because we end up writing incorrect values in LAST_REG_PLMN
[3007/ 2/ 3/ 4] MSG 15:39:33.815990 NAS MM/High [ emm_sim_handler.c 650] DS: SUB 1 =EMM= Set EPS update status to 1 (Invalidate mobility)
[3007/ 2/ 3/ 4] MSG 15:39:33.815990 NAS MM/High [ emm_sim_handler.c 691] DS: SUB 1 =EMM= Delete KSI
[3007/ 2/ 3/ 4] MSG 15:39:33.815990 NAS MM/High [ emm_security.c 2615] DS: SUB 1 =EMM= based on eps_storage_supported supported , update context in USIM(1) / EFS(0) = 1
[3007/ 3/ 4] MSG 15:39:33.815990 NAS MM/Error [ mmsim.c 2220] ds1=MM= Unable to write to EF 16469 (MMGSDI err = 4)
[3007/ 3/ 4] MSG 15:39:33.815990 NAS MM/Error [ emm_security.c 2880] DS: SUB 1 =EMM= Cannot update EF EPS NSC 0
[3007/ 2/ 3/ 4] MSG 15:39:33.815990 NAS MM/High [ emm_utility.c 6579] DS: SUB 1 =EMM= Setting RPLMN - Sim state 4, EMM state 1, Last RTAI 0
代码:
mmcoord_process_subsription_ready()
……
else
{
status = mm_load_sim_data();
if( status )
{
mm_debug_mmr_sim_available_status = MM_DEBUG_SIM_AVAILABLE_LOAD_CARD_MODE_SUCCESS;
mm_serving_plmn.info.sim_state = SYS_SIM_STATE_AVAILABLE;
(void)auth_load_security_context() ;
#ifdef FEATURE_LTE
if(mm_sub_is_rat_enabled(SYS_RAT_LTE_RADIO_ACCESS) == TRUE)
{
emm_load_security_context(emm_ctrl_data_ptr);
(void)emm_update_rplmn(emm_ctrl_data_ptr);
/* reset the mm nas ul count */
mm_reset_ul_count_at_generation();
}
/* Read all LTE_NAS NV items */
lte_nas_nv_read(emm_ctrl_data_ptr);
->
emm_load_security_context()
……
/* Read the USIM EPS NSC file */
secure_memset(sim_buffer,0, sizeof(sim_buffer));
status = mm_sim_read( MMGSDI_USIM_EPSNSC,
sim_buffer,
(dword )file_length
);
if (status != TRUE )
{
/* File present, but read error */
MSG_ERROR_DS_0(MM_SUB, "=EMM= EPS NSC file read error");
/* there is no need to read the EFS if the EPS NSC storage is allowed */
emm_ctrl_data_ptr->plmn_service_state->service_status = SYS_SRV_STATUS_LIMITED ;
emm_invalidate_mobility_info(EMM_STATUS_NOT_UPDATED,
SYS_SIM_STATE_CS_PS_INVALID,
emm_ctrl_data_ptr,
FALSE);
->
emm_invalidate_mobility_info()
……
MSG_HIGH_DS_1(MM_SUB, "=EMM= LAST_REGISTERED_TAI valid = %d",
emm_ctrl_data_ptr->last_registered_tai_valid);
if(emm_ctrl_data_ptr->last_registered_tai_valid == FALSE) /*case where SIM data was not copied into 'emm_ctrl_data'*/
{
if(FALSE == emm_load_epsloci_data(emm_ctrl_data_ptr,FALSE))
{
MSG_ERROR_DS_0(MM_SUB, "=EMM= SIM read failed, this must not happen in this stage because we end up writing incorrect values in LAST_REG_PLMN");
}
}
……
/* Invalidate NAS Security parameters */
MSG_HIGH_DS_0(MM_SUB, "=EMM= Delete KSI");
emm_invalidate_nas_security_params(emm_ctrl_data_ptr);
……
/* Invalidate USIM */
switch (sim_state)
{
case SYS_SIM_STATE_CS_PS_INVALID:
(void) mmgsdi_session_manage_illegal_subscription(mm_sim_mmgsdi_info.session_id,
MMGSDI_SESSION_APP_IS_ILLEGAL);
emm_ctrl_data_ptr->plmn_service_state->sim_state = sim_state ;
break ;