xenwatch thread deadlock after dynamic network attach

[Marek Marczykowski-Górecki <marmarek@xxxxxxxxxxxxxxxxxxxxxx>]

Hi,

I've hit yet another issue with network attach. This time, it looks like
the code to handle forceful re-attach triggers when it shouldn't. The
test is basically:
1. Start the backend domain
2. Start the frontend domain without any vif attached.
3. Attach vif (equivalent of xl network-attach).

First I get:

    [   17.476245] xen vif-0: xenbus: state reset occurred, reconnecting
    [   17.502933] xen vif-0: xenbus: state reset occurred, reconnecting
    [   17.551204] xen vif-0: xenbus: state reset occurred, reconnecting
    [   17.612171] xen vif-0: xenbus: state reset occurred, reconnecting
    [   17.654823] xen vif-0: xenbus: state reset occurred, reconnecting
    [   17.676268] xen vif-0: xenbus: state reset occurred, reconnecting
    [   17.691250] xen_netfront: Initialising Xen virtual ethernet driver
    [   17.692288] vif vif-0: xenbus: state reset occurred, reconnecting

I'm not sure why it's repeated this many times (xenstore watch triggers
this many times?), but then, all xenstore watch operations in that
domain hangs. Inspecting tasks ("t" sysrq) shows:

    [ 1494.201304] task:xenbus          state:S stack:0     pid:62    tgid:62   
 ppid:2      task_flags:0x208040 flags:0x00080000
    [ 1494.201607] Call Trace:
    [ 1494.201659]  <TASK>
    [ 1494.201711]  __schedule+0x2f3/0x780
    [ 1494.201789]  ? __pfx_xenbus_thread+0x10/0x10
    [ 1494.201890]  schedule+0x27/0xa0
    [ 1494.201966]  xenbus_thread+0x1a8/0x200
    [ 1494.202044]  ? __pfx_autoremove_wake_function+0x10/0x10
    [ 1494.202144]  kthread+0xfc/0x240
    [ 1494.202347]  ? __pfx_kthread+0x10/0x10
    [ 1494.202418]  ret_from_fork+0x158/0x170
    [ 1494.202568]  ? __pfx_kthread+0x10/0x10
    [ 1494.202636]  ret_from_fork_asm+0x1a/0x30
    [ 1494.202704]  </TASK>
    [ 1494.202773] task:xenwatch        state:D stack:0     pid:63    tgid:63   
 ppid:2      task_flags:0x208040 flags:0x00080000
    [ 1494.202936] Call Trace:
    [ 1494.202980]  <TASK>
    [ 1494.203023]  __schedule+0x2f3/0x780
    [ 1494.203091]  schedule+0x27/0xa0
    [ 1494.203177]  schedule_preempt_disabled+0x15/0x30
    [ 1494.203381]  __mutex_lock.constprop.0+0x544/0xa60
    [ 1494.203560]  ? xenbus_scanf+0xbd/0x100
    [ 1494.203636]  device_del+0x3a/0x3e0
    [ 1494.203717]  device_unregister+0x17/0x60
    [ 1494.203791]  xenbus_dev_changed+0x247/0x2a0
    [ 1494.203865]  ? __pfx_xenwatch_thread+0x10/0x10
    [ 1494.354139]  xenwatch_thread+0x92/0x1c0
    [ 1494.354274]  ? __pfx_autoremove_wake_function+0x10/0x10
    [ 1494.354545]  kthread+0xfc/0x240
    [ 1494.355389]  ? __pfx_kthread+0x10/0x10
    [ 1494.355615]  ret_from_fork+0x158/0x170
    [ 1494.355706]  ? __pfx_kthread+0x10/0x10
    [ 1494.355805]  ret_from_fork_asm+0x1a/0x30
    [ 1494.355890]  </TASK>
    ...
    [ 1496.396208] task:(udev-worker)   state:D stack:0     pid:824   tgid:824  
 ppid:270    task_flags:0x400140 flags:0x00080003
    [ 1496.398700] Call Trace:
    [ 1496.398753]  <TASK>
    [ 1496.398805]  __schedule+0x2f3/0x780
    [ 1496.398884]  schedule+0x27/0xa0
    [ 1496.398961]  schedule_timeout+0x83/0x100
    [ 1496.399036]  ? __pfx_process_timeout+0x10/0x10
    [ 1496.399141]  xennet_create_dev+0x27e/0x340 [xen_netfront]
    [ 1496.399246]  ? split+0xac/0x130
    [ 1496.399326]  ? __pfx_autoremove_wake_function+0x10/0x10
    [ 1496.399727]  netfront_probe+0x16/0x70 [xen_netfront]
    [ 1496.399833]  xenbus_dev_probe+0xe6/0x1d0
    [ 1496.399920]  really_probe+0xde/0x340
    [ 1496.400005]  ? pm_runtime_barrier+0x54/0x90
    [ 1496.400084]  ? __pfx___driver_attach+0x10/0x10
    [ 1496.400213]  __driver_probe_device+0x84/0x140
    [ 1496.400339]  driver_probe_device+0x1f/0xa0
    [ 1496.400416]  __driver_attach+0xba/0x1c0
    [ 1496.400632]  bus_for_each_dev+0x8e/0xe0
    [ 1496.400714]  bus_add_driver+0x142/0x220
    [ 1496.400790]  driver_register+0x72/0xd0
    [ 1496.400876]  __xenbus_register_frontend+0x2b/0x50
    [ 1496.400977]  ? __pfx_netif_init+0x10/0x10 [xen_netfront]
    [ 1496.401079]  do_one_initcall+0x5a/0x310
    [ 1496.401159]  do_init_module+0x90/0x250
    [ 1496.401239]  init_module_from_file+0x88/0xd0
    [ 1496.401345]  ? __pfx_ovl_file_accessed+0x10/0x10 [overlay]
    [ 1496.401557]  idempotent_init_module+0x114/0x310
    [ 1496.401656]  __x64_sys_finit_module+0x6d/0xd0
    [ 1496.401773]  do_syscall_64+0x87/0x7e0
    [ 1496.401848]  entry_SYSCALL_64_after_hwframe+0x76/0x7e
    [ 1496.401946] RIP: 0033:0x7abadbeba7b9
    [ 1496.402029] RSP: 002b:00007ffc0ffba5d8 EFLAGS: 00000246 ORIG_RAX: 
0000000000000139
    [ 1496.402163] RAX: ffffffffffffffda RBX: 00005aa7d2036580 RCX: 
00007abadbeba7b9
    [ 1496.556946] RDX: 0000000000000000 RSI: 00007abadb36d44d RDI: 
000000000000001b
    [ 1496.557171] RBP: 0000000000000000 R08: 0000000000000000 R09: 
00005aa7d20518c0
    [ 1496.560779] R10: 0000000000000000 R11: 0000000000000246 R12: 
00007abadb36d44d
    [ 1496.561000] R13: 0000000000020000 R14: 00005aa7d1f24b00 R15: 
0000000000000000
    [ 1496.561301]  </TASK>

Xenstore content at this time is:

device/vif = ""   (n0,r61)
device/vif/0 = ""   (n61,r59)
device/vif/0/backend = "/local/domain/59/backend/vif/61/0"   (n61,r59)
device/vif/0/backend-id = "59"   (n61,r59)
device/vif/0/state = "1"   (n61,r59)
device/vif/0/handle = "0"   (n61,r59)
device/vif/0/mac = "00:16:3e:5e:6c:00"   (n61,r59)
device/vif/0/trusted = "0"   (n61,r59)
device/vif/0/mtu = "1500"   (n59,r61)

/local/domain/59/backend/vif/61/0/frontend = "/local/domain/61/device/vif/0"   
(n59,r61)
/local/domain/59/backend/vif/61/0/frontend-id = "61"   (n59,r61)
/local/domain/59/backend/vif/61/0/online = "1"   (n59,r61)
/local/domain/59/backend/vif/61/0/state = "2"   (n59,r61)
/local/domain/59/backend/vif/61/0/script = "/etc/xen/scripts/vif-route-qubes"   
(n59,r61)
/local/domain/59/backend/vif/61/0/mac = "00:16:3e:5e:6c:00"   (n59,r61)
/local/domain/59/backend/vif/61/0/ip = "10.137.0.19 fd09:24ef:4179::a89:13"   
(n59,r61)
/local/domain/59/backend/vif/61/0/bridge = "xenbr0"   (n59,r61)
/local/domain/59/backend/vif/61/0/handle = "0"   (n59,r61)
/local/domain/59/backend/vif/61/0/type = "vif"   (n59,r61)
/local/domain/59/backend/vif/61/0/hotplug-status = "connected"   (n59,r61)
/local/domain/59/backend/vif/61/0/feature-sg = "1"   (n59,r61)
/local/domain/59/backend/vif/61/0/feature-gso-tcpv4 = "1"   (n59,r61)
/local/domain/59/backend/vif/61/0/feature-gso-tcpv6 = "1"   (n59,r61)
/local/domain/59/backend/vif/61/0/feature-ipv6-csum-offload = "1"   (n59,r61)
/local/domain/59/backend/vif/61/0/feature-rx-copy = "1"   (n59,r61)
/local/domain/59/backend/vif/61/0/feature-xdp-headroom = "1"   (n59,r61)
/local/domain/59/backend/vif/61/0/feature-rx-flip = "0"   (n59,r61)
/local/domain/59/backend/vif/61/0/feature-multicast-control = "1"   (n59,r61)
/local/domain/59/backend/vif/61/0/feature-dynamic-multicast-control = "1"   
(n59,r61)
/local/domain/59/backend/vif/61/0/feature-split-event-channels = "1"   (n59,r61)
/local/domain/59/backend/vif/61/0/multi-queue-max-queues = "2"   (n59,r61)
/local/domain/59/backend/vif/61/0/feature-ctrl-ring = "1"   (n59,r61)

So, from what I see, the attach happens quite early in practice -
during, or even before loading xen-netfront module. But then, the device
is misinterpreted as a stale one.

This does not happen every time, only sometimes. I guess it's related to
the timing of the network-attach call.

I'll try to add some more logging (especially what state it got from
xenstore vs what it expected), but maybe you have some ideas already?

-- 
Best Regards,
Marek Marczykowski-Górecki
Invisible Things Lab

Attachment: signature.asc
Description: PGP signature