Bug 583974 - mount hangs there when you lack proper permission to guest image
mount hangs there when you lack proper permission to guest image
Status: CLOSED UPSTREAM
Product: Virtualization Tools
Classification: Community
Component: libguestfs (Show other bugs)
unspecified
All Linux
high Severity high
: ---
: ---
Assigned To: Richard W.M. Jones
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2010-04-20 08:37 EDT by Yufang Zhang
Modified: 2012-05-03 09:51 EDT (History)
2 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2012-05-03 09:51:36 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Yufang Zhang 2010-04-20 08:37:47 EDT
Description of problem:
Starting guestfish as a non-root user and adding a guest image which you only have read permission, trying to mount will hang there.  

Version-Release number of selected component (if applicable):
guestfish 1.3.5

How reproducible:
Always

Steps to Reproduce:
1. $ id yufang
uid=500(yufang) gid=500(yufang) groups=500(yufang)

$ ll /mnt/RHEL-Server-5.4-32-pv.raw
-rw-r--r-- 1 root root 6442450944 2010-04-20 20:15 /mnt/RHEL-Server-5.4-32-pv.raw

2. As the user 'yufang', add the image as rw mode: 
$ fish/guestfish -a /mnt/RHEL-Server-5.4-32-pv.raw

3. launch the guest and try to do mount:
><fs> run
...

><fs> lvs
lvs
send_to_daemon: 0x248f070 g->state = 3, n = 28
recv_from_daemon: 0x248f070 g->state = 3, size_rtn = 0x7fff93c9f76c, buf_rtn = 0x7fff93c9f760
lvm lvs -o vg_name,lv_name --noheadings --separator /
File descriptor 3 (socket:[8013]) leaked on lvm invocation. Parent PID 1: guestfsd
proc 11 (lvs) took 0.04 seconds
/dev/VolGroup00/LogVol00
/dev/VolGroup00/LogVol01

><fs> mount /dev/VolGroup00/LogVol00 /
mount "/dev/VolGroup00/LogVol00" "/"
send_to_daemon: 0x248f070 g->state = 3, n = 64
recv_from_daemon: 0x248f070 g->state = 3, size_rtn = 0x7fff93c9f75c, buf_rtn = 0x7fff93c9f750
mount -o sync,noatime /dev/VolGroup00/LogVol00 /sysroot/
[   59.075557] kjournald starting.  Commit interval 5 seconds
[  241.549151] INFO: task mount:284 blocked for more than 120 seconds.
[  241.605020] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  241.608202] mount         D 0000000000000002     0   284      1 0x00000000
[  241.610834]  ffff88001ec8da58 0000000000000086 ffff8800176aa060 ffffffff816ba6c0
[  241.615487]  0000000000001d04 ffffffffb432624c ffff88001ec8dfd8 ffff88001ec8dfd8
[  241.618699]  ffff88001ec283d8 000000000000f980 0000000000015740 ffff88001ec283d8
[  241.621485] Call Trace:
[  241.622533]  [<ffffffff8107c359>] ? ktime_get_ts+0x85/0x8e
[  241.624602]  [<ffffffff8114132a>] ? sync_buffer+0x0/0x44
[  241.626820]  [<ffffffff8114132a>] ? sync_buffer+0x0/0x44
[  241.628784]  [<ffffffff81454c1d>] io_schedule+0x43/0x5d
[  241.630546]  [<ffffffff8114136a>] sync_buffer+0x40/0x44
[  241.633142]  [<ffffffff81455170>] __wait_on_bit+0x48/0x7b
[  241.634986]  [<ffffffff81455211>] out_of_line_wait_on_bit+0x6e/0x79
[  241.637579]  [<ffffffff8114132a>] ? sync_buffer+0x0/0x44
[  241.639639]  [<ffffffff810748c4>] ? wake_bit_function+0x0/0x33
[  241.641849]  [<ffffffff8114128d>] __wait_on_buffer+0x24/0x26
[  241.643979]  [<ffffffff811412cc>] wait_on_buffer+0x3d/0x41
[  241.645826]  [<ffffffff811415c2>] sync_dirty_buffer+0x60/0x99
[  241.648062]  [<ffffffff81187460>] ext3_commit_super.clone.0+0x61/0x69
[  241.653454]  [<ffffffff81187bdc>] ext3_setup_super+0xf0/0x1a3
[  241.655419]  [<ffffffff811e62ab>] ? security_d_instantiate+0x24/0x26
[  241.659701]  [<ffffffff8112e66a>] ? d_instantiate+0x49/0x4e
[  241.662335]  [<ffffffff8118942f>] ext3_fill_super+0x12f8/0x174e
[  241.664768]  [<ffffffff8145607b>] ? __down_write_nested+0x17/0xab
[  241.667547]  [<ffffffff8111d91c>] ? sget+0x3a5/0x3bb
[  241.669407]  [<ffffffff8111e002>] get_sb_bdev+0x139/0x19c
[  241.671495]  [<ffffffff81188137>] ? ext3_fill_super+0x0/0x174e
[  241.673643]  [<ffffffff81185b38>] ext3_get_sb+0x18/0x1a
[  241.675609]  [<ffffffff8111dbca>] vfs_kern_mount+0xa9/0x168
[  241.677996]  [<ffffffff8111dcf1>] do_kern_mount+0x4d/0xed
[  241.679913]  [<ffffffff81135c40>] do_mount+0x731/0x793
[  241.681763]  [<ffffffff810ea72b>] ? strndup_user+0x5d/0x86
[  241.683782]  [<ffffffff81135d2a>] sys_mount+0x88/0xc2
[  241.685505]  [<ffffffff81011d32>] system_call_fastpath+0x16/0x1b
[  241.688963] INFO: task flush-253:0:286 blocked for more than 120 seconds.
[  241.692571] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  241.695593] flush-253:0   D ffffffff8114132a     0   286      2 0x00000000
[  241.698025]  ffff88001eda9900 0000000000000046 0000000000000000 ffffffff816ba6c0
[  241.700161]  0000000000001f28 ffffffffb432624c ffff88001eda9fd8 ffff88001eda9fd8
[  241.702187]  ffff88001ec2b298 000000000000f980 0000000000015740 ffff88001ec2b298
[  241.706802] Call Trace:
[  241.707546]  [<ffffffff8107c359>] ? ktime_get_ts+0x85/0x8e
[  241.709047]  [<ffffffff8114132a>] ? sync_buffer+0x0/0x44
[  241.710799]  [<ffffffff81454c1d>] io_schedule+0x43/0x5d
[  241.712136]  [<ffffffff8114136a>] sync_buffer+0x40/0x44
[  241.713593]  [<ffffffff81455066>] __wait_on_bit_lock+0x46/0x8f
[  241.715388]  [<ffffffff8145511d>] out_of_line_wait_on_bit_lock+0x6e/0x79
[  241.717267]  [<ffffffff8114132a>] ? sync_buffer+0x0/0x44
[  241.718853]  [<ffffffff810748c4>] ? wake_bit_function+0x0/0x33
[  241.720442]  [<ffffffff8122a47f>] ? __lookup_tag+0x6d/0x12d
[  241.721818]  [<ffffffff811414e8>] __lock_buffer+0x2a/0x2c
[  241.723222]  [<ffffffff81141526>] lock_buffer+0x3c/0x40
[  241.724705]  [<ffffffff811424e0>] __block_write_full_page+0x15a/0x2b3
[  241.726630]  [<ffffffff81144a96>] ? blkdev_get_block+0x0/0x63
[  241.728528]  [<ffffffff81142baf>] ? end_buffer_async_write+0x0/0x129
[  241.730125]  [<ffffffff81142baf>] ? end_buffer_async_write+0x0/0x129
[  241.731997]  [<ffffffff81144a96>] ? blkdev_get_block+0x0/0x63
[  241.733620]  [<ffffffff811426c2>] block_write_full_page_endio+0x89/0x96
[  241.735870]  [<ffffffff811426e4>] block_write_full_page+0x15/0x17
[  241.737554]  [<ffffffff8114574e>] blkdev_writepage+0x18/0x1a
[  241.739526]  [<ffffffff810dcb4c>] __writepage+0x17/0x30
[  241.741256]  [<ffffffff810dd1cc>] write_cache_pages+0x25c/0x3f0
[  241.742874]  [<ffffffff810dcb35>] ? __writepage+0x0/0x30
[  241.744273]  [<ffffffff810dd384>] generic_writepages+0x24/0x26
[  241.746227]  [<ffffffff810dd3a7>] do_writepages+0x21/0x2a
[  241.747605]  [<ffffffff8113a0bc>] writeback_single_inode+0xcc/0x1f1
[  241.749394]  [<ffffffff8113a85c>] writeback_inodes_wb+0x379/0x410
[  241.752662]  [<ffffffff8113aa1b>] wb_writeback+0x128/0x1a7
[  241.754088]  [<ffffffff8113ac86>] wb_do_writeback+0x13c/0x152
[  241.755781]  [<ffffffff8113acdb>] bdi_writeback_task+0x3f/0xaf
[  241.757193]  [<ffffffff810ec576>] ? bdi_start_fn+0x0/0xd2
[  241.758844]  [<ffffffff810ec5e7>] bdi_start_fn+0x71/0xd2
[  241.760191]  [<ffffffff810ec576>] ? bdi_start_fn+0x0/0xd2
[  241.762032]  [<ffffffff8107459e>] kthread+0x7f/0x87
[  241.763407]  [<ffffffff81012d6a>] child_rip+0xa/0x20
[  241.764782]  [<ffffffff8107451f>] ? kthread+0x0/0x87
[  241.766214]  [<ffffffff81012d60>] ? child_rip+0x0/0x20
...

  
Actual results:

Expected results:

Additional info:
If I add the image as read only mode, then mount will not hang but success without any error.
Comment 1 Richard W.M. Jones 2010-04-20 09:19:03 EDT
(In reply to comment #0)
> 3. launch the guest and try to do mount:
> ><fs> run
> ...

Yufang, could you show (or attach) the complete, unedited output
please.  I need to see what options we are using for qemu and how
the kernel starts up.
Comment 2 Yufang Zhang 2010-04-20 09:29:00 EDT
(In reply to comment #1)
> (In reply to comment #0)
> > 3. launch the guest and try to do mount:
> > ><fs> run
> > ...
> 
> Yufang, could you show (or attach) the complete, unedited output
> please.  I need to see what options we are using for qemu and how
> the kernel starts up.    

Below is the output of run:
><fs> run
is_config
launch
looking for supermin appliance in appliance
looking for supermin appliance in /usr/local/lib/guestfs
looking for appliance in appliance
[00059ms] begin testing qemu features
null_vmchannel_sock = 45055
[00671ms] finished testing qemu features
accept_from_daemon: 0x22e7070 g->state = 0
/usr/bin/qemu-kvm \
    -drive file=/mnt/RHEL-Server-5.4-32-pv.raw,cache=off,if=virtio \
    -enable-kvm \
    -nographic \
    -serial stdio \
    -m 500 \
    -no-reboot \
    -no-hpet \
    -rtc-td-hack \
    -net user,vlan=0,net=10.0.2.0/8 \
    -net nic,model=virtio,vlan=0 \
    -kernel appliance/vmlinuz.fedora-12.x86_64 \
    -initrd appliance/initramfs.fedora-12.x86_64.img \
    -append 'panic=1 console=ttyS0 udevtimeout=300 noapic acpi=off printk.time=1 cgroup_disable=memory selinux=0 guestfs_vmchannel=tcp:10.0.2.2:45055 guestfs_verbose=1 TERM=xterm '
Initializing cgroup subsys cpuset
Initializing cgroup subsys cpu
Linux version 2.6.32.11-99.fc12.x86_64 (mockbuild@x86-02.phx2.fedoraproject.org) (gcc version 4.4.3 20100127 (Red Hat 4.4.3-4) (GCC) ) #1 SMP Mon Apr 5 19:59:38 UTC 2010
Command line: panic=1 console=ttyS0 udevtimeout=300 noapic acpi=off printk.time=1 cgroup_disable=memory selinux=0 guestfs_vmchannel=tcp:10.0.2.2:45055 guestfs_verbose=1 TERM=xterm 
KERNEL supported cpus:
  Intel GenuineIntel
  AMD AuthenticAMD
  Centaur CentaurHauls
BIOS-provided physical RAM map:
 BIOS-e820: 0000000000000000 - 000000000009f000 (usable)
 BIOS-e820: 000000000009f000 - 00000000000a0000 (reserved)
 BIOS-e820: 00000000000e8000 - 0000000000100000 (reserved)
 BIOS-e820: 0000000000100000 - 000000001f3f0000 (usable)
 BIOS-e820: 000000001f3f0000 - 000000001f400000 (ACPI data)
 BIOS-e820: 00000000fffbc000 - 0000000100000000 (reserved)
DMI 2.4 present.
last_pfn = 0x1f3f0 max_arch_pfn = 0x400000000
PAT not supported by CPU.
init_memory_mapping: 0000000000000000-000000001f3f0000
RAMDISK: 1d663000 - 1f3ef75e
No NUMA configuration found
Faking a node at 0000000000000000-000000001f3f0000
Bootmem setup node 0 0000000000000000-000000001f3f0000
  NODE_DATA [0000000000009000 - 000000000001efff]
  bootmap [000000000001f000 -  0000000000022e7f] pages 4
(7 early reservations) ==> bootmem [0000000000 - 001f3f0000]
  #0 [0000000000 - 0000001000]   BIOS data page ==> [0000000000 - 0000001000]
  #1 [0000006000 - 0000008000]       TRAMPOLINE ==> [0000006000 - 0000008000]
  #2 [0001000000 - 0001a53ee8]    TEXT DATA BSS ==> [0001000000 - 0001a53ee8]
  #3 [001d663000 - 001f3ef75e]          RAMDISK ==> [001d663000 - 001f3ef75e]
  #4 [000009fc00 - 0000100000]    BIOS reserved ==> [000009fc00 - 0000100000]
  #5 [0001a54000 - 0001a5403d]              BRK ==> [0001a54000 - 0001a5403d]
  #6 [0000008000 - 0000009000]          PGTABLE ==> [0000008000 - 0000009000]
found SMP MP-table at [ffff8800000fbc20] fbc20
kvm-clock: cpu 0, msr 0:18156c1, boot clock
Zone PFN ranges:
  DMA      0x00000000 -> 0x00001000
  DMA32    0x00001000 -> 0x00100000
  Normal   0x00100000 -> 0x00100000
Movable zone start PFN for each node
early_node_map[2] active PFN ranges
    0: 0x00000000 -> 0x0000009f
    0: 0x00000100 -> 0x0001f3f0
SFI: Simple Firmware Interface v0.7 http://simplefirmware.org
Intel MultiProcessor Specification v1.4
MPTABLE: OEM ID: QEMUCPU 
MPTABLE: Product ID: 0.1         
MPTABLE: APIC at: 0xFEE00000
Processor #0 (Bootup-CPU)
I/O APIC #1 Version 17 at 0xFEC00000.
Processors: 1
SMP: Allowing 16 CPUs, 15 hotplug CPUs
PM: Registered nosave memory: 000000000009f000 - 00000000000a0000
PM: Registered nosave memory: 00000000000a0000 - 00000000000e8000
PM: Registered nosave memory: 00000000000e8000 - 0000000000100000
Allocating PCI resources starting at 1f400000 (gap: 1f400000:e0bbc000)
Booting paravirtualized kernel on KVM
NR_CPUS:256 nr_cpumask_bits:256 nr_cpu_ids:16 nr_node_ids:1
PERCPU: Embedded 30 pages/cpu @ffff880001c00000 s90392 r8192 d24296 u131072
pcpu-alloc: s90392 r8192 d24296 u131072 alloc=1*2097152
pcpu-alloc: [0] 00 01 02 03 04 05 06 07 08 09 10 11 12 13 14 15 
kvm-clock: cpu 0, msr 0:1c156c1, primary cpu clock
Built 1 zonelists in Node order, mobility grouping on.  Total pages: 126037
Policy zone: DMA32
Kernel command line: panic=1 console=ttyS0 udevtimeout=300 noapic acpi=off printk.time=1 cgroup_disable=memory selinux=0 guestfs_vmchannel=tcp:10.0.2.2:45055 guestfs_verbose=1 TERM=xterm 
[    0.000000] Disabling memory control group subsystem
[    0.000000] PID hash table entries: 2048 (order: 2, 16384 bytes)
[    0.000000] Initializing CPU#0
[    0.000000] Checking aperture...
[    0.000000] No AGP bridge found
[    0.000000] Memory: 460232k/511936k available (4465k kernel code, 388k absent, 51316k reserved, 3720k data, 936k init)
[    0.000000] SLUB: Genslabs=14, HWalign=64, Order=0-3, MinObjects=0, CPUs=16, Nodes=1
[    0.000000] Hierarchical RCU implementation.
[    0.000000] NR_IRQS:4352 nr_irqs:536
[    0.000000] Console: colour VGA+ 80x25
[    0.000000] console [ttyS0] enabled
[    0.000000] Detected 2260.832 MHz processor.
[    0.002999] Calibrating delay loop (skipped) preset value.. 4521.66 BogoMIPS (lpj=2260832)
[    0.004171] Security Framework initialized
[    0.005030] SELinux:  Disabled at boot.
[    0.007824] Dentry cache hash table entries: 65536 (order: 7, 524288 bytes)
[    0.010327] Inode-cache hash table entries: 32768 (order: 6, 262144 bytes)
[    0.012263] Mount-cache hash table entries: 256
[    0.015217] Initializing cgroup subsys ns
[    0.016025] Initializing cgroup subsys cpuacct
[    0.018010] Initializing cgroup subsys memory
[    0.019050] Initializing cgroup subsys devices
[    0.020010] Initializing cgroup subsys freezer
[    0.022019] Initializing cgroup subsys net_cls
[    0.025022] CPU: L1 I cache: 32K, L1 D cache: 32K
[    0.027001] CPU: L2 cache: 2048K
[    0.028014] CPU 0/0x0 -> Node 0
[    0.030019] mce: CPU supports 10 MCE banks
[    0.032145] Performance Events: unsupported p6 CPU model 2 no PMU driver, software events only.
[    0.036195] SMP alternatives: switching to UP code
[    0.173097] ftrace: converting mcount calls to 0f 1f 44 00 00
[    0.175016] ftrace: allocating 23786 entries in 94 pages
[    0.230299] Setting APIC routing to physical flat
[    0.232116] CPU0: Intel QEMU Virtual CPU version 0.11.0 stepping 03
[    0.337558] Brought up 1 CPUs
[    0.338007] Total of 1 processors activated (4521.66 BogoMIPS).
[    0.341025] devtmpfs: initialized
[    0.346799] regulator: core version 0.5
[    0.348132] Time: 13:26:45  Date: 04/20/10
[    0.350212] NET: Registered protocol family 16
[    0.353679] PCI: Using configuration type 1 for base access
[    0.356498] bio: create slab <bio-0> at 0
[    0.357229] ACPI: Interpreter disabled.
[    0.359071] vgaarb: loaded
[    0.360273] SCSI subsystem initialized
[    0.361335] usbcore: registered new interface driver usbfs
[    0.363059] usbcore: registered new interface driver hub
[    0.365090] usbcore: registered new device driver usb
[    0.368175] PCI: Probing PCI hardware
[    0.371459] pci 0000:00:01.3: quirk: region b000-b03f claimed by PIIX4 ACPI
[    0.373022] pci 0000:00:01.3: quirk: region b100-b10f claimed by PIIX4 SMB
[    0.384715] vgaarb: device added: PCI:0000:00:02.0,decodes=io+mem,owns=io+mem,locks=none
[    0.386235] pci 0000:00:01.0: PIIX/ICH IRQ router [8086:7000]
[    0.390279] NetLabel: Initializing
[    0.391004] NetLabel:  domain hash size = 128
[    0.393003] NetLabel:  protocols = UNLABELED CIPSOv4
[    0.396042] NetLabel:  unlabeled traffic allowed by default
[    0.397319] Switching to clocksource kvm-clock
[    0.415948] pnp: PnP ACPI: disabled
[    0.418282] NET: Registered protocol family 2
[    0.420438] IP route cache hash table entries: 4096 (order: 3, 32768 bytes)
[    0.423918] TCP established hash table entries: 16384 (order: 6, 262144 bytes)
[    0.428303] TCP bind hash table entries: 16384 (order: 6, 262144 bytes)
[    0.431535] TCP: Hash tables configured (established 16384 bind 16384)
[    0.434524] TCP reno registered
[    0.436692] NET: Registered protocol family 1
[    0.438906] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
[    0.441624] pci 0000:00:01.0: PIIX3: Enabling Passive Release
[    0.444320] pci 0000:00:01.0: Activating ISA DMA hang workarounds
[    0.448716] Trying to unpack rootfs image as initramfs...
[    1.390816] Freeing initrd memory: 30257k freed
[    1.412073] platform rtc_cmos: registered platform RTC device (no PNP device found)
[    1.416044] audit: initializing netlink socket (disabled)
[    1.418675] type=2000 audit(1271770007.418:1): initialized
[    1.431901] HugeTLB registered 2 MB page size, pre-allocated 0 pages
[    1.438863] VFS: Disk quotas dquot_6.5.2
[    1.440672] Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    1.444409] msgmni has been set to 957
[    1.446585] alg: No test for stdrng (krng)
[    1.448440] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
[    1.452062] io scheduler noop registered
[    1.453644] io scheduler anticipatory registered
[    1.456393] io scheduler deadline registered
[    1.457707] io scheduler cfq registered (default)
[    1.459177] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
[    1.461088] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
[    1.463765] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
[    1.467249] pci-stub: invalid id string ""
[    1.472967] Non-volatile memory driver v1.3
[    1.474255] Linux agpgart interface v0.103
[    1.475666] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
�[    1.722693] serial8250: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
[    1.736319] brd: module loaded
[    1.738866] loop: module loaded
[    1.740285] input: Macintosh mouse button emulation as /devices/virtual/input/input0
[    1.744147] scsi0 : ata_piix
[    1.744949] scsi1 : ata_piix
[    1.745705] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc000 irq 14
[    1.747807] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc008 irq 15
[    1.752351] Fixed MDIO Bus: probed
[    1.754003] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    1.756877] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[    1.758841] uhci_hcd: USB Universal Host Controller Interface driver
[    1.760742] PNP: No PS/2 controller found. Probing ports directly.
[    1.763579] serio: i8042 KBD port at 0x60,0x64 irq 1
[    1.765370] serio: i8042 AUX port at 0x60,0x64 irq 12
[    1.767641] mice: PS/2 mouse device common for all mice
[    1.769676] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1
[    1.773330] rtc_cmos rtc_cmos: rtc core: registered rtc_cmos as rtc0
[    1.778143] rtc0: alarms up to one day, 114 bytes nvram
[    1.779983] device-mapper: uevent: version 1.0.3
[    1.784614] device-mapper: ioctl: 4.15.0-ioctl (2009-04-01) initialised: dm-devel@redhat.com
[    1.788589] cpuidle: using governor ladder
[    1.789831] cpuidle: using governor menu
[    1.791494] usbcore: registered new interface driver hiddev
[    1.793682] usbcore: registered new interface driver usbhid
[    1.796074] usbhid: v2.6:USB HID core driver
[    1.797999] nf_conntrack version 0.5.0 (3831 buckets, 15324 max)
[    1.799974] CONFIG_NF_CT_ACCT is deprecated and will be removed soon. Please use
[    1.801980] nf_conntrack.acct=1 kernel parameter, acct=1 nf_conntrack module option or
[    1.804026] sysctl net.netfilter.nf_conntrack_acct=1 to enable it.
[    1.805703] ip_tables: (C) 2000-2006 Netfilter Core Team
[    1.807379] TCP cubic registered
[    1.808250] Initializing XFRM netlink socket
[    1.809435] NET: Registered protocol family 17
[    1.811906] registered taskstats version 1
[    1.813675] No TPM chip found, activating TPM-bypass!
[    1.816195]   Magic number: 6:243:433
[    1.819123] rtc_cmos rtc_cmos: setting system clock to 2010-04-20 13:26:47 UTC (1271770007)
[    1.821809] Initalizing network drop monitor service
[    1.905377] ata2.00: ATAPI: QEMU DVD-ROM, 0.11.0, max UDMA/100
[    1.911903] ata2.00: configured for MWDMA2
[    1.922924] scsi 1:0:0:0: CD-ROM            QEMU     QEMU DVD-ROM     0.11 PQ: 0 ANSI: 5
[    1.933625] sr0: scsi3-mmc drive: 4x/4x xa/form2 tray
[    1.935737] Uniform CD-ROM driver Revision: 3.20
[    1.938373] sr 1:0:0:0: Attached scsi generic sg0 type 5
[    1.941412] Freeing unused kernel memory: 936k freed
[    1.948043] Write protecting the kernel read-only data: 6592k
Starting /init script ...
Starting udev: [    2.177948] udev: starting version 145
[    2.217087] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input2
[    2.403206] virtio-pci 0000:00:03.0: found PCI INT A -> IRQ 11
[    2.443920] virtio-pci 0000:00:04.0: found PCI INT A -> IRQ 11
[    2.496888] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0xb100, revision 0
[    2.514561] virtio-pci 0000:00:05.0: found PCI INT A -> IRQ 10
[    2.573158]  vda: vda1 vda2
[  OK  ]
FATAL: Module dm_mod not found.
  Reading all physical volumes.  This may take a while...
  Found volume group "VolGroup00" using metadata type lvm2
  2 logical volume(s) in volume group "VolGroup00" now active
total 0
lrwxrwxrwx 1 root root          13 Apr 20 09:26 MAKEDEV -> /sbin/MAKEDEV
drwxr-xr-x 2 root root          80 Apr 20 09:26 VolGroup00
drwxr-xr-x 2 root root         640 Apr 20 09:26 block
drwxr-xr-x 2 root root          60 Apr 20 09:26 bsg
lrwxrwxrwx 1 root root           3 Apr 20  2010 cdrom -> sr0
drwxr-xr-x 2 root root        2140 Apr 20  2010 char
crw------- 1 root root      5,   1 Apr 20 09:26 console
lrwxrwxrwx 1 root root          11 Apr 20 09:26 core -> /proc/kcore
drwxr-xr-x 3 root root          60 Apr 20 09:26 cpu
crw-rw---- 1 root root     10,  61 Apr 20 09:26 cpu_dma_latency
drwxr-xr-x 5 root root         100 Apr 20  2010 disk
brw-rw---- 1 root disk    253,   0 Apr 20 09:26 dm-0
brw-rw---- 1 root disk    253,   1 Apr 20 09:26 dm-1
lrwxrwxrwx 1 root root          13 Apr 20 09:26 fd -> /proc/self/fd
crw-rw-rw- 1 root root      1,   7 Apr 20 09:26 full
crw-rw-rw- 1 root root     10, 229 Apr 20 09:26 fuse
drwxr-xr-x 2 root root          40 Apr 20 09:26 hugepages
drwxr-xr-x 3 root root         180 Apr 20  2010 input
crw-rw---- 1 root root      1,  11 Apr 20 09:26 kmsg
brw-rw---- 1 root disk      7,   0 Apr 20 09:26 loop0
brw-rw---- 1 root disk      7,   1 Apr 20 09:26 loop1
brw-rw---- 1 root disk      7,   2 Apr 20 09:26 loop2
brw-rw---- 1 root disk      7,   3 Apr 20 09:26 loop3
brw-rw---- 1 root disk      7,   4 Apr 20 09:26 loop4
brw-rw---- 1 root disk      7,   5 Apr 20 09:26 loop5
brw-rw---- 1 root disk      7,   6 Apr 20 09:26 loop6
brw-rw---- 1 root disk      7,   7 Apr 20 09:26 loop7
crw-rw---- 1 root lp        6,   0 Apr 20 09:26 lp0
crw-rw---- 1 root lp        6,   1 Apr 20 09:26 lp1
crw-rw---- 1 root lp        6,   2 Apr 20 09:26 lp2
crw-rw---- 1 root lp        6,   3 Apr 20 09:26 lp3
drwxr-xr-x 2 root root         100 Apr 20 09:26 mapper
crw-rw---- 1 root root     10, 227 Apr 20 09:26 mcelog
crw-r----- 1 root kmem      1,   1 Apr 20 09:26 mem
drwxr-xr-x 2 root root          60 Apr 20 09:26 net
crw-rw---- 1 root root     10,  60 Apr 20 09:26 network_latency
crw-rw---- 1 root root     10,  59 Apr 20 09:26 network_throughput
crw-rw-rw- 1 root root      1,   3 Apr 20 09:26 null
crw-r----- 1 root kmem     10, 144 Apr 20 09:26 nvram
crw-rw---- 1 root root      1,  12 Apr 20 09:26 oldmem
crw-r----- 1 root kmem      1,   4 Apr 20 09:26 port
crw------- 1 root root    108,   0 Apr 20 09:26 ppp
crw-rw-rw- 1 root tty       5,   2 Apr 20 09:26 ptmx
drwxr-xr-x 2 root root          40 Apr 20 09:26 pts
brw-rw---- 1 root disk      1,   0 Apr 20 09:26 ram0
brw-rw---- 1 root disk      1,   1 Apr 20 09:26 ram1
brw-rw---- 1 root disk      1,  10 Apr 20 09:26 ram10
brw-rw---- 1 root disk      1,  11 Apr 20 09:26 ram11
brw-rw---- 1 root disk      1,  12 Apr 20 09:26 ram12
brw-rw---- 1 root disk      1,  13 Apr 20 09:26 ram13
brw-rw---- 1 root disk      1,  14 Apr 20 09:26 ram14
brw-rw---- 1 root disk      1,  15 Apr 20 09:26 ram15
brw-rw---- 1 root disk      1,   2 Apr 20 09:26 ram2
brw-rw---- 1 root disk      1,   3 Apr 20 09:26 ram3
brw-rw---- 1 root disk      1,   4 Apr 20 09:26 ram4
brw-rw---- 1 root disk      1,   5 Apr 20 09:26 ram5
brw-rw---- 1 root disk      1,   6 Apr 20 09:26 ram6
brw-rw---- 1 root disk      1,   7 Apr 20 09:26 ram7
brw-rw---- 1 root disk      1,   8 Apr 20 09:26 ram8
brw-rw---- 1 root disk      1,   9 Apr 20 09:26 ram9
crw-rw-rw- 1 root root      1,   8 Apr 20 09:26 random
drwxr-xr-x 2 root root          60 Apr 20 09:26 raw
lrwxrwxrwx 1 root root           4 Apr 20 09:26 rtc -> rtc0
crw-rw---- 1 root root    254,   0 Apr 20 09:26 rtc0
lrwxrwxrwx 1 root root           3 Apr 20  2010 scd0 -> sr0
crw-rw---- 1 root cdrom    21,   0 Apr 20 09:26 sg0
drwxr-xr-x 2 root root          40 Apr 20 09:26 shm
crw-rw---- 1 root root     10, 231 Apr 20 09:26 snapshot
brw-rw---- 1 root cdrom    11,   0 Apr 20 09:26 sr0
lrwxrwxrwx 1 root root          15 Apr 20 09:26 stderr -> /proc/self/fd/2
lrwxrwxrwx 1 root root          15 Apr 20 09:26 stdin -> /proc/self/fd/0
lrwxrwxrwx 1 root root          15 Apr 20 09:26 stdout -> /proc/self/fd/1
crw-rw-rw- 1 root tty       5,   0 Apr 20 09:26 tty
crw--w---- 1 root tty       4,   0 Apr 20  2010 tty0
crw--w---- 1 root tty       4,   1 Apr 20 09:26 tty1
crw--w---- 1 root tty       4,  10 Apr 20 09:26 tty10
crw--w---- 1 root tty       4,  11 Apr 20 09:26 tty11
crw--w---- 1 root tty       4,  12 Apr 20 09:26 tty12
crw--w---- 1 root tty       4,  13 Apr 20 09:26 tty13
crw--w---- 1 root tty       4,  14 Apr 20 09:26 tty14
crw--w---- 1 root tty       4,  15 Apr 20 09:26 tty15
crw--w---- 1 root tty       4,  16 Apr 20 09:26 tty16
crw--w---- 1 root tty       4,  17 Apr 20 09:26 tty17
crw--w---- 1 root tty       4,  18 Apr 20 09:26 tty18
crw--w---- 1 root tty       4,  19 Apr 20 09:26 tty19
crw--w---- 1 root tty       4,   2 Apr 20 09:26 tty2
crw--w---- 1 root tty       4,  20 Apr 20 09:26 tty20
crw--w---- 1 root tty       4,  21 Apr 20 09:26 tty21
crw--w---- 1 root tty       4,  22 Apr 20 09:26 tty22
crw--w---- 1 root tty       4,  23 Apr 20 09:26 tty23
crw--w---- 1 root tty       4,  24 Apr 20 09:26 tty24
crw--w---- 1 root tty       4,  25 Apr 20 09:26 tty25
crw--w---- 1 root tty       4,  26 Apr 20 09:26 tty26
crw--w---- 1 root tty       4,  27 Apr 20 09:26 tty27
crw--w---- 1 root tty       4,  28 Apr 20 09:26 tty28
crw--w---- 1 root tty       4,  29 Apr 20 09:26 tty29
crw--w---- 1 root tty       4,   3 Apr 20 09:26 tty3
crw--w---- 1 root tty       4,  30 Apr 20 09:26 tty30
crw--w---- 1 root tty       4,  31 Apr 20 09:26 tty31
crw--w---- 1 root tty       4,  32 Apr 20 09:26 tty32
crw--w---- 1 root tty       4,  33 Apr 20 09:26 tty33
crw--w---- 1 root tty       4,  34 Apr 20 09:26 tty34
crw--w---- 1 root tty       4,  35 Apr 20 09:26 tty35
crw--w---- 1 root tty       4,  36 Apr 20 09:26 tty36
crw--w---- 1 root tty       4,  37 Apr 20 09:26 tty37
crw--w---- 1 root tty       4,  38 Apr 20 09:26 tty38
crw--w---- 1 root tty       4,  39 Apr 20 09:26 tty39
crw--w---- 1 root tty       4,   4 Apr 20 09:26 tty4
crw--w---- 1 root tty       4,  40 Apr 20 09:26 tty40
crw--w---- 1 root tty       4,  41 Apr 20 09:26 tty41
crw--w---- 1 root tty       4,  42 Apr 20 09:26 tty42
crw--w---- 1 root tty       4,  43 Apr 20 09:26 tty43
crw--w---- 1 root tty       4,  44 Apr 20 09:26 tty44
crw--w---- 1 root tty       4,  45 Apr 20 09:26 tty45
crw--w---- 1 root tty       4,  46 Apr 20 09:26 tty46
crw--w---- 1 root tty       4,  47 Apr 20 09:26 tty47
crw--w---- 1 root tty       4,  48 Apr 20 09:26 tty48
crw--w---- 1 root tty       4,  49 Apr 20 09:26 tty49
crw--w---- 1 root tty       4,   5 Apr 20 09:26 tty5
crw--w---- 1 root tty       4,  50 Apr 20 09:26 tty50
crw--w---- 1 root tty       4,  51 Apr 20 09:26 tty51
crw--w---- 1 root tty       4,  52 Apr 20 09:26 tty52
crw--w---- 1 root tty       4,  53 Apr 20 09:26 tty53
crw--w---- 1 root tty       4,  54 Apr 20 09:26 tty54
crw--w---- 1 root tty       4,  55 Apr 20 09:26 tty55
crw--w---- 1 root tty       4,  56 Apr 20 09:26 tty56
crw--w---- 1 root tty       4,  57 Apr 20 09:26 tty57
crw--w---- 1 root tty       4,  58 Apr 20 09:26 tty58
crw--w---- 1 root tty       4,  59 Apr 20 09:26 tty59
crw--w---- 1 root tty       4,   6 Apr 20 09:26 tty6
crw--w---- 1 root tty       4,  60 Apr 20 09:26 tty60
crw--w---- 1 root tty       4,  61 Apr 20 09:26 tty61
crw--w---- 1 root tty       4,  62 Apr 20 09:26 tty62
crw--w---- 1 root tty       4,  63 Apr 20 09:26 tty63
crw--w---- 1 root tty       4,   7 Apr 20 09:26 tty7
crw--w---- 1 root tty       4,   8 Apr 20 09:26 tty8
crw--w---- 1 root tty       4,   9 Apr 20 09:26 tty9
crw-rw---- 1 root dialout   4,  64 Apr 20 09:26 ttyS0
crw-rw---- 1 root dialout   4,  65 Apr 20 09:26 ttyS1
crw-rw---- 1 root dialout   4,  66 Apr 20 09:26 ttyS2
crw-rw---- 1 root dialout   4,  67 Apr 20 09:26 ttyS3
crw-rw-rw- 1 root root      1,   9 Apr 20 09:26 urandom
crw-rw---- 1 root root    251,   0 Apr 20 09:26 usbmon0
crw-rw---- 1 vcsa tty       7,   0 Apr 20 09:26 vcs
crw-rw---- 1 vcsa tty       7,   1 Apr 20 09:26 vcs1
crw-rw---- 1 vcsa tty       7, 128 Apr 20 09:26 vcsa
crw-rw---- 1 vcsa tty       7, 129 Apr 20 09:26 vcsa1
brw-rw---- 1 root disk    252,   0 Apr 20  2010 vda
brw-rw---- 1 root disk    252,   1 Apr 20  2010 vda1
brw-rw---- 1 root disk    252,   2 Apr 20  2010 vda2
crw-rw---- 1 root root     10,  63 Apr 20 09:26 vga_arbiter
crw-rw-rw- 1 root root      1,   5 Apr 20 09:26 zero
rootfs / rootfs rw 0 0
/proc /proc proc rw,relatime 0 0
/sys /sys sysfs rw,relatime 0 0
none /dev devtmpfs rw,relatime,size=230116k,nr_inodes=57529,mode=755 0 0
  PV         VG         Fmt  Attr PSize PFree
  /dev/vda2  VolGroup00 lvm2 a-   5.88G    0 
  VG         #PV #LV #SN Attr   VSize VFree
  VolGroup00   1   2   0 wz--n- 5.88G    0 
  LV       VG         Attr   LSize Origin Snap%  Move Log Copy%  Convert
  LogVol00 VolGroup00 -wi-a- 4.84G                                      
  LogVol01 VolGroup00 -wi-a- 1.03G                                      
eth0      Link encap:Ethernet  HWaddr 52:54:00:12:34:56  
          inet addr:10.0.2.10  Bcast:10.255.255.255  Mask:255.0.0.0
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
          RX packets:0 errors:0 dropped:0 overruns:0 frame:0
          TX packets:0 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000 
          RX bytes:0 (0.0 b)  TX bytes:0 (0.0 b)

lo        Link encap:Local Loopback  
          inet addr:127.0.0.1  Mask:255.0.0.0
          UP LOOPBACK RUNNING  MTU:16436  Metric:1
          RX packets:0 errors:0 dropped:0 overruns:0 frame:0
          TX packets:0 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:0 
          RX bytes:0 (0.0 b)  TX bytes:0 (0.0 b)

Kernel IP routing table
Destination     Gateway         Genmask         Flags   MSS Window  irtt Iface
10.0.0.0        0.0.0.0         255.0.0.0       U         0 0          0 eth0
0.0.0.0         10.0.2.2        0.0.0.0         UG        0 0          0 eth0
Module                  Size  Used by
virtio_balloon          3271  0 
virtio_net             14171  0 
virtio_blk              4597  2 
i2c_piix4              12139  0 
virtio_pci              6211  0 
virtio_ring             5164  1 virtio_pci
i2c_core               26876  1 i2c_piix4
virtio                  4282  4 virtio_balloon,virtio_net,virtio_blk,virtio_pci
Tue Apr 20 09:26:49 EDT 2010
uptime: 4.36 1.22
verbose daemon enabled
linux commmand line: panic=1 console=ttyS0 udevtimeout=300 noapic acpi=off printk.time=1 cgroup_disable=memory selinux=0 guestfs_vmchannel=tcp:10.0.2.2:45055 guestfs_verbose=1 TERM=xterm 

vmchannel: tcp:10.0.2.2:45055
recv_from_daemon: 0x22e7070 g->state = 1, size_rtn = 0x7fff82ec3aac, buf_rtn = 0x7fff82ec3a48
[10488ms] appliance is up
Comment 3 Richard W.M. Jones 2010-04-20 10:21:12 EDT
Which version of qemu is this?

Is the filesystem that you are trying to mount ext3?  XFS?

Is the disk encrypted?

-----

Reading around the issue, the error message
"INFO: task mount ... blocked for more than 120 seconds."
isn't very informative for us.  It just says that
an I/O operation was dropped by the block device
(eg. qemu or virtio is dropping I/O operations),
or else the kernel has lost track of an I/O op.  But
either way, mount is waiting for an I/O op to return
which isn't returning, and eventually everything
times out after 120 seconds.  Without knowing
what I/O op was dropped for what reason, there's
not much we can do.

FWIW I cannot reproduce this on Fedora 13,
but that has a different version of qemu and
a different kernel, so anything could be
different.
Comment 4 Richard W.M. Jones 2010-04-20 10:22:08 EDT
(In reply to comment #3)
> Which version of qemu is this?
> 
> Is the filesystem that you are trying to mount ext3?  XFS?
> 
> Is the disk encrypted?

Also:

If you add '--ro' to the guestfish command line,
does that fix the problem?

How about if you use the 'mount-ro' command
instead of 'mount'?
Comment 5 Yufang Zhang 2010-04-20 23:48:57 EDT
(In reply to comment #4)
> (In reply to comment #3)
> > Which version of qemu is this?
> > 
> > Is the filesystem that you are trying to mount ext3?  XFS?
> > 
> > Is the disk encrypted?
> 
> Also:
> 
> If you add '--ro' to the guestfish command line,
> does that fix the problem?
Yeah, by adding the image readonly(with --ro), we could mount successfully. 

> How about if you use the 'mount-ro' command
> instead of 'mount'?   
By adding the image as rw but using the 'mount-ro' command, we could also mount successfully.
Comment 6 Yufang Zhang 2010-04-20 23:52:25 EDT
(In reply to comment #3)
> Which version of qemu is this?

# rpm -qa | grep qemu
qemu-kvm-0.10.6-9.fc11.x86_64
qemu-system-x86-0.10.6-9.fc11.x86_64
qemu-common-0.10.6-9.fc11.x86_64
qemu-img-0.10.6-9.fc11.x86_64

> Is the filesystem that you are trying to mount ext3?  XFS?
The filesystem is ext3, which exists on a LV.

> Is the disk encrypted?
The disk is not encrypted.

> -----
> 
> Reading around the issue, the error message
> "INFO: task mount ... blocked for more than 120 seconds."
> isn't very informative for us.  It just says that
> an I/O operation was dropped by the block device
> (eg. qemu or virtio is dropping I/O operations),
> or else the kernel has lost track of an I/O op.  But
> either way, mount is waiting for an I/O op to return
> which isn't returning, and eventually everything
> times out after 120 seconds.  Without knowing
> what I/O op was dropped for what reason, there's
> not much we can do.
> 
> FWIW I cannot reproduce this on Fedora 13,
> but that has a different version of qemu and
> a different kernel, so anything could be
> different.
Comment 7 Yufang Zhang 2010-04-21 01:50:33 EDT
(In reply to comment #6)
> (In reply to comment #3)
> > Which version of qemu is this?
> 
> # rpm -qa | grep qemu
> qemu-kvm-0.10.6-9.fc11.x86_64
> qemu-system-x86-0.10.6-9.fc11.x86_64
> qemu-common-0.10.6-9.fc11.x86_64
> qemu-img-0.10.6-9.fc11.x86_64
Sorry I login to wrong machine to got above qemu information, qemu information from the machine that I can reproduce the bug is as follows:

# rpm -qa | grep qemu
qemu-user-0.11.0-13.fc12.x86_64
gpxe-roms-qemu-0.9.9-1.20091018git.fc12.noarch
qemu-system-mips-0.11.0-13.fc12.x86_64
qemu-system-sh4-0.11.0-13.fc12.x86_64
qemu-kvm-0.11.0-13.fc12.x86_64
qemu-common-0.11.0-13.fc12.x86_64
qemu-img-0.11.0-13.fc12.x86_64
qemu-system-sparc-0.11.0-13.fc12.x86_64
qemu-0.11.0-13.fc12.x86_64
qemu-system-cris-0.11.0-13.fc12.x86_64
qemu-system-ppc-0.11.0-13.fc12.x86_64
qemu-system-x86-0.11.0-13.fc12.x86_64
qemu-system-m68k-0.11.0-13.fc12.x86_64
qemu-system-arm-0.11.0-13.fc12.x86_64

> > Is the filesystem that you are trying to mount ext3?  XFS?
> The filesystem is ext3, which exists on a LV.
> 
> > Is the disk encrypted?
> The disk is not encrypted.
> 
> > -----
> > 
> > Reading around the issue, the error message
> > "INFO: task mount ... blocked for more than 120 seconds."
> > isn't very informative for us.  It just says that
> > an I/O operation was dropped by the block device
> > (eg. qemu or virtio is dropping I/O operations),
> > or else the kernel has lost track of an I/O op.  But
> > either way, mount is waiting for an I/O op to return
> > which isn't returning, and eventually everything
> > times out after 120 seconds.  Without knowing
> > what I/O op was dropped for what reason, there's
> > not much we can do.
> > 
> > FWIW I cannot reproduce this on Fedora 13,
> > but that has a different version of qemu and
> > a different kernel, so anything could be
> > different.
Comment 8 Richard W.M. Jones 2011-04-12 13:58:36 EDT
I can't reproduce the reporter's original problem.  With
libguestfs 1.9.18 I get this error from qemu instead:

$ guestfish -N lvfs exit
$ chmod -w test1.img 
$ ll test1.img 
-r--r--r--. 1 rjones rjones 104857600 Apr 12 18:56 test1.img
$ guestfish -a test1.img -m /dev/VG/LV ll /
qemu-kvm: -drive file=test1.img,cache=off,if=virtio: could not open disk image test1.img: Permission denied
libguestfs: error: unexpected end of file when reading from daemon
Comment 9 Richard W.M. Jones 2012-05-03 09:51:36 EDT
Trying to reproduce this on latest upstream:

$ guestfish -N lvfs exit
$ chmod -w test1.img
$ ll test1.img
-r--r--r--. 1 rjones rjones 104857600 May  3 14:48 test1.img
$ guestfish -a test1.img -m /dev/VG/LV ll /
libguestfs: error: test1.img: Permission denied

This is correct behaviour, and happens because I
changed the permissions test in the code:

http://git.annexia.org/?p=libguestfs.git;a=commitdiff;h=31bf0cf313f21bdeb0d166c4c76aad050ad32232

Therefore I am closing this bug.

Note You need to log in before you can comment on or make changes to this bug.