Unexpected shutdowns on mangOH Red

paulmeis · March 31, 2020, 1:52pm

Hi,

My mangOH Red is having a strange behaviour : the board shutdowns automatically ~30 seconds after it boots.
I can prevent the shutdown by quickly connecting with ssh and doing cm radio off on the board. But as soon as I re-activate radio, the board shutdowns.
By looking at the logs, it seems like something is triggering the PSM of the board (I redirected legato logs to the same output as kernel logs to see everything at once).

[15:25:56:166] Jan  6 02:02:38 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | supervisor.c HandleRebootExpiry() 633 | Expired reboot timer␍␊
[15:27:33:264] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c app_Create() 3258 | Creating app 'tools'␍␊
[15:27:33:264] Jan  6 02:04:14 swi-mdm9x28-wp user.warn Legato: -WRN- | supervisor[1962]/supervisor T=main | proc.c GetWatchdogAction() 362 | cm@0 watchdogAction '' in proc section␍␊
[15:27:33:264] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c app_Start() 3471 | Starting app 'tools'␍␊
[15:27:33:264] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c CreateFileLink() 2154 | Created file link '/legato/systems/current/apps/tools/read-only/lib/libComponent_uartMode.so' to '/legato/systems/current/appsWriteable/tools/lib/libCom␍␊
[15:27:33:307] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c CreateFileLink() 2154 | Created file link '/legato/systems/current/apps/tools/read-only/lib/libComponent_secstore.so' to '/legato/systems/current/appsWriteable/tools/lib/libCom␍␊
[15:27:33:351] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c CreateFileLink() 2154 | Created file link '/legato/systems/current/apps/tools/read-only/lib/libComponent_cm.so' to '/legato/systems/current/appsWriteable/tools/lib/libComponent␍␊
[15:27:33:351] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c CreateFileLink() 2154 | Created file link '/legato/systems/current/apps/tools/read-only/lib/libComponent_moduleLoad.so' to '/legato/systems/current/appsWriteable/tools/lib/libC␍␊
[15:27:33:394] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c CreateFileLink() 2154 | Created file link '/legato/systems/current/apps/tools/read-only/lib/libComponent_fwupdate.so' to '/legato/systems/current/appsWriteable/tools/lib/libCom␍␊
[15:27:33:394] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c CreateFileLink() 2154 | Created file link '/legato/systems/current/apps/tools/read-only/lib/libComponent_pmtool.so' to '/legato/systems/current/appsWriteable/tools/lib/libCompo␍␊
[15:27:33:438] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c CreateFileLink() 2154 | Created file link '/legato/systems/current/apps/tools/read-only/lib/libComponent_le_pa_uartMode_default.so' to '/legato/systems/current/appsWriteable/to␍␊
[15:27:33:438] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c CreateFileLink() 2154 | Created file link '/legato/systems/current/apps/tools/read-only/lib/libComponent_swiQmi.so' to '/legato/systems/current/appsWriteable/tools/lib/libCompo␍␊
[15:27:33:482] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c CreateFileLink() 2154 | Created file link '/legato/systems/current/apps/tools/read-only/lib/libComponent_le_pa_uartMode.so' to '/legato/systems/current/appsWriteable/tools/lib/␍␊
[15:27:33:482] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c CreateFileLink() 2154 | Created file link '/legato/systems/current/apps/tools/read-only/lib/libComponent_gnss.so' to '/legato/systems/current/appsWriteable/tools/lib/libCompone␍␊
[15:27:33:525] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c CreateFileLink() 2154 | Created file link '/legato/systems/current/apps/tools/read-only/bin/cm' to '/legato/systems/current/appsWriteable/tools/bin/cm'.␍␊
[15:27:33:569] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c CreateFileLink() 2154 | Created file link '/legato/systems/current/apps/tools/read-only/bin/gnss' to '/legato/systems/current/appsWriteable/tools/bin/gnss'.␍␊
[15:27:33:569] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c CreateFileLink() 2154 | Created file link '/legato/systems/current/apps/tools/read-only/bin/kmod' to '/legato/systems/current/appsWriteable/tools/bin/kmod'.␍␊
[15:27:33:612] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c CreateFileLink() 2154 | Created file link '/legato/systems/current/apps/tools/read-only/bin/fwupdate' to '/legato/systems/current/appsWriteable/tools/bin/fwupdate'.␍␊
[15:27:33:612] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c CreateFileLink() 2154 | Created file link '/legato/systems/current/apps/tools/read-only/bin/secstore' to '/legato/systems/current/appsWriteable/tools/bin/secstore'.␍␊
[15:27:33:656] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c CreateFileLink() 2154 | Created file link '/legato/systems/current/apps/tools/read-only/bin/uartMode' to '/legato/systems/current/appsWriteable/tools/bin/uartMode'.␍␊
[15:27:33:656] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c CreateFileLink() 2154 | Created file link '/legato/systems/current/apps/tools/read-only/bin/pmtool' to '/legato/systems/current/appsWriteable/tools/bin/pmtool'.␍␊
[15:27:33:700] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c CreateFileLink() 2084 | Skipping file link '/legato/systems/current/apps/tools/read-only/lib/libComponent_swiQmi.so' to '/legato/systems/current/appsWriteable/tools/lib/libComp␍␊
[15:27:33:700] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c CreateFileLink() 2084 | Skipping file link '/legato/systems/current/apps/tools/read-only/lib/libComponent_le_pa_uartMode.so' to '/legato/systems/current/appsWriteable/tools/lib␍␊
[15:27:33:744] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c CreateFileLink() 2154 | Created file link '/legato/systems/current/apps/tools/read-only/scripts/cm' to '/legato/systems/current/appsWriteable/tools/scripts/cm'.␍␊
[15:27:33:744] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | proc.c proc_Start() 1403 | Starting process 'cm@0' with pid 2441␍␊
[15:27:33:786] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | supervisor.c SigChildHandler() 899 | Reaping unconfigured child process 2437.␍␊
[15:27:33:786] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[2441]/supervisor T=main | proc.c proc_Start() 1363 | Execing 'scripts/cm'␍␊
[15:27:33:786] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[2441]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxCoreDumpFileBytes to value 8192.␍␊
[15:27:33:830] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[2441]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxFileBytes to value 90112.␍␊
[15:27:33:830] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[2441]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxLockedMemoryBytes to value 8192.␍␊
[15:27:33:830] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[2441]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxFileDescriptors to value 256.␍␊
[15:27:33:873] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[2441]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxMQueueBytes to value 512.␍␊
[15:27:33:873] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[2441]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxThreads to value 20.␍␊
[15:27:33:917] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[2441]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxQueuedSignals to value 100.␍␊
[15:27:33:917] Jan  6 02:04:14 swi-mdm9x28-wp user.warn Legato: -WRN- | _UNKNOWN_[2442]/framework T=main | safeRef.c le_ref_CreateRef() 547 | Safe reference map maximum exceeded for refFdMonitors, new size 42␍␊
[15:27:33:917] Jan  6 02:04:14 swi-mdm9x28-wp user.warn Legato: -WRN- | cellNetService[2029]/framework T=main | safeRef.c le_ref_CreateRef() 547 | Safe reference map maximum exceeded for refFdMonitors, new size 42␍␊
[15:27:33:960] Jan  6 02:04:14 swi-mdm9x28-wp user.info Legato:  INFO | modemDaemon[2067]/modemDaemon T=main | le_mdc.c CloseSessionEventHandler() 961 | SessionRef 0x7f5fcc98 has been closed␍␊
[15:27:33:960] Jan  6 02:04:14 swi-mdm9x28-wp user.err Legato: =ERR= | modemDaemon[2067]/modemDaemon T=main | le_sms.c CloseSessionEventHandler() 2203 | SessionRef (0x7f5fd1d8) has been closed␍␊
[15:27:33:960] Jan  6 02:04:14 swi-mdm9x28-wp user.warn kernel: [  252.037882] PSM: Modem oprt mode - 0␍␊
[15:27:34:003] Jan  6 02:04:15 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | proc.c proc_SigChildHandler() 2079 | Process 'cm@0' (PID: 2441) has exited with exit code 0.␍␊
[15:27:34:003] Jan  6 02:04:15 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c app_StopComplete() 4753 | app 'tools' has stopped.␍␊
[15:27:34:003] Jan  6 02:04:15 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | apps.c DeactivateAppContainer() 374 | Application 'tools' has stopped.␍␊
[15:27:34:047] Jan  6 02:04:16 swi-mdm9x28-wp user.info Legato:  INFO | dcsDaemon[2038]/dcsCellular T=main | dcsCellular.c DcsCellularPacketSwitchHandler() 726 | Packet switch state: previous 0, new 1␍␊
[15:27:34:047] Jan  6 02:04:16 swi-mdm9x28-wp user.info Legato:  INFO | dcsDaemon[2038]/dcs T=main | dcs_db.c le_dcs_EventNotifierTechStateTransition() 310 | Notify all channels of technology 2 of system state transition to up␍␊
[15:27:34:090] Jan  6 02:04:16 swi-mdm9x28-wp user.err time_daemon_mdm:[672]: tod_update_ind_cb: Got Update from modem msg_id 39␍␊
[15:27:34:090] Jan  6 02:04:16 swi-mdm9x28-wp user.err time_daemon_mdm:[672]: Daemon:read_offset: Sending read request for offset 1␍␊
[15:27:34:090] Jan  6 02:04:16 swi-mdm9x28-wp user.err time_daemon_mdm:[672]: Daemon:read_offset:Time received 1585661253009␍␊
[15:27:34:090] Jan  6 02:04:16 swi-mdm9x28-wp user.err time_daemon_mdm:[672]: genoff_opr: Base = 1, val = 1585661253009, operation = 0␍␊
[15:27:34:090] Jan  6 02:04:16 swi-mdm9x28-wp user.err time_daemon_mdm:[672]: rtc_get: Time read from RTC -- year = 70, month = 0,day = 1␍␊
[15:27:34:134] Jan  6 02:04:16 swi-mdm9x28-wp user.err time_daemon_mdm:[672]: Value read from RTC seconds = 257000␍␊
[15:27:34:134] Jan  6 02:04:16 swi-mdm9x28-wp user.err time_daemon_mdm:[672]: new time 1585661253009 ␍␊
[15:27:34:134] Jan  6 02:04:16 swi-mdm9x28-wp user.err time_daemon_mdm:[672]: delta 1585660996009 genoff 1585660996009 ␍␊
[15:27:34:134] Jan  6 02:04:16 swi-mdm9x28-wp user.err time_daemon_mdm:[672]: genoff_persistent_update: Writing genoff = 1585660996009 to memory␍␊
[15:27:34:177] Jan  6 02:04:16 swi-mdm9x28-wp user.err time_daemon_mdm:[672]: Opening File: /data/time/ats_1␍␊
[15:27:34:177] Jan  6 02:04:16 swi-mdm9x28-wp user.err time_daemon_mdm:[672]: time_persistent_memory_opr:Genoff write operation ␍␊
[15:27:34:177] Jan  6 02:04:16 swi-mdm9x28-wp user.err time_daemon_mdm:[672]: Daemon:read_offset: offset 1 updated␍␊
[15:27:34:177] Jan  6 02:04:16 swi-mdm9x28-wp user.err time_daemon_mdm:[672]: read_offset: Updating system time to sec=1585661253, usec=9000␍␊
[15:27:34:177] Mar 31 15:27:33 swi-mdm9x28-wp user.err time_daemon_mdm:[672]: read_offset: Local Genoff update for base = 1 , rc = 0␍␊
[15:27:58:965] Mar 31 15:27:57 swi-mdm9x28-wp user.warn kernel: [  278.297681] PSM: Supported: 1␍␊
[15:27:58:965] Mar 31 15:27:57 swi-mdm9x28-wp user.warn kernel: [  278.297830] PSM: Auto ready rcvd, tau timer: 21579␍␊
[15:27:58:965] Mar 31 15:27:57 swi-mdm9x28-wp user.warn kernel: [  278.298138] PSM: backup_nv_path /data/psm/psm_nv_backup.txt␍␊
[15:27:58:965] Mar 31 15:27:57 swi-mdm9x28-wp user.warn kernel: [  278.308273] PSM: Sent enter req. Waiting for modem Complete indication.␍␊
[15:27:58:965] Mar 31 15:27:57 swi-mdm9x28-wp user.warn kernel: [  278.439148] PSM: Supported: 1␍␊
[15:27:58:993] Mar 31 15:27:57 swi-mdm9x28-wp user.warn kernel: [  278.439234] PSM: Ready for shutdown␍␊
[15:27:59:087] [  278.663705] swimcu_pm_wusrc_config: check statep->gpio_pin_mask 0x0 ␍␊
[15:27:59:087] [  278.669663] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:22) mode:FIFO slv_addr:0x3a MSTR_STS:0x0c1300c8 OPER:0x00000090␍␊
[15:27:59:087] [  278.685758] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:22) mode:FIFO slv_addr:0x3a MSTR_STS:0x0c1300c8 OPER:0x00000090␍␊
[15:27:59:087] [  278.711784] pm_set_mcu_ulpm_enable: wakeup source setup mask=0x2␍␊
[15:27:59:228] rcK: Executing run_K_scripts... ␍␊
[15:27:59:244] Stopping linkmon: no linkmon found; none killed␍␊
[15:27:59:276] done␍␊
[15:27:59:276] [  278.903820] gbam_disconnect_work: gbam_disconnect_work: Bam channel is not opened␍␊
[15:27:59:297] [  278.925554] [RMNET:HI] rmnet_config_notify_cb(): Kernel is trying to unregister ecm0␍␊
[15:27:59:382] [  279.010394] [RMNET:HI] rmnet_config_notify_cb(): Kernel is trying to unregister ecm0␍␊
[15:27:59:966] Mar 31 15:27:58 swi-mdm9x28-wp user.warn kernel: [  278.654042] PSM: modem_flag_path /data/psm/modem_flag␍␊
[15:27:59:966] Mar 31 15:27:58 swi-mdm9x28-wp user.warn kernel: [  278.658198] PSM: Shutdown Device␍␊
[15:27:59:966] Mar 31 15:27:58 swi-mdm9x28-wp user.warn kernel: [  278.658260] PSM: Supported: 1␍␊
[15:27:59:966] Mar 31 15:27:58 swi-mdm9x28-wp user.warn kernel: [  278.663191] PSMS vendor_shutdown poweroff.␍␊
[15:27:59:966] Mar 31 15:27:58 swi-mdm9x28-wp user.info kernel: [  278.663689] pm_set_mcu_ulpm_enable: SWIMCU_PM_PSM_SYNC - continue sync with MCU␍␊
[15:28:00:010] Mar 31 15:27:58 swi-mdm9x28-wp user.err kernel: [  278.663705] swimcu_pm_wusrc_config: check statep->gpio_pin_mask 0x0 ␍␊
[15:28:00:010] Mar 31 15:27:58 swi-mdm9x28-wp user.info kernel: [  278.669022] swimcu_pm_psm_timer_config: user-selected psm sync option 2␍␊
[15:28:00:010] Mar 31 15:27:58 swi-mdm9x28-wp user.info kernel: [  278.669078] swimcu_pm_psm_time_get: alarm 21860 rtc 282 interval 21578␍␊
[15:28:00:010] Mar 31 15:27:58 swi-mdm9x28-wp user.info kernel: [  278.669088] swimcu_pm_psm_timer_config: configured psm time 21578␍␊
[15:28:00:053] Mar 31 15:27:58 swi-mdm9x28-wp user.info kernel: [  278.669098] swimcu_pm_psm_timer_config: at floor of tempreture variation 21146␍␊
[15:28:00:053] Mar 31 15:27:58 swi-mdm9x28-wp user.info kernel: [  278.669110] swimcu_mdm_sec_to_mcu_time_ms: mdm time=21146 seconds to be calibrated 30000/29253␍␊
[15:28:00:053] Mar 31 15:27:58 swi-mdm9x28-wp user.info kernel: [  278.669121] swimcu_mdm_sec_to_mcu_time_ms: mcu time 21685000 ms + remainder time 980 ms = 21685980 ms␍␊
[15:28:00:053] Mar 31 15:27:58 swi-mdm9x28-wp user.info kernel: [  278.669130] swimcu_pm_psm_timer_config: device calibration 21685980␍␊
[15:28:00:096] Mar 31 15:27:58 swi-mdm9x28-wp user.info kernel: [  278.669141] swimcu_pm_psm_timer_config: sending psm_sync_config sync option 2 max_wait 40000 psm time 21685980␍␊
[15:28:00:096] Mar 31 15:27:58 swi-mdm9x28-wp user.err kernel: [  278.669663] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:22) mode:FIFO slv_addr:0x3a MSTR_STS:0x0c1300c8 OPER:0x00000090␍␊
[15:28:00:096] Mar 31 15:27:58 swi-mdm9x28-wp user.err kernel: [  278.685758] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:22) mode:FIFO slv_addr:0x3a MSTR_STS:0x0c1300c8 OPER:0x00000090␍␊
[15:28:00:140] Mar 31 15:27:58 swi-mdm9x28-wp user.err kernel: [  278.711784] pm_set_mcu_ulpm_enable: wakeup source setup mask=0x2␍␊
[15:28:00:140] Mar 31 15:27:58 swi-mdm9x28-wp user.info kernel: [  278.716765] swimcu_pm_data_store: sending persistent data group 0 to MCU␍␊
[15:28:00:140] Mar 31 15:27:58 swi-mdm9x28-wp user.info kernel: [  278.728277] swimcu_pm_data_store: sending persistent data group 1 to MCU␍␊
[15:28:00:184] Mar 31 15:27:58 swi-mdm9x28-wp user.info kernel: [  278.739897] pm_set_mcu_ulpm_enable: sending ulpm_config␍␊
[15:28:00:184] Mar 31 15:27:58 swi-mdm9x28-wp user.info kernel: [  278.749230] pm_set_mcu_ulpm_enable: Set PSM power off sequence flag to BAM DMUX␍␊
[15:28:00:184] Mar 31 13:27:58 swi-mdm9x28-wp daemon.info : starting pid 2481, tty '': '/etc/init.d/rcK'␍␊
[15:28:00:184] Mar 31 15:27:58 swi-mdm9x28-wp user.info kernel: [  278.902763] diag: USB channel diag disconnected␍␊
[15:28:00:227] Mar 31 15:27:58 swi-mdm9x28-wp user.err kernel: [  278.903820] gbam_disconnect_work: gbam_disconnect_work: Bam channel is not opened␍␊
[15:28:00:227] Mar 31 15:27:58 swi-mdm9x28-wp user.err kernel: [  278.925554] [RMNET:HI] rmnet_config_notify_cb(): Kernel is trying to unregister ecm0␍␊
[15:28:00:227] Mar 31 15:27:58 swi-mdm9x28-wp user.err kernel: [  279.010394] [RMNET:HI] rmnet_config_notify_cb(): Kernel is trying to unregister ecm0␍␊
[15:28:00:227] Mar 31 15:27:58 swi-mdm9x28-wp user.err Legato: =ERR= | dcsDaemon[2038] | ifconfig: ecm0: error fetching interface information: Device not found␍␊
[15:28:00:270] Mar 31 15:27:58 swi-mdm9x28-wp user.info qmi_shutdown_modem: subsystem_control_shutdown␍␊
[15:28:00:270] Mar 31 15:27:58 swi-mdm9x28-wp user.warn kernel: [  279.088924] QTI:LINK_DOWN Processed␍␊
[15:28:00:270] Mar 31 15:27:58 swi-mdm9x28-wp user.err qmi_shutdown_modem: QMUXD: WARNING qmi_qmux_if_pwr_up_init failed! rc=-6␍␊
[15:28:00:270] Mar 31 15:27:58 swi-mdm9x28-wp user.info qmi_shutdown_modem: Initialize QMI DMS Client␍␊
[15:28:00:270] Mar 31 15:27:58 swi-mdm9x28-wp user.warn kernel: [  279.093529] QTI:LINK_DOWN message posted␍␊
[15:28:02:926] Mar 31 15:28:01 swi-mdm9x28-wp user.info qmi_shutdown_modem: In the shutdown path␍␊
[15:28:05:492] Stopping port_bridge: no port_bridge found; none killed␍␊
[15:28:05:604] Stopping qmi_ip: no qmi_ip_multiclient found; none killed␍␊
[15:28:05:643] Stopping eMBMs_TunnelingModule: no eMBMs_TunnelingModule found; none killed␍␊
[15:28:05:684] Stopping netmgrd: stopped netmgrd (pid 1136)␍␊
[15:28:05:700] done␍␊
[15:28:05:732] Stopping qmuxd: stopped qmuxd (pid 1087)␍␊
[15:28:05:780] done␍␊
[15:28:05:860] no QCMAP_ConnectionManager found; none killed␍␊
[15:28:05:880] Stopping fs-scrub-daemon: no fs-scrub-daemon found; none killed␍␊
[15:28:05:959] Mar 31 15:28:04 swi-mdm9x28-wp user.info qmi_shutdown_modem: Success.␍␊
[15:28:05:959] Mar 31 15:28:04 swi-mdm9x28-wp user.info qmi_shutdown_modem: Modem shutdown command failed␍␊
[15:28:05:959] Stopping thermal-engine: stopped thermal-engine (pid 1095)␍␊
[15:28:05:976] done␍␊
[15:28:06:040] stopped qti (pid 1441)␍␊
[15:28:06:056] Stopping reboot daemon: stopped reboot-daemon (pid 1059)␍␊
[15:28:06:072] done␍␊
[15:28:06:103] Legato shutdown sequence␍␊
[15:28:06:312] Stopping Legato.Mar 31 15:28:05 swi-mdm9x28-wp user.warn kernel: [  285.428646] Stopping QCMAP_ConnectionManager: ␍␊
[15:28:06:972] Mar 31 15:28:05 swi-mdm9x28-wp user.warn kernel: [  285.622638] Stopping qti: done␍␊
[15:28:06:972] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c app_Stop() 3596 | Stopping app 'appAccel'␍␊
[15:28:06:972] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | apps.c ShutdownNextApp() 445 | Application 'appAccel' has stopped.␍␊
[15:28:06:972] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c app_Stop() 3596 | Stopping app 'atService'␍␊
[15:28:07:015] Mar 31 15:28:05 swi-mdm9x28-wp user.crit Legato: *CRT* | atClientDaemon[1999]/framework T=main | signals.c TermSignalHandler() 449 | Terminated␍␊
[15:28:07:015] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | watchdog[1977]/watchdogDaemon T=main | watchdog.c CleanUpClosedClient() 355 | Client session closed␍␊
[15:28:07:015] Mar 31 15:28:05 swi-mdm9x28-wp user.crit Legato: *CRT* | atServerDaemon[2000]/framework T=main | signals.c TermSignalHandler() 449 | Terminated␍␊
[15:28:07:058] Mar 31 15:28:05 swi-mdm9x28-wp user.emerg Legato: *EMR* | portDaemon[2077]/framework T=main | messagingSession.c ClientSocketHangUp() 873 | Session closed by server (portDaemon.portDaemon.le_atServer:b7ddff0d499d71d3a23372d9447cbc78).␍␊
[15:28:07:058] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | watchdog[1977]/watchdogDaemon T=main | watchdog.c CleanUpClosedClient() 355 | Client session closed␍␊
[15:28:07:058] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | watchdog[1977]/watchdogDaemon T=main | watchdog.c CleanUpClosedClient() 355 | Client session closed␍␊
[15:28:07:101] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | proc.c proc_SigChildHandler() 2079 | Process 'portDaemon' (PID: 2077) has exited with exit code 1.␍␊
[15:28:07:101] Mar 31 15:28:05 swi-mdm9x28-wp user.crit Legato: *CRT* | supervisor[1962]/supervisor T=main | app.c app_SigChildHandler() 4072 | Process 'portDaemon' in app 'portService' faulted: Restarting process.␍␊
[15:28:07:144] Mar 31 15:28:05 swi-mdm9x28-wp user.err Legato: =ERR= | supervisor[1962]/supervisor T=main | proc.c proc_Start() 1244 | Process 'portDaemon' cannot be started because framework is shutting down.␍␊
[15:28:07:144] Mar 31 15:28:05 swi-mdm9x28-wp user.err Legato: =ERR= | supervisor[1962]/supervisor T=main | app.c app_SigChildHandler() 4078 | Could not restart process 'portDaemon' in app 'portService'.␍␊
[15:28:07:144] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c app_Stop() 3596 | Stopping app 'portService'␍␊
[15:28:07:188] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c app_StopComplete() 4753 | app 'portService' has stopped.␍␊
[15:28:07:188] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | apps.c DeactivateAppContainer() 374 | Application 'portService' has stopped.␍␊
[15:28:07:188] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c app_StopComplete() 4753 | app 'atService' has stopped.␍␊
[15:28:07:231] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | apps.c ShutdownNextApp() 445 | Application 'atService' has stopped.␍␊
[15:28:07:231] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c app_Stop() 3596 | Stopping app 'audioService'␍␊
[15:28:07:231] Mar 31 15:28:05 swi-mdm9x28-wp user.crit Legato: *CRT* | audioDaemon[2009]/framework T=main | signals.c TermSignalHandler() 449 | Terminated␍␊
[15:28:07:275] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | powerManagerService[2096]/powerMgr T=main | le_pm.c OnClientDisconnect() 298 | Client pid 2009 disconnected.␍␊
[15:28:07:275] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | powerManagerService[2096]/powerMgr T=main | le_pm.c OnClientDisconnect() 323 | Deleting wakeup source 'legato_MediaStream_audioDaemon' on behalf of pid 2009.␍␊
[15:28:07:275] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | watchdog[1977]/watchdogDaemon T=main | watchdog.c CleanUpClosedClient() 355 | Client session closed␍␊
[15:28:07:318] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c app_StopComplete() 4753 | app 'audioService' has stopped.␍␊
[15:28:07:318] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | apps.c ShutdownNextApp() 445 | Application 'audioService' has stopped.␍␊
[15:28:07:318] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c app_Stop() 3596 | Stopping app 'avcService'␍␊
[15:28:07:362] Mar 31 15:28:05 swi-mdm9x28-wp user.crit Legato: *CRT* | avcDaemon[2020]/framework T=main | signals.c TermSignalHandler() 449 | Terminated␍␊
[15:28:07:362] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | dcsDaemon[2038]/dcsDaemon T=main | dcsServer.c CloseSessionEventHandler() 1329 | Client 0x7f5a9df0 killed, remove allocated resources␍␊
[15:28:07:362] Mar 31 15:28:05 swi-mdm9x28-wp user.err Legato: =ERR= | modemDaemon[2067]/modemDaemon T=main | le_sms.c CloseSessionEventHandler() 2203 | SessionRef (0x7f5fb488) has been closed␍␊
[15:28:07:405] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | modemDaemon[2067]/modemDaemon T=main | le_mdc.c CloseSessionEventHandler() 961 | SessionRef 0x7f5fb828 has been closed␍␊
[15:28:07:405] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | dcsDaemon[2038]/dcsDaemon T=main | dcsServer.c CloseSessionEventHandler() 1329 | Client 0x7f5aaa58 killed, remove allocated resources␍␊
[15:28:07:405] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | modemDaemon[2067]/modemDaemon T=main | le_mdc.c CloseSessionEventHandler() 961 | SessionRef 0x7f5fbbb8 has been closed␍␊
[15:28:07:449] Mar 31 15:28:05 swi-mdm9x28-wp user.err Legato: =ERR= | modemDaemon[2067]/modemDaemon T=main | le_sms.c CloseSessionEventHandler() 2203 | SessionRef (0x7f5fbf48) has been closed␍␊
[15:28:07:449] Mar 31 15:28:05 swi-mdm9x28-wp user.err Legato: =ERR= | posDaemon[2086]/posDaemon T=main | le_gnss.c CloseSessionEventHandler() 1271 | SessionRef (0x7f577c48) has been closed␍␊
[15:28:07:449] Mar 31 15:28:05 swi-mdm9x28-wp user.err Legato: =ERR= | posDaemon[2086]/posDaemon T=main | le_pos.c PosCloseSessionEventHandler() 1189 | SessionRef (0x7f577bb8) has been closed␍␊
[15:28:07:492] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | watchdog[1977]/watchdogDaemon T=main | watchdog.c CleanUpClosedClient() 355 | Client session closed␍␊
[15:28:07:492] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c app_StopComplete() 4753 | app 'avcService' has stopped.␍␊
[15:28:07:492] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | apps.c ShutdownNextApp() 445 | Application 'avcService' has stopped.␍␊
[15:28:07:536] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c app_Stop() 3596 | Stopping app 'cellNetService'␍␊
[15:28:07:536] Mar 31 15:28:05 swi-mdm9x28-wp user.crit Legato: *CRT* | cellNetService[2029]/framework T=main | signals.c TermSignalHandler() 449 | Terminated␍␊
[15:28:07:536] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | watchdog[1977]/watchdogDaemon T=main | watchdog.c CleanUpClosedClient() 355 | Client session closed␍␊
[15:28:07:579] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c app_StopComplete() 4753 | app 'cellNetService' has stopped.␍␊
[15:28:07:579] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | apps.c ShutdownNextApp() 445 | Application 'cellNetService' has stopped.␍␊
[15:28:07:579] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c app_Stop() 3596 | Stopping app 'dataConnectionService'␍␊
[15:28:07:623] Mar 31 15:28:05 swi-mdm9x28-wp user.crit Legato: *CRT* | dcsInternal[2039]/framework T=main | signals.c TermSignalHandler() 449 | Terminated␍␊
[15:28:07:623] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | watchdog[1977]/watchdogDaemon T=main | watchdog.c CleanUpClosedClient() 355 | Client session closed␍␊
[15:28:07:623] Mar 31 15:28:05 swi-mdm9x28-wp user.crit Legato: *CRT* | dcsDaemon[2038]/framework T=main | signals.c TermSignalHandler() 449 | Terminated␍␊
[15:28:07:666] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | modemDaemon[2067]/modemDaemon T=main | le_mdc.c CloseSessionEventHandler() 961 | SessionRef 0x7f5fad68 has been closed␍␊
[15:28:07:666] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | modemDaemon[2067]/modemDaemon T=main | le_mdc.c CloseSessionEventHandler() 961 | SessionRef 0x7f5fb0f8 has been closed␍␊
[15:28:07:666] Mar 31 15:28:05 swi-mdm9x28-wp user.info Legato:  INFO | watchdog[1977]/watchdogDaemon T=main | watchdog.c CleanUpClosedClient() 355 | Client session closed␍␊
[15:28:07:710] Mar 31 15:28:06 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c app_StopComplete() 4753 | app 'dataConnectionService' has stopped.␍␊
[15:28:07:710] Mar 31 15:28:06 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | apps.c ShutdownNextApp() 445 | Application 'dataConnectionService' has stopped.␍␊
[15:28:07:710] Mar 31 15:28:06 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1962]/supervisor T=main | app.c app_Stop() 3596 | Stopping app 'fwupdateService'␍␊

(I couldn’t put the complete log output here because of topic characters limit but I can post the rest below if needed.)
This behavior appeared some time after I tried to run the ShakeNWake app (source) which uses low power.
This is why I tried removing any custom app from the board, but this did not change anything.
I tried to reset the userspace and re-flash the last firmware with

swiflash -m wp77xx -i red_wp77xx_0.5.0.spk -r

But this did not change anything either.
I also tried to power the board with an external power supply (to provide more current then my PC USB ports) but the behavior did not change.

I am out of ideas, can anyone help me please ?

Thank you in advance !

jyijyi · March 31, 2020, 2:37pm

What is AT!POWERMODE?

paulmeis · March 31, 2020, 3:46pm

Hmm sorry I am not used to AT commands, when I enter AT!POWERMODE? it asks for a password, what am I supposed to enter here ?

jyijyi · March 31, 2020, 4:41pm

You should enter AT command in usb AT port.

paulmeis · April 1, 2020, 7:23am

Result of AT!POWERMODE? is:
!POWERMODE: No request, status=2-Initialized

jyijyi · April 1, 2020, 7:32am

not sure if you can set it to mode 0 to disable the PSM mode.
Please give a try.

paulmeis · April 1, 2020, 8:31am

Thank you for your answers @jyijyi, I also found this post that describes a similar problem.

But when I enter the command AT!PCINFO? I get this:

[10:28:47:916] State: Low Power Mode
[10:28:47:916] LPM voters - Temp:0, Volt:0, User:1, W_DISABLE:0, IMSWITCH:0, BIOS:0, LWM2M:0, OMADM:0, FOTA:0
[10:28:47:916] LPM persistence - User:1

So I guess the LPM is triggered by something in the user space ?

jyijyi · April 1, 2020, 8:49am

is it because you type " cm radio off"?
also you can check AT!IMPREF? to see if the PRI is matching the FW.

paulmeis · April 1, 2020, 9:39am

Yes you are right, when I restart radio with cm radio on I can run AT!PCINFO? before it shuts down and I get this:

[11:33:41:861] State: Online
[11:33:41:861] LPM voters - Temp:0, Volt:0, User:0, W_DISABLE:0, IMSWITCH:0, BIOS:0, LWM2M:0, OMADM:0, FOTA:0␍␊
[11:33:41:861] LPM persistence - None

When I run AT!IMPREF? I get:

[11:33:06:974] !IMPREF: 
[11:33:06:974]  preferred fw version:    02.32.02.00
[11:33:06:974]  preferred carrier name:  SIERRA
[11:33:06:974]  preferred config name:   SIERRA_001.027_000
[11:33:06:974]  preferred subpri index:  001
[11:33:06:974]  current fw version:      02.32.02.00
[11:33:06:974]  current carrier name:    SIERRA
[11:33:06:974]  current config name:     SIERRA_001.027_000
[11:33:06:974]  current subpri index:    001

When I run AT!POWERMODE=0 it correctly disable PSM.
I can see this output when running AT!POWERMODE?:

!POWERMODE: mode=0-DISABLE, status=-12-Not attached to network

But the board still shuts down when I restart radio…
Thanks again for your support !

paulmeis · April 1, 2020, 10:14am

Okay I did it wrong, I was finally able to disable PSM by running (in order):

cm radio on on the mangOH
AT!POWERMODE=0 on USB

Now PSM is disabled and the board stays ON ! The AT!POWERMODE? returns:

!POWERMODE: No request, status=9-PSM disabled

It’s a satisfying workaround for now, but I might have to use PSM in the future… What would you suggest ?

Thank you very much for your support !

jyijyi · April 1, 2020, 11:19am

you can try other value of mode parmeter in AT!powermode

Topic		Replies	Views
mangOH Red + wp7603 – System shutdowns after installing textLoc (Low Power) sample app mangOH Red	7	1291	May 10, 2021
Qcpwrdn shut down issue on WP7603 mangOH Red	6	1391	July 19, 2022
Mangoh Red Crashes after Stopping audioService mangOH Red	1	621	June 20, 2018
Data connection drops randomly and radio powers down mangOH Red	16	1961	March 18, 2019
WP7504 Keeps reseting on mangOH Red but not on mangOH Green mangOH Red	7	1128	September 29, 2017

Unexpected shutdowns on mangOH Red

Related topics