netdev - Re: [PATCH REPOST 1/2] can: flexcan: fix deadlock when using self wakeup

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <35190c5b-f8be-8784-5b4f-32a691a6cffe@geanix.com>
Date:   Tue, 20 Aug 2019 13:55:52 +0200
From:   Sean Nyekjaer <sean@...nix.com>
To:     Joakim Zhang <qiangqing.zhang@....com>,
        "mkl@...gutronix.de" <mkl@...gutronix.de>,
        "linux-can@...r.kernel.org" <linux-can@...r.kernel.org>
Cc:     "wg@...ndegger.com" <wg@...ndegger.com>,
        "netdev@...r.kernel.org" <netdev@...r.kernel.org>,
        dl-linux-imx <linux-imx@....com>,
        Martin Hundebøll <martin@...nix.com>
Subject: Re: [PATCH REPOST 1/2] can: flexcan: fix deadlock when using self
 wakeup


>> Unfortunatly it's still possible to reproduce the deadlock with this patch...
>>
>> [  689.921717] flexcan: probe of 2094000.flexcan failed with error -110
>>
>> My test setup:
>> PC with CAN-USB dongle connected to can0 and can1.
>>
>> PC:
>> $ while true; do cansend can0 '123#DEADBEEF'; done
>>
>> iMX6ull:
>> root@...26:~# systemctl suspend
>>
>>
>> [  365.858054] systemd[1]: Reached target Sleep.
>> root@...26:~# [  365.939826] systemd[1]: Starting Suspend...
>> [  366.115839] systemd-sleep[248]: Suspending system...
>> [  366.517949] dpm_run_callback(): platform_pm_suspend+0x0/0x5c returns
>> -110 [  366.518249] PM: Device 2094000.flexcan failed to suspend: error -110
>> [  366.518406] PM: Some devices failed to suspend, or early wake event
>> detected [  366.732162] dpm_run_callback():
>> platform_pm_suspend+0x0/0x5c returns -110 [  366.732285] PM: Device
>> 2090000.flexcan failed to suspend: error -110 [  366.732330] PM: Some
>> devices failed to suspend, or early wake event detected [  366.890637]
>> systemd-sleep[248]: System resumed.
> 
> CAN1, CAN0 suspended failed, then CAN0, CAN1 resumed back, so CAN0/CAN1 can work fine.
> 
>> [  366.923062] systemd[1]: Started Suspend.
>> [  366.942819] systemd[1]: sleep.target: Unit not needed anymore. Stopping.
>> [  366.954791] systemd[1]: Stopped target Sleep.
>> [  366.962402] systemd[1]: Reached target Suspend.
>> [  366.977546] systemd-logind[135]: Operation 'sleep' finished.
>> [  366.979194] systemd[1]: suspend.target: Unit not needed anymore.
>> Stopping.
>> [  366.993831] systemd[1]: Stopped target Suspend.
>> [  367.139972] systemd-networkd[220]: usb0: Lost carrier [  367.294077]
>> systemd-networkd[220]: usb0: Gained carrier
>>
>> root@...26:~# candump can0 | head -n 2
>>
>>     can0  123   [4]  DE AD BE EF
>>     can0  123   [4]  DE AD BE EF
>> root@...26:~# candump can1 | head -n 2
>>
>>     can1  123   [4]  DE AD BE EF
>>     can1  123   [4]  DE AD BE EF
>> root@...26:~# systemctl suspend
>>
>> root@...26:~# [  385.106658] systemd[1]: Reached target Sleep.
>> [  385.147602] systemd[1]: Starting Suspend...
>> [  385.246421] systemd-sleep[260]: Suspending system...
>> [  385.634733] dpm_run_callback(): platform_pm_suspend+0x0/0x5c returns
>> -110 [  385.634855] PM: Device 2090000.flexcan failed to suspend: error -110
>> [  385.634897] PM: Some devices failed to suspend, or early wake event
>> detected [  385.856251] PM: noirq suspend of devices failed [  385.998364]
>> systemd-sleep[260]: System resumed.
> 
> CAN0 suspended failed, CAN1 noirq suspended failed, then CAN1, CAN0 resumed back, so CAN0/CAN1 can work fine.
> 
>> [  386.023390] systemd[1]: Started Suspend.
>> [  386.031570] systemd[1]: sleep.target: Unit not needed anymore. Stopping.
>> [  386.055886] systemd[1]: Stopped target Sleep.
>> [  386.061430] systemd[1]: Reached target Suspend.
>> [  386.066142] systemd[1]: suspend.target: Unit not needed anymore.
>> Stopping.
>> [  386.112575] systemd-networkd[220]: usb0: Lost carrier [  386.116797]
>> systemd-logind[135]: Operation 'sleep' finished.
>> [  386.146161] systemd[1]: Stopped target Suspend.
>> [  386.260866] systemd-networkd[220]: usb0: Gained carrier root@...26:~#
>> candump can0 | head -n 2
>>     can0  123   [4]  DE AD BE EF
>>     can0  123   [4]  DE AD BE EF
>> root@...26:~# candump can1 | head -n 2
>>
>>     can1  123   [4]  DE AD BE EF
>>     can1  123   [4]  DE AD BE EF
>> root@...26:~# systemctl suspend
>>
>> [  396.919303] systemd[1]: Reached target Sleep.
>> root@...26:~# [  396.964722] systemd[1]: Starting Suspend...
>> [  397.067336] systemd-sleep[268]: Suspending system...
>> [  397.574571] PM: noirq suspend of devices failed [  397.834731] PM: noirq
>> suspend of devices failed [  397.807996] systemd-networkd[220]: usb0: Lost
>> carrier [  398.156295] dpm_run_callback(): platform_pm_suspend+0x0/0x5c
>> returns -110 [  398.156339] PM: Device 2094000.flexcan failed to suspend:
>> error -110 [  398.156509] PM: Some devices failed to suspend, or early wake
>> event detected [  398.053555] systemd-sleep[268]: Failed to write
>> /sys/power/state:
>> Device or resource busy
> 
> But the log here is very strange and chaotic, it looks like CAN0 suspended failed, then resumed back, so CAN0 can work fine.
> CAN1 noirq suspend failed, but have not resumed back, so CAN1 still in stop mode, cannot work. I think this may be other device noirq suspend failed
> broke the resume of CAN1.
> 
> Could you do more debug to help locate the issue?
> 
>> [  398.074751] systemd[1]: systemd-suspend.service: Main process exited,
>> code=exited, status=1/FAILURE [  398.076779] systemd[1]:
> 
>> systemd-suspend.service: Failed with result 'exit-code'.
>> [  398.109255] systemd[1]: Failed to start Suspend.
>> [  398.118704] systemd[1]: Dependency failed for Suspend.
>> [  398.136283] systemd-logind[135]: Operation 'sleep' finished.
>> [  398.137770] systemd[1]: suspend.target: Job suspend.target/start failed
>> with result 'dependency'.
>> [  398.139105] systemd[1]: sleep.target: Unit not needed anymore. Stopping.
>> [  398.167590] systemd[1]: Stopped target Sleep.
>> [  398.201558] systemd-networkd[220]: usb0: Gained carrier
> 
> Log here also strange.
> 
> Best Regards,
> Joakim Zhang
>> root@...26:~# candump can0 | head -n 2
>>     can0  123   [4]  DE AD BE EF
>>     can0  123   [4]  DE AD BE EF
>> root@...26:~# candump can1 | head -n 2
>>
>> nothing on can1 anymore :-(
>>
>> root@...26:~# rmmod flexcan
>> [  622.884746] systemd-networkd[220]: can1: Lost carrier [  623.046766]
>> systemd-networkd[220]: can0: Lost carrier root@...26:~# insmod
>> /mnt/flexcan.ko [  628.323981] flexcan 2094000.flexcan: registering netdev
>> failed
>>
>> and can1 fails to register with:
>> [  628.347485] flexcan: probe of 2094000.flexcan failed with error -110
>>
>> /Sean

I have added some more debug, same test setup:
https://gist.github.com/sknsean/81208714de23aa3639d3e31dccb2f3e0

root@...26:~# systemctl suspend 
 

...
https://gist.github.com/sknsean/2a786f1543305056d4de03d387872403

/Sean