Systemctl suspend causes Power off state

Technical Support
, ,
1

Good morning,

we have 3 boards equipped with Apalis iMX6Q 2GB IT, with a custom software which puts the SOM in Suspend mode in some verified external condition.
Both 3 boards work at the same time and with the same external interface.

Once systemctl suspend command is asserted, all 3 board go in suspend, and with WAKEUP pin we are able to return in RUN condition.

All seems to work fine, but in some cases the Suspend seems to turn in Power off state…or so it seems, because we can’t wake up the SOM even by moving the RESET pin.

We’ve performed a lot of test, and this “strange” behaviour happens most of the cases after the first boot.

Other particulary fact is that the “failed” Suspend mode happens simultaneosly on all 3 boards.

Could you please help us to figure out what really happens?

2

Hi @Samuele , how are you?

Welcome to the community! Please feel free to have a look around and ask questions whenever you need it.

Regarding your problem, we’d like to ask you a few more points.

  • Which version of Apalis iMX6Q 2GB IT are you using?
  • What is the carrier board and version?
  • Have you tested a reference image to see if you have the same behavior?

Thanks a lot!

Best regards,
Guilherme

3

Hi @gclaudino.tx, I’m fine thanks, and I hope you are well.

The version of the board is 1.1C and the carrier board is manufactured by us.

We have the same problem with all carrier, the strange behaviour happens with:

  • systemctl suspend from command line;
  • systemctl suspend from bash script;
  • QProcess::startDetached("systemctl suspend"); from qt consolle application;

What really blow out our mind is that, even if this could be a kernel bug, or software bug, or anything else…the simultaneosity on all boards is hard to explain.

Could it be a fail during Suspend process which may cause a “middle of nowhere” condition?

I mean: could it be that the SOM is in an unknown state? Not suspended, not power off and not in running? Because, even by toggling the RESET pin the SOM doesn’t restart, and based on what our HW dept reports, all the requested power supplies are ok.

Thank you.

4

Hi @Samuele ,

Thanks for answering. The fact that it happens in all modules seems to reduce the random characteristic of this issue.

Could you please test it on a Toradex carrier board and on one of our reference images? If the issue still happens, then we can try to reproduce it here.

Thanks again.

Best regards,
Guilherme

5

Thank you,

we’ll try to reproduce the issue on your carrier board and get the last log.

Just one question: we have left VCC_BACKUP floating because we didn’t use the RTC, but could it be that a sort of noise on this PIN causes a loss of configuration?

Other question: the service which runs our application is called suspend.service, could it be also a problem?

Thank you

6

Hi @Samuele ,

This should not be an issue. As you mentioned as long as you are not using the RTC you’re fine.

I will let you know if this is an issue.

Best Regards
Kevin

7

Hi,

finally I’ve got the strange behavior on our board, and this is the log:

Dec 19 08:31:30 apalis-imx6 daemon.info avahi-daemon[537]: Found user 'avahi' (UID 995) and group 'avahi' (GID 994).
Dec 19 08:31:30 apalis-imx6 daemon.info avahi-daemon[537]: Successfully dropped root privileges.
Dec 19 08:31:30 apalis-imx6 daemon.info avahi-daemon[537]: avahi-daemon 0.7 starting up.
Dec 19 08:31:30 apalis-imx6 daemon.info avahi-daemon[537]: Successfully called chroot().
Dec 19 08:31:30 apalis-imx6 daemon.info avahi-daemon[537]: Successfully dropped remaining capabilities.
Dec 19 08:31:30 apalis-imx6 daemon.err avahi-daemon[548]: ../../avahi-0.7/avahi-daemon/chroot.c: open() failed: No such file or directory
Dec 19 08:31:30 apalis-imx6 daemon.warn avahi-daemon[537]: Failed to open /etc/resolv.conf: Invalid argument
Dec 19 08:31:30 apalis-imx6 daemon.info avahi-daemon[537]: Loading service file /services/sftp-ssh.service.
Dec 19 08:31:30 apalis-imx6 daemon.info avahi-daemon[537]: Loading service file /services/ssh.service.
Dec 19 08:31:30 apalis-imx6 daemon.info avahi-daemon[537]: Network interface enumeration completed.
Dec 19 08:31:30 apalis-imx6 daemon.info avahi-daemon[537]: Server startup complete. Host name is apalis-imx6.local. Local service cookie is 3719887894.
Dec 19 08:31:30 apalis-imx6 daemon.info avahi-daemon[537]: Service "apalis-imx6" (/services/ssh.service) successfully established.
Dec 19 08:31:30 apalis-imx6 daemon.info avahi-daemon[537]: Service "apalis-imx6" (/services/sftp-ssh.service) successfully established.
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: Connection Manager version 1.35
Dec 19 08:31:30 apalis-imx6 user.warn kernel: [    9.919220] using random self ethernet address
Dec 19 08:31:30 apalis-imx6 user.warn kernel: [    9.923792] using random host ethernet address
Dec 19 08:31:30 apalis-imx6 daemon.err connmand[536]: iptables support missing error 2 (No such file or directory)
Dec 19 08:31:30 apalis-imx6 daemon.warn connmand[536]: Failed to flush table 'mangle': Invalid argument
Dec 19 08:31:30 apalis-imx6 daemon.err connmand[536]: iptables support missing error 2 (No such file or directory)
Dec 19 08:31:30 apalis-imx6 daemon.warn connmand[536]: Failed to flush table 'nat': Invalid argument
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: Checking loopback interface settings
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: System hostname is apalis-imx6
Dec 19 08:31:30 apalis-imx6 user.info kernel: [    9.987961] mostcore: MOST Linux Driver mld-1.8.3 2020-05-15 14:46:59+02:00
Dec 19 08:31:30 apalis-imx6 daemon.info dbus-daemon[535]: [system] Successfully activated service 'org.freedesktop.systemd1'
Dec 19 08:31:30 apalis-imx6 user.info kernel: [   10.020342] mostcore: registered new application interfacing module networking
Dec 19 08:31:30 apalis-imx6 user.info kernel: [   10.041300] aim_cdev: init()
Dec 19 08:31:30 apalis-imx6 user.info kernel: [   10.045802] mostcore: registered new application interfacing module cdev
Dec 19 08:31:30 apalis-imx6 daemon.info dbus-daemon[535]: [system] Activating via systemd: service name='fi.w1.wpa_supplicant1' unit='wpa_supplicant.service' requested by ':1.4' (uid=0 pid=536 comm="/usr/sbin/connmand -n ")
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: lo {newlink} index 1 address 00:00:00:00:00:00 mtu 65536
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: lo {newlink} index 1 operstate 0 <UNKNOWN>
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: can0 {newlink} index 2 address 00:00:00:00:00:00 mtu 16
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: can0 {newlink} index 2 operstate 2 <DOWN>
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: can1 {newlink} index 3 address 00:00:00:00:00:00 mtu 16
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: can1 {newlink} index 3 operstate 2 <DOWN>
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: eth0 {create} index 4 type 1 <ETHER>
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: eth0 {update} flags 4098 <DOWN>
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: eth0 {newlink} index 4 address 00:14:2D:A4:C2:B2 mtu 1500
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: eth0 {newlink} index 4 operstate 2 <DOWN>
Dec 19 08:31:30 apalis-imx6 daemon.info dbus-daemon[535]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.4' (uid=0 pid=536 comm="/usr/sbin/connmand -n ")
Dec 19 08:31:30 apalis-imx6 user.notice kernel: [   10.074724] usb 1-1: claimed gadget: Vendor=0424 ProdID=cf19 Bus=01 Device=02
Dec 19 08:31:30 apalis-imx6 user.notice kernel: [   10.081955] usb 1-1: device path: /sys/bus/usb/devices/1-1:1.0
Dec 19 08:31:30 apalis-imx6 user.info kernel: [   10.082659] mostcore: registered new MOST device mdev0 (usb_device 1-1:1.0)
Dec 19 08:31:30 apalis-imx6 user.notice kernel: [   10.096225] usb 1-1: claimed gadget: Vendor=0424 ProdID=cf19 Bus=01 Device=02
Dec 19 08:31:30 apalis-imx6 user.notice kernel: [   10.105758] usb 1-1: device path: /sys/bus/usb/devices/1-1:1.1
Dec 19 08:31:30 apalis-imx6 daemon.info dbus-daemon[535]: [system] Successfully activated service 'fi.w1.wpa_supplicant1'
Dec 19 08:31:30 apalis-imx6 user.info kernel: [   10.175827] Micrel KSZ9031 Gigabit PHY 2188000.ethernet-1:07: attached PHY driver [Micrel KSZ9031 Gigabit PHY] (mii_bus:phy_addr=2188000.ethernet-1:07, irq=124)
Dec 19 08:31:30 apalis-imx6 user.info kernel: [   10.192383] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: Adding interface eth0 [ ethernet ]
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: eth0 {update} flags 36867 <UP>
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: eth0 {newlink} index 4 address 00:14:2D:A4:C2:B2 mtu 1500
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: eth0 {newlink} index 4 operstate 2 <DOWN>
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: meth0 {create} index 5 type 1 <ETHER>
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: meth0 {update} flags 4098 <DOWN>
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: meth0 {newlink} index 5 address 00:00:00:00:00:00 mtu 1500
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: meth0 {newlink} index 5 operstate 2 <DOWN>
Dec 19 08:31:30 apalis-imx6 user.info kernel: [   10.199279] mostcore: registered new MOST device mdev1 (usb_device 1-1:1.1)
Dec 19 08:31:30 apalis-imx6 user.notice kernel: [   10.206741] usb 1-1: claimed gadget: Vendor=0424 ProdID=cf19 Bus=01 Device=02
Dec 19 08:31:30 apalis-imx6 user.notice kernel: [   10.214039] usb 1-1: device path: /sys/bus/usb/devices/1-1:1.2
Dec 19 08:31:30 apalis-imx6 user.info kernel: [   10.221395] mostcore: registered new MOST device mdev2 (usb_device 1-1:1.2)
Dec 19 08:31:30 apalis-imx6 user.info kernel: [   10.228856] usbcore: registered new interface driver hdm_usb
Dec 19 08:31:30 apalis-imx6 user.warn kernel: [   10.253595] usb 1-1: Broken pipe on ep8e
Dec 19 08:31:30 apalis-imx6 user.warn kernel: [   10.261436] usb 1-1: Broken pipe on ep8e
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: Adding interface meth0 [ ethernet ]
Dec 19 08:31:30 apalis-imx6 user.info kernel: [   10.267172] IPv6: ADDRCONF(NETDEV_UP): meth0: link is not ready
Dec 19 08:31:30 apalis-imx6 user.info kernel: [   10.274620] usb0: HOST MAC 00:14:2d:ff:ff:fe
Dec 19 08:31:30 apalis-imx6 user.info kernel: [   10.279276] usb0: MAC 00:14:2d:ff:ff:ff
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: meth0 {update} flags 168003 <UP,RUNNING>
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: meth0 {newlink} index 5 address 00:00:00:00:00:00 mtu 1500
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: meth0 {newlink} index 5 operstate 0 <UNKNOWN>
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: usb0 {create} index 6 type 1 <ETHER>
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: usb0 {update} flags 4098 <DOWN>
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: usb0 {newlink} index 6 address 00:00:00:00:00:00 mtu 1500
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: usb0 {newlink} index 6 operstate 2 <DOWN>
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: Ignoring interface usb0 (filtered)
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: Adding interface usb0 [ gadget ]
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: usb0 {newlink} index 6 address 00:14:2D:FF:FF:FF mtu 1500
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: usb0 {newlink} index 6 operstate 2 <DOWN>
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: Ignoring interface usb0 (filtered)
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: meth0 {RX} 19 packets 2732 bytes
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: meth0 {TX} 0 packets 0 bytes
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: meth0 {update} flags 167939 <UP>
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: meth0 {newlink} index 5 address 00:00:00:00:00:00 mtu 1500
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: meth0 {newlink} index 5 operstate 2 <DOWN>
Dec 19 08:31:30 apalis-imx6 user.warn kernel: [   10.343495] usb 1-1: Broken pipe on ep8e
Dec 19 08:31:30 apalis-imx6 user.warn kernel: [   10.353951] usb 1-1: Broken pipe on ep8e
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: usb0 {update} flags 4099 <UP>
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: usb0 {newlink} index 6 address 00:14:2D:FF:FF:FF mtu 1500
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: usb0 {newlink} index 6 operstate 2 <DOWN>
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: Ignoring interface usb0 (filtered)
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: usb0 {newlink} index 6 address 00:14:2D:FF:FF:FF mtu 1500
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: usb0 {newlink} index 6 operstate 2 <DOWN>
Dec 19 08:31:30 apalis-imx6 daemon.info connmand[536]: Ignoring interface usb0 (filtered)
Dec 19 08:31:30 apalis-imx6 user.info kernel: [   10.530234] IPv6: ADDRCONF(NETDEV_UP): usb0: link is not ready
Dec 19 08:31:30 apalis-imx6 daemon.info dbus-daemon[535]: [system] Successfully activated service 'org.freedesktop.hostname1'
Dec 19 08:31:30 apalis-imx6 daemon.notice rpc.statd[625]: Version 3.1.1 starting
Dec 19 08:31:30 apalis-imx6 daemon.warn rpc.statd[625]: Flags: No-Daemon TI-RPC
Dec 19 08:31:31 apalis-imx6 user.info kernel: [   11.274687] meth0: set mac 20-00-00-00-02-c2
Dec 19 08:31:31 apalis-imx6 user.info kernel: [   11.278986] IPv6: ADDRCONF(NETDEV_CHANGE): meth0: link becomes ready
Dec 19 08:31:31 apalis-imx6 daemon.info connmand[536]: meth0 {add} route ff00:: gw :: scope 0 <UNIVERSE>
Dec 19 08:31:31 apalis-imx6 daemon.info connmand[536]: meth0 {add} route fe80:: gw :: scope 0 <UNIVERSE>
Dec 19 08:31:31 apalis-imx6 daemon.info connmand[536]: meth0 {RX} 23 packets 3940 bytes
Dec 19 08:31:31 apalis-imx6 daemon.info connmand[536]: meth0 {TX} 0 packets 0 bytes
Dec 19 08:31:31 apalis-imx6 daemon.info connmand[536]: meth0 {update} flags 102467 <UP,RUNNING,LOWER_UP>
Dec 19 08:31:31 apalis-imx6 daemon.info connmand[536]: meth0 {newlink} index 5 address 20:00:00:00:02:C2 mtu 1500
Dec 19 08:31:31 apalis-imx6 daemon.info connmand[536]: meth0 {newlink} index 5 operstate 6 <UP>
Dec 19 08:31:31 apalis-imx6 daemon.warn connmand[536]: Skipping disconnect of carrier, network is connecting.
Dec 19 08:31:31 apalis-imx6 daemon.info avahi-daemon[537]: Joining mDNS multicast group on interface meth0.IPv4 with address 10.0.1.32.
Dec 19 08:31:31 apalis-imx6 daemon.err connmand[536]: Failed to set hostname to apalis-imx6
Dec 19 08:31:31 apalis-imx6 daemon.info avahi-daemon[537]: New relevant interface meth0.IPv4 for mDNS.
Dec 19 08:31:31 apalis-imx6 daemon.info avahi-daemon[537]: Registering new address record for 10.0.1.32 on meth0.IPv4.
Dec 19 08:31:31 apalis-imx6 daemon.info connmand[536]: meth0 {add} address 10.0.1.32/24 label meth0 family 2
Dec 19 08:31:31 apalis-imx6 daemon.info connmand[536]: meth0 {add} route 10.0.1.0 gw 0.0.0.0 scope 253 <LINK>
Dec 19 08:31:31 apalis-imx6 daemon.info connmand[536]: meth0 {add} route 10.0.1.1 gw 0.0.0.0 scope 253 <LINK>
Dec 19 08:31:31 apalis-imx6 daemon.info connmand[536]: meth0 {add} route 0.0.0.0 gw 10.0.1.1 scope 0 <UNIVERSE>
Dec 19 08:31:31 apalis-imx6 daemon.info connmand[536]: meth0 {add} route 82.165.8.211 gw 10.0.1.1 scope 0 <UNIVERSE>
Dec 19 08:31:33 apalis-imx6 daemon.info avahi-daemon[537]: Joining mDNS multicast group on interface meth0.IPv6 with address fe80::2200:ff:fe00:2c2.
Dec 19 08:31:33 apalis-imx6 daemon.info avahi-daemon[537]: New relevant interface meth0.IPv6 for mDNS.
Dec 19 08:31:33 apalis-imx6 daemon.info avahi-daemon[537]: Registering new address record for fe80::2200:ff:fe00:2c2 on meth0.*.
Dec 19 08:31:34 apalis-imx6 user.notice root: resizing mmcblk0p2 to fill its full partition size
Dec 19 08:31:35 apalis-imx6 user.info kernel: [   15.501063] Console: switching to colour dummy device 80x30
Dec 19 08:32:03 apalis-imx6 authpriv.info dropbear[821]: Child connection from ::ffff:10.0.1.1:55312
Dec 19 08:32:03 apalis-imx6 authpriv.notice dropbear[821]: Auth succeeded with blank password for 'root' from ::ffff:10.0.1.1:55312
Dec 19 08:32:03 apalis-imx6 authpriv.info dropbear[821]: Exit (root): Disconnect received
Dec 19 08:32:03 apalis-imx6 user.info kernel: [   43.381684] PM: suspend entry (deep)
Dec 19 08:32:03 apalis-imx6 user.info kernel: [   43.385379] PM: Syncing filesystems ... done.
Dec 19 08:32:04 apalis-imx6 daemon.info avahi-daemon[537]: Interface meth0.IPv6 no longer relevant for mDNS.
Dec 19 08:32:04 apalis-imx6 daemon.info avahi-daemon[537]: Leaving mDNS multicast group on interface meth0.IPv6 with address fe80::2200:ff:fe00:2c2.
Dec 19 08:32:04 apalis-imx6 daemon.info avahi-daemon[537]: Interface meth0.IPv4 no longer relevant for mDNS.
Dec 19 08:32:04 apalis-imx6 daemon.info avahi-daemon[537]: Leaving mDNS multicast group on interface meth0.IPv4 with address 10.0.1.32.
Dec 19 08:32:04 apalis-imx6 daemon.info avahi-daemon[537]: Withdrawing address record for fe80::2200:ff:fe00:2c2 on meth0.
Dec 19 08:32:04 apalis-imx6 daemon.info avahi-daemon[537]: Withdrawing address record for 10.0.1.32 on meth0.
Dec 19 08:32:04 apalis-imx6 daemon.info connmand[536]: (null) {RX} 1108 packets 1446186 bytes
Dec 19 08:32:04 apalis-imx6 daemon.info connmand[536]: (null) {TX} 895 packets 78112 bytes
Dec 19 08:32:04 apalis-imx6 daemon.info connmand[536]: (null) {update} flags 36866 <DOWN>
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   43.399721] Freezing user space processes ... (elapsed 0.001 seconds) done.
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   43.408300] OOM killer disabled.
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   43.411534] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   43.421817] mostcore: deregistering MOST device mdev0 (usb_device 1-1:1.0)
Dec 19 08:32:04 apalis-imx6 user.err kernel: [   43.432710] usb 1-1: URB submit failed with error -2.
Dec 19 08:32:04 apalis-imx6 user.err kernel: [   43.437811] mostcore: hdm enqueue failed
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   43.441821] mostcore: deregistering MOST device mdev1 (usb_device 1-1:1.1)
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   43.523370] mostcore: deregistering MOST device mdev2 (usb_device 1-1:1.2)
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   43.601372] PM: suspend devices took 0.180 seconds
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   43.609003] Disabling non-boot CPUs ...
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   43.763952] Enabling non-boot CPUs ...
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   43.768392] CPU1 is up
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   43.771434] CPU2 is up
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   43.774488] CPU3 is up
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   43.784669] mxc_sdc_fb fb@0: 1920x1200 h_sync,r,l: 18,100,20  v_sync,l,u: 2,6,4 pixclock=149992000 Hz
Dec 19 08:32:04 apalis-imx6 user.warn kernel: [   43.986425] usb 1-1:1.0: rebind failed: -517
Dec 19 08:32:04 apalis-imx6 user.warn kernel: [   43.990804] usb 1-1:1.1: rebind failed: -517
Dec 19 08:32:04 apalis-imx6 user.warn kernel: [   43.995224] usb 1-1:1.2: rebind failed: -517
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   44.000157] PM: resume devices took 0.220 seconds
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   44.004911] OOM killer enabled.
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   44.008063] Restarting tasks ...
Dec 19 08:32:04 apalis-imx6 user.notice kernel: [   44.008336] usb 1-1: claimed gadget: Vendor=0424 ProdID=cf19 Bus=01 Device=02
Dec 19 08:32:04 apalis-imx6 user.warn kernel: [   44.011910] done.
Dec 19 08:32:04 apalis-imx6 user.notice kernel: [   44.019002] usb 1-1: device path: /sys/bus/usb/devices/1-1:1.0
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   44.028404] mostcore: registered new MOST device mdev0 (usb_device 1-1:1.0)
Dec 19 08:32:04 apalis-imx6 user.notice kernel: [   44.028831] usb 1-1: claimed gadget: Vendor=0424 ProdID=cf19 Bus=01 Device=02
Dec 19 08:32:04 apalis-imx6 user.notice kernel: [   44.042952] usb 1-1: device path: /sys/bus/usb/devices/1-1:1.1
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   44.044585] mostcore: registered new MOST device mdev1 (usb_device 1-1:1.1)
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   44.054570] PM: suspend exit
Dec 19 08:32:04 apalis-imx6 user.notice kernel: [   44.062715] usb 1-1: claimed gadget: Vendor=0424 ProdID=cf19 Bus=01 Device=02
Dec 19 08:32:04 apalis-imx6 user.notice kernel: [   44.070080] usb 1-1: device path: /sys/bus/usb/devices/1-1:1.2
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   44.080705] mostcore: registered new MOST device mdev2 (usb_device 1-1:1.2)
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   44.115902] ata1: SATA link down (SStatus 0 SControl 300)
Dec 19 08:32:04 apalis-imx6 daemon.info connmand[536]: meth0 {newlink} index 5 address 20:00:00:00:02:C2 mtu 1500
Dec 19 08:32:04 apalis-imx6 daemon.info connmand[536]: meth0 {newlink} index 5 operstate 2 <DOWN>
Dec 19 08:32:04 apalis-imx6 daemon.err connmand[536]: Removing default gateway route failed (No such device)
Dec 19 08:32:04 apalis-imx6 daemon.err connmand[536]: Deleting host route failed (No such device)
Dec 19 08:32:04 apalis-imx6 daemon.err connmand[536]: Removing default gateway route failed (No such device)
Dec 19 08:32:04 apalis-imx6 daemon.err connmand[536]: Deleting host route failed (No such device)
Dec 19 08:32:04 apalis-imx6 daemon.err connmand[536]: Removing default gateway route failed (No such device)
Dec 19 08:32:04 apalis-imx6 daemon.info connmand[536]: (null) {del} route fe80:: gw :: scope 0 <UNIVERSE>
Dec 19 08:32:04 apalis-imx6 daemon.info connmand[536]: (null) {del} route ff00:: gw :: scope 0 <UNIVERSE>
Dec 19 08:32:04 apalis-imx6 daemon.info connmand[536]: (null) {del} address 10.0.1.32/24 label meth0
Dec 19 08:32:04 apalis-imx6 daemon.info connmand[536]: meth0 {dellink} index 5 operstate 2 <DOWN>
Dec 19 08:32:04 apalis-imx6 daemon.info connmand[536]: (null) {RX} 1108 packets 1446186 bytes
Dec 19 08:32:04 apalis-imx6 daemon.info connmand[536]: (null) {TX} 895 packets 78112 bytes
Dec 19 08:32:04 apalis-imx6 daemon.info connmand[536]: (null) {remove} index 5
Dec 19 08:32:04 apalis-imx6 daemon.info connmand[536]: Remove interface (null) [ ethernet ]
Dec 19 08:32:04 apalis-imx6 daemon.info connmand[536]: meth0 {create} index 7 type 1 <ETHER>
Dec 19 08:32:04 apalis-imx6 daemon.info connmand[536]: meth0 {update} flags 4098 <DOWN>
Dec 19 08:32:04 apalis-imx6 daemon.info connmand[536]: meth0 {newlink} index 7 address 00:00:00:00:00:00 mtu 1500
Dec 19 08:32:04 apalis-imx6 daemon.info connmand[536]: meth0 {newlink} index 7 operstate 2 <DOWN>
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   44.431115] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   44.437020] IPv6: ADDRCONF(NETDEV_UP): usb0: link is not ready
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   44.437025] IPv6: ADDRCONF(NETDEV_UP): meth0: link is not ready
Dec 19 08:32:04 apalis-imx6 user.info kernel: [   44.449966] IPv6: ADDRCONF(NETDEV_UP): meth0: link is not ready
Dec 19 08:32:04 apalis-imx6 daemon.info connmand[536]: Adding interface meth0 [ ethernet ]
Dec 19 08:32:04 apalis-imx6 daemon.info connmand[536]: meth0 {update} flags 168003 <UP,RUNNING>
Dec 19 08:32:04 apalis-imx6 daemon.info connmand[536]: meth0 {newlink} index 7 address 00:00:00:00:00:00 mtu 1500
Dec 19 08:32:04 apalis-imx6 daemon.info connmand[536]: meth0 {newlink} index 7 operstate 0 <UNKNOWN>
Dec 19 08:32:04 apalis-imx6 daemon.info connmand[536]: meth0 {update} flags 167939 <UP>
Dec 19 08:32:04 apalis-imx6 daemon.info connmand[536]: meth0 {newlink} index 7 address 00:00:00:00:00:00 mtu 1500
Dec 19 08:32:04 apalis-imx6 daemon.info connmand[536]: meth0 {newlink} index 7 operstate 2 <DOWN>
Dec 19 08:32:04 apalis-imx6 user.warn kernel: [   44.501887] usb 1-1: Broken pipe on ep8e
Dec 19 08:32:04 apalis-imx6 user.warn kernel: [   44.516298] usb 1-1: Broken pipe on ep8e
Dec 19 08:32:05 apalis-imx6 user.info kernel: [   45.514942] meth0: set mac 20-00-00-00-02-c2
Dec 19 08:32:05 apalis-imx6 user.info kernel: [   45.519275] IPv6: ADDRCONF(NETDEV_CHANGE): meth0: link becomes ready
Dec 19 08:32:05 apalis-imx6 daemon.info connmand[536]: meth0 {add} route ff00:: gw :: scope 0 <UNIVERSE>
Dec 19 08:32:05 apalis-imx6 daemon.info connmand[536]: meth0 {add} route fe80:: gw :: scope 0 <UNIVERSE>
Dec 19 08:32:05 apalis-imx6 daemon.info connmand[536]: meth0 {update} flags 102467 <UP,RUNNING,LOWER_UP>
Dec 19 08:32:05 apalis-imx6 daemon.info connmand[536]: meth0 {newlink} index 7 address 20:00:00:00:02:C2 mtu 1500
Dec 19 08:32:05 apalis-imx6 daemon.info connmand[536]: meth0 {newlink} index 7 operstate 6 <UP>
Dec 19 08:32:05 apalis-imx6 daemon.warn connmand[536]: Skipping disconnect of carrier, network is connecting.
Dec 19 08:32:05 apalis-imx6 daemon.info avahi-daemon[537]: Joining mDNS multicast group on interface meth0.IPv4 with address 10.0.1.32.
Dec 19 08:32:05 apalis-imx6 daemon.info avahi-daemon[537]: New relevant interface meth0.IPv4 for mDNS.
Dec 19 08:32:05 apalis-imx6 daemon.info avahi-daemon[537]: Registering new address record for 10.0.1.32 on meth0.IPv4.
Dec 19 08:32:05 apalis-imx6 daemon.err connmand[536]: Failed to set hostname to apalis-imx6
Dec 19 08:32:05 apalis-imx6 daemon.info connmand[536]: meth0 {add} address 10.0.1.32/24 label meth0 family 2
Dec 19 08:32:05 apalis-imx6 daemon.info connmand[536]: meth0 {add} route 10.0.1.0 gw 0.0.0.0 scope 253 <LINK>
Dec 19 08:32:05 apalis-imx6 daemon.info connmand[536]: meth0 {add} route 10.0.1.1 gw 0.0.0.0 scope 253 <LINK>
Dec 19 08:32:05 apalis-imx6 daemon.info connmand[536]: meth0 {add} route 0.0.0.0 gw 10.0.1.1 scope 0 <UNIVERSE>
Dec 19 08:32:05 apalis-imx6 daemon.info connmand[536]: meth0 {add} route 82.165.8.211 gw 10.0.1.1 scope 0 <UNIVERSE>
Dec 19 08:32:07 apalis-imx6 daemon.info avahi-daemon[537]: Joining mDNS multicast group on interface meth0.IPv6 with address fe80::2200:ff:fe00:2c2.
Dec 19 08:32:07 apalis-imx6 daemon.info avahi-daemon[537]: New relevant interface meth0.IPv6 for mDNS.
Dec 19 08:32:07 apalis-imx6 daemon.info avahi-daemon[537]: Registering new address record for fe80::2200:ff:fe00:2c2 on meth0.*.
Dec 19 08:32:36 apalis-imx6 authpriv.info dropbear[1019]: Child connection from ::ffff:10.0.1.1:55326
Dec 19 08:32:36 apalis-imx6 authpriv.notice dropbear[1019]: Auth succeeded with blank password for 'root' from ::ffff:10.0.1.1:55326
Dec 19 08:34:17 apalis-imx6 daemon.warn connmand[536]: Online check failed for 0x1f2b638 Wired
Dec 19 08:34:17 apalis-imx6 daemon.info connmand[536]: meth0 {del} route 82.165.8.211 gw 10.0.1.1 scope 0 <UNIVERSE>

Do you see something that could help?

Now we will try on your carrier board.

Thank you

Best regards

Samuele

8

Good morning @kevin.tx and @gclaudino.tx ,

this is what Apalis print before turning off.

 [   34.393067] usb_otg_vbus: disabling
[  167.265983] usb 1-1.1: Broken pipe on ep8e
[  167.285688] usb 1-1.1: Broken pipe on ep8e
[ 2490.143515] PM: suspend entry (deep)
[ 2490.147112] PM: Syncing filesystems ... done.
[ 2490.160874] Freezing user space processes ... (elapsed 0.001 seconds) done.
[ 2490.169222] OOM killer disabled.
[ 2490.172457] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[ 2490.182242] mostcore: deregistering MOST device mdev0 (usb_device 1-1.1:1.0)
[ 2490.193077] usb 1-1.1: URB submit failed with error -2.
[ 2490.193176] mostcore: deregistering MOST device mdev1 (usb_device 1-1.1:1.1)
[ 2490.198315] mostcore: hdm enqueue failed
[ 2490.253353] mostcore: deregistering MOST device mdev2 (usb_device 1-1.1:1.2)
[ 2490.284798] PM: suspend devices took 0.110 seconds
[ 2490.292238] Disabling non-boot CPUs ...

I hope this could help in some way

Thank you

Best regards

Samuele

9

Hi @Samuele ,

Thanks for all the logs.

Is the second log you posted from the Toradex Carrier Board?

Best Regards
Kevin

10

Hi @kevin.tx

no, it cames from our board.

Now we’re trying to reply the behavior on IXORA V1.0A carrier board.

Best regards
Samuele

11

Good morning @kevin.tx,

this log cames from Apalis on IXORA when our device is connected on USB and the strange behavior happens (all power leds are turned off):

root@apalis-imx6:~# systemctl suspend
root@apalis-imx6:~# [  177.942870] PM: suspend entry (deep)
[  177.946498] PM: Syncing filesystems ... done.
[  177.958085] Freezing user space processes ... (elapsed 0.001 seconds) done.
[  177.966468] OOM killer disabled.
[  177.969704] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[  177.979118] mostcore: deregistering MOST device mdev0 (usb_device 1-1.3:1.0)
[  177.989863] usb 1-1.3: URB submit failed with error -2.
[  177.989974] mostcore: deregistering MOST device mdev1 (usb_device 1-1.3:1.1)
[  177.995145] mostcore: hdm enqueue failed
[  178.053341] mostcore: deregistering MOST device mdev2 (usb_device 1-1.3:1.2)
[  178.092351] PM: suspend devices took 0.110 seconds
[  178.100617] Disabling non-boot CPUs ...

This is the log with the same setup but without the strange behavior:

root@apalis-imx6:~# systemctl suspend
root@apalis-imx6:~# [   40.329441] PM: suspend entry (deep)
[   40.333088] PM: Syncing filesystems ... done.
[   40.349546] Freezing user space processes ... (elapsed 0.001 seconds) done.
[   40.357866] OOM killer disabled.
[   40.361098] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[   40.370631] mostcore: deregistering MOST device mdev0 (usb_device 1-1.1:1.0)
[   40.382466] usb 1-1.1: URB submit failed with error -2.
[   40.382562] mostcore: deregistering MOST device mdev1 (usb_device 1-1.1:1.1)
[   40.387733] mostcore: hdm enqueue failed
[   40.443409] mostcore: deregistering MOST device mdev2 (usb_device 1-1.1:1.2)
[   40.479190] PM: suspend devices took 0.110 seconds
[   40.487132] Disabling non-boot CPUs ...

And this is the log without uor USB device connected:

root@apalis-imx6:~# systemctl suspend
root@apalis-imx6:~# [   49.436398] PM: suspend entry (deep)
[   49.439993] PM: Syncing filesystems ... done.
[   49.465365] Freezing user space processes ... (elapsed 0.001 seconds) done.
[   49.473719] OOM killer disabled.
[   49.476953] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[   49.605049] PM: suspend devices took 0.120 seconds
[   49.612356] Disabling non-boot CPUs ...

---- update ----
Another case @kevin.tx, the strange behavior happens even with a USB key, this is the log

root@apalis-imx6:~# systemctl suspend
root@apalis-imx6:~# [   81.199223] PM: suspend entry (deep)
[   81.202821] PM: Syncing filesystems ... done.
[   81.214930] Freezing user space processes ... (elapsed 0.001 seconds) done.
[   81.223246] OOM killer disabled.
[   81.226479] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[   81.320640] PM: suspend devices took 0.080 seconds
[   81.328719] Disabling non-boot CPUs ...

To restart the board we need to press 2 times the power button.

I hope that all these logs could be helpful.

Thank you for support

Best regards
Samuele

1 Like
12

Hi @Samuele ,

Thanks for the update. We’ll start a few tests on our side to check about the issue as it seems not to be carrier board related.

Once we get things tested, we’ll come back to you.

Best regards,
Guilherme

13

Thank you.

Best regards
Samuele

14

Hi @Samuele ,

Thanks for providing the logs and the additional information.

As @gclaudino.tx mentioned, we’ll have a look at it and let you know as soon as possible.

Best Regards
Kevin

15

Hi @Samuele ,

As Kevin said, we checked it and the default suspend service is actually linked to a service called systemd-suspend.service. Therefore, you can create your own suspend.service. However, please be aware that calling systemctl suspend will invoke the standard systemd-suspend.service as stated in the file /lib/systemd/system/suspend.target. This is explained in the systemctl manual (you can type man systemctl on your host machine).

To use your custom service, you should add parameters such as start and stop: systemctl start suspend. Therefore, it may be a good practice to have it named as something different like suspend2 or my-own-suspend to avoid confusion. Maybe you can try to change the name of your customized service and test it again.

However, we have not yet been able to reproduce this issue on our side. We already did a few resets but none of them has caused the board to power off. Are we missing any additional steps?
For instance, missing requirements would be things like:

  • image customization;
  • multiple suspends in sequence without reboot;
  • leaving the board on for more than x minutes;
  • et. al.

In addition, you said that your application calls the suspend mode. Does the power off happen immediately after calling suspend when the issue appeared?

And finally, as a final check, does this behavior happens on our linux-reference-images or all these logs do come from a custom image?

Thanks again.

Best regards,
Guilherme

16

Hi @gclaudino.tx

about the name of our service, we will rename it in order to not generate some confusion when we need to suspend the system instead of run our service.

Concerning the issue, it is very difficult to reproduce it because there isn’t a particular sequence or case that causes it…what we have see is that it happens when a USB device is connected to the board when we assert the systemctl suspend command (even with a standard USB key).

The image is customized, uname -a returns Linux apalis-imx6 4.14.159-3.0.3+gfff496c2a1bd.

Most of all the time that the issue happens is after a long period of power off state, after the first boot (with a USB already plugged) atthe first systemctl suspend the system power off again, or so it seems, because we need to press 2 times the SW1 button on IXORA to restart it.

What really blow out my mind is that when we assert the command on all the boards in our system, they power off simultaneously when the issue happens.

Thank you again for your support.

Best regards.
Samuele

17

Hi @Samuele ,

At this stage, I would recommend trying the new kernel if this is an option for you. In the test that @gclaudino.tx performed he was using kernel 5.4 and there we could not see the behavior you reported.

Give this a try and let us know if you run into any issues.

Have a great day.

Best Regards
Kevin

18

Thank you @kevin.tx for your feedback.

For now it is not an option because we are in delivery.
Could it be useful for you if we send you our .sdcard image?

Thank you.

Best Regards.
Samuele

19

Hi @Samuele ,

Yes, you could share the image using share.toradex.com. Please be aware that it is very probable that you’ll have to rebuild your image anyway. Therefore, exchanging the Kernel might actually be an option.

Thanks again.

20

Hi @gclaudino.tx

I have uploaded the package.
https://share.toradex.com/n09grwylcno3fhk

If you could give a try to our image it would be very kind.

Thank you

Best regards.
Samuele