New issue
Advanced search Search tips

Issue 899302 link

Starred by 2 users

Issue metadata

Status: Verified
Owner:
Closed: Nov 2
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

Restarting VMs failing with DiskImageLock error

Project Member Reported by jkardatzke@chromium.org, Oct 26

Issue description

This is from the new performance test for starting/stopping Crostini VMs.

There's a few of them failing with this line:

2018-10-25T20:33:01.173854-07:00 ERR localhos[11496]: crosvm[27]: [src/main.rs:538] The architecture failed to build the vm: DiskImageLock(Error(11))

Here's a specific test failure:

https://stainless.corp.google.com/browse/chromeos-autotest-results/252114932-chromeos-test/

And for some more context:

2018-10-25T20:32:49.398821-07:00 INFO vm_concierge[11326]: Received StopVm request
2018-10-25T20:32:49.519030-07:00 INFO VM(3)[11357]: [  121.949251] maitred: Received shutdown request#015
2018-10-25T20:32:49.525771-07:00 INFO VM(3)[11320]:  tremplin[143]: 2018/10/26 03:32:45 Received GetContainerInfo RPC: penguin#012
2018-10-25T20:32:49.525780-07:00 INFO VM(3)[11320]:  tremplin[143]: 2018/10/26 03:32:46 Received GetContainerUsername RPC: penguin#012
2018-10-25T20:32:49.612297-07:00 INFO vm_cicerone[11346]:  Process 10 exited with status 255
2018-10-25T20:32:59.564520-07:00 INFO VM(3)[11357]: [  132.080986] maitred: Detaching loopback devices#015
2018-10-25T20:32:59.568798-07:00 INFO VM(3)[11357]: [  132.085217] maitred: Removing device mapper devices#015
2018-10-25T20:32:59.570944-07:00 INFO VM(3)[11357]: [  132.087710] maitred: Unmounting filesystems#015
2018-10-25T20:32:59.575958-07:00 INFO VM(3)[11357]: [  132.090391] maitred: Unmounting /mnt/stateful/lxd/devices/penguin/disk.cros_containers.opt-google-cros-containers#015
2018-10-25T20:32:59.584487-07:00 INFO VM(3)[11357]: [  132.099215] maitred: Unmounting /mnt/stateful/lxd/devices/penguin/disk.sshd_config.dev-.ssh-sshd_config#015
2018-10-25T20:32:59.595615-07:00 INFO VM(3)[11357]: [  132.110269] maitred: Unmounting /mnt/stateful/lxd/devices/penguin/disk.ssh_host_key.dev-.ssh-ssh_host_key#015
2018-10-25T20:32:59.599912-07:00 INFO VM(3)[11357]: [  132.115260] lxdbr0: port 1(vethETG7QN) entered disabled state#015
2018-10-25T20:32:59.605852-07:00 INFO VM(3)[11357]: [  132.120118] maitred: Unmounting /mnt/stateful/lxd/devices/penguin/disk.ssh_authorized_keys.dev-.ssh-ssh_authorized_keys#015
2018-10-25T20:32:59.607992-07:00 INFO VM(3)[11357]: [  132.120178] device vethETG7QN left promiscuous mode#015
2018-10-25T20:32:59.611069-07:00 INFO VM(3)[11357]: [  132.120184] lxdbr0: port 1(vethETG7QN) entered disabled state#015
2018-10-25T20:32:59.615982-07:00 INFO VM(3)[11357]: [  132.131173] maitred: Unmounting /mnt/stateful/lxd/devices/penguin/disk.host-ip.dev-.host_ip#015
2018-10-25T20:32:59.623331-07:00 INFO VM(3)[11357]: [  132.138109] maitred: Unmounting /mnt/stateful/lxd/devices/penguin/disk.cros_milestone.dev-.cros_milestone#015
2018-10-25T20:32:59.633367-07:00 INFO VM(3)[11357]: [  132.148096] maitred: Unmounting /mnt/stateful/lxd/devices/penguin/disk.container_token.dev-.container_token#015
2018-10-25T20:33:00.780247-07:00 ERR localhos[11351]: 9s[2]: [9s/src/main.rs:149] error while handling client 3:1025: failed to fill whole buffer
2018-10-25T20:33:00.815021-07:00 INFO VM(3)[11357]: [  133.331404] Unregister pv shared memory for cpu 1#015
2018-10-25T20:33:00.817796-07:00 INFO VM(3)[11357]: [  133.333886] Unregister pv shared memory for cpu 0#015
2018-10-25T20:33:00.821046-07:00 INFO VM(3)[11357]: [  133.337644] reboot: Restarting system#015
2018-10-25T20:33:00.823155-07:00 INFO VM(3)[11357]: [  133.339893] reboot: machine restart#015
2018-10-25T20:33:00.828770-07:00 INFO localhos[11356]: crosvm[4]: [src/linux.rs:933] vcpu requested shutdown
2018-10-25T20:33:00.905931-07:00 INFO localhos[11356]: crosvm[4]: [src/main.rs:534] crosvm has exited normally
2018-10-25T20:33:00.905947-07:00 ERR localhos[11364]: crosvm[1]: [devices/src/proxy.rs:104] error: child device process failed send: Connection refused (os error 111)
2018-10-25T20:33:00.906324-07:00 ERR localhos[11365]: crosvm[1]: [devices/src/proxy.rs:104] error: child device process failed send: Connection refused (os error 111)
2018-10-25T20:33:01.009442-07:00 WARNING localhos[11356]: crosvm[4]: [src/main.rs:694] not all child processes have exited; sending SIGKILL
2018-10-25T20:33:01.021565-07:00 INFO vm_cicerone[11346]: Received NotifyVmStopped request
2018-10-25T20:33:01.021657-07:00 WARNING vm_cicerone[11346]: Latent container left in VM termina of penguin
2018-10-25T20:33:01.025175-07:00 ERR vm_concierge[11326]: Unable to send signal to 5: No such process
2018-10-25T20:33:01.037486-07:00 INFO seneschal[11325]: Received request to stop server
2018-10-25T20:33:01.038296-07:00 INFO seneschal[11325]: Process 2 killed by signal 15
2018-10-25T20:33:01.050605-07:00 INFO vm_concierge[11326]: Received CreateDiskImage request
2018-10-25T20:33:01.054390-07:00 INFO vm_concierge[11326]: Received StartVm request
2018-10-25T20:33:01.057538-07:00 INFO seneschal[11325]: Received request to start new 9p server
2018-10-25T20:33:01.072812-07:00 WARNING seneschal[11325]: libminijail[1]: non-debug build: ignoring request to enable seccomp logging
2018-10-25T20:33:01.080177-07:00 INFO seneschal[11325]: Started server on /run/seneschal/scoped_dir_oJqp2F
2018-10-25T20:33:01.091607-07:00 WARNING kernel: [ 5579.993838] audit_printk_skb: 165 callbacks suppressed
2018-10-25T20:33:01.091647-07:00 NOTICE kernel: [ 5579.993856] audit: type=1400 audit(1540524781.088:206497): avc:  granted  { execute } for  pid=11494 comm="seneschal" name="9s" dev="dm-0" ino=10689 scontext=u:r:minijail:s0 tcontext=u:object_r:cros_unconfined_exec:s0 tclass=file
2018-10-25T20:33:01.114751-07:00 NOTICE kernel: [ 5580.017639] audit: type=1401 audit(1540524781.112:206498): op=security_bounded_transition seresult=denied oldcontext=u:r:minijail:s0 newcontext=u:r:minijailed:s0
2018-10-25T20:33:01.114784-07:00 NOTICE kernel: [ 5580.018023] audit: type=1400 audit(1540524781.112:206499): avc:  granted  { execute } for  pid=11494 comm="9s" path="/usr/bin/9s" dev="dm-0" ino=10689 scontext=u:r:minijail:s0 tcontext=u:object_r:cros_unconfined_exec:s0 tclass=file
2018-10-25T20:33:01.144796-07:00 INFO localhos[11496]: crosvm[27]: [src/linux.rs:771] crosvm entering multiprocess mode
2018-10-25T20:33:01.173854-07:00 ERR localhos[11496]: crosvm[27]: [src/main.rs:538] The architecture failed to build the vm: DiskImageLock(Error(11))

 
Owner: smbar...@chromium.org
Project Member

Comment 2 by bugdroid1@chromium.org, Oct 31

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform/crosvm/+/49dd2e219deeb685980d3b27545c09d43cc157be

commit 49dd2e219deeb685980d3b27545c09d43cc157be
Author: Stephen Barber <smbarber@chromium.org>
Date: Wed Oct 31 03:59:50 2018

main: increase child wait timeout to 1 second

BUG= chromium:899302 
TEST=vm.CrostiniStartTime

Change-Id: Ie434bc8ec2df7a7e8d1102feab5b84ebcdbb113d
Reviewed-on: https://chromium-review.googlesource.com/1306821
Commit-Ready: Stephen Barber <smbarber@chromium.org>
Tested-by: Stephen Barber <smbarber@chromium.org>
Reviewed-by: Zach Reizner <zachr@chromium.org>

[modify] https://crrev.com/49dd2e219deeb685980d3b27545c09d43cc157be/src/main.rs

Status: Verified (was: Available)
Verified on 11215.0.0.

Sign in to add a comment