Xen project Mailing List

Re: [Xen-devel] [PATCH 3/3] libxl: datacopier: Avoid theoretical eof/POLLHUP race

To: Ian Jackson <Ian.Jackson@xxxxxxxxxxxxx>, <xen-devel@xxxxxxxxxxxxxxxxxxx>, Andrew Cooper <andrew.cooper3@xxxxxxxxxx>, Ian Campbell <ian.campbell@xxxxxxxxxx>, Ross Lagerwall <ross.lagerwall@xxxxxxxxxx>, "Wei Liu" <wei.liu2@xxxxxxxxxx>

From: Roger Pau Monné <roger.pau@xxxxxxxxxx>

Date: Tue, 7 Apr 2015 13:14:28 +0200

Delivery-date: Tue, 07 Apr 2015 11:14:46 +0000

List-id: Xen developer discussion <xen-devel.lists.xen.org>

El 02/04/15 a les 18.29, Ian Jackson ha escrit: > Ian Jackson writes ("[PATCH 3/3] libxl: datacopier: Avoid theoretical > eof/POLLHUP race"): >> We solve the race with a poll of the reading fd, to double-check, when >> we detect eof via read. (This is only necessary if the caller has >> specified callback_pollhup, as otherwise POLLHUP|POLLIN - and, >> presumably, POLLIN followed perhaps by POLLHUP|POLLIN, is to be >> treated as eof anyway.) > > I have been unable to reproduce this race. On Linux, the pty master > returns EGAIN from read, not EOF, when the bootloader exits. > > Below is the patch I used to test this. I think this should repro the > bug on FreeBSD when doing "xl create" of a guest which (a) uses pygrub > (b) autoboots within 15 seconds. > > Roger, can you conveniently test this ? With the hacky patch below > you should see the bug, which should in turn be fixed by the 3/3 I am > just replying to. Hello, I don't seem to be able to trigger the issue with the debug patch applied. AFAICT pygrub is blocked (probably because the output buffer is full) and total execution greatly exceeds 15s seconds. Here is the full output: # xl -vvv create debian.cfg Parsing config from debian.cfg libxl: debug: libxl_create.c:1512:do_domain_create: ao 0x802834080: create: how=0x0 callback=0x0 poller=0x80281f0a0 libxl: debug: libxl_device.c:269:libxl__device_disk_set_backend: Disk vdev=xvda spec.backend=unknown libxl: debug: libxl_device.c:298:libxl__device_disk_set_backend: Disk vdev=xvda, using backend phy libxl: debug: libxl_create.c:915:initiate_domain_create: running bootloader libxl: debug: libxl_device.c:269:libxl__device_disk_set_backend: Disk vdev=(null) spec.backend=phy libxl: debug: libxl.c:3020:libxl__device_disk_local_initiate_attach: locally attaching PHY disk /dev/zvol/tank/debian libxl: debug: libxl_bootloader.c:411:bootloader_disk_attached_cb: Config bootloader value: pygrub libxl: debug: libxl_bootloader.c:427:bootloader_disk_attached_cb: Checking for bootloader in libexec path: /usr/local/lib/xen/bin/pygrub libxl: debug: libxl_create.c:1528:do_domain_create: ao 0x802834080: inprogress: poller=0x80281f0a0, flags=i libxl: debug: libxl_event.c:577:libxl__ev_xswatch_register: watch w=0x802836780 wpath=/local/domain/4 token=3/0: register slotnum=3 libxl: debug: libxl_event.c:1942:libxl__ao_progress_report: ao 0x802834080: progress report: ignored libxl: debug: libxl_bootloader.c:537:bootloader_gotptys: executing bootloader: /usr/local/lib/xen/bin/pygrub libxl: debug: libxl_bootloader.c:541:bootloader_gotptys: bootloader arg: /usr/local/lib/xen/bin/pygrub libxl: debug: libxl_bootloader.c:541:bootloader_gotptys: bootloader arg: --output=/var/run/xen/bootloader.4.out libxl: debug: libxl_bootloader.c:541:bootloader_gotptys: bootloader arg: --output-format=simple0 libxl: debug: libxl_bootloader.c:541:bootloader_gotptys: bootloader arg: --output-directory=/var/run/xen/bootloader.4.d libxl: debug: libxl_bootloader.c:541:bootloader_gotptys: bootloader arg: /dev/zvol/tank/debian libxl: debug: libxl_event.c:514:watchfd_callback: watch w=0x802836780 wpath=/local/domain/4 token=3/0: event epath=/local/domain/4 DC READABLE DC READABLE CONTINUING 1 DC READABLE LOOP DC READABLE READ r=315 Resource temporarily unavailable DC READABLE LOOP DC READABLE READ r=-1 Resource temporarily unavailable DC READABLE DC READABLE CONTINUING 1 DC READABLE LOOP DC READABLE READ r=71 Resource temporarily unavailable DC READABLE LOOP DC READABLE READ r=-1 Resource temporarily unavailable DC READABLE DC READABLE CONTINUING 1 DC READABLE LOOP DC READABLE READ r=988 Resource temporarily unavailable DC READABLE LOOP DC READABLE READ r=-1 Resource temporarily unavailable DC READABLE DC READABLE CONTINUING 1 DC READABLE LOOP DC READABLE READ r=127 Resource temporarily unavailable DC READABLE LOOP DC READABLE READ r=-1 Resource temporarily unavailable DC READABLE DC READABLE CONTINUING 1 DC READABLE LOOP DC READABLE READ r=127 Resource temporarily unavailable DC READABLE LOOP DC READABLE READ r=-1 Resource temporarily unavailable DC READABLE DC READABLE CONTINUING 1 DC READABLE LOOP DC READABLE READ r=127 Resource temporarily unavailable DC READABLE LOOP DC READABLE READ r=-1 Resource temporarily unavailable DC READABLE DC READABLE CONTINUING 1 DC READABLE LOOP DC READABLE READ r=127 Resource temporarily unavailable DC READABLE LOOP DC READABLE READ r=-1 Resource temporarily unavailable DC READABLE DC READABLE CONTINUING 1 DC READABLE LOOP DC READABLE READ r=127 Resource temporarily unavailable DC READABLE LOOP DC READABLE READ r=-1 Resource temporarily unavailable DC READABLE DC READABLE CONTINUING 1 DC READABLE LOOP DC READABLE READ r=127 Resource temporarily unavailable DC READABLE LOOP DC READABLE READ r=-1 Resource temporarily unavailable DC READABLE DC READABLE CONTINUING 1 DC READABLE LOOP DC READABLE READ r=127 Resource temporarily unavailable DC READABLE LOOP DC READABLE READ r=-1 Resource temporarily unavailable DC READABLE DC READABLE CONTINUING 1 DC READABLE LOOP DC READABLE READ r=127 Resource temporarily unavailable DC READABLE LOOP DC READABLE READ r=-1 Resource temporarily unavailable DC READABLE DC READABLE CONTINUING 1 DC READABLE LOOP DC READABLE READ r=127 Resource temporarily unavailable DC READABLE LOOP DC READABLE READ r=-1 Resource temporarily unavailable DC READABLE DC READABLE CONTINUING 1 DC READABLE LOOP DC READABLE READ r=127 Resource temporarily unavailable DC READABLE LOOP DC READABLE READ r=-1 Resource temporarily unavailable DC READABLE DC READABLE CONTINUING 1 DC READABLE LOOP DC READABLE READ r=127 Resource temporarily unavailable DC READABLE LOOP DC READABLE READ r=-1 Resource temporarily unavailable DC READABLE DC READABLE CONTINUING 1 DC READABLE LOOP DC READABLE READ r=127 Resource temporarily unavailable DC READABLE LOOP DC READABLE READ r=-1 Resource temporarily unavailable DC READABLE DC READABLE CONTINUING 1 DC READABLE LOOP DC READABLE READ r=22 Resource temporarily unavailable DC READABLE LOOP DC READABLE READ r=105 Resource temporarily unavailable DC READABLE LOOP DC READABLE READ r=-1 Resource temporarily unavailable DC READABLE DC READABLE CONTINUING 1 DC READABLE LOOP DC READABLE READ r=134 Resource temporarily unavailable DC READABLE LOOP DC READABLE READ r=-1 Resource temporarily unavailable DC READABLE DC READABLE CONTINUING 1 DC READABLE LOOP DC READABLE READ r=20 Resource temporarily unavailable DC READABLE LOOP DC READABLE READ r=-1 Resource temporarily unavailable DC READABLE DC READABLE CONTINUING 21 libxl: debug: libxl_aoutils.c:190:datacopier_pollhup_handled: received POLLHUP on bootloader pty during copy of bootloader output for domain 4 libxl: debug: libxl_bootloader.c:636:bootloader_finished: bootloader completed libxl: debug: libxl_bootloader.c:138:bootloader_result_command: bootloader output contained kernel /var/run/xen/bootloader.4.d/boot_kernel._RYFNa libxl: debug: libxl_bootloader.c:138:bootloader_result_command: bootloader output contained ramdisk /var/run/xen/bootloader.4.d/boot_ramdisk.Tj3qTl libxl: debug: libxl_bootloader.c:138:bootloader_result_command: bootloader output contained args root=UUID=d1854b6d-e90f-4497-a614-5566ececc345 ro quiet libxl: debug: libxl_bootloader.c:649:bootloader_finished: bootloader execution successful libxl: debug: libxl_event.c:615:libxl__ev_xswatch_deregister: watch w=0x802836780 wpath=/local/domain/4 token=3/0: deregister slotnum=3 domainbuilder: detail: xc_dom_allocate: cmdline="root=UUID=d1854b6d-e90f-4497-a614-5566ececc345 ro quiet", features="(null)" libxl: debug: libxl_dom.c:536:libxl__build_pv: pv kernel mapped 1 path /var/run/xen/bootloader.4.d/boot_kernel._RYFNa domainbuilder: detail: xc_dom_kernel_mem: called domainbuilder: detail: xc_dom_ramdisk_mem: called domainbuilder: detail: xc_dom_boot_xen_init: ver 4.6, caps xen-3.0-x86_64 xen-3.0-x86_32p hvm-3.0-x86_32 hvm-3.0-x86_32p hvm-3.0-x86_64 domainbuilder: detail: xc_dom_parse_image: called domainbuilder: detail: xc_dom_find_loader: trying multiboot-binary loader ... domainbuilder: detail: loader probe failed domainbuilder: detail: xc_dom_find_loader: trying Linux bzImage loader ... domainbuilder: detail: xc_dom_malloc : 11430 kB domainbuilder: detail: xc_dom_do_gunzip: unzip ok, 0x2aaa36 -> 0xb299c0 domainbuilder: detail: loader probe OK xc: detail: elf_parse_binary: phdr: paddr=0x1000000 memsz=0x554000 xc: detail: elf_parse_binary: phdr: paddr=0x1600000 memsz=0x950e0 xc: detail: elf_parse_binary: phdr: paddr=0x1696000 memsz=0x13400 xc: detail: elf_parse_binary: phdr: paddr=0x16aa000 memsz=0x294000 xc: detail: elf_parse_binary: memory: 0x1000000 -> 0x193e000 xc: detail: elf_xen_parse_note: GUEST_OS = "linux" xc: detail: elf_xen_parse_note: GUEST_VERSION = "2.6" xc: detail: elf_xen_parse_note: XEN_VERSION = "xen-3.0" xc: detail: elf_xen_parse_note: VIRT_BASE = 0xffffffff80000000 xc: detail: elf_xen_parse_note: ENTRY = 0xffffffff816aa200 xc: detail: elf_xen_parse_note: HYPERCALL_PAGE = 0xffffffff81001000 xc: detail: elf_xen_parse_note: FEATURES = "!writable_page_tables|pae_pgdir_above_4gb" xc: detail: elf_xen_parse_note: PAE_MODE = "yes" xc: detail: elf_xen_parse_note: LOADER = "generic" xc: detail: elf_xen_parse_note: unknown xen elf note (0xd) xc: detail: elf_xen_parse_note: SUSPEND_CANCEL = 0x1 xc: detail: elf_xen_parse_note: HV_START_LOW = 0xffff800000000000 xc: detail: elf_xen_parse_note: PADDR_OFFSET = 0x0 xc: detail: elf_xen_addr_calc_check: addresses: xc: detail: virt_base = 0xffffffff80000000 xc: detail: elf_paddr_offset = 0x0 xc: detail: virt_offset = 0xffffffff80000000 xc: detail: virt_kstart = 0xffffffff81000000 xc: detail: virt_kend = 0xffffffff8193e000 xc: detail: virt_entry = 0xffffffff816aa200 xc: detail: p2m_base = 0xffffffffffffffff domainbuilder: detail: xc_dom_parse_elf_kernel: xen-3.0-x86_64: 0xffffffff81000000 -> 0xffffffff8193e000 domainbuilder: detail: xc_dom_mem_init: mem 1024 MB, pages 0x40000 pages, 4k each domainbuilder: detail: xc_dom_mem_init: 0x40000 pages domainbuilder: detail: xc_dom_boot_mem_init: called domainbuilder: detail: x86_compat: guest xen-3.0-x86_64, address size 64 domainbuilder: detail: xc_dom_malloc : 2048 kB domainbuilder: detail: xc_dom_build_image: called domainbuilder: detail: xc_dom_alloc_segment: kernel : 0xffffffff81000000 -> 0xffffffff8193e000 (pfn 0x1000 + 0x93e pages) domainbuilder: detail: xc_dom_pfn_to_ptr_retcount: domU mapping: pfn 0x1000+0x93e at 0x804c00000 xc: detail: elf_load_binary: phdr 0 at 0x804c00000 -> 0x805154000 xc: detail: elf_load_binary: phdr 1 at 0x805200000 -> 0x8052950e0 xc: detail: elf_load_binary: phdr 2 at 0x805296000 -> 0x8052a9400 xc: detail: elf_load_binary: phdr 3 at 0x8052aa000 -> 0x805329000 domainbuilder: detail: xc_dom_alloc_segment: ramdisk : 0xffffffff8193e000 -> 0xffffffff836b9000 (pfn 0x193e + 0x1d7b pages) domainbuilder: detail: xc_dom_malloc : 176 kB domainbuilder: detail: xc_dom_pfn_to_ptr_retcount: domU mapping: pfn 0x193e+0x1d7b at 0x805600000 domainbuilder: detail: xc_dom_do_gunzip: unzip ok, 0x9c2a27 -> 0x1d7ac10 domainbuilder: detail: xc_dom_alloc_segment: phys2mach : 0xffffffff836b9000 -> 0xffffffff838b9000 (pfn 0x36b9 + 0x200 pages) domainbuilder: detail: xc_dom_pfn_to_ptr_retcount: domU mapping: pfn 0x36b9+0x200 at 0x803e00000 domainbuilder: detail: xc_dom_alloc_page : start info : 0xffffffff838b9000 (pfn 0x38b9) domainbuilder: detail: xc_dom_alloc_page : xenstore : 0xffffffff838ba000 (pfn 0x38ba) domainbuilder: detail: xc_dom_alloc_page : console : 0xffffffff838bb000 (pfn 0x38bb) domainbuilder: detail: nr_page_tables: 0x0000ffffffffffff/48: 0xffff000000000000 -> 0xffffffffffffffff, 1 table(s) domainbuilder: detail: nr_page_tables: 0x0000007fffffffff/39: 0xffffff8000000000 -> 0xffffffffffffffff, 1 table(s) domainbuilder: detail: nr_page_tables: 0x000000003fffffff/30: 0xffffffff80000000 -> 0xffffffffbfffffff, 1 table(s) domainbuilder: detail: nr_page_tables: 0x00000000001fffff/21: 0xffffffff80000000 -> 0xffffffff83bfffff, 30 table(s) domainbuilder: detail: xc_dom_alloc_segment: page tables : 0xffffffff838bc000 -> 0xffffffff838dd000 (pfn 0x38bc + 0x21 pages) domainbuilder: detail: xc_dom_pfn_to_ptr_retcount: domU mapping: pfn 0x38bc+0x21 at 0x800681000 domainbuilder: detail: xc_dom_alloc_page : boot stack : 0xffffffff838dd000 (pfn 0x38dd) domainbuilder: detail: xc_dom_build_image : virt_alloc_end : 0xffffffff838de000 domainbuilder: detail: xc_dom_build_image : virt_pgtab_end : 0xffffffff83c00000 domainbuilder: detail: xc_dom_boot_image: called domainbuilder: detail: arch_setup_bootearly: doing nothing domainbuilder: detail: xc_dom_compat_check: supported guest type: xen-3.0-x86_64 <= matches domainbuilder: detail: xc_dom_compat_check: supported guest type: xen-3.0-x86_32p domainbuilder: detail: xc_dom_compat_check: supported guest type: hvm-3.0-x86_32 domainbuilder: detail: xc_dom_compat_check: supported guest type: hvm-3.0-x86_32p domainbuilder: detail: xc_dom_compat_check: supported guest type: hvm-3.0-x86_64 domainbuilder: detail: xc_dom_update_guest_p2m: dst 64bit, pages 0x40000 domainbuilder: detail: clear_page: pfn 0x38bb, mfn 0x194457 domainbuilder: detail: clear_page: pfn 0x38ba, mfn 0x194458 domainbuilder: detail: xc_dom_pfn_to_ptr_retcount: domU mapping: pfn 0x38b9+0x1 at 0x80067e000 domainbuilder: detail: start_info_x86_64: called domainbuilder: detail: setup_hypercall_page: vaddr=0xffffffff81001000 pfn=0x1001 domainbuilder: detail: domain builder memory footprint domainbuilder: detail: allocated domainbuilder: detail: malloc : 13726 kB domainbuilder: detail: anon mmap : 0 bytes domainbuilder: detail: mapped domainbuilder: detail: file mmap : 0 bytes domainbuilder: detail: domU mmap : 40 MB domainbuilder: detail: arch_setup_bootlate: shared_info: pfn 0x0, mfn 0xd75fd domainbuilder: detail: shared_info_x86_64: called domainbuilder: detail: vcpu_x86_64: called domainbuilder: detail: vcpu_x86_64: cr3: pfn 0x38bc mfn 0x194456 domainbuilder: detail: launch_vm: called, ctxt=0x80067c004 domainbuilder: detail: xc_dom_release: called libxl: debug: libxl_device.c:269:libxl__device_disk_set_backend: Disk vdev=xvda spec.backend=phy libxl: debug: libxl_event.c:577:libxl__ev_xswatch_register: watch w=0x8028693c8 wpath=/local/domain/0/backend/vbd/4/51712/state token=3/1: register slotnum=3 libxl: debug: libxl_event.c:514:watchfd_callback: watch w=0x8028693c8 wpath=/local/domain/0/backend/vbd/4/51712/state token=3/1: event epath=/local/domain/0/backend/vbd/4/51712/state libxl: debug: libxl_event.c:834:devstate_watch_callback: backend /local/domain/0/backend/vbd/4/51712/state wanted state 2 still waiting state 1 libxl: debug: libxl_event.c:514:watchfd_callback: watch w=0x8028693c8 wpath=/local/domain/0/backend/vbd/4/51712/state token=3/1: event epath=/local/domain/0/backend/vbd/4/51712/state libxl: debug: libxl_event.c:830:devstate_watch_callback: backend /local/domain/0/backend/vbd/4/51712/state wanted state 2 ok libxl: debug: libxl_event.c:615:libxl__ev_xswatch_deregister: watch w=0x8028693c8 wpath=/local/domain/0/backend/vbd/4/51712/state token=3/1: deregister slotnum=3 libxl: debug: libxl_event.c:629:libxl__ev_xswatch_deregister: watch w=0x8028693c8: deregister unregistered libxl: debug: libxl_event.c:629:libxl__ev_xswatch_deregister: watch w=0x802869450: deregister unregistered libxl: debug: libxl_event.c:577:libxl__ev_xswatch_register: watch w=0x802869748 wpath=/local/domain/0/backend/vif/4/0/state token=3/2: register slotnum=3 libxl: debug: libxl_event.c:514:watchfd_callback: watch w=0x802869748 wpath=/local/domain/0/backend/vif/4/0/state token=3/2: event epath=/local/domain/0/backend/vif/4/0/state libxl: debug: libxl_event.c:834:devstate_watch_callback: backend /local/domain/0/backend/vif/4/0/state wanted state 2 still waiting state 1 libxl: debug: libxl_event.c:514:watchfd_callback: watch w=0x802869748 wpath=/local/domain/0/backend/vif/4/0/state token=3/2: event epath=/local/domain/0/backend/vif/4/0/state libxl: debug: libxl_event.c:830:devstate_watch_callback: backend /local/domain/0/backend/vif/4/0/state wanted state 2 ok libxl: debug: libxl_event.c:615:libxl__ev_xswatch_deregister: watch w=0x802869748 wpath=/local/domain/0/backend/vif/4/0/state token=3/2: deregister slotnum=3 libxl: debug: libxl_event.c:629:libxl__ev_xswatch_deregister: watch w=0x802869748: deregister unregistered libxl: debug: libxl_device.c:1030:device_hotplug: calling hotplug script: /usr/local/etc/xen/scripts/vif-bridge /local/domain/0/backend/vif/4/0 libxl: debug: libxl_aoutils.c:519:libxl__async_exec_start: forking to execute: /usr/local/etc/xen/scripts/vif-bridge /local/domain/0/backend/vif/4/0 libxl: debug: libxl_event.c:629:libxl__ev_xswatch_deregister: watch w=0x8028697d0: deregister unregistered libxl: debug: libxl_event.c:629:libxl__ev_xswatch_deregister: watch w=0x8028697d0: deregister unregistered libxl: debug: libxl_event.c:1942:libxl__ao_progress_report: ao 0x802834080: progress report: ignored libxl: debug: libxl_event.c:1766:libxl__ao_complete: ao 0x802834080: complete, rc=0 libxl: debug: libxl_event.c:1738:libxl__ao__destroy: ao 0x802834080: destroy xc: debug: hypercall buffer: total allocations:390 total releases:390 xc: debug: hypercall buffer: current allocations:0 maximum allocations:4 xc: debug: hypercall buffer: cache current size:4 xc: debug: hypercall buffer: cache hits:374 misses:4 toobig:12 _______________________________________________ Xen-devel mailing list Xen-devel@xxxxxxxxxxxxx http://lists.xen.org/xen-devel

©2013 Xen Project, A Linux Foundation Collaborative Project. All Rights Reserved.
Linux Foundation is a registered trademark of The Linux Foundation.
Xen Project is a trademark of The Linux Foundation.