Can't go to ULPM without USB

mangOH Yellow
1

Hello everyone !

I a trying to use the ULPM of my mangOH Yellow to measure current consumption in this mode.

I took inspiration from the ShakeNWake Demo to make my own app that goes into ULPM if the generic push button of the board is pressed (GPIO25 on mangOH Yellow), and wakes up if the board is shaken.

This works just fine if I use the USB main power supply to power the board. The board goes into ULPM when I press the button, and boots back if I shake it.

Then I wanted to do the same thing using a battery to power the board instead of my PC.
So I unplugged the USB connector providing power to the board, removed the jumper selecting the power source and plugged a power source into the battery connector (CN1000) of the board.
It boots normally, but when I press the button to enter ULPM, I get some errors in the logs and the board doesnā€™t go into ULPM.

[12:27:27:895] Apr 15 12:27:25 swi-mdm9x28-wp user.info kernel: [   43.901130] swimcu_pm_wusrc_config: configured GPIO wakeup source 0x10000 āāŠ
[12:27:27:895] Apr 15 12:27:25 swi-mdm9x28-wp user.err kernel: [   43.901168] swimcu_pm_wusrc_config: check statep->gpio_pin_mask 0x10000 āāŠ
[12:27:27:895] Apr 15 12:27:25 swi-mdm9x28-wp user.err kernel: [   43.921377] MCU Protocol Command 0xC2 failed, retry=1

And after a series of retries, I get this:

[12:27:31:779] Apr 15 12:27:31 swi-mdm9x28-wp user.err kernel: [   49.006450] MCU Protocol Command 0xC2 failed, retry=11āāŠ
[12:27:31:827] Apr 15 12:27:31 swi-mdm9x28-wp user.err kernel: [   49.020481] swimcu_pm_wusrc_config: failed to GPIO config 0x10000 (-2)āāŠ
[12:27:31:827] Apr 15 12:27:31 swi-mdm9x28-wp user.info kernel: [   49.026113] swimcu_pm_wusrc_config_resetāāŠ
[12:27:31:827] Apr 15 12:27:31 swi-mdm9x28-wp user.err kernel: [   49.026143] swimcu_psm_enable_attr_store: Failed to enable mode 6: -5

What is preventing my board to go into ULPM ?
I can provide my code if needed, but it was too big for a single postā€¦

[Edit]
In fact it doesnā€™t work that well even with USB plugged in, I sometimes encounter the same problem of the board not going into ULPM. I can press the button 2 times in a row and get a different behavior :expressionless: But itā€™s exactly the same error each time it fails.
I found this post where another person seems to have the same kind of problem, but itā€™s still unresolved.

2

Hi @paulmeis.

I feel your frustration. I stumbled upon this issue well over a year ago now. While I did manage to resolve it, I couldnā€™t get SW to reproduce the issue on their end.
So, this may not work for you but hereā€™s what I found, for what itā€™s worth.

By the way, can you share the output of cm info here as well as Legato version and FW release version?

There may be two issues at play here.

1. The Modem fails to shutdown if USB autosleep is enabled (default)

Try disabling it with this command:

echo off > /sys/power/autosleep

Note that is only temporary and it will re-enabled automatically at the next boot.

To disable it permanently, you must modify /etc/init.d/enable_autosleep.sh

See this forum post for a handy script written to automate this: Script to disable USB autosleep

Another observation I made was that the issue doesnā€™t occur if a SIM card is absent. If a SIM is inserted and registered on a cellular network prior to the ShutDown call, it will fail to shutdown. :upside_down_face:

2. Device will not enter ULPM/PSM mode if GPIO36/38 is selected as the wakeup source

I note that the ShakeNWake demo uses GPIO36 as the wakeup source.

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

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.

Not sure which FW Release youā€™re using. Just something to consider.

Lastly, you might find something useful over in the Legato forum in this thread: Suddenly unable to enter ULPM

Cheers,
Raf

1 Like
3

Thank you very much @Raf for this detailed answer !

First of all, my Legato version is 19.11.0 and my cm info gives:

Device:                        WP7702
IMEI:                          352653090153073
IMEISV:                        4
FSN:                           VU911670311510
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):          9907365
PRI Revision:                  001.006 
Carrier PRI Name:              SIERRA
Carrier PRI Revision:          001.027_000
SKU:                           1103530
Last Reset Cause:              Power Down
Resets Count:                  Expected: 441	Unexpected: 0

This is the version corresponding to the release note you talked about, so I guess my problem is related to this bugā€¦

However thanks to your advice I was able to enter ULPM by doing the following:

  • Disabled the USB autosleep by modifying the /etc/init.d/enable_autosleep.sh
  • Plugged the main power USB port of the board to my computer, but removed the jumper used to select power source
  • Plugged the battery connector of the board to a 3.7 power source

Now my board can go into ULPM and wakes up when the accelerometer detects a movement !
But the board can sometimes go into Kernel Panic from time to time, and I did not figured out why yetā€¦ iā€™ll post the logs if I stubble upon this again.

Thank you again ! :smiley:

[Edit]
I got another Kernel Panic this morning, here are the logs:

49259 - Legato shutdown sequence
49560 - Stopping LegatoApr 17 09:28:38 swi-mdm9x28-wp user.warn kernel: [   57.934884] Stopping QCMAP_ConnectionManager: 
49560 - Apr 17 09:28:38 swi-mdm9x28-wp user.warn kernel: [   58.150709] Stopping qti: done
49560 - Apr 17 09:28:38 swi-mdm9x28-wp user.warn Legato: -WRN- | configTree[955]/framework T=main | safeRef.c le_ref_CreateRef() 547 | Safe reference map maximum exceeded for refPathIteratorMap, new size 42
49560 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[925]/supervisor T=main | app.c app_Stop() 3596 | Stopping app 'appAccel'
49892 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | gpioService[1532]/sysfsGpio T=main | gpioSysfsUtils.c gpioSysfs_SessionCloseHandlerFunc() 1215 | Releasing GPIO 38
49892 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | gpioService[1532]/sysfsGpio T=main | gpioSysfsUtils.c gpioSysfs_SessionCloseHandlerFunc() 1215 | Releasing GPIO 25
49935 - Apr 17 09:28:38 swi-mdm9x28-wp user.notice kernel: [   58.583018] audit: type=1400 audit(1587108518.587:2): lsm=SMACK fn=smack_unix_may_send action=denied subject="app.appAccel" object="syslog" requested=w pid=1465 comm="appAccel" path="/dev/log"
49935 - Apr 17 09:28:38 swi-mdm9x28-wp user.notice kernel: [   58.583243] audit: type=1400 audit(1587108518.587:3): lsm=SMACK fn=smack_inode_permission action=denied subject="app.appAccel" object="app.appAccelrwx" requested=x pid=1465 comm="appAccel" name="appAccel" dev="ubifs" ino=304
49991 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[925]/supervisor T=main | app.c app_StopComplete() 4753 | app 'appAccel' has stopped.
49991 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[925]/supervisor T=main | apps.c ShutdownNextApp() 445 | Application 'appAccel' has stopped.
49991 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[925]/supervisor T=main | app.c app_Stop() 3596 | Stopping app 'atService'
49991 - Apr 17 09:28:38 swi-mdm9x28-wp user.crit Legato: *CRT* | atClientDaemon[1474]/framework T=main | signals.c TermSignalHandler() 449 | Terminated
50028 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | watchdog[986]/watchdogDaemon T=main | watchdog.c CleanUpClosedClient() 355 | Client session closed
50028 - Apr 17 09:28:38 swi-mdm9x28-wp user.crit Legato: *CRT* | atServerDaemon[1475]/framework T=main | signals.c TermSignalHandler() 449 | Terminated
50028 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | watchdog[986]/watchdogDaemon T=main | watchdog.c CleanUpClosedClient() 355 | Client session closed
50059 - Apr 17 09:28:38 swi-mdm9x28-wp user.emerg Legato: *EMR* | portDaemon[1551]/framework T=main | messagingSession.c ClientSocketHangUp() 873 | Session closed by server (portDaemon.portDaemon.le_atServer:b7ddff0d499d71d3a23372d9447cbc78).
50059 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | watchdog[986]/watchdogDaemon T=main | watchdog.c CleanUpClosedClient() 355 | Client session closed
50095 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[925]/supervisor T=main | proc.c proc_SigChildHandler() 2079 | Process 'portDaemon' (PID: 1551) has exited with exit code 1.
50443 - .[   59.421982] 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:0x0c1343c8 OPER:0x00000090
50443 - [   59.436905] 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:0x0c1343c8 OPER:0x00000090
50842 - Apr 17 09:28:38 swi-mdm9x28-wp user.crit Legato: *CRT* | supervisor[925]/supervisor T=main | app.c app_SigChildHandler() 4072 | Process 'portDaemon' in app 'portService' faulted: Restarting process.
50842 - Apr 17 09:28:38 swi-mdm9x28-wp user.err Legato: =ERR= | supervisor[925]/supervisor T=main | proc.c proc_Start() 1244 | Process 'portDaemon' cannot be started because framework is shutting down.
50896 - Apr 17 09:28:38 swi-mdm9x28-wp user.err Legato: =ERR= | supervisor[925]/supervisor T=main | app.c app_SigChildHandler() 4078 | Could not restart process 'portDaemon' in app 'portService'.
50896 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[925]/supervisor T=main | app.c app_Stop() 3596 | Stopping app 'portService'
50896 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[925]/supervisor T=main | app.c app_StopComplete() 4753 | app 'portService' has stopped.
50934 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[925]/supervisor T=main | apps.c DeactivateAppContainer() 374 | Application 'portService' has stopped.
50934 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[925]/supervisor T=main | app.c app_StopComplete() 4753 | app 'atService' has stopped.
50934 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[925]/supervisor T=main | apps.c ShutdownNextApp() 445 | Application 'atService' has stopped.
51001 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[925]/supervisor T=main | app.c app_Stop() 3596 | Stopping app 'audioService'
51001 - Apr 17 09:28:38 swi-mdm9x28-wp user.crit Legato: *CRT* | audioDaemon[1484]/framework T=main | signals.c TermSignalHandler() 449 | Terminated
51001 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | powerManagerService[1572]/powerMgr T=main | le_pm.c OnClientDisconnect() 298 | Client pid 1484 disconnected.
51034 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | powerManagerService[1572]/powerMgr T=main | le_pm.c OnClientDisconnect() 323 | Deleting wakeup source 'legato_MediaStream_audioDaemon' on behalf of pid 1484.
51034 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | watchdog[986]/watchdogDaemon T=main | watchdog.c CleanUpClosedClient() 355 | Client session closed
51034 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[925]/supervisor T=main | app.c app_StopComplete() 4753 | app 'audioService' has stopped.
51059 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[925]/supervisor T=main | apps.c ShutdownNextApp() 445 | Application 'audioService' has stopped.
51059 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[925]/supervisor T=main | app.c app_Stop() 3596 | Stopping app 'avcService'
51059 - Apr 17 09:28:38 swi-mdm9x28-wp user.crit Legato: *CRT* | avcDaemon[1494]/framework T=main | signals.c TermSignalHandler() 449 | Terminated
51101 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | dcsDaemon[1512]/dcsDaemon T=main | dcsServer.c CloseSessionEventHandler() 1329 | Client 0x7f5a9df0 killed, remove allocated resources
51101 - Apr 17 09:28:38 swi-mdm9x28-wp user.err Legato: =ERR= | modemDaemon[1541]/modemDaemon T=main | le_sms.c CloseSessionEventHandler() 2203 | SessionRef (0x7f5fb430) has been closed
51101 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | modemDaemon[1541]/modemDaemon T=main | le_mdc.c CloseSessionEventHandler() 961 | SessionRef 0x7f5fb7d0 has been closed
51143 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | dcsDaemon[1512]/dcsDaemon T=main | dcsServer.c CloseSessionEventHandler() 1329 | Client 0x7f5aaa58 killed, remove allocated resources
51143 - Apr 17 09:28:38 swi-mdm9x28-wp user.err Legato: =ERR= | posDaemon[1560]/posDaemon T=main | le_gnss.c CloseSessionEventHandler() 1271 | SessionRef (0x7f577c48) has been closed
51143 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | modemDaemon[1541]/modemDaemon T=main | le_mdc.c CloseSessionEventHandler() 961 | SessionRef 0x7f5fbb60 has been closed
51194 - Apr 17 09:28:38 swi-mdm9x28-wp user.err Legato: =ERR= | modemDaemon[1541]/modemDaemon T=main | le_sms.c CloseSessionEventHandler() 2203 | SessionRef (0x7f5fbef0) has been closed
51194 - Apr 17 09:28:38 swi-mdm9x28-wp user.err Legato: =ERR= | posDaemon[1560]/posDaemon T=main | le_pos.c PosCloseSessionEventHandler() 1189 | SessionRef (0x7f577bb8) has been closed
51194 - Apr 17 09:28:38 swi-mdm9x28-wp user.info Legato:  INFO | watchdog[986]/watchdogDaemon T=main | watchdog.c CleanUpClosedClient() 355 | Client session closed
51235 - Apr 17 09:28:39 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[925]/supervisor T=main | app.c app_StopComplete() 4753 | app 'avcService' has stopped.
51235 - Apr 17 09:28:39 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[925]/supervisor T=main | apps.c ShutdownNextApp() 445 | Application 'avcService' has stopped.
51235 - Apr 17 09:28:39 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[925]/supervisor T=main | app.c app_Stop() 3596 | Stopping app 'cellNetService'
51295 - Apr 17 09:28:39 swi-mdm9x28-wp user.crit Legato: *CRT* | cellNetService[1503]/framework T=main | signals.c TermSignalHandler() 449 | Terminated
51295 - Apr 17 09:28:39 swi-mdm9x28-wp user.info Legato:  INFO | watchdog[986]/watchdogDaemon T=main | watchdog.c CleanUpClosedClient() 355 | Client session closed
51295 - Apr 17 09:28:39 swi-mdm9x28-wp user.warn kernel: [   59.026804] cellNetService (1503) used greatest stack depth: 4480 bytes left
51334 - Apr 17 09:28:39 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[925]/supervisor T=main | app.c app_StopComplete() 4753 | app 'cellNetService' has stopped.
51334 - Apr 17 09:28:39 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[925]/supervisor T=main | apps.c ShutdownNextApp() 445 | Application 'cellNetService' has stopped.
51334 - Apr 17 09:28:39 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[925]/supervisor T=main | app.c app_Stop() 3596 | Stopping app 'dataConnectionService'
51334 - Apr 17 09:28:39 swi-mdm9x28-wp user.crit Legato: *CRT* | dcsInternal[1513]/framework T=main | signals.c TermSignalHandler() 449 | Terminated
51358 - Apr 17 09:28:39 swi-mdm9x28-wp user.info Legato:  INFO | watchdog[986]/watchdogDaemon T=main | watchdog.c CleanUpClosedClient() 355 | Client session closed
51358 - Apr 17 09:28:39 swi-mdm9x28-wp user.crit Legato: *CRT* | dcsDaemon[1512]/framework T=main | signals.c TermSignalHandler() 449 | Terminated
51358 - Apr 17 09:28:39 swi-mdm9x28-wp user.info Legato:  INFO | modemDaemon[1541]/modemDaemon T=main | le_mdc.c CloseSessionEventHandler() 961 | SessionRef 0x7f5fae40 has been closed
51444 - Apr 17 09:28:39 swi-mdm9x28-wp user.info Legato:  INFO | modemDaemon[1541]/modemDaemon T=main | le_mdc.c CloseSessionEventHandler() 961 | SessionRef 0x7f5fb0a0 has been closed
51444 - Apr 17 09:28:39 swi-mdm9x28-wp user.info Legato:  INFO | watchdog[986]/watchdogDaemon T=main | watchdog.c CleanUpClosedClient() 355 | Client session closed
51444 - Apr 17 09:28:39 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[925]/supervisor T=main | app.c app_StopComplete() 4753 | app 'dataConnectionService' has stopped.
51444 - Apr 17 09:28:39 swi-mdm9x28-wp user.info Legato:  INFO | supervisor[925]/supervisor T=main | apps.c ShutdownNextApp() 445 | Application 'dataConnec[   60.389884] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:2 cur:0 tx) bc(rx:2 tx:1) mode:FIFO slv_addr:0x55 MSTR_STS:0x001363c8 OPER:0x00000010
51444 - tionService' has stopped.
51486 - Apr 17 09:28:39 swi-mdm9x28-wp user.i[   60.408971] i2c-msm-v2 78b8000.i2c: NACK: slave not responding, ensure its powered: msgs(n:2 cur:0 tx) bc(rx:2 tx:1) mode:FIFO slv_addr:0x55 MSTR_STS:0x001363c8 OPER:0x00000010
51486 - nfo Legato:  INFO | supervisor[925]/supervisor T=main | app.c app_Stop() 3596 | Stopping app 'fwupdateService'
51486 - Apr 17 09:28:39 [   60.437269] ------------[ cut here ]------------
51486 - [   60.445793] WARNING: CPU: 0 PID: 163 at /usr/src/kernel/kernel/locking/mutex.c:514 __mutex_lock_slowpath+0xd0/0x2e0()
51486 - [   60.456365] DEBUG_LOCKS_WARN_ON(l->magic != l)
51536 - [   60.460615] Modules linked in: mangoh_yellow_dev(O-) opt300x(O) rtc_pcf85063(O) expander(O) bq27xxx_battery(O) bq25601(O) bmi160_i2c(O) bmi160(O) bnep(O) hci_uart(O) bluetooth(O) ecdh_generic kpp compat(O) ftdi_sio usbserial
51536 - [   60.480674] CPU: 0 PID: 163 Comm: kworker/0:2 Tainted: G           O   3.18.140 #1
51536 - [   60.488229] Workqueue: events power_supply_changed_work
51536 - [   60.493450] [<c0014428>] (unwind_backtrace) from [<c00122ac>] (show_stack+0x10/0x14)
51536 - [   60.501166] [<c00122ac>] (show_stack) from [<c001f4a8>] (warn_slowpath_common+0x60/0x80)
51600 - [   60.509234] [<c001f4a8>] (warn_slowpath_common) from [<c001f4f4>] (warn_slowpath_fmt+0x2c/0x3c)
51600 - [   60.517914] [<c001f4f4>] (warn_slowpath_fmt) from [<c07935d4>] (__mutex_lock_slowpath+0xd0/0x2e0)
51600 - [   60.526768] [<c07935d4>] (__mutex_lock_slowpath) from [<c0793804>] (mutex_lock+0x20/0x3c)
51600 - [   60.534947] [<c0793804>] (mutex_lock) from [<bf0a7d34>] (bq27xxx_battery_get_property+0x1c/0x4a4 [bq27xxx_battery])
51634 - [   60.545357] [<bf0a7d34>] (bq27xxx_battery_get_property [bq27xxx_battery]) from [<c04716a4>] (power_supply_show_property+0x54/0x190)
51634 - [   60.557152] [<c04716a4>] (power_supply_show_property) from [<c04718f8>] (power_supply_uevent+0xe4/0x224)
51634 - [   60.566619] [<c04718f8>] (power_supply_uevent) from [<c02de07c>] (dev_uevent+0x170/0x2a8)
51634 - [   60.574778] [<c02de07c>] (dev_uevent) from [<c020e67c>] (kobject_uevent_env+0x26c/0x5b0)
51634 - [   60.582848] [<c020e67c>] (kobject_uevent_env) from [<c0470fa4>] (power_supply_changed_work+0x98/0xe0)
51659 - [   60.592051] [<c0470fa4>] (power_supply_changed_work) from [<c0031174>] (process_one_work+0x1bc/0x2e0)
51659 - [   60.601247] [<c0031174>] (process_one_work) from [<c0031f30>] (worker_thread+0x2dc/0x3b8)
51659 - [   60.609409] [<c0031f30>] (worker_thread) from [<c00357dc>] (kthread+0xc8/0xd4)
51659 - [   60.616612] [<c00357dc>] (kthread) from [<c000e798>] (ret_from_fork+0x14/0x3c)
51659 - [   60.623815] ---[ end trace 9db2b4ef3f819dad ]---

Looks like itā€™s a mutex problem with the battery gaugeā€¦ But my power source is a current drain measurement tool and not a battery, maybe thatā€™s why :expressionless: