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

[Roger Pau Monné <roger.pau@xxxxxxxxxx>]

On Fri, Jan 21, 2022 at 01:34:54PM +0000, James Dingwall wrote:
> 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"

The relevant point here is that `hotplug-status = "connected"` in the
backend xenstore nodes, and that's set by the hotplug script.

Having hotplug-status == "connected" will allow the backend to proceed
to the connected state, so there's some component in your system that
sets this xenstore node before `xl devd` get a change to run the
hotplug script, hence me asking for any udev rules in the previous
email.

If it's not an udev rule then I'm lost. Do you have any modifications
to the Xen tools that could set this xenstore node?

Regards, Roger.