Unexpected +KCELLMEAS URC prevents PSM from functioning properly

Yes, here is a log that shows psm works good without KCELLMEAS=1,10. I think the problem may not be the KCELLMEAS here,

As you said here, something is waking up the module, and automatically I am getting kcellmeas after 10secs as it is expected according to the reference guides. I think the psm loop issue occurs because of my software, that doesn’t expect that much quick kcellmeas. The problem is that the first wake up by something we dont know ATM.

+CEREG: 4,,,,,,"00001111","00001111"
3957 hl_netfeasa.c 36 |+CEREG: 4,,,,,,"00001111","00001111"|
[00:01:53.961,000] <dbg> modem_hl7812_rx: hl7812_netfeasa_rx: 3959 hl7812_rx_netfeasa.c msg: +CEREG: 4,,,,,,"00001111","00001111"
[00:01:53.961,000] <dbg> modem_hl7812_rx: hl7812_netfeasa_rx: HANDLE +CEREG:  (len:28)
[00:01:53.961,000] <dbg> modem_hl7812_rx: on_cmd_network_report: val: 4,,,,,,"00001111","00001111" stat: -1 urc_res_code: 0
[00:01:53.961,000] <dbg> modem_hl7812_rx: on_cmd_network_report: use URC CEREG parser
[00:01:53.961,000] <dbg> modem_hl7812_rx: on_cmd_network_report: Network status: 4,,,,,,"00001111","00001111"
[00:01:53.961,000] <dbg> modem_hl7812_rx: on_cmd_network_report: network state val: 4   0 valid parsed data: 1
[00:01:53.961,000] <dbg> modem_hl7812: get_network_state_string: get_network_state_string 4
[00:01:53.961,000] <dbg> modem_hl7812: set_network_state: SET NETWORK STATE: OUT_OF_COVERAGE
[00:01:53.961,000] <dbg> modem_hl7812: get_network_state_string: get_network_state_string 4
[00:01:53.961,000] <inf> modem_hl7812: Network State: 4 OUT_OF_COVERAGE
[00:01:53.961,000] <dbg> modem_hl7812: allow_sleep_timeout: Keep sleep 2424
[00:01:53.961,000] <dbg> modem_hl7812: allow_sleep_with_timeout: sleep scheduled
[00:01:53.961,000] <wrn> modem_hl7812: MDM_WAKE_PIN -> NOT_ASSERTED
4,,,,,,"00001111","00001111" 7
[00:01:53.963,000] <wrn> modem_hl7812: MDM_UART_CTS:1(37576660)
[00:01:53.963,000] <dbg> modem_hl7812_rx: on_cmd_network_report: Network supports psm, active_timer: 00001111 tau: 00001111 
[00:01:53.963,000] <dbg> modem_hl7812: allow_sleep_work_callback: 1081 0 1 0 0 

+PSMEV: 1
3957 hl_netfeasa.c 9 |+PSMEV: 1|
[00:01:53.963,000] <dbg> modem_hl7812_rx: hl7812_netfeasa_rx: 3959 hl7812_rx_netfeasa.c msg: +PSMEV: 1
[00:01:53.964,000] <dbg> modem_hl7812_rx: hl7812_netfeasa_rx: HANDLE +PSMEV:  (len:1)
[00:01:53.964,000] <dbg> modem_hl7812_rx: on_cmd_psm_event: PSMEV1: 1 sleep state: AWAKE
[00:01:53.964,000] <dbg> modem_hl7812: allow_sleep: Keep sleep 1032
[00:01:53.964,000] <dbg> modem_hl7812: allow_sleep_with_timeout: sleep scheduled
[00:01:53.964,000] <dbg> modem_hl7812_rx: on_cmd_psm_event: Current pm status: 1
[00:01:53.969,000] <dbg> modem_hl7812: check_hl7812_awake: 289 hl7812_netfeasa.c WHEREamIcallingfrom: 3 
[00:01:53.969,000] <dbg> modem_hl7812: is_cmd_ready: 274 290 LOWPOWER VGPIO:1 GPIO6:1 UART_CTS:1 
[00:01:58.964,000] <dbg> modem_hl7812: allow_sleep_work_callback: 1081 0 1 0 0 

1099 Allow sleep
[00:01:58.964,000] <dbg> modem_hl7812: shutdown_uart: UART pm_device_state_get: 0 1 1 1
[00:01:58.964,000] <wrn> modem_hl7812: Power OFF the UART
[00:01:58.964,000] <wrn> modem_hl7812: VGPIO:0
[00:01:58.964,000] <wrn> modem_hl7812: Preparing IO for reset/sleep
[00:01:58.964,000] <dbg> modem_hl7812: shutdown_uart: UART pm_device_state_get: 0 1 1 0
[00:01:58.964,000] <wrn> modem_hl7812: Power OFF the UART
[00:01:58.964,000] <wrn> modem_hl7812: MDM_WAKE_PIN -> NOT_ASSERTED
[00:01:58.964,000] <wrn> modem_hl7812: MDM_UART_CTS:0(5000488)
[00:01:58.964,000] <wrn> modem_hl7812: MDM_GPIO6:0
[00:01:58.964,000] <dbg> modem_hl7812: shutdown_uart: UART pm_device_state_get: 1 0 0 0
[00:01:58.964,000] <wrn> modem_hl7812: MDM_WAKE_PIN -> NOT_ASSERTED
[00:01:58.964,000] <dbg> modem_hl7812: check_hl7812_awake: 289 hl7812_netfeasa.c WHEREamIcallingfrom: 842 
[00:01:58.964,000] <dbg> modem_hl7812: is_cmd_ready: 274 290 LOWPOWER VGPIO:0 GPIO6:0 UART_CTS:0 
[00:01:58.964,000] <wrn> modem_hl7812: NOT awake
[00:01:58.964,000] <dbg> modem_hl7812: check_hl7812_awake: set_sleep_state(iface_ctx.desired_sleep_level);
[00:01:58.964,000] <dbg> modem_hl7812: set_sleep_state: set_sleep_state was: AWAKE, now: HIBERNATE
[00:01:58.964,000] <dbg> modem_hl7812: set_sleep_state: entered hibernate cancel shutdown work
[00:01:58.964,000] <dbg> modem_hl7812: generate_sleep_state_event: generate_sleep_state_event Sleep State: HIBERNATE gpio6: 0
[00:01:58.964,000] <dbg> modem_module: lte_evt_handler: MODEM MODULE LTE_LC_EVT_MODEM_SLEEP_ENTER
[00:01:58.964,000] <dbg> modem_hl7812: check_hl7812_awake: 289 hl7812_netfeasa.c WHEREamIcallingfrom: 950 
[00:01:58.964,000] <dbg> modem_hl7812: is_cmd_ready: 274 290 LOWPOWER VGPIO:0 GPIO6:0 UART_CTS:0 
[00:01:58.969,000] <dbg> modem_hl7812: check_hl7812_awake: 289 hl7812_netfeasa.c WHEREamIcallingfrom: 3 
[00:01:58.969,000] <dbg> modem_hl7812: is_cmd_ready: 274 290 LOWPOWER VGPIO:0 GPIO6:0 UART_CTS:0 
[00:01:58.985,000] <wrn> modem_hl7812: VGPIO:1
[00:01:58.985,000] <dbg> modem_hl7812: mdm_vgpio_callback_isr: iface_ctx.off2: 0
[00:01:58.985,000] <dbg> modem_hl7812: power_on_uart: UART pm_device_state_get: 1 0
[00:01:58.985,000] <wrn> modem_hl7812: Power ON the UART
[00:01:58.985,000] <dbg> modem_hl7812: allow_sleep: Keep awake 907
[00:01:58.985,000] <dbg> modem_hl7812: allow_sleep_with_timeout: Keep awake
[00:01:58.985,000] <wrn> modem_hl7812: MDM_WAKE_PIN -> ASSERTED
[00:01:58.985,000] <dbg> modem_hl7812: allow_sleep: Keep sleep 911
[00:01:58.985,000] <dbg> modem_hl7812: allow_sleep_with_timeout: sleep scheduled
[00:01:58.985,000] <wrn> modem_hl7812: MDM_UART_CTS:1(20996)
[00:01:58.985,000] <wrn> modem_hl7812: MDM_GPIO6:1
[00:01:58.985,000] <dbg> modem_hl7812: power_on_uart: UART pm_device_state_get: 0 0
[00:01:58.985,000] <dbg> modem_hl7812: allow_sleep: Keep awake 983
[00:01:58.985,000] <dbg> modem_hl7812: allow_sleep_with_timeout: Keep awake
[00:01:58.985,000] <wrn> modem_hl7812: MDM_WAKE_PIN -> ASSERTED
[00:01:58.985,000] <dbg> modem_hl7812: allow_sleep: Keep sleep 987
[00:01:58.985,000] <dbg> modem_hl7812: allow_sleep_with_timeout: sleep scheduled
[00:01:58.985,000] <dbg> modem_hl7812: check_hl7812_awake: 289 hl7812_netfeasa.c WHEREamIcallingfrom: 842 
[00:01:58.985,000] <dbg> modem_hl7812: is_cmd_ready: 274 290 LOWPOWER VGPIO:1 GPIO6:1 UART_CTS:1 
[00:01:58.985,000] <dbg> modem_hl7812: check_hl7812_awake: 289 hl7812_netfeasa.c WHEREamIcallingfrom: 950 
[00:01:58.985,000] <dbg> modem_hl7812: is_cmd_ready: 274 290 LOWPOWER VGPIO:1 GPIO6:1 UART_CTS:1 
[00:01:58.990,000] <dbg> modem_hl7812: check_hl7812_awake: 289 hl7812_netfeasa.c WHEREamIcallingfrom: 3 
[00:01:58.990,000] <dbg> modem_hl7812: is_cmd_ready: 274 290 LOWPOWER VGPIO:1 GPIO6:1 UART_CTS:1 
[00:01:59.054,000] <wrn> modem_hl7812: MDM_UART_CTS:0(69092)
[00:01:59.059,000] <dbg> modem_hl7812: check_hl7812_awake: 289 hl7812_netfeasa.c WHEREamIcallingfrom: 3 
[00:01:59.059,000] <dbg> modem_hl7812: is_cmd_ready: 274 290 LOWPOWER VGPIO:1 GPIO6:1 UART_CTS:0 
[00:01:59.370,000] <wrn> sensor_module: MODEM_EVT_LTE_PSM_ENTER
1464 sensor_module.c
[00:01:59.370,000] <dbg> ext_sensors: ext_sensors_all_power_down: sensor power status: 0
[00:01:59.370,000] <dbg> SENSORS_CMD: sensors_command_parser: Sub cmd: 9 SN+PRESS_CPOF=0
[00:02:00.370,000] <dbg> SENSORS_CMD: sn_command_switch: lps22@5c power down!
{"status":{"status":{"echo":"SN+PRESS_CPOF=0","cmd":"SENSOR","sub_cmd":"DEV_REQ_TURN_OFF","step":"FINISH_TEST","result":"DONE"}},"devices":{"name":"pressure","power":"PM_DEVICE_STATE_OFF"}}
[00:02:00.421,000] <dbg> SENSORS_CMD: sensors_command_parser: Sub cmd: 9 SN+EFLASH_CPOF=0
[00:02:01.421,000] <dbg> SENSORS_CMD: sn_command_switch: mx25r6435f@0 power down!
{"status":{"status":{"echo":"SN+EFLASH_CPOF=0","cmd":"SENSOR","sub_cmd":"DEV_REQ_TURN_OFF","step":"FINISH_TEST","result":"DONE"}},"devices":{"name":"extrnal_memory","power":"PM_DEVICE_STATE_OFF"}}
[00:02:01.455,000] <dbg> SENSORS_CMD: sensors_command_parser: Sub cmd: 9 SN+ACCEL_CPOF=0
[00:02:02.455,000] <dbg> SENSORS_CMD: sn_command_switch: lis2dw12@0 power down!
{"status":{"status":{"echo":"SN+ACCEL_CPOF=0","cmd":"SENSOR","sub_cmd":"DEV_REQ_TURN_OFF","step":"FINISH_TEST","result":"DONE"}},"devices":{"name":"accelorometer","power":"PM_DEVICE_STATE_OFF"}}
1472 sensor_module.c
[00:02:03.985,000] <dbg> modem_hl7812: allow_sleep_work_callback: 1081 0 1 0 0 

1099 Allow sleep
[00:02:03.985,000] <dbg> modem_hl7812: shutdown_uart: UART pm_device_state_get: 0 1 0 1
[00:02:03.985,000] <wrn> modem_hl7812: Power OFF the UART
[00:02:03.985,000] <wrn> modem_hl7812: MDM_WAKE_PIN -> NOT_ASSERTED
[00:02:04.729,000] <wrn> modem_hl7812: MDM_GPIO6:0
[00:02:04.729,000] <dbg> modem_hl7812: shutdown_uart: UART pm_device_state_get: 1 0 0 1
[00:02:04.729,000] <dbg> modem_hl7812: check_hl7812_awake: 289 hl7812_netfeasa.c WHEREamIcallingfrom: 950 
[00:02:04.729,000] <dbg> modem_hl7812: is_cmd_ready: 274 290 LOWPOWER VGPIO:1 GPIO6:0 UART_CTS:0 
[00:02:06.052,000] <wrn> modem_hl7812: MDM_UART_DSR:0
[00:02:06.052,000] <wrn> modem_hl7812: VGPIO:0
[00:02:06.052,000] <wrn> modem_hl7812: Preparing IO for reset/sleep
[00:02:06.052,000] <dbg> modem_hl7812: shutdown_uart: UART pm_device_state_get: 1 0 0 0
[00:02:06.052,000] <wrn> modem_hl7812: MDM_WAKE_PIN -> NOT_ASSERTED
[00:02:06.053,000] <dbg> modem_hl7812: check_hl7812_awake: 289 hl7812_netfeasa.c WHEREamIcallingfrom: 842 
[00:02:06.053,000] <dbg> modem_hl7812: is_cmd_ready: 274 290 LOWPOWER VGPIO:0 GPIO6:0 UART_CTS:0 
[00:02:15.737,000] <dbg> util_module: watchdog_handler: WATCHDOG_EVT_FEED
[00:03:15.737,000] <dbg> util_module: watchdog_handler: WATCHDOG_EVT_FEED

I cant try this one. But I tried something maybe similar to this. I used +KCELLMEAS=0 instead. I ran +KCELLMEAS=0 every 3 secs for 2mins, though, the device never got valid kcellmeas until I started UDP/TCP comms.

My application needs to send data whenever it wakes up. So, thats why I only set kcellmeas=1,10 on time during modem driver initialization.