Hi,
I’m experiencing an issue where any operation seemingly related to the Modem core and MCU core is failing/timing-out.
Device: WP7700
Firmware Image: 9999999_9908397_SWI9X06Y_02.32.02.00_00_TELSTRA_001.035_000-full.spk
Legato: 19.07.1
I can still SSH in to the device, Legato is still running, and all apps are still running.
To illustrate the problem, when I run cm info, it takes ~5 seconds before each line is printed and all the data is “blank”.
root@swi-mdm9x28-wp:/tmp/legato_logs# cm info
Device:
IMEI:
IMEISV:
FSN:
Firmware Version:
Bootloader Version:
MCU Version: 000.000
Carrier PRI Name:
Carrier PRI Revision:
SKU:
Last Reset Cause: Unknown
Resets Count: Expected: 1918 Unexpected: 6
Here’s the corresponding logread capture:
Oct 23 11:16:12 swi-mdm9x28-wp user.warn Legato: -WRN- | supervisor[25906]/supervisor T=main | proc.c GetWatchdogAction() 362 | cm@0 watchdogAction '' in proc section
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | app.c app_Start() 3469 | Starting app 'tools'
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | app.c CreateFileLink() 2083 | Skipping file link '/legato/systems/current/apps/tools/read-only/lib/libComponent_uartMode.so' to '/legato/systems/current/appsWriteable/tools/lib/libC
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | app.c CreateFileLink() 2083 | Skipping file link '/legato/systems/current/apps/tools/read-only/lib/libComponent_secstore.so' to '/legato/systems/current/appsWriteable/tools/lib/libC
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | app.c CreateFileLink() 2083 | Skipping file link '/legato/systems/current/apps/tools/read-only/lib/libComponent_cm.so' to '/legato/systems/current/appsWriteable/tools/lib/libCompone
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | app.c CreateFileLink() 2083 | Skipping file link '/legato/systems/current/apps/tools/read-only/lib/libComponent_moduleLoad.so' to '/legato/systems/current/appsWriteable/tools/lib/li
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | app.c CreateFileLink() 2083 | Skipping file link '/legato/systems/current/apps/tools/read-only/lib/libComponent_fwupdate.so' to '/legato/systems/current/appsWriteable/tools/lib/libC
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | app.c CreateFileLink() 2083 | Skipping file link '/legato/systems/current/apps/tools/read-only/lib/libComponent_pmtool.so' to '/legato/systems/current/appsWriteable/tools/lib/libCom
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | app.c CreateFileLink() 2083 | Skipping file link '/legato/systems/current/apps/tools/read-only/lib/libComponent_le_pa_uartMode_default.so' to '/legato/systems/current/appsWriteable/
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | app.c CreateFileLink() 2083 | Skipping file link '/legato/systems/current/apps/tools/read-only/lib/libComponent_swiQmi.so' to '/legato/systems/current/appsWriteable/tools/lib/libCom
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | app.c CreateFileLink() 2083 | Skipping file link '/legato/systems/current/apps/tools/read-only/lib/libComponent_le_pa_uartMode.so' to '/legato/systems/current/appsWriteable/tools/li
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | app.c CreateFileLink() 2083 | Skipping file link '/legato/systems/current/apps/tools/read-only/lib/libComponent_gnss.so' to '/legato/systems/current/appsWriteable/tools/lib/libCompo
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | app.c CreateFileLink() 2083 | Skipping file link '/legato/systems/current/apps/tools/read-only/bin/cm' to '/legato/systems/current/appsWriteable/tools/bin/cm': Already exists
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | app.c CreateFileLink() 2083 | Skipping file link '/legato/systems/current/apps/tools/read-only/bin/gnss' to '/legato/systems/current/appsWriteable/tools/bin/gnss': Already exists
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | app.c CreateFileLink() 2083 | Skipping file link '/legato/systems/current/apps/tools/read-only/bin/kmod' to '/legato/systems/current/appsWriteable/tools/bin/kmod': Already exists
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | app.c CreateFileLink() 2083 | Skipping file link '/legato/systems/current/apps/tools/read-only/bin/fwupdate' to '/legato/systems/current/appsWriteable/tools/bin/fwupdate': Already e
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | app.c CreateFileLink() 2083 | Skipping file link '/legato/systems/current/apps/tools/read-only/bin/secstore' to '/legato/systems/current/appsWriteable/tools/bin/secstore': Already e
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | app.c CreateFileLink() 2083 | Skipping file link '/legato/systems/current/apps/tools/read-only/bin/uartMode' to '/legato/systems/current/appsWriteable/tools/bin/uartMode': Already e
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | app.c CreateFileLink() 2083 | Skipping file link '/legato/systems/current/apps/tools/read-only/bin/pmtool' to '/legato/systems/current/appsWriteable/tools/bin/pmtool': Already exist
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | app.c CreateFileLink() 2083 | Skipping file link '/legato/systems/current/apps/tools/read-only/lib/libComponent_swiQmi.so' to '/legato/systems/current/appsWriteable/tools/lib/libCom
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | app.c CreateFileLink() 2083 | Skipping file link '/legato/systems/current/apps/tools/read-only/lib/libComponent_le_pa_uartMode.so' to '/legato/systems/current/appsWriteable/tools/li
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | app.c CreateFileLink() 2083 | Skipping file link '/legato/systems/current/apps/tools/read-only/scripts/cm' to '/legato/systems/current/appsWriteable/tools/scripts/cm': Already exist
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | proc.c proc_Start() 1403 | Starting process 'cm@0' with pid 375
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | supervisor.c SigChildHandler() 899 | Reaping unconfigured child process 371.
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[375]/supervisor T=main | proc.c proc_Start() 1363 | Execing 'scripts/cm'
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[375]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxCoreDumpFileBytes to value 8192.
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[375]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxFileBytes to value 90112.
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[375]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxLockedMemoryBytes to value 8192.
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[375]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxFileDescriptors to value 256.
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[375]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxMQueueBytes to value 512.
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[375]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxThreads to value 20.
Oct 23 11:16:12 swi-mdm9x28-wp user.info Legato: INFO | supervisor[375]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxQueuedSignals to value 100.
Oct 23 11:16:12 swi-mdm9x28-wp user.warn Legato: -WRN- | _UNKNOWN_[376]/framework T=main | safeRef.c le_ref_CreateRef() 537 | Safe reference map maximum references exceeded for refFdMonitors.
Oct 23 11:16:17 swi-mdm9x28-wp user.err Legato: =ERR= | modemDaemon[26107]/swiQmi T=main | swiQmi.c swiQmi_CheckResponse() 795 | Sending QMI_DMS_GET_DEVICE_MODEL_ID_REQ_V01 failed: rc=-3 (Timeout), resp.result=0.[0x00], resp.error=0.[0x00]
Oct 23 11:16:17 swi-mdm9x28-wp user.err Legato: =ERR= | modemDaemon[26107]/modemDaemon T=main | le_info.c le_info_GetDeviceModel() 256 | Failed to get the device model
Oct 23 11:16:22 swi-mdm9x28-wp user.err Legato: =ERR= | modemDaemon[26107]/swiQmi T=main | swiQmi.c swiQmi_CheckResponse() 795 | Sending QMI_DMS_GET_DEVICE_SERIAL_NUMBERS_REQ_V01 failed: rc=-3 (Timeout), resp.result=0.[0x00], resp.error=0.[0x00]
Oct 23 11:16:22 swi-mdm9x28-wp user.err Legato: =ERR= | modemDaemon[26107]/modemDaemon T=main | le_info.c le_info_GetImei() 52 | Failed to get the IMEI
Oct 23 11:16:24 swi-mdm9x28-wp user.debug Legato: DBUG | gblScheduler[26067]/framework T=main | timer.c ProcessExpiredTimer() 392 | Timer 'Chain00' expired
Oct 23 11:16:24 swi-mdm9x28-wp user.debug Legato: DBUG | gblScheduler[26067]/framework T=main | timer.c le_timer_Start() 1105 | Starting timer 'Chain00'
Oct 23 11:16:24 swi-mdm9x28-wp user.debug Legato: DBUG | gblScheduler[26067]/framework T=main | timer.c RestartTimerPhys() 289 | timer 'Chain00' started
Oct 23 11:16:27 swi-mdm9x28-wp user.err Legato: =ERR= | modemDaemon[26107]/swiQmi T=main | swiQmi.c swiQmi_CheckResponse() 795 | Sending QMI_DMS_GET_DEVICE_SERIAL_NUMBERS_REQ_V01 failed: rc=-3 (Timeout), resp.result=0.[0x00], resp.error=0.[0x00]
Oct 23 11:16:27 swi-mdm9x28-wp user.err Legato: =ERR= | modemDaemon[26107]/modemDaemon T=main | le_info.c le_info_GetImeiSv() 96 | Failed to get the IMEISV
Oct 23 11:16:32 swi-mdm9x28-wp user.err Legato: =ERR= | modemDaemon[26107]/swiQmi T=main | swiQmi.c swiQmi_CheckResponse() 795 | Sending QMI_DMS_SWI_GET_FSN_REQ_V01 failed: rc=-3 (Timeout), resp.result=0.[0x00], resp.error=0.[0x00]
Oct 23 11:16:32 swi-mdm9x28-wp user.err Legato: =ERR= | modemDaemon[26107]/le_pa T=main | pa_info_qmi.c pa_info_GetPlatformSerialNumber() 1326 | Failed to get the Platform Serial Number string !!
Oct 23 11:16:37 swi-mdm9x28-wp user.err Legato: =ERR= | modemDaemon[26107]/swiQmi T=main | swiQmi.c swiQmi_CheckResponse() 795 | Sending QMI_DMS_GET_DEVICE_REV_ID_REQ_V01 failed: rc=-3 (Timeout), resp.result=0.[0x00], resp.error=0.[0x00]
Oct 23 11:16:42 swi-mdm9x28-wp user.err Legato: =ERR= | modemDaemon[26107]/swiQmi T=main | swiQmi.c swiQmi_CheckResponse() 795 | Sending QMI_DMS_GET_DEVICE_REV_ID_REQ_V01 failed: rc=-3 (Timeout), resp.result=0.[0x00], resp.error=0.[0x00]
Oct 23 11:16:42 swi-mdm9x28-wp user.err kernel: [18077.299703] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:2) mode:FIFO slv_addr:0x3a MSTR_STS:0x091343c8 OPER:0x00000090
Oct 23 11:16:42 swi-mdm9x28-wp user.err kernel: [18077.314611] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:2) mode:FIFO slv_addr:0x3a MSTR_STS:0x091343c8 OPER:0x00000090
Oct 23 11:16:42 swi-mdm9x28-wp user.err kernel: [18077.334343] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:2) mode:FIFO slv_addr:0x3a MSTR_STS:0x0d1300c8 OPER:0x00000090
Oct 23 11:16:42 swi-mdm9x28-wp user.err kernel: [18077.349702] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:2) mode:FIFO slv_addr:0x3a MSTR_STS:0x0d1300c8 OPER:0x00000090
Oct 23 11:16:42 swi-mdm9x28-wp user.err kernel: [18077.367428] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:2) mode:FIFO slv_addr:0x3a MSTR_STS:0x0d1300c8 OPER:0x00000090
Oct 23 11:16:42 swi-mdm9x28-wp user.err kernel: [18077.383423] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:2) mode:FIFO slv_addr:0x3a MSTR_STS:0x0d1300c8 OPER:0x00000090
Oct 23 11:16:42 swi-mdm9x28-wp user.err kernel: [18077.401296] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:2) mode:FIFO slv_addr:0x3a MSTR_STS:0x0d1300c8 OPER:0x00000090
Oct 23 11:16:42 swi-mdm9x28-wp user.err kernel: [18077.416754] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:2) mode:FIFO slv_addr:0x3a MSTR_STS:0x0d1300c8 OPER:0x00000090
Oct 23 11:16:42 swi-mdm9x28-wp user.err kernel: [18077.434025] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:2) mode:FIFO slv_addr:0x3a MSTR_STS:0x0d1300c8 OPER:0x00000090
Oct 23 11:16:42 swi-mdm9x28-wp user.err kernel: [18077.449483] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:2) mode:FIFO slv_addr:0x3a MSTR_STS:0x0d1300c8 OPER:0x00000090
Oct 23 11:16:42 swi-mdm9x28-wp user.err kernel: [18077.467477] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:2) mode:FIFO slv_addr:0x3a MSTR_STS:0x0d1300c8 OPER:0x00000090
Oct 23 11:16:42 swi-mdm9x28-wp user.err kernel: [18077.482978] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:2) mode:FIFO slv_addr:0x3a MSTR_STS:0x0d1300c8 OPER:0x00000090
Oct 23 11:16:42 swi-mdm9x28-wp user.err kernel: [18077.498128] mci_protocol_frame_send: write frame fail to I2C: -107 of 2
Oct 23 11:16:42 swi-mdm9x28-wp user.info kernel: [18077.504336] swimcu_set_fault_mask: 0x1, cnt 18
Oct 23 11:16:42 swi-mdm9x28-wp user.err kernel: [18077.504511] swimcu_ping: Failed to send PING
Oct 23 11:16:47 swi-mdm9x28-wp user.err Legato: =ERR= | modemDaemon[26107]/swiQmi T=main | swiQmi.c swiQmi_CheckResponse() 795 | Sending QMI_DMS_GET_DEVICE_REV_ID_REQ_V01 failed: rc=-3 (Timeout), resp.result=0.[0x00], resp.error=0.[0x00]
Oct 23 11:16:47 swi-mdm9x28-wp user.err Legato: =ERR= | cm[376]/cm T=main | cm_info.c cm_info_PrintGetPriId() 256 | The function failed to get the value.
Oct 23 11:16:52 swi-mdm9x28-wp user.err Legato: =ERR= | modemDaemon[26107]/swiQmi T=main | swiQmi.c swiQmi_CheckResponse() 795 | Sending QMI_DMS_SWI_GET_CWE_PKGS_INFO_REQ_V01 failed: rc=-3 (Timeout), resp.result=0.[0x00], resp.error=0.[0x00]
Oct 23 11:16:52 swi-mdm9x28-wp user.err Legato: =ERR= | modemDaemon[26107]/le_pa T=main | pa_info_qmi.c pa_info_GetCarrierPri() 1196 | PRI ID field option is not valid!!
Oct 23 11:16:57 swi-mdm9x28-wp user.err Legato: =ERR= | modemDaemon[26107]/swiQmi T=main | swiQmi.c swiQmi_CheckResponse() 795 | Sending QMI_DMS_SWI_GET_CWE_PKGS_INFO_REQ_V01 failed: rc=-3 (Timeout), resp.result=0.[0x00], resp.error=0.[0x00]
Oct 23 11:16:57 swi-mdm9x28-wp user.err Legato: =ERR= | modemDaemon[26107]/le_pa T=main | pa_info_qmi.c pa_info_GetSku() 1260 | CheckResponseCode is not valid ! res.-6
Oct 23 11:17:02 swi-mdm9x28-wp user.err Legato: =ERR= | modemDaemon[26107]/swiQmi T=main | swiQmi.c swiQmi_CheckResponse() 795 | Sending QMI_DMS_GET_DEVICE_REV_ID_REQ_V01 failed: rc=-3 (Timeout), resp.result=0.[0x00], resp.error=0.[0x00]
Oct 23 11:17:02 swi-mdm9x28-wp user.err Legato: =ERR= | cm[376]/cm T=main | cm_info.c cm_info_PrintResetCause() 126 | Failed to get last reset cause: LE_FAULT
Oct 23 11:17:02 swi-mdm9x28-wp user.err Legato: =ERR= | modemDaemon[26107]/modemDaemon T=main | le_sms.c CloseSessionEventHandler() 2181 | SessionRef (0x7f5fde10) has been closed
Oct 23 11:17:02 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | proc.c proc_SigChildHandler() 2079 | Process 'cm@0' (PID: 375) has exited with exit code 0.
Oct 23 11:17:02 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | app.c app_StopComplete() 4751 | app 'tools' has stopped.
Oct 23 11:17:02 swi-mdm9x28-wp user.info Legato: INFO | supervisor[25906]/supervisor T=main | apps.c DeactivateAppContainer() 374 | Application 'tools' has stopped.
As you can see, all "qmi" and "MCU" operations fail.
It may be obvious from the log above but worth mentioning that issuing AT commands to /dev/ttyAT also fails - the connection times out.
Unfortunately, I was unable to capture a log event of when this started. However, it began roughly 1 hour after I applied a system update. I saw similar behaviour a day earlier on the same device but it took well over 24 hours before it became problematic.
Please note that the same system update was applied to 4 other devices which aren’t showing this issue.
I’m reluctant to reset the device just yet in case there’s any other valuable information I can extract from it.
Has anyone seen anything like this before?