Re: xen-netfront crash when detaching network while some network activity

["Marek Marczykowski-Górecki" <marmarek@invisiblethingslab.com>]

[-- Attachment #1.1: Type: text/plain, Size: 3602 bytes --]

On Thu, Jan 21, 2016 at 12:30:48PM +0000, Joao Martins wrote:
> 
> 
> On 01/20/2016 09:59 PM, Konrad Rzeszutek Wilk wrote:
> > On Tue, Dec 01, 2015 at 11:32:58PM +0100, Marek Marczykowski-Górecki wrote:
> >> On Tue, Dec 01, 2015 at 05:00:42PM -0500, Konrad Rzeszutek Wilk wrote:
> >>> On Tue, Nov 17, 2015 at 03:45:15AM +0100, Marek Marczykowski-Górecki wrote:
> >>>> On Wed, Oct 21, 2015 at 08:57:34PM +0200, Marek Marczykowski-Górecki wrote:
> >>>>> On Wed, May 27, 2015 at 12:03:12AM +0200, Marek Marczykowski-Górecki wrote:
> >>>>>> On Tue, May 26, 2015 at 11:56:00AM +0100, David Vrabel wrote:
> >>>>>>> On 22/05/15 12:49, Marek Marczykowski-Górecki wrote:
> >>>>>>>> Hi all,
> >>>>>>>>
> >>>>>>>> I'm experiencing xen-netfront crash when doing xl network-detach while
> >>>>>>>> some network activity is going on at the same time. It happens only when
> >>>>>>>> domU has more than one vcpu. Not sure if this matters, but the backend
> >>>>>>>> is in another domU (not dom0). I'm using Xen 4.2.2. It happens on kernel
> >>>>>>>> 3.9.4 and 4.1-rc1 as well.
> >>>>>>>>
> >>>>>>>> Steps to reproduce:
> >>>>>>>> 1. Start the domU with some network interface
> >>>>>>>> 2. Call there 'ping -f some-IP'
> >>>>>>>> 3. Call 'xl network-detach NAME 0'
> >>>
> >>> Do you see this all the time or just on occassions?
> >>
> >> Using above procedure - all the time.
> >>
> >>> I tried to reproduce it and couldn't see it. Is your VM an PV or HVM?
> >>
> >> PV, started by libvirt. This may have something to do, the problem didn't
> >> existed on older Xen (4.1) and started by xl. I'm not sure about kernel
> >> version there, but I think I've tried there 3.18 too, which has this
> >> problem.
> >>
> >> But I don't see anything special in domU config file (neither backend
> >> nor frontend) - it may be some libvirt default. If that's really the
> >> cause. Can I (and how) get any useful information about that?
> > 
> > libvirt naturally does some libxl calls, and they may be different.
> > 
> > Any chance you could give me an idea of:
> >  - What commands you use in libvirt?
> >  - Do you use a bond or bridge?
> >  - What version of libvirt you are using?
> > 
> > Thanks!
> > CC-ing Joao just in case he has seen this.
> >>
> Hm, So far I couldn't reproduce the issue with upstream Xen/linux/libvirt, using
> both libvirt or plain xl (both on a bridge setup) and also irrespective of the
> both load and direction of traffic (be it a ping flood, pktgen with min.
> sized packets or iperf).

I've ran the test again, on vanilla 4.4 and collected some info:
 - xenstore dump of frontend (xs-frontend-before.txt)
 - xenstore dump of backend (xs-backend-before.txt)
 - kernel messages (console output) (console.log)
 - kernel config (config-4.4)
 - libvirt config of that domain (netdebug.conf)

Versions:
 - kernel 4.4 (frontend), 4.2.8 (backend)
 - libvirt 1.2.20
 - xen 4.6.0

In backend domain there is no bridge or anything like that - only
routing. The same in frontend - nothing fancy - just IP set on eth0
there.

Steps to reproduce were the same:
 - start frontend domain (virsh create ...)
 - call ping -f
 - xl network-detach NAME 0

Note that the crash doesn't happen with attached patch applied (as noted
in mail on Oct 21), but I have no idea whether is it a proper fix, or
just prevents the crash by a coincidence.

-- 
Best Regards,
Marek Marczykowski-Górecki
Invisible Things Lab
A: Because it messes up the order in which people normally read text.
Q: Why is top-posting such a bad thing?

[-- Attachment #1.2: console.log --]
[-- Type: text/plain, Size: 29664 bytes --]

[    0.000000] x86/PAT: Configuration [0-7]: WB  WT  UC- UC  WC  WP  UC  UC  
[    0.000000] Initializing cgroup subsys cpuset
[    0.000000] Initializing cgroup subsys cpu
[    0.000000] Initializing cgroup subsys cpuacct
[    0.000000] Linux version 4.4.0-1.pvops.qubes.x86_64 (user@devel-3rdparty) (gcc version 4.9.2 20150212 (Red Hat 4.9.2-6) (GCC) ) #20 SMP Fri Jan 22 00:39:29 CET 2016
[    0.000000] Command line: root=/dev/mapper/dmroot ro nomodeset console=hvc0 rd_NO_PLYMOUTH 3 rd.break
[    0.000000] x86/fpu: Legacy x87 FPU detected.
[    0.000000] x86/fpu: Using 'lazy' FPU context switches.
[    0.000000] ACPI in unprivileged domain disabled
[    0.000000] Released 0 page(s)
[    0.000000] e820: BIOS-provided physical RAM map:
[    0.000000] Xen: [mem 0x0000000000000000-0x000000000009ffff] usable
[    0.000000] Xen: [mem 0x00000000000a0000-0x00000000000fffff] reserved
[    0.000000] Xen: [mem 0x0000000000100000-0x00000000f9ffffff] usable
[    0.000000] NX (Execute Disable) protection: active
[    0.000000] DMI not present or invalid.
[    0.000000] Hypervisor detected: Xen
[    0.000000] e820: last_pfn = 0xfa000 max_arch_pfn = 0x400000000
[    0.000000] MTRR: Disabled
[    0.000000] RAMDISK: [mem 0x02030000-0x027c6fff]
[    0.000000] NUMA turned off
[    0.000000] Faking a node at [mem 0x0000000000000000-0x00000000f9ffffff]
[    0.000000] NODE_DATA(0) allocated [mem 0x18837000-0x18848fff]
[    0.000000] Zone ranges:
[    0.000000]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
[    0.000000]   DMA32    [mem 0x0000000001000000-0x00000000f9ffffff]
[    0.000000]   Normal   empty
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000000001000-0x000000000009ffff]
[    0.000000]   node   0: [mem 0x0000000000100000-0x00000000f9ffffff]
[    0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x00000000f9ffffff]
[    0.000000] p2m virtual area at ffffc90000000000, size is 40000000
[    0.000000] Remapped 0 page(s)
[    0.000000] SFI: Simple Firmware Interface v0.81 http://simplefirmware.org
[    0.000000] smpboot: Allowing 2 CPUs, 0 hotplug CPUs
[    0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff]
[    0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000fffff]
[    0.000000] e820: [mem 0xfa000000-0xffffffff] available for PCI devices
[    0.000000] Booting paravirtualized kernel on Xen
[    0.000000] Xen version: 4.6.0 (preserve-AD)
[    0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
[    0.000000] setup_percpu: NR_CPUS:64 nr_cpumask_bits:64 nr_cpu_ids:2 nr_node_ids:1
[    0.000000] PERCPU: Embedded 33 pages/cpu @ffff880013c00000 s98264 r8192 d28712 u1048576
[    0.000000] Built 1 zonelists in Node order, mobility grouping on.  Total pages: 1007882
[    0.000000] Policy zone: DMA32
[    0.000000] Kernel command line: root=/dev/mapper/dmroot ro nomodeset console=hvc0 rd_NO_PLYMOUTH 3 rd.break
[    0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes)
[    0.000000] Memory: 302592K/4095612K available (6670K kernel code, 1222K rwdata, 2980K rodata, 1452K init, 1424K bss, 3793020K reserved, 0K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=1
[    0.000000] Hierarchical RCU implementation.
[    0.000000] 	Build-time adjustment of leaf fanout to 64.
[    0.000000] 	RCU restricting CPUs from NR_CPUS=64 to nr_cpu_ids=2.
[    0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=2
[    0.000000] Using NULL legacy PIC
[    0.000000] NR_IRQS:4352 nr_irqs:48 0
[    0.000000] xen:events: Using FIFO-based ABI
[    0.000000] 	Offload RCU callbacks from all CPUs
[    0.000000] 	Offload RCU callbacks from CPUs: 0-1.
[    0.000000] Console: colour dummy device 80x25
[    0.000000] console [tty0] enabled
[    0.000000] console [hvc0] enabled
[    0.000000] clocksource: xen: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
[    0.000000] installing Xen timer for CPU 0
[    0.000000] tsc: Detected 1995.104 MHz processor
[    0.001000] Calibrating delay loop (skipped), value calculated using timer frequency.. 3990.20 BogoMIPS (lpj=1995104)
[    0.001000] pid_max: default: 32768 minimum: 301
[    0.001000] Security Framework initialized
[    0.001611] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes)
[    0.004023] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes)
[    0.005197] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes)
[    0.005237] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes)
[    0.005788] Initializing cgroup subsys io
[    0.005803] Initializing cgroup subsys memory
[    0.005821] Initializing cgroup subsys devices
[    0.005832] Initializing cgroup subsys freezer
[    0.005843] Initializing cgroup subsys net_cls
[    0.005853] Initializing cgroup subsys perf_event
[    0.005863] Initializing cgroup subsys net_prio
[    0.005873] Initializing cgroup subsys hugetlb
[    0.005956] CPU: Physical Processor ID: 0
[    0.005963] CPU: Processor Core ID: 1
[    0.005977] Last level iTLB entries: 4KB 128, 2MB 4, 4MB 4
[    0.005983] Last level dTLB entries: 4KB 256, 2MB 0, 4MB 32, 1GB 0
[    0.039457] ftrace: allocating 25787 entries in 101 pages
[    0.047128] Could not initialize VPMU for cpu 0, error -95
[    0.047220] Performance Events: unsupported p6 CPU model 15 no PMU driver, software events only.
[    0.047979] NMI watchdog: disabled (cpu0): hardware events not enabled
[    0.047990] NMI watchdog: Shutting down hard lockup detector on all cpus
[    0.048139] SMP alternatives: switching to SMP code
[    0.078846] installing Xen timer for CPU 1
[    0.079180] x86: Booted up 1 node, 2 CPUs
[    0.079316] devtmpfs: initialized
[    0.083816] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
[    0.084096] atomic64_test: passed for x86-64 platform with CX8 and with SSE
[    0.084108] pinctrl core: initialized pinctrl subsystem
[    0.104107] RTC time: 165:165:165, date: 165/165/65
[    0.110246] NET: Registered protocol family 16
[    0.110284] xen:grant_table: Grant tables using version 1 layout
[    0.110310] Grant table initialized
[    0.111010] PCI: setting up Xen PCI frontend stub
[    0.115090] ACPI: Interpreter disabled.
[    0.115090] xen:balloon: Initialising balloon driver
[    0.181042] xen_balloon: Initialising balloon driver
[    0.181110] vgaarb: loaded
[    0.182053] SCSI subsystem initialized
[    0.182165] dmi: Firmware registration failed.
[    0.183040] PCI: System does not support PCI
[    0.183050] PCI: System does not support PCI
[    0.183237] NetLabel: Initializing
[    0.183248] NetLabel:  domain hash size = 128
[    0.183254] NetLabel:  protocols = UNLABELED CIPSOv4
[    0.183279] NetLabel:  unlabeled traffic allowed by default
[    0.185019] clocksource: Switched to clocksource xen
[    0.195845] pnp: PnP ACPI: disabled
[    0.200085] NET: Registered protocol family 2
[    0.200441] TCP established hash table entries: 32768 (order: 6, 262144 bytes)
[    0.200691] TCP bind hash table entries: 32768 (order: 7, 524288 bytes)
[    0.200901] TCP: Hash tables configured (established 32768 bind 32768)
[    0.200975] UDP hash table entries: 2048 (order: 4, 65536 bytes)
[    0.201057] UDP-Lite hash table entries: 2048 (order: 4, 65536 bytes)
[    0.201180] NET: Registered protocol family 1
[    0.201284] Unpacking initramfs...
[    0.219827] Freeing initrd memory: 7772K (ffff880002030000 - ffff8800027c7000)
[    0.220918] futex hash table entries: 512 (order: 3, 32768 bytes)
[    0.220977] audit: initializing netlink subsys (disabled)
[    0.221036] audit: type=2000 audit(1453421870.210:1): initialized
[    0.221566] HugeTLB registered 2 MB page size, pre-allocated 0 pages
[    0.224154] zbud: loaded
[    0.224502] VFS: Disk quotas dquot_6.6.0
[    0.224567] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    0.225281] Key type big_key registered
[    0.230104] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 253)
[    0.230168] io scheduler noop registered
[    0.230177] io scheduler deadline registered
[    0.230239] io scheduler cfq registered (default)
[    0.230356] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
[    0.230371] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
[    0.230721] xen:xen_evtchn: Event-channel device installed
[    0.231501] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    0.232242] Non-volatile memory driver v1.3
[    0.232585] loop: module loaded
[    0.283555] blkfront: xvda: flush diskcache: enabled; persistent grants: enabled; indirect descriptors: enabled;
[    0.287743] tun: Universal TUN/TAP device driver, 1.6
[    0.287754] tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com>
[    0.287959] xen_netfront: Initialising Xen virtual ethernet driver
[    0.291795] blkfront: xvdb: flush diskcache: enabled; persistent grants: enabled; indirect descriptors: enabled;
[    0.295457] i8042: PNP: No PS/2 controller found. Probing ports directly.
[    1.314402] i8042: No controller found
[    1.314436] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x39843a855e2, max_idle_ns: 881590688655 ns
[    1.314792] mousedev: PS/2 mouse device common for all mice
[    1.315247] device-mapper: uevent: version 1.0.3
[    1.315492] device-mapper: ioctl: 4.34.0-ioctl (2015-10-28) initialised: dm-devel@redhat.com
[    1.315696] dmi-sysfs: dmi entry is absent.
[    1.315738] hidraw: raw HID events driver (C) Jiri Kosina
[    1.315852] drop_monitor: Initializing network drop monitor service
[    1.315956] Initializing XFRM netlink socket
[    1.316215] NET: Registered protocol family 10
[    1.316696] mip6: Mobile IPv6
[    1.316710] NET: Registered protocol family 17
[    1.317235] registered taskstats version 1
[    1.317290] zswap: loaded using pool lzo/zbud
[    1.386055] blkfront: xvdc: flush diskcache: enabled; persistent grants: enabled; indirect descriptors: enabled;
[    1.392405] blkfront: xvdd: flush diskcache: enabled; persistent grants: enabled; indirect descriptors: enabled;
[    1.417232]   Magic number: 1:252:3141
[    1.417399] console [netcon0] enabled
[    1.417417] netconsole: network logging started
[    1.417441] hctosys: unable to open rtc device (rtc0)
[    1.420219] Freeing unused kernel memory: 1452K (ffffffff81d33000 - ffffffff81e9e000)
[    1.420258] Write protecting the kernel read-only data: 12288k
[    1.434129] Freeing unused kernel memory: 1508K (ffff880001687000 - ffff880001800000)
[    1.435108] Freeing unused kernel memory: 1116K (ffff880001ae9000 - ffff880001c00000)
Qubes initramfs script here:
[    1.440455] random: modprobe urandom read with 33 bits of entropy available
modprobe: chdir(4.4.0-1.pvops.qubes.x86_64): No such file or directory
modprobe: chdir(4.4.0-1.pvops.qubes.x86_64): No such file or directory
Qubes: Cannot load Xen Block Frontend...
Waiting for /dev/xvda* devices...
Qubes: Doing COW setup for AppVM...
sfdisk: Checking that no-one is using this disk right now ...
sfdisk: OK
sfdisk:  /dev/xvdc: unrecognized partition table type
sfdisk: No partitions found
sfdisk: Warning: partition 1 does not end at a cylinder boundary
sfdisk: Warning: partition 2 does not start at a cylinder boundary
sfdisk: Warning: partition 2 does not end at a cylinder boundary
sfdisk: Warning: no primary partition is marked bootable (active)
This does not matter for LILO, but the DOS MBR will not boot this disk.
[    1.448877]  xvdc: xvdc1 xvdc2
sfdisk: If you created or changed a DOS partition, /dev/foo7, say, then use dd(1)
to zero the first 512 bytes:  dd if=/dev/zero of=/dev/foo7 bs=512 count=1
(See fdisk(8).)
Setting up swapspace version 1, size = 1073737728 bytes
UUID=da20ab8f-e3b2-460f-8ea1-c77204a0f63d
Qubes: done.
modprobe: chdir(4.4.0-1.pvops.qubes.x86_64): No such file or directory
[    1.464947] EXT4-fs (dm-0): couldn't mount as ext3 due to feature incompatibilities
[    1.465108] EXT4-fs (dm-0): couldn't mount as ext2 due to feature incompatibilities
[    1.466566] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
Waiting for /dev/xvdd device...
[    1.471024] EXT4-fs (xvdd): mounting ext3 file system using the ext4 subsystem
[    1.471931] EXT4-fs (xvdd): mounted filesystem with ordered data mode. Opts: (null)
[    1.474541] EXT4-fs (dm-0): re-mounted. Opts: data=ordered
[    1.484119] EXT4-fs (dm-0): re-mounted. Opts: data=ordered
mount: mounting /tmp/modules/4.4.0-1.pvops.qubes.x86_64 on /sysroot/lib/modules/4.4.0-1.pvops.qubes.x86_64 failed: No such file or directory
[    1.578686] systemd[1]: systemd 216 running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ -LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN)
[    1.578778] systemd[1]: Detected virtualization 'xen'.
[    1.578793] systemd[1]: Detected architecture 'x86-64'.

Welcome to .[0;34mFedora 21 (Twenty One).[0m!

[    1.579269] systemd[1]: No hostname configured.
[    1.579287] systemd[1]: Set hostname to <localhost>.
[    1.643346] systemd[1]: Configuration file /usr/lib/systemd/system/auditd.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway.
[    1.673346] systemd[1]: Starting Forward Password Requests to Wall Directory Watch.
[    1.673475] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[    1.673505] systemd[1]: Expecting device dev-hvc0.device...
         Expecting device dev-hvc0.device...
[    1.673685] systemd[1]: Starting Remote File Systems.
[.[32m  OK  .[0m] Reached target Remote File Systems.
[    1.673773] systemd[1]: Reached target Remote File Systems.
[    1.673823] systemd[1]: Starting Arbitrary Executable File Formats File System Automount Point.
[.[32m  OK  .[0m] Set up automount Arbitrary Executab...ats File System Automount Point.
[    1.674059] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[    1.674091] systemd[1]: Starting Encrypted Volumes.
[.[32m  OK  .[0m] Reached target Encrypted Volumes.
[    1.674175] systemd[1]: Reached target Encrypted Volumes.
[    1.674201] systemd[1]: Expecting device dev-xvdc1.device...
         Expecting device dev-xvdc1.device...
[    1.674287] systemd[1]: Starting Root Slice.
[.[32m  OK  .[0m] Created slice Root Slice.
[    1.690630] systemd[1]: Created slice Root Slice.
[    1.690661] systemd[1]: Starting Delayed Shutdown Socket.
[.[32m  OK  .[0m] Listening on Delayed Shutdown Socket.
[    1.690788] systemd[1]: Listening on Delayed Shutdown Socket.
[    1.690813] systemd[1]: Starting /dev/initctl Compatibility Named Pipe.
[.[32m  OK  .[0m] Listening on /dev/initctl Compatibility Named Pipe.
[    1.690938] systemd[1]: Listening on /dev/initctl Compatibility Named Pipe.
[    1.690970] systemd[1]: Starting udev Control Socket.
[.[32m  OK  .[0m] Listening on udev Control Socket.
[    1.691101] systemd[1]: Listening on udev Control Socket.
[    1.691130] systemd[1]: Starting udev Kernel Socket.
[.[32m  OK  .[0m] Listening on udev Kernel Socket.
[    1.691234] systemd[1]: Listening on udev Kernel Socket.
[    1.691257] systemd[1]: Starting User and Session Slice.
[.[32m  OK  .[0m] Created slice User and Session Slice.
[    1.691711] systemd[1]: Created slice User and Session Slice.
[    1.691745] systemd[1]: Starting Journal Socket.
[.[32m  OK  .[0m] Listening on Journal Socket.
[    1.691894] systemd[1]: Listening on Journal Socket.
[    1.691942] systemd[1]: Starting System Slice.
[.[32m  OK  .[0m] Created slice System Slice.
[    1.692393] systemd[1]: Created slice System Slice.
[    1.692442] systemd[1]: Mounting Temporary Directory...
         Mounting Temporary Directory...
[    1.692722] systemd[1]: tmp.mount: Directory /tmp to mount over is not empty, mounting anyway.
[    1.694761] systemd[1]: Starting Journal Socket (/dev/log).
[    1.696712] systemd[1]: Starting udev Coldplug all Devices...
         Starting udev Coldplug all Devices...
[    1.699255] systemd[1]: Mounting Huge Pages File System...
         Mounting Huge Pages File System...
[    1.701608] systemd[1]: Mounting Debug File System...
         Mounting Debug File System...
[    1.704788] systemd[1]: Mounting POSIX Message Queue File System...
         Mounting POSIX Message Queue File System...
[    1.719399] systemd[1]: Started Create list of required static device nodes for the current kernel.
[    1.719508] systemd[1]: Starting system-serial\x2dgetty.slice.
[.[32m  OK  .[0m] Created slice system-serial\x2dgetty.slice.
[    1.720294] systemd[1]: Created slice system-serial\x2dgetty.slice.
[    1.720357] systemd[1]: Started Collect Read-Ahead Data.
[    1.720401] systemd[1]: Started Replay Read-Ahead Data.
[    1.720437] systemd[1]: Starting File System Check on Root Device...
         Starting File System Check on Root Device...
[    1.727937] systemd[1]: Starting Load Kernel Modules...
         Starting Load Kernel Modules...
[    1.730073] systemd[1]: Starting Setup Virtual Console...
         Starting Setup Virtual Console...
[    1.745613] systemd[1]: Starting Load legacy module configuration...
         Starting Load legacy module configuration...
[    1.764453] systemd[1]: Started Set Up Additional Binary Formats.
[    1.764540] systemd[1]: Starting Slices.
[.[32m  OK  .[0m] Reached target Slices.
[    1.764610] systemd[1]: Reached target Slices.
[.[32m  OK  .[0m] Mounted POSIX Message Queue File System.
[    1.765640] systemd[1]: Mounted POSIX Message Queue File System.
[.[32m  OK  .[0m] Mounted Debug File System.
[    1.765721] systemd[1]: Mounted Debug File System.
[.[32m  OK  .[0m] Mounted Huge Pages File System.
[    1.765779] systemd[1]: Mounted Huge Pages File System.
[.[32m  OK  .[0m] Mounted Temporary Directory.
[    1.765860] systemd[1]: Mounted Temporary Directory.
[.[32m  OK  .[0m] Listening on Journal Socket (/dev/log).
[    1.766401] systemd[1]: Listening on Journal Socket (/dev/log).
[    1.768972] systemd[1]: systemd-modules-load.service: main process exited, code=exited, status=1/FAILURE
[.[1;31mFAILED.[0m] Failed to start Load Kernel Modules.
See "systemctl status systemd-modules-load.service" for details.
[    1.769555] systemd[1]: Failed to start Load Kernel Modules.
[    1.769579] systemd[1]: Unit systemd-modules-load.service entered failed state.
[    1.774333] systemd[1]: systemd-modules-load.service failed.
[.[32m  OK  .[0m] Started Setup Virtual Console.
[    1.774886] systemd[1]: Started Setup Virtual Console.
[    1.806920] systemd[1]: Mounting Configuration File System...
         Mounting Configuration File System...
[    1.809565] systemd[1]: Starting Apply Kernel Variables...
         Starting Apply Kernel Variables...
[    1.879402] systemd[1]: Mounted FUSE Control File System.
[    1.879728] systemd[1]: Starting Journal Service...
         Starting Journal Service...
[.[32m  OK  .[0m] Started udev Coldplug all Devices.
[    1.898192] systemd[1]: Started udev Coldplug all Devices.
[    1.923752] systemd[1]: Starting Show Plymouth Boot Screen...
         Starting Show Plymouth Boot Screen...
[.[32m  OK  .[0m] Mounted Configuration File System.
[    1.950124] systemd[1]: Mounted Configuration File System.
[.[32m  OK  .[0m] Started Load legacy module configuration.
[    1.950948] systemd[1]: Started Load legacy module configuration.
[.[32m  OK  .[0m] Started Apply Kernel Variables.
[    1.951688] systemd[1]: Started Apply Kernel Variables.
[    1.982704] systemd-fsck[142]: /dev/mapper/dmroot: clean, 139351/655360 files, 1285520/2621440 blocks
[.[32m  OK  .[0m] Started Journal Service.
[    1.984482] systemd[1]: Started Journal Service.
[.[32m  OK  .[0m] Started File System Check on Root Device.
[    2.049986] EXT4-fs (dm-0): re-mounted. Opts: (null)
[    2.118620] systemd-journald[173]: Received request to flush runtime journal from PID 1
[    5.367681] Adding 1048572k swap on /dev/xvdc1.  Priority:-1 extents:1 across:1048572k SSFS
         Starting Remount Root and Kernel File Systems...
[.[32m  OK  .[0m] Started Remount Root and Kernel File Systems.
         Starting Configure read-only root support...
         Starting Flush Journal to Persistent Storage...
         Starting Create Static Device Nodes in /dev...
         Starting Load/Save Random Seed...
[.[32m  OK  .[0m] Started Configure read-only root support.
[.[32m  OK  .[0m] Started Load/Save Random Seed.
[.[32m  OK  .[0m] Started Create Static Device Nodes in /dev.
         Starting udev Kernel Device Manager...
[.[32m  OK  .[0m] Reached target Local File Systems (Pre).
         Mounting /proc/xen...
[.[32m  OK  .[0m] Mounted /proc/xen.
[.[32m  OK  .[0m] Reached target Local File Systems.
         Starting Qubes DB agent...
         Starting Tell Plymouth To Write Out Runtime Data...
[.[32m  OK  .[0m] Started Tell Plymouth To Write Out Runtime Data.
[.[32m  OK  .[0m] Started Qubes DB agent.
         Starting Qubes Random Seed...
         Starting Init Qubes Services settings...
[.[32m  OK  .[0m] Started udev Kernel Device Manager.
[.[32m  OK  .[0m] Started Qubes Random Seed.
[.[32m  OK  .[0m] Started Flush Journal to Persistent Storage.
         Starting Create Volatile Files and Directories...
[.[32m  OK  .[0m] Found device /dev/hvc0.
[.[32m  OK  .[0m] Started Create Volatile Files and Directories.
         Starting Update UTMP about System Boot/Shutdown...
[.[32m  OK  .[0m] Started Update UTMP about System Boot/Shutdown.
.%G[.[32m  OK  .[0m] Started Init Qubes Services settings.
[.[32m  OK  .[0m] Found device /dev/xvdc1.
         Activating swap /dev/xvdc1...
[.[32m  OK  .[0m] Activated swap /dev/xvdc1.
[.[32m  OK  .[0m] Reached target Swap.
[.[32m  OK  .[0m] Reached target System Initialization.
[.[32m  OK  .[0m] Listening on CUPS Printing Service Sockets.
         Starting Manage Sound Card State (restore and store)...
[.[32m  OK  .[0m] Started Manage Sound Card State (restore and store).
[.[32m  OK  .[0m] Reached target Timers.
[.[32m  OK  .[0m] Listening on D-Bus System Message Bus Socket.
[.[32m  OK  .[0m] Reached target Sockets.
[.[32m  OK  .[0m] Started Show Plymouth Boot Screen.
[.[32m  OK  .[0m] Reached target Paths.
[.[32m  OK  .[0m] Reached target Basic System.
         Starting ABRT Automated Bug Reporting Tool...
[.[32m  OK  .[0m] Started ABRT Automated Bug Reporting Tool.
         Starting Initialize and mount /rw and /home...
         Starting Initialize and mount /rw and /home...
         Starting ABRT kernel log watcher...
[.[32m  OK  .[0m] Started ABRT kernel log watcher.
         Starting Install ABRT coredump hook...
         Starting Entropy Daemon based on the HAVEGE algorithm...
[.[32m  OK  .[0m] Started Entropy Daemon based on the HAVEGE algorithm.
         Starting Machine Check Exception Logging Daemon...
[    5.654686] random: nonblocking pool is initialized
         Starting Qubes memory information reporter...
         Starting Qubes remote exec agent...
         Starting ABRT Xorg log watcher...
[.[32m  OK  .[0m] Started ABRT Xorg log watcher.
         Starting Qubes base firewall settings...
         Starting Login Service...
         Starting Permit User Sessions...
         Starting LSB: Start/stop xen driver domain daemon...
         Starting D-Bus System Message Bus...
[    5.823870] EXT4-fs (xvdb): recovery complete
[.[32m  OK  .[0m] Started D-Bus System Message Bus.
[    5.831639] EXT4-fs (xvdb): mounted filesystem with ordered data mode. Opts: discard
[.[32m  OK  .[0m] Started Initialize and mount /rw and /home.
[.[32m  OK  .[0m] Started Initialize and mount /rw and /home.
[.[32m  OK  .[0m] Started Install ABRT coredump hook.
[.[32m  OK  .[0m] Started Machine Check Exception Logging Daemon.
[.[32m  OK  .[0m] Started Qubes memory information reporter.
[.[32m  OK  .[0m] Started Qubes remote exec agent.
[.[1;31mFAILED.[0m] Failed to start Qubes base firewall settings.
See "systemctl status qubes-iptables.service" for details.
[.[32m  OK  .[0m] Started Permit User Sessions.
[.[32m  OK  .[0m] Started LSB: Start/stop xen driver domain daemon.
[.[32m  OK  .[0m] Started Login Service.
         Starting Job spooling tools...
[.[32m  OK  .[0m] Started Job spooling tools.
         Starting Wait for Plymouth Boot Screen to Quit...
         Starting Terminate Plymouth Boot Screen...
         Starting Qubes misc post-boot actions...
         Starting Qubes GUI Agent...

Fedora release 21 (Twenty One)
Kernel 4.4.0-1.pvops.qubes.x86_64 on an x86_64 (hvc0)

netdebug login: [A\b \b\b \broot
Last login: Fri Jan 22 01:18:08 on 
[root@netdebug ~]# ping \b\b\b\b\b.[Kip r
default via 10.137.2.1 dev eth0 
10.137.2.1 dev eth0  scope link 
[root@netdebug ~]# ping -f 10.137.2.1
PING 10.137.2.1 (10.137.2.1) 56(84) bytes of data.
(...)

...........[  111.001689] page:ffffea00004bffc0 count:0 mapcount:0 mapping:          (null) index:0x0
[  111.001710] flags: 0x3fff8000000000()
[  111.001718] page dumped because: VM_BUG_ON_PAGE(atomic_read(&page->_count) == 0)
[  111.001739] ------------[ cut here ]------------
[  111.001746] kernel BUG at include/linux/mm.h:342!
[  111.001753] invalid opcode: 0000 [#1] SMP 
[  111.001761] Modules linked in:
[  111.001769] CPU: 1 PID: 23 Comm: xenwatch Not tainted 4.4.0-1.pvops.qubes.x86_64 #20
[  111.001780] task: ffff880012c88000 ti: ffff880012c7c000 task.ti: ffff880012c7c000
[  111.001790] RIP: e030:[<ffffffff81174a38>]  [<ffffffff81174a38>] __free_pages+0x38/0x40
[  111.001807] RSP: e02b:ffff880012c7fc30  EFLAGS: 00010246
[  111.001814] RAX: 0000000000000044 RBX: 000077ff80000000 RCX: 0000000000000044
[  111.001822] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff880013d0de10
[  111.001829] RBP: ffff880012c7fc30 R08: 0000000000000000 R09: 0000000000000000
[  111.001837] R10: ffffea0000453f00 R11: ffffffff81863ec0 R12: 0000000000000000
[  111.001844] R13: ffff880012eb9c00 R14: ffff880012fff000 R15: 0000000000000000
[  111.001857] FS:  00007f84805fe700(0000) GS:ffff880013d00000(0000) knlGS:0000000000000000
[  111.001867] CS:  e033 DS: 0000 ES: 0000 CR0: 000000008005003b
[  111.001874] CR2: 000055af04b6d000 CR3: 00000000008e8000 CR4: 0000000000002660
[  111.001882] Stack:
[  111.001887]  ffff880012c7fc50 ffffffff81174a9c 000000000000000e 0000000000000004
[  111.001900]  ffff880012c7fc80 ffffffff813f709e ffff87ffffffffff ffff880011528d68
[  111.001912]  ffff880012eb9c00 ffff880011528000 ffff880012c7fce8 ffffffff814b58c2
[  111.001924] Call Trace:
[  111.001932]  [<ffffffff81174a9c>] free_pages+0x5c/0x70
[  111.001942]  [<ffffffff813f709e>] gnttab_end_foreign_access+0x12e/0x160
[  111.001952]  [<ffffffff814b58c2>] xennet_disconnect_backend.isra.26+0x162/0x3b0
[  111.001963]  [<ffffffff814b5b91>] xennet_remove+0x31/0x80
[  111.001971]  [<ffffffff814011e5>] xenbus_dev_remove+0x55/0xb0
[  111.001980]  [<ffffffff8145d596>] __device_release_driver+0x96/0x130
[  111.002639]  [<ffffffff8145d653>] device_release_driver+0x23/0x30
[  111.002639]  [<ffffffff8145c3a1>] bus_remove_device+0x101/0x170
[  111.002639]  [<ffffffff814586a9>] device_del+0x139/0x270
[  111.002639]  [<ffffffff813ffb60>] ? unregister_xenbus_watch+0x1d0/0x1d0
[  111.002639]  [<ffffffff814587fe>] device_unregister+0x1e/0x60
[  111.002639]  [<ffffffff81401053>] xenbus_dev_changed+0xa3/0x1e0
[  111.002639]  [<ffffffff8167f18b>] ? _raw_spin_lock_irqsave+0x1b/0x40
[  111.002639]  [<ffffffff813ffb60>] ? unregister_xenbus_watch+0x1d0/0x1d0
[  111.002639]  [<ffffffff81402ea5>] frontend_changed+0x25/0x50
[  111.002639]  [<ffffffff813ffbe7>] xenwatch_thread+0x87/0x140
[  111.002639]  [<ffffffff810b3b60>] ? wait_woken+0x80/0x80
[  111.002639]  [<ffffffff81090838>] kthread+0xd8/0xf0
[  111.002639]  [<ffffffff81090760>] ? kthread_park+0x60/0x60
[  111.002639]  [<ffffffff8167f70f>] ret_from_fork+0x3f/0x70
[  111.002639]  [<ffffffff81090760>] ? kthread_park+0x60/0x60
[  111.002639] Code: c0 74 1c f0 ff 4f 1c 74 02 5d c3 85 f6 74 07 e8 ff f8 ff ff 5d c3 31 f6 e8 f6 fd ff ff 5d c3 48 c7 c6 20 27 a2 81 e8 28 47 02 00 <0f> 0b 66 0f 1f 44 00 00 66 66 66 66 90 48 85 ff 75 02 f3 c3 55 
[  111.002639] RIP  [<ffffffff81174a38>] __free_pages+0x38/0x40
[  111.002639]  RSP <ffff880012c7fc30>
[  111.003417] ---[ end trace e389324fec932a31 ]---
..............................................................\x03
--- 10.137.2.1 ping statistics ---
27465 packets transmitted, 27392 received, 0% packet loss, time 11156ms
rtt min/avg/max/mdev = 0.053/0.071/12.598/0.109 ms, pipe 2, ipg/ewma 0.406/0.060 ms

[-- Attachment #1.3: netdebug.conf --]
[-- Type: text/plain, Size: 1881 bytes --]

<domain type='xen'>
  <name>netdebug</name>
  <uuid>4e22b40c-e06e-46d1-aaaa-2293487b81b9</uuid>
  <memory unit='MiB'>4000</memory>
  <currentMemory unit='MiB'>400</currentMemory>
  <vcpu placement='static'>2</vcpu>
  <os>
    <type arch='x86_64' machine='xenpv'>linux</type>
    <kernel>/var/lib/qubes/vm-kernels/4.4-debug/vmlinuz</kernel>
    <initrd>/var/lib/qubes/vm-kernels/4.4-debug/initramfs</initrd>
    <cmdline>root=/dev/mapper/dmroot ro nomodeset console=hvc0 rd_NO_PLYMOUTH 3 rd.break</cmdline>
  </os>
  <clock offset='utc' adjustment='reset'>
    <timer name="tsc" mode="native"/>
  </clock>
  <on_poweroff>destroy</on_poweroff>
  <on_reboot>destroy</on_reboot>
  <on_crash>destroy</on_crash>
  <devices>
    <disk type='block' device='disk'>
      <driver name='phy'/>
      <source dev='/var/lib/qubes/vm-templates/fedora-21/root.img:/var/lib/qubes/vm-templates/fedora-21/root-cow.img'/>
      <target dev='xvda' bus='xen'/>
      <readonly/>
      <script path='block-snapshot'/>
    </disk>

    <disk type='block' device='disk'>
      <driver name='phy'/>
      <source dev='/var/lib/qubes/appvms/netdebug/private.img'/>
      <target dev='xvdb' bus='xen'/>
    </disk>

    <disk type='block' device='disk'>
      <driver name='phy'/>
      <source dev='/var/lib/qubes/appvms/netdebug/volatile.img'/>
      <target dev='xvdc' bus='xen'/>
    </disk>

    <disk type='block' device='disk'>
      <driver name='phy'/>
      <source dev='/var/lib/qubes/vm-kernels/4.4-debug/modules.img'/>
      <target dev='xvdd' bus='xen'/>
      <readonly/>
    </disk>

    <interface type='ethernet'>
      <mac address='00:16:3E:5E:6C:1B'/>
      <ip address='10.137.2.29'/>
      <script path='vif-route-qubes'/>
      <backenddomain name='sys-firewall'/>
    </interface>


    <console type='pty'>
      <target type='xen' port='0'/>
    </console>
  </devices>
</domain>


[-- Attachment #1.4: xs-backend-before.txt --]
[-- Type: text/plain, Size: 1228 bytes --]

/local/domain/2/backend/vif/49/0/frontend = "/local/domain/49/device/vif/0"   (n2,r49)
/local/domain/2/backend/vif/49/0/frontend-id = "49"   (n2,r49)
/local/domain/2/backend/vif/49/0/online = "1"   (n2,r49)
/local/domain/2/backend/vif/49/0/state = "4"   (n2,r49)
/local/domain/2/backend/vif/49/0/script = "/etc/xen/scripts/vif-route-qubes"   (n2,r49)
/local/domain/2/backend/vif/49/0/mac = "00:16:3e:5e:6c:1b"   (n2,r49)
/local/domain/2/backend/vif/49/0/ip = "10.137.2.29"   (n2,r49)
/local/domain/2/backend/vif/49/0/handle = "0"   (n2,r49)
/local/domain/2/backend/vif/49/0/type = "vif"   (n2,r49)
/local/domain/2/backend/vif/49/0/feature-sg = "1"   (n2,r49)
/local/domain/2/backend/vif/49/0/feature-gso-tcpv4 = "1"   (n2,r49)
/local/domain/2/backend/vif/49/0/feature-gso-tcpv6 = "1"   (n2,r49)
/local/domain/2/backend/vif/49/0/feature-ipv6-csum-offload = "1"   (n2,r49)
/local/domain/2/backend/vif/49/0/feature-rx-copy = "1"   (n2,r49)
/local/domain/2/backend/vif/49/0/feature-rx-flip = "0"   (n2,r49)
/local/domain/2/backend/vif/49/0/feature-split-event-channels = "1"   (n2,r49)
/local/domain/2/backend/vif/49/0/multi-queue-max-queues = "2"   (n2,r49)
/local/domain/2/backend/vif/49/0/hotplug-status = "connected"   (n2,r49)

[-- Attachment #1.5: xs-frontend-before.txt --]
[-- Type: text/plain, Size: 1503 bytes --]

/local/domain/49/device/vif/0 = ""   (n49,r2)
/local/domain/49/device/vif/0/backend = "/local/domain/2/backend/vif/49/0"   (n49,r2)
/local/domain/49/device/vif/0/backend-id = "2"   (n49,r2)
/local/domain/49/device/vif/0/state = "4"   (n49,r2)
/local/domain/49/device/vif/0/handle = "0"   (n49,r2)
/local/domain/49/device/vif/0/mac = "00:16:3e:5e:6c:1b"   (n49,r2)
/local/domain/49/device/vif/0/multi-queue-num-queues = "2"   (n49,r2)
/local/domain/49/device/vif/0/queue-0 = ""   (n49,r2)
/local/domain/49/device/vif/0/queue-0/tx-ring-ref = "1280"   (n49,r2)
/local/domain/49/device/vif/0/queue-0/rx-ring-ref = "1281"   (n49,r2)
/local/domain/49/device/vif/0/queue-0/event-channel-tx = "19"   (n49,r2)
/local/domain/49/device/vif/0/queue-0/event-channel-rx = "20"   (n49,r2)
/local/domain/49/device/vif/0/queue-1 = ""   (n49,r2)
/local/domain/49/device/vif/0/queue-1/tx-ring-ref = "1282"   (n49,r2)
/local/domain/49/device/vif/0/queue-1/rx-ring-ref = "1283"   (n49,r2)
/local/domain/49/device/vif/0/queue-1/event-channel-tx = "21"   (n49,r2)
/local/domain/49/device/vif/0/queue-1/event-channel-rx = "22"   (n49,r2)
/local/domain/49/device/vif/0/request-rx-copy = "1"   (n49,r2)
/local/domain/49/device/vif/0/feature-rx-notify = "1"   (n49,r2)
/local/domain/49/device/vif/0/feature-sg = "1"   (n49,r2)
/local/domain/49/device/vif/0/feature-gso-tcpv4 = "1"   (n49,r2)
/local/domain/49/device/vif/0/feature-gso-tcpv6 = "1"   (n49,r2)
/local/domain/49/device/vif/0/feature-ipv6-csum-offload = "1"   (n49,r2)

[-- Attachment #1.6: config-4.4 --]
[-- Type: application/x-troff-man, Size: 91440 bytes --]

[-- Attachment #1.7: xen-netfront-detach-crash.patch --]
[-- Type: text/plain, Size: 1128 bytes --]

When it get to free_page(queue->grant_tx_page[i]), the use counter on this page
is already 0, which cause a crash. Not sure if this is the proper fix
(according to git log this may introduce some memory leak), but at least it
prevent the crash.

Details in this thread:
http://xen.markmail.org/thread/pw5edbtqienjx4q5

diff --git a/drivers/net/xen-netfront.c b/drivers/net/xen-netfront.c
index f821a97..a5efbb0 100644
--- a/drivers/net/xen-netfront.c
+++ b/drivers/net/xen-netfront.c
@@ -1065,9 +1069,10 @@ static void xennet_release_tx_bufs(struct netfront_queue *queue)
 
 		skb = queue->tx_skbs[i].skb;
 		get_page(queue->grant_tx_page[i]);
-		gnttab_end_foreign_access(queue->grant_tx_ref[i],
-					  GNTMAP_readonly,
-					  (unsigned long)page_address(queue->grant_tx_page[i]));
+		gnttab_end_foreign_access_ref(
+				queue->grant_tx_ref[i], GNTMAP_readonly);
+		gnttab_release_grant_reference(
+				&queue->gref_tx_head, queue->grant_tx_ref[i]);
 		queue->grant_tx_page[i] = NULL;
 		queue->grant_tx_ref[i] = GRANT_INVALID_REF;
 		add_id_to_freelist(&queue->tx_skb_freelist, queue->tx_skbs, i);

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 473 bytes --]