Suddenly unable to enter ULPM

Legato Linux distribution (Yocto project)
1

Having a 5 minute ULPM cycle on a battery powered MangOH Red Rev6 with a WP7607 module.
It works properly for a few hours and suddenly it is impossible to enter ULPM. Any suggestions for workaround is greatly appreciated since this is a showstopper for us.
(devMode and CF3 USB is not used)

Device: WP7607
IMEI: 359779080xxxxx
IMEISV: 6
FSN: VN84220007xxxx
Firmware Version: SWI9X07Y_02.28.03.03 000000 jenkins 2019/05/21 03:33:04
Bootloader Version: SWI9X07Y_02.28.03.03 000000 jenki[34054.693083] 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:0x0c1300c8 OPER:0x00000090
ns 2019/05/21 03:33:04
[34054.709712] 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:0x0c1300c8 OPER:0x00000090
MCU Version: 002.011
PRI Part Number (PN): 9907327
PRI Revision: 001.004
Carrier PRI Name: GENERIC
Carrier PRI Revision: 002.068_000
SKU: 1103511
Last Reset Cause: Reset, User Requested
Resets Count: Expected: 114 Unexpected: 0

dmesg and log here:
[33802.557477] pm_set_mcu_ulpm_enable: SWIMCU_PM_ULPS_ENTER - continue sync with MCU
[33802.558318] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:14) mode:FIFO slv_addr:0x3a MSTR_STS:0x0c1300c8 OPER:0x00000090
[33802.573980] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:14) mode:FIFO slv_addr:0x3a MSTR_STS:0x0c1300c8 OPER:0x00000090
[33802.604573] swimcu_pm_wusrc_config: check statep->gpio_pin_mask 0x0
[33802.609911] swimcu_mdm_sec_to_mcu_time_ms: mdm time=60 seconds to be calibrated 30000/29316
[33802.609925] swimcu_mdm_sec_to_mcu_time_ms: mcu time 61000 ms + remainder time 399 ms = 61399 ms
[33802.622292] swimcu_pm_wusrc_config: ULPM wakeup time 60 (mcu=61399)
[33802.622317] pm_set_mcu_ulpm_enable: wakeup source setup mask=0x2
[33802.627294] swimcu_pm_data_store: sending persistent data group 0 to MCU
[33802.640268] swimcu_pm_data_store: sending persistent data group 1 to MCU
[33802.652713] pm_set_mcu_ulpm_enable: sending wait_time_config
[33802.665236] pm_set_mcu_ulpm_enable: sending ulpm_config<3>[33802.674756] pm_ulpm_config: pm enable fail 1
[33802.678015] pm_set_mcu_ulpm_enable: pm enable fail -5
[33802.684023] swimcu_pm_wusrc_config_reset
[33802.706189] enable_store: Failed to enable mode 6: -5

Sep 17 14:06:08 swi-mdm9x28-wp user.info Legato: INFO | supervisor[850]/supervisor T=main | proc.c proc_Start() 1401 | Starting process ‘pmtool@0’ with pid 18620
Sep 17 14:06:08 swi-mdm9x28-wp user.info Legato: INFO | supervisor[18620]/supervisor T=main | proc.c proc_Start() 1361 | Execing ‘bin/pmtool’
Sep 17 14:06:08 swi-mdm9x28-wp user.info Legato: INFO | supervisor[18620]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxCoreDumpFileBytes to value 8192.
Sep 17 14:06:08 swi-mdm9x28-wp user.info Legato: INFO | supervisor[18620]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxFileBytes to value 90112.
Sep 17 14:06:08 swi-mdm9x28-wp user.info Legato: INFO | supervisor[18620]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxLockedMemoryBytes to value 8192.
Sep 17 14:06:08 swi-mdm9x28-wp user.info Legato: INFO | supervisor[18620]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxFileDescriptors to value 256.
Sep 17 14:06:08 swi-mdm9x28-wp user.info Legato: INFO | supervisor[18620]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxMQueueBytes to value 512.
Sep 17 14:06:08 swi-mdm9x28-wp user.info Legato: INFO | supervisor[18620]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxThreads to value 20.
Sep 17 14:06:08 swi-mdm9x28-wp user.info Legato: INFO | supervisor[18620]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxQueuedSignals to value 100.
Sep 17 14:06:08 swi-mdm9x28-wp user.debug Legato: DBUG | powerManagerService[1476]/framework T=main | unixSocket.c ExtractFileDescriptor() 34 | Received fd (18).
Sep 17 14:06:08 swi-mdm9x28-wp user.debug Legato: DBUG | powerManagerService[1476]/framework T=main | unixSocket.c ExtractFileDescriptor() 34 | Received fd (19).
Sep 17 14:06:08 swi-mdm9x28-wp user.debug Legato: DBUG | powerManagerService[1476]/framework T=main | unixSocket.c ExtractFileDescriptor() 34 | Received fd (20).
Sep 17 14:06:08 swi-mdm9x28-wp user.info Legato: INFO | powerManagerService[1476]/powerMgr T=main | le_pm.c OnClientConnect() 270 | Connection from client pmtool/18620
Sep 17 14:06:08 swi-mdm9x28-wp user.info kernel: [34154.391679] pm_set_mcu_ulpm_enable: Request PM 1
Sep 17 14:06:08 swi-mdm9x28-wp user.info kernel: [34154.392189] pm_set_mcu_ulpm_enable: SWIMCU_PM_ULPS_ENTER - continue sync with MCU
Sep 17 14:06:08 swi-mdm9x28-wp user.err kernel: [34154.392568] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:14) mode:FIFO slv_addr:0x3a MSTR_STS:0x001363c8 OPER:0x00000090
Sep 17 14:06:08 swi-mdm9x28-wp user.err kernel: [34154.407467] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:14) mode:FIFO slv_addr:0x3a MSTR_STS:0x001363c8 OPER:0x00000090
Sep 17 14:06:08 swi-mdm9x28-wp user.debug Legato: DBUG | powerManagerService[1476]/framework T=main | le_ulpm_server.c CleanupClientData() 160 | Client 0x7f5740d8 is closed !!!
Sep 17 14:06:08 swi-mdm9x28-wp user.debug Legato: DBUG | powerManagerService[1476]/framework T=main | le_bootReason_server.c CleanupClientData() 160 | Client 0x7f574318 is closed !!!
Sep 17 14:06:08 swi-mdm9x28-wp user.info Legato: INFO | powerManagerService[1476]/powerMgr T=main | le_pm.c OnClientDisconnect() 298 | Client pid 18620 disconnected.
Sep 17 14:06:08 swi-mdm9x28-wp user.debug Legato: DBUG | powerManagerService[1476]/framework T=main | le_pm_server.c CleanupClientData() 160 | Client 0x7f574288 is closed !!!
Sep 17 14:06:08 swi-mdm9x28-wp user.info Legato: INFO | supervisor[850]/supervisor T=main | proc.c proc_SigChildHandler() 2077 | Process ‘pmtool@0’ (PID: 18620) has exited with exit code 0.
Sep 17 14:06:08 swi-mdm9x28-wp user.info Legato: INFO | supervisor[850]/supervisor T=main | app.c app_StopComplete() 4751 | app ‘tools’ has stopped.
Sep 17 14:06:08 swi-mdm9x28-wp user.info Legato: INFO | supervisor[850]/supervisor T=main | apps.c DeactivateAppContainer() 374 | Application ‘tools’ has stopped.
Sep 17 14:06:09 swi-mdm9x28-wp user.err kernel: [34154.449565] swimcu_pm_wusrc_config: check statep->gpio_pin_mask 0x0
Sep 17 14:06:09 swi-mdm9x28-wp user.info kernel: [34154.455199] swimcu_mdm_sec_to_mcu_time_ms: mdm time=60 seconds to be calibrated 30000/29316
Sep 17 14:06:09 swi-mdm9x28-wp user.info kernel: [34154.455212] swimcu_mdm_sec_to_mcu_time_ms: mcu time 61000 ms + remainder time 399 ms = 61399 ms
Sep 17 14:06:09 swi-mdm9x28-wp user.info kernel: [34154.464298] swimcu_pm_wusrc_config: ULPM wakeup time 60 (mcu=61399)
Sep 17 14:06:09 swi-mdm9x28-wp user.err kernel: [34154.464316] pm_set_mcu_ulpm_enable: wakeup source setup mask=0x2
Sep 17 14:06:09 swi-mdm9x28-wp user.info kernel: [34154.469291] swimcu_pm_data_store: sending persistent data group 0 to MCU
Sep 17 14:06:09 swi-mdm9x28-wp user.info kernel: [34154.480447] swimcu_pm_data_store: sending persistent data group 1 to MCU
Sep 17 14:06:09 swi-mdm9x28-wp user.info kernel: [34154.489761] pm_set_mcu_ulpm_enable: sending wait_time_config
Sep 17 14:06:09 swi-mdm9x28-wp user.info kernel: [34154.501806] pm_set_mcu_ulpm_enable: sending ulpm_config<3>[34154.509862] pm_ulpm_config: pm enable fail 1
Sep 17 14:06:09 swi-mdm9x28-wp user.err kernel: [34154.514289] pm_set_mcu_ulpm_enable: pm enable fail -5
Sep 17 14:06:09 swi-mdm9x28-wp user.info kernel: [34154.518400] swimcu_pm_wusrc_config_reset
Sep 17 14:06:09 swi-mdm9x28-wp user.err kernel: [34154.542615] swimcu_psm_enable_attr_store: Failed to enable mode 6: -5

2

Hi @Redferne.

I’ve also recently experienced this albeit with WP7700 modules on custom boards.

Our application is designed to wake-up, do some work for roughly 1 minute, then enter ULPM and sleep for the remainder of the hour. For the most part, this works and can do so for weeks/months but there’s a slim chance it won’t and this is a showstopper for us, too.

Its unfortunate but the return value of le_ulpm_ShutDown simply reports the result of initiation to ULPM. There’s no guarantee that the shutdown will actually succeed!

Additionally, le_bootReason_WasTimer sometimes reports false after waking up from a Timer Boot. In fact, it did so on the interval captured in the log below.
Maybe this is a clue? It wasn’t able to establish comms with the swi power management MCU during/after boot?

I’m also in the same boat as you - hoping for a fix or a solid workaround.

Legato version:               19.01.0_631a5d541f3e7e96db241b33d94a4a29

Device:                        WP7700
IMEI:                          3538050901xxxxx
IMEISV:                        2
FSN:                           W8912100xxxxxx
Firmware Version:              SWI9X06Y_02.16.06.00 7605a6 jenkins 2018/06/20 17:56:12
Bootloader Version:            SWI9X06Y_02.16.06.00 7605a6 jenkins 2018/06/20 17:56:12
MCU Version:                   002.009
PRI Part Number (PN):          9908049
PRI Revision:                  001.002
Carrier PRI Name:              GENERIC
Carrier PRI Revision:          001.028_001
SKU:                           1103736

Log:

Jan  6 00:08:35 swi-mdm9x28-wp user.debug Legato:  DBUG | logFileService[933]/logFileServiceComponent T=main | logFileService.c writeToLogFile() 253 | Log File Entry: 06/01/1980 00:08:35 | DEBUG | Enter ULPM for 00:50:15.
Jan  6 00:08:35 swi-mdm9x28-wp user.debug Legato:  DBUG | logFileService[933]/logFileServiceComponent T=main | logFileService.c writeToLogFile() 253 | Log File Entry: 06/01/1980 00:08:35 | INFO | -
Jan  6 00:08:35 swi-mdm9x28-wp user.debug Legato:  DBUG | logFileService[933]/logFileServiceComponent T=main | logFileService.c writeToLogFile() 253 | Log File Entry: 06/01/1980 00:08:35 | INFO | Initiating 'ULPM Sleep' shutdown.
Jan  6 00:08:35 swi-mdm9x28-wp user.debug Legato:  DBUG | logFileService[933]/logFileServiceComponent T=main | logFileService.c writeToLogFile() 253 | Log File Entry: 06/01/1980 00:08:35 | INFO | Shutting down...
Jan  6 00:08:35 swi-mdm9x28-wp user.info Legato:  INFO | watchdog[817]/watchdogDaemon T=main | watchdog.c CleanUpClosedClient() 355 | Client session closed
Jan  6 00:08:35 swi-mdm9x28-wp user.debug Legato:  DBUG | scheduler[915]/framework T=main | le_wdog_client.c le_wdog_DisconnectService() 529 | ======= Stopping client for 'scheduler.watchdogChain.le_wdog' service ========
Jan  6 00:08:35 swi-mdm9x28-wp user.warn kernel: [  410.656580] PSM: Server Healthcheck timerid : 2136631240
Jan  6 00:08:35 swi-mdm9x28-wp user.warn kernel: [  410.656650] PSM: Supported: 0
Jan  6 00:08:35 swi-mdm9x28-wp user.warn kernel: [  410.657929] PSM: Client health check timerid : -1244657360
Jan  6 00:08:35 swi-mdm9x28-wp user.err kernel: [  410.658303] swimcu_pm_wusrc_config: check statep->gpio_pin_mask 0x0
Jan  6 00:08:35 swi-mdm9x28-wp user.info kernel: [  410.664171] swimcu_mdm_sec_to_mcu_time_ms: mdm time=3015 seconds to be calibrated 500/485
Jan  6 00:08:35 swi-mdm9x28-wp user.info kernel: [  410.664186] swimcu_mdm_sec_to_mcu_time_ms: mcu time 3108000 ms + remainder time 3108 ms = 3111108 ms
Jan  6 00:08:35 swi-mdm9x28-wp user.err kernel: [  410.665080] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:18) mode:FIFO slv_addr:0x3a MSTR_STS:0x0c1300c8 OPER:0x00000090
Jan  6 00:08:35 swi-mdm9x28-wp user.err kernel: [  410.683257] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:18) mode:FIFO slv_addr:0x3a MSTR_STS:0x0c1300c8 OPER:0x00000090
Jan  6 00:08:35 swi-mdm9x28-wp user.err kernel: [  410.701352] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:18) mode:FIFO slv_addr:0x3a MSTR_STS:0x0c1300c8 OPER:0x00000090
Jan  6 00:08:35 swi-mdm9x28-wp user.err kernel: [  410.721698] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:18) mode:FIFO slv_addr:0x3a MSTR_STS:0x0c1300c8 OPER:0x00000090
Jan  6 00:08:35 swi-mdm9x28-wp user.err kernel: [  410.739429] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:18) mode:FIFO slv_addr:0x3a MSTR_STS:0x0c1300c8 OPER:0x00000090
Jan  6 00:08:35 swi-mdm9x28-wp user.err kernel: [  410.757643] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:18) mode:FIFO slv_addr:0x3a MSTR_STS:0x0c1300c8 OPER:0x00000090
Jan  6 00:08:35 swi-mdm9x28-wp user.err kernel: [  410.773369] mci_protocol_frame_send: write frame fail to I2C: -107 of 18
Jan  6 00:08:35 swi-mdm9x28-wp user.info kernel: [  410.778938] swimcu_set_fault_mask: 0x1, cnt 2
Jan  6 00:08:35 swi-mdm9x28-wp user.err kernel: [  410.779115] Failed to send request c2 (-105)
Jan  6 00:08:35 swi-mdm9x28-wp user.err kernel: [  410.783811] swimcu_pm_wusrc_config: timer wu fail -105
Jan  6 00:08:35 swi-mdm9x28-wp user.info kernel: [  410.788488] swimcu_pm_wusrc_config_reset
Jan  6 00:08:35 swi-mdm9x28-wp user.warn kernel: [  410.789102] PSM: Supported: 0
Jan  6 00:34:28 swi-mdm9x28-wp user.info Legato:  INFO | modemDaemon[939]/le_pa T=main | pa_mrc_qmi.c pa_mrc_GetNetworkRegState() 2332 | called
Jan  6 00:34:28 swi-mdm9x28-wp user.info Legato:  INFO | dcsDaemon[862]/dcsCellular T=main | dcsCellular.c DcsCellularPacketSwitchHandler() 671 | Packet switch state: previous 0, new 1
Jan  6 00:34:28 swi-mdm9x28-wp user.info Legato:  INFO | dcsDaemon[862]/dcs T=main | dcs_db.c le_dcs_EventNotifierTechStateTransition() 210 | Notify all channels of technology 2 of system state transition to up
Jan  6 00:34:28 swi-mdm9x28-wp user.debug Legato:  DBUG | logFileService[933]/logFileServiceComponent T=main | logFileService.c writeToLogFile() 253 | Log File Entry: 06/01/1980 00:34:28 | DIAG | -
Jan  6 00:34:28 swi-mdm9x28-wp user.debug Legato:  DBUG | logFileService[933]/logFileServiceComponent T=main | logFileService.c writeToLogFile() 253 | Log File Entry: 06/01/1980 00:34:28 | DIAG | Current Cellular Network state is [Home network]
Jan  6 00:34:34 swi-mdm9x28-wp user.err time_daemon_mdm:[608]: tod_update_ind_cb: Got Update from modem msg_id 39
Jan  6 00:34:34 swi-mdm9x28-wp user.err time_daemon_mdm:[608]: Daemon:read_offset: Sending read request for offset 1
Jan  6 00:34:34 swi-mdm9x28-wp user.err time_daemon_mdm:[608]: Daemon:read_offset:Time received 1568691217010
Jan  6 00:34:34 swi-mdm9x28-wp user.err time_daemon_mdm:[608]: genoff_opr: Base = 1, val = 1568691217010, operation = 0
Jan  6 00:34:34 swi-mdm9x28-wp user.err time_daemon_mdm:[608]: rtc_get: Time read from RTC -- year = 70, month = 0,day = 1
Jan  6 00:34:34 swi-mdm9x28-wp user.err time_daemon_mdm:[608]: Value read from RTC seconds = 2074000
Jan  6 00:34:34 swi-mdm9x28-wp user.err time_daemon_mdm:[608]: new time 1568691217010
Jan  6 00:34:34 swi-mdm9x28-wp user.err time_daemon_mdm:[608]: delta 1568689143010 genoff 1568689143010
Jan  6 00:34:34 swi-mdm9x28-wp user.err time_daemon_mdm:[608]: genoff_persistent_update: Writing genoff = 1568689143010 to memory
Jan  6 00:34:34 swi-mdm9x28-wp user.err time_daemon_mdm:[608]: Opening File: /data/time/ats_1
Jan  6 00:34:34 swi-mdm9x28-wp user.err time_daemon_mdm:[608]: time_persistent_memory_opr:Genoff write operation
Jan  6 00:34:34 swi-mdm9x28-wp user.err time_daemon_mdm:[608]: Daemon:read_offset: offset 1 updated
Jan  6 00:34:34 swi-mdm9x28-wp user.err time_daemon_mdm:[608]: read_offset: Updating system time to sec=1568691217, usec=10000
Sep 17 03:33:37 swi-mdm9x28-wp user.err time_daemon_mdm:[608]: read_offset: Local Genoff update for base = 1 , rc = 0
*** Device remains awake ...***

***...CF3 USB connected several hours later ***
Sep 17 03:59:04 swi-mdm9x28-wp user.info kernel: [ 3497.393219] gpio_check_and_wake: wake-n_gpio26 STATE=WAKEUP
Sep 17 03:59:04 swi-mdm9x28-wp user.info kernel: [ 3497.398948] gpio_check_and_wake: wake-n_gpio26 STATE=SLEEP
Sep 17 04:54:38 swi-mdm9x28-wp user.info kernel: [ 6831.694727] msm_otg 78d9000.usb: USB exited from low power mode
Sep 17 04:54:39 swi-mdm9x28-wp user.info kernel: [ 6831.795609] msm_hsusb msm_hsusb: CI13XXX_CONTROLLER_RESUME_EVENT received
Sep 17 04:54:39 swi-mdm9x28-wp user.info kernel: [ 6831.795702] msm_otg 78d9000.usb: Avail curr from USB = 100
Sep 17 04:54:39 swi-mdm9x28-wp user.info kernel: [ 6831.795815] android_work: android_work: did not send uevent (0 0 00000000)
Sep 17 04:54:39 swi-mdm9x28-wp user.info kernel: [ 6831.842462] android_work: android_work: sent uevent USB_STATE=CONNECTED
Sep 17 04:54:39 swi-mdm9x28-wp user.info kernel: [ 6831.875413] android_usb gadget: high-speed config #1: 86000c8.android_usb
Sep 17 04:54:39 swi-mdm9x28-wp user.info kernel: [ 6831.875455] diag: USB channel diag connected
Sep 17 04:54:39 swi-mdm9x28-wp user.info kernel: [ 6831.875558] msm_otg 78d9000.usb: Avail curr from USB = 500
Sep 17 04:54:39 swi-mdm9x28-wp user.err kernel: [ 6831.875958] gbam_connect_work: gbam_connect_work: Bam channel is not ready
Sep 17 04:54:39 swi-mdm9x28-wp user.info kernel: [ 6831.940289] android_work: android_work: sent uevent USB_STATE=CONFIGURED
Sep 17 04:54:40 swi-mdm9x28-wp user.warn kernel: [ 6833.021359] QTI:USB tethered modem SMD port opened
Sep 17 04:54:40 swi-mdm9x28-wp user.err kernel: [ 6833.023289] msm_hsusb msm_hsusb: [ep_queue] request already in queue
Sep 17 04:54:45 swi-mdm9x28-wp user.info kernel: [ 6838.205670] IPv6: ADDRCONF(NETDEV_CHANGE): ecm0: link becomes ready
Sep 17 04:54:45 swi-mdm9x28-wp user.warn kernel: [ 6838.246936] QTI:LINK_UP Processed
Sep 17 04:54:45 swi-mdm9x28-wp user.warn kernel: [ 6838.248918] QTI:ECM mode
Sep 17 04:54:45 swi-mdm9x28-wp user.warn kernel: [ 6838.255298] QTI:LINK_UP message posted
3

Also reported here: ULPM fimrware version 002.011 doesn't work for wp77xx

4

We did a little more testing with Release 12 (MCU Version: 002.013). It looks like any call to pmtool shutdown (or a write to /sys/module/swimcu_pm/boot_source/enable will enable PSM and thus disallow ULPM. After the request has been made, it is possible to disable PSM through the AT command AT+CPSMS=0 at which point the device enters ULPM mode.

It is impossible to disable the PSM mode before hand because it seems that the ULPM shutdown request itself is what is enabling the PSM in the first place thus preventing the shutdown. So a theoretical way to have this work is to have the application software write to the sysfs file and then to send the AT command, not ideal but it could work.

I have not done any reliability testing on this solution.

5

I’ve seen this PSM issue on a WP7702 module here as well. The workaround to forcefully disable PSM using AT+CPSMS=0 seems to work, but maybe it’s just luck. However just now a saw yet another issue with ULPM on a WP7607 (which does not have PSM, using LTE Cat-4 or Cat-1). Application can get stuck with this error:

Jan  6 02:32:28 swi-mdm9x28-wp user.err kernel: [  114.656869] pm_set_mcu_ulpm_enable: ULPM REQ (6) is not supported on this module
Jan  6 02:32:28 swi-mdm9x28-wp user.info kernel: [  114.663514] pm_set_mcu_ulpm_enable: Request PM 1
Jan  6 02:32:28 swi-mdm9x28-wp user.err kernel: [  114.690294] swimcu_psm_enable_attr_store: Failed to enable mode 6: -22

@elliotmr What module are you using? MCU Version 002.013 is different from 002.011 which is what’s running here.

6

I am using a WP7700 with Legato 19.07.1 (from leaf).

Device:                        WP7700
IMEI:                          xxxx
IMEISV:                        4
FSN:                           xxxx
Firmware Version:              SWI9X06Y_02.32.02.00 c2e98c jenkins 2019/08/30 07:28:21
Bootloader Version:            SWI9X06Y_02.32.02.00 c2e98c jenkins 2019/08/30 07:28:21
MCU Version:                   002.013
PRI Part Number (PN):          9908049
PRI Revision:                  001.002
Carrier PRI Name:              ATT
Carrier PRI Revision:          001.051_000
SKU:                           1103736
Last Reset Cause:              Power Down
Resets Count:                  Expected: 23     Unexpected: 3
7

Funny thing. I upgraded the WP7607 to R13.2 and rebuilt the system with Legato 19.07.1 and I’m no longer seeing this issue. Happy days!

8

This all looks promising. I shall upgrade, rebuild, and run some tests.

From the WP77xx R12 Release Notes:
https://source.sierrawireless.com/resources/airprime/software/release_notes/wp77xx-release-12-customer-release-notes/

Page 9, QTI9X06-208, Update MCU FW to version 002.013:

MCU FW Version has been updated to 002.013 in this release.

Includes bug fix:
• MCU-104 / QTI9X07-3371 - I2C bus failure occurs when reading ADC2 and entering ULPM

In some corner cases with MCU communication, such as reading ADC2 (from MCU) when ULPM mode is requested, an I2C bus failure occurs.
The I2C bus failure prevents all future communication with MCU or any other devices on the I2C bus after resuming from ULPM. This issue was fixed in MCU FW 002.013.

However, be aware of this Known Issue:

Page 25, QTI9X06-192, Device will not enter ULPM/PSM mode if GPIO36/38 is selected as the wakeup source:

If GPIOs 36 and 38 are configured as a wakeup source with logic level high as the wakeup trigger, the device is unable to enter PSM or ULPM. The issue doesn’t happen when using all other types of wakeup triggers.

Also, no mention of what @elliotmr found with PSM enabling after a request to ULPM shutdown - so be wary of that, too.

1 Like
9

I also can confirm the exact same behaviour as @elliotmr and @Redferne with Release 12 for WP7700 and Legato 19.07.1 from Leaf.

PSM is automatically enabled after a call to le_ulpm_ShutDown. The device will not enter ULPM.

Disabling PSM via AT command after a request to enter ULPM puts the device into ULPM.

It’s a hack but I’ve had success with this running on a device for 5 days now, with the device entering ULPM for ~28 minutes every 30 minutes (48 times p/day):

if (le_ulpm_ShutDown() == LE_OK) {
  // wait for background psm-trickery to complete...
  sleep(5);

  // forcefully disable PSM - error handling omitted for brevity
  FILE *fp = popen("echo -e \"at+cpsms=0\r\n\" > /dev/ttyAT", "r");
  pclose(fp);
}

Log:

** > le_ulpm_BootOnTimer() is called with 1895 seconds **
** > le_ulpm_ShutDown() is called and returned LE_OK **
swi-mdm9x28-wp user.info Legato:  INFO | scheduler[3866]/schedulerComponent T=main | schedulerComponent.c psmOverride() 919 | Forcefully disable PSM...
** > sleep for 5 seconds while background psm stuff happens **
Oct  9 01:27:15 swi-mdm9x28-wp user.info kernel: [  863.914399] pm_set_mcu_ulpm_enable: Request PM 1
Oct  9 01:27:15 swi-mdm9x28-wp user.warn kernel: [  864.028585] PSM: backup_nv_path /data/psm/psm_nv_backup.txt
** > popen("echo -e \"at+cpsms=0\r\n\" > /dev/ttyAT", "r") is run to disable psm**
Oct  9 01:27:20 swi-mdm9x28-wp user.info kernel: [  868.934683] pm_set_mcu_ulpm_enable: SWIMCU_PM_ULPS_ENTER - continue sync with MCU
Oct  9 01:27:20 swi-mdm9x28-wp user.err kernel: [  868.934706] swimcu_pm_wusrc_config: check statep->gpio_pin_mask 0x0
Oct  9 01:27:20 swi-mdm9x28-wp user.warn kernel: [  868.940972] PSM: backup_nv_path /data/psm/psm_nv_backup.txt
Oct  9 01:27:20 swi-mdm9x28-wp user.info kernel: [  868.951081] swimcu_mdm_sec_to_mcu_time_ms: mdm time=1895 seconds to be calibrated 30000/29338
Oct  9 01:27:20 swi-mdm9x28-wp user.info kernel: [  868.951099] swimcu_mdm_sec_to_mcu_time_ms: mcu time 1937000 ms + remainder time 759 ms = 1937759 ms
** > MCU I2C communication issues are still observed but it seems to work regardless **
Oct  9 01:27:20 swi-mdm9x28-wp user.err kernel: [  868.951984] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:18) mode:FIFO slv_addr:0x3a MSTR_STS:0x0c1300c8 OPER:0x00000090
Oct  9 01:27:20 swi-mdm9x28-wp user.err kernel: [  868.967376] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:18) mode:FIFO slv_addr:0x3a MSTR_STS:0x0c1300c8 OPER:0x00000090
Oct  9 01:27:20 swi-mdm9x28-wp user.info kernel: [  868.991007] swimcu_pm_wusrc_config: ULPM wakeup time 1895 (mcu=1937759)
Oct  9 01:27:20 swi-mdm9x28-wp user.err kernel: [  868.991023] pm_set_mcu_ulpm_enable: wakeup source setup mask=0x2
Oct  9 01:27:20 swi-mdm9x28-wp user.info kernel: [  868.995998] swimcu_pm_data_store: sending persistent data group 0 to MCU
Oct  9 01:27:20 swi-mdm9x28-wp user.info kernel: [  869.008137] swimcu_pm_data_store: sending persistent data group 1 to MCU
Oct  9 01:27:20 swi-mdm9x28-wp user.info kernel: [  869.019425] pm_set_mcu_ulpm_enable: sending wait_time_config
Connection reset by 192.168.2.2 port 22
** > Device is in ULPM **

Module Info:

Device:                        WP7700
IMEI:                          xxxxxxxxxxxxxxx
IMEISV:                        4
FSN:                           xxxxxxxxxxxxxx
Firmware Version:              SWI9X06Y_02.32.02.00 c2e98c jenkins 2019/08/30 07:28:21
Bootloader Version:            SWI9X06Y_02.32.02.00 c2e98c jenkins 2019/08/30 07:28:21
MCU Version:                   002.013
PRI Part Number (PN):          9908049
PRI Revision:                  001.002
Carrier PRI Name:              GENERIC
Carrier PRI Revision:          001.055_000
SKU:                           1103736
Last Reset Cause:              Power Down
Resets Count:                  Expected: 1859   Unexpected: 2
10

hi @raf,
could you please check the responses of the following commands
AT!POWERMODE?
AT! POWERWAKE?
before calling le_ulpm_ShutDown() and after calling it, without using at+cpsms command?
Best Regards

11

Hi @plu,

Thanks for the response. I used pmtool instead for simplicity. See below.

Note: This was peformed after a clean reboot.

BEFORE calling pmtool bootOn timer 60; pmtool shutdown

at!powermode?
!POWERMODE: No request, status=2-Initialized

OK
at!powerwake?
!POWERWAKE:
PSM TIMER: 35712000,ACTIVE TIMER:2880,SYNC: 2

OK

AFTER calling pmtool bootOn timer 60; pmtool shutdown

at!powermode?
!POWERMODE: No request, status=8-PSM enabled

OK
at!powerwake?
!POWERWAKE:
ULPM TIMER: 60
PSM TIMER: 35712000,ACTIVE TIMER:2880,SYNC: 2

OK

Capture of entire process through logread -f:

root@swi-mdm9x28-wp:~# logread -f
Oct 21 14:20:27 swi-mdm9x28-wp user.info swiapp: qmi_at_unsol_ind_cb: ind id:33
Oct 21 14:20:27 swi-mdm9x28-wp user.info swiapp: Received AT command forward request from modem
Oct 21 14:20:27 swi-mdm9x28-wp user.info swiapp: fwdcmd.opcode=5
Oct 21 14:20:27 swi-mdm9x28-wp user.info swiapp: fwdcmd.name=!powermode
Oct 21 14:20:27 swi-mdm9x28-wp user.info swiapp: fwdcmd.ntokens=1
Oct 21 14:20:27 swi-mdm9x28-wp user.info swiapp: ctrCond signalling complete.
Oct 21 14:20:27 swi-mdm9x28-wp user.info swiapp: Recieved ctrCond: p: 0, S:0, nr: 1
Oct 21 14:20:27 swi-mdm9x28-wp user.info swiapp: POWERMODE has been detected
Oct 21 14:20:27 swi-mdm9x28-wp user.info swiapp: resp. buffer is ^M !POWERMODE: No request, status=2-Initialized^M
Oct 21 14:20:27 swi-mdm9x28-wp user.info swiapp: resp_length is 61
Oct 21 14:20:27 swi-mdm9x28-wp user.info swiapp: AT response Buffer ^M !POWERMODE: No request, status=2-Initialized^M
Oct 21 14:20:27 swi-mdm9x28-wp user.info swiapp: AT Resp-buffer Len 61
Oct 21 14:20:27 swi-mdm9x28-wp user.info swiapp: sending QMI_AT_FWD_RESP_AT_CMD_REQ_V01 message
Oct 21 14:20:27 swi-mdm9x28-wp user.info swiapp: qmi_client_send_msg_sync returned: 0
Oct 21 14:20:27 swi-mdm9x28-wp user.info swiapp: Send response 1 complete.
Oct 21 14:20:27 swi-mdm9x28-wp user.info swiapp: New request processing complete.
Oct 21 14:20:27 swi-mdm9x28-wp user.info swiapp: Waiting for ctrCond
Oct 21 14:20:37 swi-mdm9x28-wp user.warn kernel: [   83.080998] QTI:USB tethered modem SMD port opened
Oct 21 14:20:37 swi-mdm9x28-wp user.err kernel: [   83.084857] msm_hsusb msm_hsusb: [ep_queue] request already in queue
Oct 21 14:20:41 swi-mdm9x28-wp user.info swiapp: qmi_at_unsol_ind_cb: ind id:33
Oct 21 14:20:41 swi-mdm9x28-wp user.info swiapp: Received AT command forward request from modem
Oct 21 14:20:41 swi-mdm9x28-wp user.info swiapp: fwdcmd.opcode=5
Oct 21 14:20:41 swi-mdm9x28-wp user.info swiapp: fwdcmd.name=!powerwake
Oct 21 14:20:41 swi-mdm9x28-wp user.info swiapp: fwdcmd.ntokens=1
Oct 21 14:20:41 swi-mdm9x28-wp user.info swiapp: ctrCond signalling complete.
Oct 21 14:20:41 swi-mdm9x28-wp user.info swiapp: Recieved ctrCond: p: 0, S:0, nr: 1
Oct 21 14:20:41 swi-mdm9x28-wp user.info swiapp: POWERWAKE has been detected
Oct 21 14:20:41 swi-mdm9x28-wp user.err kernel: [   87.255126] 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:0x0c1300c8 OPER:0x00000090
Oct 21 14:20:41 swi-mdm9x28-wp user.err kernel: [   87.269897] 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:0x0c1300c8 OPER:0x00000090
Oct 21 14:20:41 swi-mdm9x28-wp user.info swiapp: resp. buffer is ^M !POWERWAKE: PSM TIMER: 35712000,ACTIVE TIMER:2880,SYNC: 2^M
Oct 21 14:20:41 swi-mdm9x28-wp user.info swiapp: resp_length is 74
Oct 21 14:20:41 swi-mdm9x28-wp user.info swiapp: AT response Buffer ^M !POWERWAKE: PSM TIMER: 35712000,ACTIVE TIMER:2880,SYNC: 2^M
Oct 21 14:20:41 swi-mdm9x28-wp user.info swiapp: AT Resp-buffer Len 74
Oct 21 14:20:41 swi-mdm9x28-wp user.info swiapp: sending QMI_AT_FWD_RESP_AT_CMD_REQ_V01 message
Oct 21 14:20:41 swi-mdm9x28-wp user.info swiapp: qmi_client_send_msg_sync returned: 0
Oct 21 14:20:41 swi-mdm9x28-wp user.info swiapp: Send response 1 complete.
Oct 21 14:20:41 swi-mdm9x28-wp user.info swiapp: New request processing complete.
Oct 21 14:20:41 swi-mdm9x28-wp user.info swiapp: Waiting for ctrCond
Oct 21 14:20:45 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/supervisor T=main | supervisor.c HandleRebootExpiry() 633 | Expired reboot timer
Oct 21 14:20:51 swi-mdm9x28-wp authpriv.info dropbear[1874]: Child connection from 192.168.2.3:54522
Oct 21 14:20:51 swi-mdm9x28-wp authpriv.notice dropbear[1874]: Auth succeeded with blank password for 'root' from 192.168.2.3:54522
Oct 21 14:20:51 swi-mdm9x28-wp authpriv.warn dropbear[1875]: lastlog_perform_login: Couldn't stat /var/log/lastlog: No such file or directory
Oct 21 14:20:51 swi-mdm9x28-wp authpriv.warn dropbear[1875]: lastlog_openseek: /var/log/lastlog is not a file or directory!
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/supervisor T=main | app.c app_Create() 3256 | Creating app 'tools'
Oct 21 14:21:11 swi-mdm9x28-wp user.warn Legato: -WRN- | supervisor[1082]/supervisor T=main | proc.c GetWatchdogAction() 362 | pmtool@0 watchdogAction '' in proc section
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/supervisor T=main | app.c app_Start() 3469 | Starting app 'tools'
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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/libCo
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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/libCo
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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/libComponen
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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/lib
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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/libCo
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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/libComp
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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/t
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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/libComp
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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/lib
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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/libCompon
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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 ex
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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 ex
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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 ex
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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 exists
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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/libComp
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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/lib
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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 exists
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/supervisor T=main | proc.c proc_Start() 1403 | Starting process 'pmtool@0' with pid 1913
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/supervisor T=main | supervisor.c SigChildHandler() 899 | Reaping unconfigured child process 1909.
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1913]/supervisor T=main | proc.c proc_Start() 1363 | Execing 'bin/pmtool'
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1913]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxCoreDumpFileBytes to value 8192.
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1913]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxFileBytes to value 90112.
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1913]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxLockedMemoryBytes to value 8192.
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1913]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxFileDescriptors to value 256.
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1913]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxMQueueBytes to value 512.
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1913]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxThreads to value 20.
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1913]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxQueuedSignals to value 100.
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | powerManagerService[1413]/powerMgr T=main | le_pm.c OnClientConnect() 270 | Connection from client pmtool/1913
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | powerManagerService[1413]/powerMgr T=main | le_pm.c OnClientDisconnect() 298 | Client pid 1913 disconnected.
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/supervisor T=main | proc.c proc_SigChildHandler() 2079 | Process 'pmtool@0' (PID: 1913) has exited with exit code 0.
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/supervisor T=main | app.c app_StopComplete() 4751 | app 'tools' has stopped.
Oct 21 14:21:11 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/supervisor T=main | apps.c DeactivateAppContainer() 374 | Application 'tools' has stopped.
Oct 21 14:21:16 swi-mdm9x28-wp user.info kernel: [  121.761092] sierra_startup_monitor
Oct 21 14:21:23 swi-mdm9x28-wp user.warn Legato: -WRN- | supervisor[1082]/supervisor T=main | proc.c GetWatchdogAction() 362 | pmtool@0 watchdogAction '' in proc section
Oct 21 14:21:23 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/supervisor T=main | app.c app_Start() 3469 | Starting app 'tools'
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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/libCo
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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/libCo
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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/libComponen
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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/lib
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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/libCo
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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/libComp
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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/t
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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/libComp
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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/lib
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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/libCompon
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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 ex
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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 ex
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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 ex
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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 exists
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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/libComp
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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/lib
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/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 exists
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/supervisor T=main | proc.c proc_Start() 1403 | Starting process 'pmtool@0' with pid 1945
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/supervisor T=main | supervisor.c SigChildHandler() 899 | Reaping unconfigured child process 1941.
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1945]/supervisor T=main | proc.c proc_Start() 1363 | Execing 'bin/pmtool'
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1945]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxCoreDumpFileBytes to value 8192.
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1945]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxFileBytes to value 90112.
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1945]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxLockedMemoryBytes to value 8192.
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1945]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxFileDescriptors to value 256.
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1945]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxMQueueBytes to value 512.
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1945]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxThreads to value 20.
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1945]/supervisor T=main | resourceLimits.c SetRLimitValue() 301 | Setting resource limit maxQueuedSignals to value 100.
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | powerManagerService[1413]/powerMgr T=main | le_pm.c OnClientConnect() 270 | Connection from client pmtool/1945
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | powerManagerService[1413]/powerMgr T=main | le_pm.c OnClientDisconnect() 298 | Client pid 1945 disconnected.
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/supervisor T=main | proc.c proc_SigChildHandler() 2079 | Process 'pmtool@0' (PID: 1945) has exited with exit code 0.
Oct 21 14:21:24 swi-mdm9x28-wp user.info kernel: [  129.415599] pm_set_mcu_ulpm_enable: Request PM 1
Oct 21 14:21:24 swi-mdm9x28-wp user.warn kernel: [  129.425424] PSM: backup_nv_path /data/psm/psm_nv_backup.txt
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/supervisor T=main | app.c app_StopComplete() 4751 | app 'tools' has stopped.
Oct 21 14:21:24 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[1082]/supervisor T=main | apps.c DeactivateAppContainer() 374 | Application 'tools' has stopped.
Oct 21 14:21:24 swi-mdm9x28-wp user.warn kernel: [  129.530347] PSM: backup_nv_path /data/psm/psm_nv_backup.txt
Oct 21 14:21:36 swi-mdm9x28-wp user.info swiapp: qmi_at_unsol_ind_cb: ind id:33
Oct 21 14:21:36 swi-mdm9x28-wp user.info swiapp: Received AT command forward request from modem
Oct 21 14:21:36 swi-mdm9x28-wp user.info swiapp: fwdcmd.opcode=5
Oct 21 14:21:36 swi-mdm9x28-wp user.info swiapp: fwdcmd.name=!powermode
Oct 21 14:21:36 swi-mdm9x28-wp user.info swiapp: fwdcmd.ntokens=1
Oct 21 14:21:36 swi-mdm9x28-wp user.info swiapp: ctrCond signalling complete.
Oct 21 14:21:36 swi-mdm9x28-wp user.info swiapp: Recieved ctrCond: p: 0, S:0, nr: 1
Oct 21 14:21:36 swi-mdm9x28-wp user.info swiapp: POWERMODE has been detected
Oct 21 14:21:36 swi-mdm9x28-wp user.info swiapp: resp. buffer is ^M !POWERMODE: No request, status=8-PSM enabled^M
Oct 21 14:21:36 swi-mdm9x28-wp user.info swiapp: resp_length is 61
Oct 21 14:21:36 swi-mdm9x28-wp user.info swiapp: AT response Buffer ^M !POWERMODE: No request, status=8-PSM enabled^M
Oct 21 14:21:36 swi-mdm9x28-wp user.info swiapp: AT Resp-buffer Len 61
Oct 21 14:21:36 swi-mdm9x28-wp user.info swiapp: sending QMI_AT_FWD_RESP_AT_CMD_REQ_V01 message
Oct 21 14:21:36 swi-mdm9x28-wp user.info swiapp: qmi_client_send_msg_sync returned: 0
Oct 21 14:21:36 swi-mdm9x28-wp user.info swiapp: Send response 1 complete.
Oct 21 14:21:36 swi-mdm9x28-wp user.info swiapp: New request processing complete.
Oct 21 14:21:36 swi-mdm9x28-wp user.info swiapp: Waiting for ctrCond
Oct 21 14:21:54 swi-mdm9x28-wp user.info swiapp: qmi_at_unsol_ind_cb: ind id:33
Oct 21 14:21:54 swi-mdm9x28-wp user.info swiapp: Received AT command forward request from modem
Oct 21 14:21:54 swi-mdm9x28-wp user.info swiapp: fwdcmd.opcode=5
Oct 21 14:21:54 swi-mdm9x28-wp user.info swiapp: fwdcmd.name=!powerwake
Oct 21 14:21:54 swi-mdm9x28-wp user.info swiapp: fwdcmd.ntokens=1
Oct 21 14:21:54 swi-mdm9x28-wp user.info swiapp: ctrCond signalling complete.
Oct 21 14:21:54 swi-mdm9x28-wp user.info swiapp: Recieved ctrCond: p: 0, S:0, nr: 1
Oct 21 14:21:54 swi-mdm9x28-wp user.info swiapp: POWERWAKE has been detected
Oct 21 14:21:54 swi-mdm9x28-wp user.err kernel: [  159.385793] 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:0x001363c8 OPER:0x00000090
Oct 21 14:21:54 swi-mdm9x28-wp user.err kernel: [  159.400601] 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:0x001363c8 OPER:0x00000090
Oct 21 14:21:54 swi-mdm9x28-wp user.info swiapp: resp. buffer is ^M !POWERWAKE: ULPM TIMER: 60 PSM TIMER: 35712000,ACTIVE TIMER:2880,SYNC: 2^M
Oct 21 14:21:54 swi-mdm9x28-wp user.info swiapp: resp_length is 89
Oct 21 14:21:54 swi-mdm9x28-wp user.info swiapp: AT response Buffer ^M !POWERWAKE: ULPM TIMER: 60 PSM TIMER: 35712000,ACTIVE TIMER:2880,SYNC: 2^M
Oct 21 14:21:54 swi-mdm9x28-wp user.info swiapp: AT Resp-buffer Len 89
Oct 21 14:21:54 swi-mdm9x28-wp user.info swiapp: sending QMI_AT_FWD_RESP_AT_CMD_REQ_V01 message
Oct 21 14:21:54 swi-mdm9x28-wp user.info swiapp: qmi_client_send_msg_sync returned: 0
Oct 21 14:21:54 swi-mdm9x28-wp user.info swiapp: Send response 1 complete.
Oct 21 14:21:54 swi-mdm9x28-wp user.info swiapp: New request processing complete.
Oct 21 14:21:54 swi-mdm9x28-wp user.info swiapp: Waiting for ctrCond
12

hi @raf,
thanks for your information, I opened an investigation internally .
Best Regards

13

I have tested with WP77xx R13.3, Legato 19.12.0, after pmtool shutdown, PSM always disabled

BEFORE calling pmtool bootOn timer 60; pmtool shutdown:
at!powermode?
!POWERMODE: No request, status=9-PSM disabled

OK
at
OK
at!powermode?
!POWERMODE: No request, status=2-Initialized

AFTER calling pmtool bootOn timer 60; pmtool shutdown:
at!powermode?
!POWERMODE: No request, status=9-PSM disabled

OK
at!powerwake?
!POWERWAKE:
ULPM TIMER: 60
PSM TIMER: 3240,ACTIVE TIMER:20,SYNC: 2
Last Wake Event: 1

OK

Can enter ULPM:
Jan 6 10:16:52 swi-mdm9x28-wp user.info kernel: [ 9418.598592] pm_set_mcu_ulpm_enable: Request PM 1
Jan 6 10:16:52 swi-mdm9x28-wp user.info kernel: [ 9418.599133] pm_set_mcu_ulpm_enable: SWIMCU_PM_ULPS_ENTER - continue sync with MCU
Jan 6 10:16:52 swi-mdm9x28-wp user.err kernel: [ 9418.599150] swimcu_pm_wusrc_config: check statep->gpio_pin_mask 0x0
Jan 6 10:16:52 swi-mdm9x28-wp user.info Legato: INFO | powerManagerService[968]/powerMgr T=main | le_pm.c OnClientDisconnect() 298 | Client pid 25299 disconnected.
Jan 6 10:16:52 swi-mdm9x28-wp user.info Legato: INFO | supervisor[856]/supervisor T=main | proc.c proc_SigChildHandler() 2079 | Process ‘pmtool@0’ (PID: 25299) has exited with exit code 0.
Jan 6 10:16:52 swi-mdm9x28-wp user.info kernel: [ 9418.611663] swimcu_mdm_sec_to_mcu_time_ms: mdm time=60 seconds to be calibrated 30000/29506
Jan 6 10:16:52 swi-mdm9x28-wp user.info kernel: [ 9418.611683] swimcu_mdm_sec_to_mcu_time_ms: mcu time 61000 ms + remainder time 4 ms = 61004 ms
Jan 6 10:16:52 swi-mdm9x28-wp user.err kernel: [ 9418.612070] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:1 cur:0 tx) bc(rx:0 tx:18) mode:FIFO slv_addr:0x3a MSTR_STS:0x001363c8 OPER:0x00000090
Jan 6 10:16:52 swi-mdm9x28-wp user.info kernel: [ 9418.633733] swimcu_pm_wusrc_config: ULPM wakeup time 60 (mcu=61004)
Jan 6 10:16:52 swi-mdm9x28-wp user.err kernel: [ 9418.633753] pm_set_mcu_ulpm_enable: wakeup source setup mask=0x2
Jan 6 10:16:52 swi-mdm9x28-wp user.info kernel: [ 9418.638728] swimcu_pm_data_store: sending persistent data group 0 to MCU
Jan 6 10:16:52 swi-mdm9x28-wp user.info Legato: INFO | supervisor[856]/supervisor T=main | app.c app_StopComplete() 4763 | app ‘tools’ has stopped.
Jan 6 10:16:52 swi-mdm9x28-wp user.info Legato: INFO | supervisor[856]/supervisor T=main | apps.c DeactivateAppContainer() 374 | Application ‘tools’ has stopped.
Jan 6 10:16:52 swi-mdm9x28-wp user.info kernel: [ 9418.649125] swimcu_pm_data_store: sending persistent data group 1 to MCU
Jan 6 10:16:52 swi-mdm9x28-wp user.info kernel: [ 9418.660207] pm_set_mcu_ulpm_enable: sending wait_time_config
Jan 6 03:16:52 swi-mdm9x28-wp daemon.info init: starting pid 25303, tty ‘’: ‘/etc/init.d/rcK’
Jan 6 10:16:52 swi-mdm9x28-wp user.info kernel: [ 9418.670328] pm_set_mcu_ulpm_enable: sending ulpm_config<6>[ 9418.833665] diag: USB channel diag disconnected
Jan 6 10:16:52 swi-mdm9x28-wp user.err kernel: [ 9418.834842] gbam_disconnect_work: gbam_disconnect_work: Bam channel is not opened

Regards,
Quan

14

hi
issue solved on last release,
BR

15

@Quanhuynh Are you sure that was a WP77xx module you tested with? As far as I can tell, Release 12 is the latest available for WP77xx.

However, R13.3 is available for WP76xx.

@plu
So, the issue still remains unsolved for WP77xx until the next release, TBD?

16

@raf sorry to make you confuse, I tested with WP76xx release 13, WP77xx release 12 and 11 but still unable to reproduce the issue. I think the bug does not happen if we install fresh, only occur after running a long time with the app turn on and off UPLM. wp77_release11.txt (253.3 KB) wp77_release12.txt (45.6 KB)

17

Was there ever a conclusion on this? I’m seeing the same thing on the WP7702 running any of the R12 firmware. It seems to depend on whether or not you’re connected on LTE. If you’re connected on LTE, then pmtool shutdown doesn’t work until you do AT+CPSMS=0 afterward. The process of doing pmtool shutdown seems to be activating PSM, which then stops ULPM from working.

If you’re connected on 2G, or not connected to a network at all, then pmtool shutdown works fine.

Another workaround is to do AT!POWERMODE=3 instead of le_ulpm_ShutDown(). But…AT!POWERMODE only seems to be enabled as a command in the Sierra and GCF firmwares. AT!POWERMODE? returns ERROR on the other firmwares I tried.

I’m trying to figure out which workaround is best. If a new modem firmware comes out this month that fixes it, I’d rather just use the new firmware and do everything the “right” way. Otherwise, I have no choice but to do one of these hacky workarounds.

18

Thanks @dougg3 for your information,

There are some similar issues which le_ulpm_ShutDown() is called more than once at the time the problem happen, I am writting a test app to verify that.

it is possible for le_ulpm_ShutDown() to be called more than once from our app. I realize that preventing this in the caller of le_ulpm_ShutDown() is not the proper way to fix it but it sounds like this may at least avoid the problem for now"

If the problem only happen when the network is connected, I will check by calling Legato API to disconnect the network in function le_ulpm_ShutDown().