Giter Club home page Giter Club logo

Comments (7)

mpvader avatar mpvader commented on July 27, 2024

Log output showing the error:

Configuring network interfaces... [    6.557104] net eth0: initializing cpsw version 1.12 (0)
[    6.565215] net eth0: phy found : id is : 0x7c0f1
[    6.570314] libphy: PHY 4a101000.mdio:01 not found
[    6.575342] net eth0: phy 4a101000.mdio:01 not found on slave 1
[    6.587466] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
udhcpc (v1.23.2) started
Sending discover...
Sending discover...
Sending discover...
No lease, forking to background
[   15.831436] c_can_platform 481cc000.can can0: setting BTR=1c05 BRPE=0000
done.
Starting system message bus: Setting up watches.
Watches established.
/var/run/dbus/ CREATE system_bus_socket
Starting syslogd/klogd: done
Starting php-fpm  done
Starting Connection Manager
Starting Hiawatha Web Server: hiawatha.
Starting crond: OK
Starting simple-upnpd
dbus[880]: [system] Activating service name='fi.w1.wpa_supplicant1' (using servicehelper)
dbus[880]: [system] Successfully activated service 'fi.w1.wpa_supplicant1'
[   24.279456] ieee80211 phy0: rt2x00lib_request_firmware: Info - Loading firmware file 'rt2870.bin'
[   24.393464] ieee80211 phy0: rt2x00lib_request_firmware: Info - Firmware detected - version: 0.29

beaglebone login: [   24.656378] random: nonblocking pool is initialized
[   25.206929] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   26.730822] wlan0: authenticate with 98:fc:11:ae:b5:04
[   26.831685] wlan0: send auth to 98:fc:11:ae:b5:04 (try 1/3)
[   26.843218] wlan0: authenticated
[   26.881219] wlan0: associate with 98:fc:11:ae:b5:04 (try 1/3)
[   26.899338] wlan0: RX AssocResp from 98:fc:11:ae:b5:04 (capab=0x431 status=0 aid=4)
[   26.959517] wlan0: associated
[   26.963460] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[   34.681228] c_can_platform 481cc000.can can0: setting BTR=1c05 BRPE=0000
[   34.688347]
[   34.689907] =================================
[   34.694470] [ INFO: inconsistent lock state ]
[   34.699038] 4.1.15-venus #1 Not tainted
[   34.703054] ---------------------------------
[   34.707619] inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
[   34.713915] vrmlogger.py/956 [HC0[0]:SC1[1]:HE1:SE0] takes:
[   34.719756]  (pinctrl_list_mutex){+.?...}, at: [<c02586d4>] pinctrl_get+0x2c/0x458
[   34.727732] {SOFTIRQ-ON-W} state was registered at:
[   34.732843]   [<c04be4a8>] mutex_lock_nested+0x44/0x34c
[   34.738334]   [<c02586d4>] pinctrl_get+0x2c/0x458
[   34.743268]   [<c0258b2c>] devm_pinctrl_get+0x2c/0x68
[   34.748566]   [<c02c1b58>] pinctrl_bind_pins+0x2c/0xf8
[   34.753960]   [<c02a9708>] driver_probe_device+0x60/0x2b8
[   34.759632]   [<c02a9a38>] __driver_attach+0x94/0x98
[   34.764840]   [<c02a7e54>] bus_for_each_dev+0x68/0x9c
[   34.770140]   [<c02a8f90>] bus_add_driver+0x14c/0x1f4
[   34.775439]   [<c02aa1cc>] driver_register+0x78/0xf8
[   34.780647]   [<c06c2a3c>] regulator_dummy_init+0x64/0x88
[   34.786318]   [<c06c277c>] regulator_init+0x90/0xa8
[   34.791435]   [<c0009638>] do_one_initcall+0x8c/0x1d8
[   34.796736]   [<c069ed30>] kernel_init_freeable+0x120/0x1c0
[   34.802585]   [<c04b93dc>] kernel_init+0x8/0xe8
[   34.807347]   [<c000f238>] ret_from_fork+0x14/0x3c
[   34.812378] irq event stamp: 174360
[   34.816031] hardirqs last  enabled at (174360): [<c0071778>] vprintk_emit+0x220/0x588
[   34.824256] hardirqs last disabled at (174359): [<c00715a8>] vprintk_emit+0x50/0x588
[   34.832379] softirqs last  enabled at (174246): [<c0035aa4>] __do_softirq+0x2d4/0x364
[   34.840604] softirqs last disabled at (174253): [<c0035e68>] irq_exit+0xfc/0x130
[   34.848362]
[   34.848362] other info that might help us debug this:
[   34.855204]  Possible unsafe locking scenario:
[   34.855204]
[   34.861408]        CPU0
[   34.863966]        ----
[   34.866524]   lock(pinctrl_list_mutex);
[   34.870549]   <Interrupt>
[   34.873289]     lock(pinctrl_list_mutex);
[   34.877495]
[   34.877495]  *** DEADLOCK ***
[   34.877495]
[   34.883702] 1 lock held by vrmlogger.py/956:
[   34.888173]  #0:  (((&priv->restart_timer))){+.-...}, at: [<c007c620>] call_timer_fn+0x0/0x194
[   34.897231]
[   34.897231] stack backtrace:
[   34.901801] CPU: 0 PID: 956 Comm: vrmlogger.py Not tainted 4.1.15-venus #1
[   34.909007] Hardware name: Generic AM33XX (Flattened Device Tree)
[   34.915411] [<c00147c4>] (unwind_backtrace) from [<c0012914>] (show_stack+0x10/0x14)
[   34.923536] [<c0012914>] (show_stack) from [<c04bb8bc>] (print_usage_bug.part.12+0x290/0x29c)
[   34.932480] [<c04bb8bc>] (print_usage_bug.part.12) from [<c0066484>] (mark_lock+0x68c/0x770)
[   34.941331] [<c0066484>] (mark_lock) from [<c0067158>] (__lock_acquire+0x6cc/0x1da0)
[   34.949452] [<c0067158>] (__lock_acquire) from [<c006912c>] (lock_acquire+0xac/0x12c)
[   34.957666] [<c006912c>] (lock_acquire) from [<c04be4a8>] (mutex_lock_nested+0x44/0x34c)
[   34.966154] [<c04be4a8>] (mutex_lock_nested) from [<c02586d4>] (pinctrl_get+0x2c/0x458)
[   34.974560] [<c02586d4>] (pinctrl_get) from [<c02d91c8>] (c_can_start+0x200/0x2c8)
[   34.982502] [<c02d91c8>] (c_can_start) from [<c02d92a4>] (c_can_set_mode+0x14/0x68)
[   34.990535] [<c02d92a4>] (c_can_set_mode) from [<c02d7a00>] (can_restart+0x94/0xc8)
[   34.998567] [<c02d7a00>] (can_restart) from [<c007c6b4>] (call_timer_fn+0x94/0x194)
[   35.006597] [<c007c6b4>] (call_timer_fn) from [<c007ca88>] (run_timer_softirq+0x1ec/0x2cc)
[   35.015266] [<c007ca88>] (run_timer_softirq) from [<c00358d4>] (__do_softirq+0x104/0x364)
[   35.023844] [<c00358d4>] (__do_softirq) from [<c0035e68>] (irq_exit+0xfc/0x130)
[   35.031513] [<c0035e68>] (irq_exit) from [<c00729cc>] (__handle_domain_irq+0x58/0xa8)
[   35.039727] [<c00729cc>] (__handle_domain_irq) from [<c0009458>] (omap_intc_handle_irq+0xc8/0xd0)
[   35.049038] [<c0009458>] (omap_intc_handle_irq) from [<c04c25e4>] (__irq_usr+0x44/0x60)
[   35.057428] Exception stack(0xdd40bfb0 to 0xdd40bff8)
[   35.062726] bfa0:                                     000aec48 4f40fc94 0b8c8eab 44da029b
[   35.071302] bfc0: 00000009 b6dc8cb4 b6dc62d4 b6dc6274 b6dc62a4 b6cf837c 00000000 b66e7a50
[   35.079877] bfe0: b6cf8424 bef21538 b6cd4570 4f4fd72c 20000010 ffffffff
[   35.087080] c_can_platform 481cc000.can: obtain a copy of previously claimed pinctrl
[   35.110134] IPv6: ADDRCONF(NETDEV_CHANGE): can0: link becomes ready

from venus.

mpvader avatar mpvader commented on July 27, 2024

I had a hunch, that since vrmlogger.py crashed above, it might be related to vrmlogger.py actually calling both connman (over D-Bus) as well as executing ifconfig as a subprocess. But that is ruled out now. Disabling vrmlogger entirely still gives a deadlock after boot.

And also rebooting multiple times gives multiple different deadlocks. Like this one, which does not mention vrmlogger.py:

dbus[926]: [system] Activating service name='fi.w1.wpa_supplicant1' (using servicehelper)
dbus[926]: [system] Successfully activated service 'fi.w1.wpa_supplicant1'
[   29.313413] random: nonblocking pool is initialized
[   32.735320] c_can_platform 481cc000.can can0: setting BTR=1c05 BRPE=0000
[   32.742396]
[   32.743957] =================================
[   32.748519] [ INFO: inconsistent lock state ]
[   32.753087] 4.1.15-venus #1 Not tainted
[   32.757103] ---------------------------------
[   32.761667] inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
[   32.767963] swapper/0 [HC0[0]:SC1[1]:HE1:SE0] takes:
[   32.773165]  (pinctrl_list_mutex){+.?...}, at: [<c02586d4>] pinctrl_get+0x2c/0x458
[   32.781142] {SOFTIRQ-ON-W} state was registered at:
[   32.786253]   [<c04be978>] mutex_lock_nested+0x44/0x34c
[   32.791743]   [<c02586d4>] pinctrl_get+0x2c/0x458
[   32.796677]   [<c0258b2c>] devm_pinctrl_get+0x2c/0x68
[   32.801976]   [<c02c1b58>] pinctrl_bind_pins+0x2c/0xf8
[   32.807368]   [<c02a9708>] driver_probe_device+0x60/0x2b8
[   32.813039]   [<c02a9a38>] __driver_attach+0x94/0x98
[   32.818247]   [<c02a7e54>] bus_for_each_dev+0x68/0x9c
[   32.823545]   [<c02a8f90>] bus_add_driver+0x14c/0x1f4
[   32.828844]   [<c02aa1cc>] driver_register+0x78/0xf8
[   32.834051]   [<c06c4a3c>] regulator_dummy_init+0x64/0x88
[   32.839724]   [<c06c477c>] regulator_init+0x90/0xa8
[   32.844840]   [<c0009638>] do_one_initcall+0x8c/0x1d8
[   32.850140]   [<c06a0d30>] kernel_init_freeable+0x120/0x1c0
[   32.855988]   [<c04b98ac>] kernel_init+0x8/0xe8
[   32.860750]   [<c000f238>] ret_from_fork+0x14/0x3c
[   32.865781] irq event stamp: 38572
[   32.869341] hardirqs last  enabled at (38572): [<c0071778>] vprintk_emit+0x220/0x588
[   32.877474] hardirqs last disabled at (38571): [<c00715a8>] vprintk_emit+0x50/0x588
[   32.885507] softirqs last  enabled at (38554): [<c0035d50>] irq_enter+0x68/0x84
[   32.893184] softirqs last disabled at (38555): [<c0035e68>] irq_exit+0xfc/0x130
[   32.900851]
[   32.900851] other info that might help us debug this:
[   32.907693]  Possible unsafe locking scenario:
[   32.907693]
[   32.913897]        CPU0
[   32.916455]        ----
[   32.919012]   lock(pinctrl_list_mutex);
[   32.923037]   <Interrupt>
[   32.925777]     lock(pinctrl_list_mutex);
[   32.929984]
[   32.929984]  *** DEADLOCK ***
[   32.929984]
[   32.936191] 1 lock held by swapper/0:
[   32.940025]  #0:  (((&priv->restart_timer))){+.-...}, at: [<c007c620>] call_timer_fn+0x0/0x194
[   32.949080]
[   32.949080] stack backtrace:
[   32.953650] CPU: 0 PID: 0 Comm: swapper Not tainted 4.1.15-venus #1
[   32.960218] Hardware name: Generic AM33XX (Flattened Device Tree)
[   32.966621] [<c00147c4>] (unwind_backtrace) from [<c0012914>] (show_stack+0x10/0x14)
[   32.974745] [<c0012914>] (show_stack) from [<c04bbd8c>] (print_usage_bug.part.12+0x290/0x29c)
[   32.983688] [<c04bbd8c>] (print_usage_bug.part.12) from [<c0066484>] (mark_lock+0x68c/0x770)
[   32.992537] [<c0066484>] (mark_lock) from [<c0067158>] (__lock_acquire+0x6cc/0x1da0)
[   33.000658] [<c0067158>] (__lock_acquire) from [<c006912c>] (lock_acquire+0xac/0x12c)
[   33.008869] [<c006912c>] (lock_acquire) from [<c04be978>] (mutex_lock_nested+0x44/0x34c)
[   33.017356] [<c04be978>] (mutex_lock_nested) from [<c02586d4>] (pinctrl_get+0x2c/0x458)
[   33.025762] [<c02586d4>] (pinctrl_get) from [<c02d91c8>] (c_can_start+0x200/0x2c8)
[   33.033702] [<c02d91c8>] (c_can_start) from [<c02d92a4>] (c_can_set_mode+0x14/0x68)
[   33.041734] [<c02d92a4>] (c_can_set_mode) from [<c02d7a00>] (can_restart+0x94/0xc8)
[   33.049764] [<c02d7a00>] (can_restart) from [<c007c6b4>] (call_timer_fn+0x94/0x194)
[   33.057794] [<c007c6b4>] (call_timer_fn) from [<c007ca88>] (run_timer_softirq+0x1ec/0x2cc)
[   33.066462] [<c007ca88>] (run_timer_softirq) from [<c00358d4>] (__do_softirq+0x104/0x364)
[   33.075039] [<c00358d4>] (__do_softirq) from [<c0035e68>] (irq_exit+0xfc/0x130)
[   33.082707] [<c0035e68>] (irq_exit) from [<c00729cc>] (__handle_domain_irq+0x58/0xa8)
[   33.090921] [<c00729cc>] (__handle_domain_irq) from [<c0009458>] (omap_intc_handle_irq+0xc8/0xd0)
[   33.100230] [<c0009458>] (omap_intc_handle_irq) from [<c04c2804>] (__irq_svc+0x44/0x5c)
[   33.108621] Exception stack(0xc06e3f50 to 0xc06e3f98)
[   33.113917] 3f40:                                     00000001 00000001 00000000 c06e75f8
[   33.122492] 3f60: c06e2000 c06e4120 00000000 c073112c 00000000 00000001 c07219b8 c06e4128
[   33.131066] 3f80: 00000000 c06e3f98 c006674c c000faf0 200e0013 ffffffff
[   33.138004] [<c04c2804>] (__irq_svc) from [<c000faf0>] (arch_cpu_idle+0x24/0x3c)
[   33.145771] [<c000faf0>] (arch_cpu_idle) from [<c005e8c8>] (cpu_startup_entry+0x250/0x2d0)
[   33.154439] [<c005e8c8>] (cpu_startup_entry) from [<c06a0c04>] (start_kernel+0x338/0x344)
[   33.163146] c_can_platform 481cc000.can: obtain a copy of previously claimed pinctrl
[   33.174538] IPv6: ADDRCONF(NETDEV_CHANGE): can0: link becomes ready

from venus.

mpvader avatar mpvader commented on July 27, 2024

assigned to Denx

from venus.

mpvader avatar mpvader commented on July 27, 2024

Reply from Denx:

The reason is clear (there is a race condition at the start-up when pinmux is set), and the small patch below solves the issue. Patch applies to branch bbb_b4.1.15.

It was not solved upstream yet, so will be posted soon.

diff --git a/drivers/net/can/dev.c b/drivers/net/can/dev.c
index 141c2a4..2c582cd 100644
--- a/drivers/net/can/dev.c
+++ b/drivers/net/can/dev.c
@@ -21,6 +21,7 @@
 #include <linux/slab.h>
 #include <linux/netdevice.h>
 #include <linux/if_arp.h>
+#include <linux/workqueue.h>
 #include <linux/can.h>
 #include <linux/can/dev.h>
 #include <linux/can/skb.h>
@@ -471,9 +472,8 @@ EXPORT_SYMBOL_GPL(can_free_echo_skb);
 /*
  * CAN device restart for bus-off recovery
  */
-static void can_restart(unsigned long data)
+static void can_restart(struct net_device *dev)
 {
-   struct net_device *dev = (struct net_device *)data;
    struct can_priv *priv = netdev_priv(dev);
    struct net_device_stats *stats = &dev->stats;
    struct sk_buff *skb;
@@ -513,6 +513,14 @@ restart:
        netdev_err(dev, "Error %d during restart", err);
 }

+static void can_restart_work(struct work_struct *work)
+{
+   struct delayed_work *dwork = to_delayed_work(work);
+   struct can_priv *priv = container_of(dwork, struct can_priv, restart_work);
+
+   can_restart(priv->dev);
+}
+
 int can_restart_now(struct net_device *dev)
 {
    struct can_priv *priv = netdev_priv(dev);
@@ -526,8 +534,8 @@ int can_restart_now(struct net_device *dev)
    if (priv->state != CAN_STATE_BUS_OFF)
        return -EBUSY;

-   /* Runs as soon as possible in the timer context */
-   mod_timer(&priv->restart_timer, jiffies);
+   cancel_delayed_work_sync(&priv->restart_work);
+   can_restart(dev);

    return 0;
 }
@@ -548,8 +556,8 @@ void can_bus_off(struct net_device *dev)
    netif_carrier_off(dev);

    if (priv->restart_ms)
-       mod_timer(&priv->restart_timer,
-             jiffies + (priv->restart_ms * HZ) / 1000);
+       schedule_delayed_work(&priv->restart_work,
+                     msecs_to_jiffies(priv->restart_ms));
 }
 EXPORT_SYMBOL_GPL(can_bus_off);

@@ -658,6 +666,7 @@ struct net_device *alloc_candev(int sizeof_priv, unsigned int echo_skb_max)
        return NULL;

    priv = netdev_priv(dev);
+   priv->dev = dev;

    if (echo_skb_max) {
        priv->echo_skb_max = echo_skb_max;
@@ -667,7 +676,7 @@ struct net_device *alloc_candev(int sizeof_priv, unsigned int echo_skb_max)

    priv->state = CAN_STATE_STOPPED;

-   init_timer(&priv->restart_timer);
+   INIT_DELAYED_WORK(&priv->restart_work, can_restart_work);

    return dev;
 }
@@ -742,8 +751,6 @@ int open_candev(struct net_device *dev)
    if (!netif_carrier_ok(dev))
        netif_carrier_on(dev);

-   setup_timer(&priv->restart_timer, can_restart, (unsigned long)dev);
-
    return 0;
 }
 EXPORT_SYMBOL_GPL(open_candev);
@@ -758,7 +765,7 @@ void close_candev(struct net_device *dev)
 {
    struct can_priv *priv = netdev_priv(dev);

-   del_timer_sync(&priv->restart_timer);
+   cancel_delayed_work_sync(&priv->restart_work);
    can_flush_echo_skb(dev);
 }
 EXPORT_SYMBOL_GPL(close_candev);
diff --git a/include/linux/can/dev.h b/include/linux/can/dev.h
index c3a9c8f..4f0590c 100644
--- a/include/linux/can/dev.h
+++ b/include/linux/can/dev.h
@@ -31,6 +31,7 @@ enum can_mode {
  * CAN common private data
  */
 struct can_priv {
+   struct net_device *dev;
    struct can_device_stats can_stats;

    struct can_bittiming bittiming, data_bittiming;
@@ -43,7 +44,7 @@ struct can_priv {
    u32 ctrlmode_supported;

    int restart_ms;
-   struct timer_list restart_timer;
+   struct delayed_work restart_work;

    int (*do_set_bittiming)(struct net_device *dev);
    int (*do_set_data_bittiming)(struct net_device *dev);

from venus.

mpvader avatar mpvader commented on July 27, 2024

tested, the patch fixes the issue.

applied
victronenergy/linux@0f6681e

from venus.

mpvader avatar mpvader commented on July 27, 2024

Patch was submitted to upstream, and applied to can:
http://marc.info/?l=linux-can&m=147453139610015&w=2

from venus.

mpvader avatar mpvader commented on July 27, 2024

and applied to net:
https://www.mail-archive.com/[email protected]/msg130014.html

So next step is linux (?)

from venus.

Related Issues (20)

Recommend Projects

  • React photo React

    A declarative, efficient, and flexible JavaScript library for building user interfaces.

  • Vue.js photo Vue.js

    πŸ–– Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.

  • Typescript photo Typescript

    TypeScript is a superset of JavaScript that compiles to clean JavaScript output.

  • TensorFlow photo TensorFlow

    An Open Source Machine Learning Framework for Everyone

  • Django photo Django

    The Web framework for perfectionists with deadlines.

  • D3 photo D3

    Bring data to life with SVG, Canvas and HTML. πŸ“ŠπŸ“ˆπŸŽ‰

Recommend Topics

  • javascript

    JavaScript (JS) is a lightweight interpreted programming language with first-class functions.

  • web

    Some thing interesting about web. New door for the world.

  • server

    A server is a program made to process requests and deliver data to clients.

  • Machine learning

    Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.

  • Game

    Some thing interesting about game, make everyone happy.

Recommend Org

  • Facebook photo Facebook

    We are working to build community through open source technology. NB: members must have two-factor auth.

  • Microsoft photo Microsoft

    Open source projects and samples from Microsoft.

  • Google photo Google

    Google ❀️ Open Source for everyone.

  • D3 photo D3

    Data-Driven Documents codes.