读取卡文件EFEPSNSC失败导致不搜网问题分析

目录

一、问题描述：

二、问题分析：

1、从日志可以看到刚搜网就收到了STOP_MODE_REQ，需要查看STOP_MODE_REQ的原因：

2、再向前找日志发现STOP_MODE_REQ的原因应该是MMGSDI_SESSION_ILLEGAL_SUBSCRIPTION_EVT导致，需要继续查看为什么会MMGSDI_SESSION_ILLEGAL_SUBSCRIPTION_EVT

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。

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 ;

4、为什么会读取卡文件EFEPSNSC (EPS NAS Security Context)失败，是SIM卡协议问题，
这里不再累述。