Re: possible kernel/libxl race with xl network-attach

[James Dingwall <james-xen@dingwall.me.uk>]

On 2022-01-13 16:11, Roger Pau Monné wrote:
> On Thu, Jan 13, 2022 at 11:19:46AM +0000, James Dingwall wrote:
>> 
>> I have been trying to debug a problem where a vif with the backend in 
>> a
>> driver domain is added to dom0.  Intermittently the hotplug script is
>> not invoked by libxl (running as xl devd) in the driver domain.  By
>> enabling some debug for the driver domain kernel and libxl I have 
>> these
>> messages:
>> 
>> driver domain kernel (Ubuntu 5.4.0-92-generic):
>> 
>> [Thu Jan 13 01:39:31 2022] [1408] 564: vif vif-0-0 vif0.0: 
>> Successfully created xenvif
>> [Thu Jan 13 01:39:31 2022] [26] 583: xen_netback:frontend_changed: 
>> /local/domain/0/device/vif/0 -> Initialising
>> [Thu Jan 13 01:39:31 2022] [26] 470: xen_netback:backend_switch_state: 
>> backend/vif/0/0 -> InitWait
>> [Thu Jan 13 01:39:31 2022] [26] 583: xen_netback:frontend_changed: 
>> /local/domain/0/device/vif/0 -> Connected
>> [Thu Jan 13 01:39:31 2022] vif vif-0-0 vif0.0: Guest Rx ready
>> [Thu Jan 13 01:39:31 2022] [26] 470: xen_netback:backend_switch_state: 
>> backend/vif/0/0 -> Connected
>> 
>> xl devd (Xen 4.14.3):
>> 
>> 2022-01-13 01:39:31 UTC libxl: debug: 
>> libxl_event.c:750:watchfd_callback: watch w=0x7ffd416b0528 
>> wpath=/local/domain/2/backend token=3/0: event 
>> epath=/local/domain/2/backend/vif/0/0/state
>> 2022-01-13 01:39:31 UTC libxl: debug: 
>> libxl_event.c:2445:libxl__nested_ao_create: ao 0x5633ac569700: nested 
>> ao, parent 0x5633ac567f90
>> 2022-01-13 01:39:31 UTC libxl: debug: 
>> libxl_event.c:750:watchfd_callback: watch w=0x5633ac569180 
>> wpath=/local/domain/2/backend/vif/0/0/state token=2/1: event 
>> epath=/local/domain/2/backend/vif/0/0/state
>> 2022-01-13 01:39:31 UTC libxl: debug: 
>> libxl_event.c:1055:devstate_callback: backend 
>> /local/domain/2/backend/vif/0/0/state wanted state 2 still waiting 
>> state 4
>> 2022-01-13 01:39:31 UTC libxl: debug: 
>> libxl_event.c:750:watchfd_callback: watch w=0x7ffd416b0528 
>> wpath=/local/domain/2/backend token=3/0: event 
>> epath=/local/domain/2/backend/vif/0/0/state
>> 2022-01-13 01:39:31 UTC libxl: debug: 
>> libxl_event.c:2445:libxl__nested_ao_create: ao 0x5633ac56a220: nested 
>> ao, parent 0x5633ac567f90
>> 2022-01-13 01:39:31 UTC libxl: debug: 
>> libxl_event.c:750:watchfd_callback: watch w=0x5633ac569180 
>> wpath=/local/domain/2/backend/vif/0/0/state token=2/1: event 
>> epath=/local/domain/2/backend/vif/0/0/state
>> 2022-01-13 01:39:31 UTC libxl: debug: 
>> libxl_event.c:1055:devstate_callback: backend 
>> /local/domain/2/backend/vif/0/0/state wanted state 2 still waiting 
>> state 4
>> 2022-01-13 01:39:51 UTC libxl: debug: 
>> libxl_aoutils.c:88:xswait_timeout_callback: backend 
>> /local/domain/2/backend/vif/0/0/state (hoping for state change to 2): 
>> xswait timeout (path=/local/domain/2/backend/vif/0/0/state)
>> 2022-01-13 01:39:51 UTC libxl: debug: 
>> libxl_event.c:850:libxl__ev_xswatch_deregister: watch w=0x5633ac569180 
>> wpath=/local/domain/2/backend/vif/0/0/state token=2/1: deregister 
>> slotnum=2
>> 2022-01-13 01:39:51 UTC libxl: debug: 
>> libxl_event.c:1039:devstate_callback: backend 
>> /local/domain/2/backend/vif/0/0/state wanted state 2  timed out
>> 2022-01-13 01:39:51 UTC libxl: debug: 
>> libxl_event.c:864:libxl__ev_xswatch_deregister: watch 
>> w=0x5633ac569180: deregister unregistered
>> 2022-01-13 01:39:51 UTC libxl: debug: 
>> libxl_device.c:1092:device_backend_callback: calling 
>> device_backend_cleanup
>> 2022-01-13 01:39:51 UTC libxl: debug: 
>> libxl_event.c:864:libxl__ev_xswatch_deregister: watch 
>> w=0x5633ac569180: deregister unregistered
>> 2022-01-13 01:39:51 UTC libxl: error: 
>> libxl_device.c:1105:device_backend_callback: unable to add device with 
>> path /local/domain/2/backend/vif/0/0
>> 2022-01-13 01:39:51 UTC libxl: debug: 
>> libxl_event.c:864:libxl__ev_xswatch_deregister: watch 
>> w=0x5633ac569280: deregister unregistered
>> 2022-01-13 01:39:51 UTC libxl: debug: 
>> libxl_device.c:1470:device_complete: device 
>> /local/domain/2/backend/vif/0/0 add failed
>> 2022-01-13 01:39:51 UTC libxl: debug: 
>> libxl_event.c:2035:libxl__ao__destroy: ao 0x5633ac568f30: destroy
>> 
>> the xenstore content for the backend:
>> 
>> # xenstore-ls /local/domain/2/backend/vif/0
>> 0 = ""
>>  frontend = "/local/domain/0/device/vif/0"
>>  frontend-id = "0"
>>  online = "1"
>>  state = "4"
>>  script = "/etc/xen/scripts/vif-zynstra"
>>  vifname = "dom0.0"
>>  mac = "00:16:3e:6c:de:82"
>>  bridge = "cluster"
>>  handle = "0"
>>  type = "vif"
>>  feature-sg = "1"
>>  feature-gso-tcpv4 = "1"
>>  feature-gso-tcpv6 = "1"
>>  feature-ipv6-csum-offload = "1"
>>  feature-rx-copy = "1"
>>  feature-rx-flip = "0"
>>  feature-multicast-control = "1"
>>  feature-dynamic-multicast-control = "1"
>>  feature-split-event-channels = "1"
>>  multi-queue-max-queues = "2"
>>  feature-ctrl-ring = "1"
>>  hotplug-status = "connected"
>> 
>> My guess is that the libxl callback is started waiting for the backend
>> state key to be set to XenbusStateInitWait (2) but the frontend in 
>> dom0
>> has already triggered the backend to transition to 
>> XenbusStateConnected
>> (4) and therefore it does not successfully complete.
> 
> I think your analysis is correct. The question is who sets
> hotplug-status to "connected" in xenstore if the hotplug script in the
> driver domain hasn't been launched by `xl devd`.
> 
> It would seem to me some other entity is launching the hotplug
> scripts, do you have some udev rules in the driver domain that do that
> and race with `xl devd` maybe?

No, there are no udev rules for xen network devices.  What it looks like 
is that the in linux/drivers/net/xen-netback/xenbus.c that the backend 
state is changed to XenbusStateConnected in response to 
frontend_changed() being called and the frontend state is 
XenbusStateConnected.  The xen-frontend.c driver has:

         case XenbusStateInitWait:
                 if (dev->state != XenbusStateInitialising)
                         break;
                 if (xennet_connect(netdev) != 0)
                         break;
                 xenbus_switch_state(dev, XenbusStateConnected);
                 break;

so it seems that if this completes in the domain with the frontend then 
the backend can process this state change before `xl devd` is launched 
and it completely misses the window where the backend state was 
XenbusStateInitWait.

This is the patch I have come up with as a workaround:

diff --git a/tools/libxl/libxl_event.c b/tools/libxl/libxl_event.c
index 7c5387e94f..408afa6ee6 100644
--- a/tools/libxl/libxl_event.c
+++ b/tools/libxl/libxl_event.c
@@ -1052,6 +1052,12 @@ static void devstate_callback(libxl__egc *egc, 
libxl__xswait_state *xsw,
          LOG(DEBUG, "backend %s wanted state %d ok", ds->w.path, 
ds->wanted);
          rc = 0;
      } else {
+        if (ds->wanted == XenbusStateInitWait && got == 
XenbusStateConnected) {
+            LOG(DEBUG, "backend %s wanted state %d interpreting"
+                " state %d as success", ds->w.path, ds->wanted, got);
+            rc = 0;
+            goto out;
+        }
          LOG(DEBUG, "backend %s wanted state %d"" still waiting state 
%d",
              ds->w.path, ds->wanted, got);
          return;

Thanks,
James