ChromeOS 11161.0.0
Chrome 72.0.3581.0

I've seen this twice in the past few days. I click on the Terminal icon and then in the hterm window it says:

[ERROR:vsh.cc(145)] Failed to launch vshd for termina:penguin

The root problem is that vsh is being launched and sshfs is attempted to be mounted before cicerone has received the container startup signal. It can also be seen in the log that we try to mount sshfs before we have received the container startup signal.


2018-10-17T12:01:40.348174-07:00 INFO vm_concierge[6401]: Received TremplinStartedSignal for owner: 53d63eda33c610d37b44cde8ed06854a05e9cc84, vm: termina
2018-10-17T12:01:40.350440-07:00 INFO vm_cicerone[6397]: Received CreateLxdContainer request
2018-10-17T12:01:40.422101-07:00 INFO vm_cicerone[6397]: Received StartLxdContainer request
2018-10-17T12:01:40.422544-07:00 INFO vm_concierge[6401]: Received GetContainerSshKeys request
2018-10-17T12:01:41.187538-07:00 INFO VM(20)[6412]: [   14.566874] lxdbr0: port 1(veth7R2ANS) entered blocking state#015
2018-10-17T12:01:41.188451-07:00 INFO VM(20)[6412]: [   14.568476] lxdbr0: port 1(veth7R2ANS) entered disabled state#015
2018-10-17T12:01:41.189443-07:00 INFO VM(20)[6412]: [   14.569449] device veth7R2ANS entered promiscuous mode#015
2018-10-17T12:01:41.190584-07:00 INFO VM(20)[6412]: [   14.570570] IPv6: ADDRCONF(NETDEV_UP): veth7R2ANS: link is not ready#015
2018-10-17T12:01:41.193396-07:00 INFO VM(20)[6412]: [   14.572190] cgroup: lxd (231) created nested cgroup for controller "memory" which has incomplete hierarchy support. Nested cgroups may change behavior in the future.#015
2018-10-17T12:01:41.194668-07:00 INFO VM(20)[6412]: [   14.574356] cgroup: "memory" requires setting use_hierarchy to 1 on the root#015
2018-10-17T12:01:41.405337-07:00 INFO VM(20)[6412]: [   14.783770] eth0: renamed from veth2DTJ84#015
2018-10-17T12:01:41.419452-07:00 INFO VM(20)[6412]: [   14.797160] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready#015
2018-10-17T12:01:41.422883-07:00 INFO VM(20)[6412]: [   14.800395] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready#015
2018-10-17T12:01:41.427316-07:00 INFO VM(20)[6412]: [   14.803671] IPv6: ADDRCONF(NETDEV_CHANGE): veth7R2ANS: link becomes ready#015
2018-10-17T12:01:41.430513-07:00 INFO VM(20)[6412]: [   14.808478] lxdbr0: port 1(veth7R2ANS) entered blocking state#015
2018-10-17T12:01:41.433106-07:00 INFO VM(20)[6412]: [   14.811467] lxdbr0: port 1(veth7R2ANS) entered forwarding state#015
2018-10-17T12:01:41.493197-07:00 INFO vm_cicerone[6397]: Received SetUpLxdContainerUser request
2018-10-17T12:01:41.573009-07:00 INFO VM(20)[6412]: [   14.952437] new mount options do not match the existing superblock, will be ignored#015
2018-10-17T12:01:41.687984-07:00 INFO vm_concierge[6401]: Received GetContainerSshKeys request
2018-10-17T12:01:41.691019-07:00 INFO VM(20)[6395]:  dnsmasq[195]: started, version 2.78 cachesize 150
2018-10-17T12:01:41.691026-07:00 INFO VM(20)[6395]:  dnsmasq[195]: compile time options: IPv6 GNU-getopt no-DBus no-i18n no-IDN DHCP DHCPv6 no-Lua no-TFTP no-conntrack ipset no-auth no-DNSSEC loop-detect inotify
2018-10-17T12:01:41.691029-07:00 WARNING VM(20)[6395]:  dnsmasq[195]: LOUD WARNING: listening on 100.115.92.193 may accept requests via interfaces other than lxdbr0
2018-10-17T12:01:41.691036-07:00 WARNING VM(20)[6395]:  dnsmasq[195]: LOUD WARNING: use --bind-dynamic rather than --bind-interfaces to avoid DNS amplification attacks via these interface(s)
2018-10-17T12:01:41.691039-07:00 INFO VM(20)[6395]:  dnsmasq-dhcp[195]: DHCP, IP range 100.115.92.194 -- 100.115.92.206, lease time 1h
2018-10-17T12:01:41.691041-07:00 INFO VM(20)[6395]:  dnsmasq-dhcp[195]: DHCP, sockets bound exclusively to interface lxdbr0
2018-10-17T12:01:41.691043-07:00 INFO VM(20)[6395]:  dnsmasq[195]: using local addresses only for domain lxd
2018-10-17T12:01:41.691045-07:00 INFO VM(20)[6395]:  dnsmasq[195]: reading /run/resolv.conf
2018-10-17T12:01:41.691047-07:00 INFO VM(20)[6395]:  dnsmasq[195]: using local addresses only for domain lxd
2018-10-17T12:01:41.691049-07:00 INFO VM(20)[6395]:  dnsmasq[195]: using nameserver 8.8.8.8#53
2018-10-17T12:01:41.691051-07:00 INFO VM(20)[6395]:  dnsmasq[195]: using nameserver 8.8.4.4#53
2018-10-17T12:01:41.691053-07:00 WARNING VM(20)[6395]:  dnsmasq[195]: LOUD WARNING: listening on 100.115.92.193 may accept requests via interfaces other than lxdbr0
2018-10-17T12:01:41.691054-07:00 WARNING VM(20)[6395]:  dnsmasq[195]: LOUD WARNING: use --bind-dynamic rather than --bind-interfaces to avoid DNS amplification attacks via these interface(s)
2018-10-17T12:01:41.691056-07:00 INFO VM(20)[6395]:  dnsmasq[195]: read /etc/hosts - 2 addresses
2018-10-17T12:01:41.691058-07:00 INFO VM(20)[6395]:  dnsmasq-dhcp[195]: read /mnt/stateful/lxd/networks/lxdbr0/dnsmasq.hosts/penguin
2018-10-17T12:01:41.691060-07:00 WARNING VM(20)[6395]:  dnsmasq[195]: LOUD WARNING: listening on 100.115.92.193 may accept requests via interfaces other than lxdbr0
2018-10-17T12:01:41.691062-07:00 WARNING VM(20)[6395]:  dnsmasq[195]: LOUD WARNING: use --bind-dynamic rather than --bind-interfaces to avoid DNS amplification attacks via these interface(s)
2018-10-17T12:01:41.691064-07:00 INFO VM(20)[6395]:  dnsmasq[195]: read /etc/hosts - 2 addresses
2018-10-17T12:01:41.691065-07:00 INFO VM(20)[6395]:  dnsmasq-dhcp[195]: read /mnt/stateful/lxd/networks/lxdbr0/dnsmasq.hosts/penguin
2018-10-17T12:01:41.691068-07:00 INFO VM(20)[6395]:  lxd[133]: lvl=info msg="Pruning expired images" t=2018-10-17T19:01:39+0000#012
2018-10-17T12:01:41.691069-07:00 INFO VM(20)[6395]:  lxd[133]: lvl=info msg="Done pruning expired images" t=2018-10-17T19:01:39+0000#012
2018-10-17T12:01:41.691071-07:00 INFO VM(20)[6395]:  lxd[133]: lvl=info msg="Expiring log files" t=2018-10-17T19:01:39+0000#012
2018-10-17T12:01:41.691074-07:00 INFO VM(20)[6395]:  lxd[133]: lvl=info msg="Updating instance types" t=2018-10-17T19:01:39+0000#012
2018-10-17T12:01:41.691076-07:00 INFO VM(20)[6395]:  lxd[133]: lvl=info msg="Done expiring log files" t=2018-10-17T19:01:39+0000#012
2018-10-17T12:01:41.691077-07:00 INFO VM(20)[6395]:  lxd[133]: lvl=info msg="Updating images" t=2018-10-17T19:01:39+0000#012
2018-10-17T12:01:41.691079-07:00 WARNING VM(20)[6395]:  dnsmasq[195]: LOUD WARNING: listening on 100.115.92.193 may accept requests via interfaces other than lxdbr0
2018-10-17T12:01:41.691081-07:00 WARNING VM(20)[6395]:  dnsmasq[195]: LOUD WARNING: use --bind-dynamic rather than --bind-interfaces to avoid DNS amplification attacks via these interface(s)
2018-10-17T12:01:41.691083-07:00 INFO VM(20)[6395]:  tremplin[200]: 2018/10/17 19:01:40 tremplin ready#012
2018-10-17T12:01:41.691085-07:00 INFO VM(20)[6395]:  tremplin[200]: 2018/10/17 19:01:40 Received CreateContainer RPC: penguin#012
2018-10-17T12:01:41.691087-07:00 INFO VM(20)[6395]:  tremplin[200]: 2018/10/17 19:01:40 Received StartContainer RPC: penguin#012
2018-10-17T12:01:41.691088-07:00 INFO VM(20)[6395]:  lxd[133]: lvl=info msg="Done updating images" t=2018-10-17T19:01:40+0000#012
2018-10-17T12:01:41.691090-07:00 INFO VM(20)[6395]:  lxd[133]: action=start created=2018-10-10T22:17:06+0000 ephemeral=false lvl=info msg="Starting container" name=penguin stateful=false t=2018-10-17T19:01:40+0000 used=2018-10-17T18:24:52+0000#012
2018-10-17T12:01:41.691092-07:00 WARNING VM(20)[6395]:  dnsmasq[195]: LOUD WARNING: listening on 100.115.92.193 may accept requests via interfaces other than lxdbr0
2018-10-17T12:01:41.691094-07:00 WARNING VM(20)[6395]:  dnsmasq[195]: LOUD WARNING: use --bind-dynamic rather than --bind-interfaces to avoid DNS amplification attacks via these interface(s)
2018-10-17T12:01:41.691095-07:00 WARNING VM(20)[6395]:  dnsmasq[195]: LOUD WARNING: listening on 100.115.92.193 may accept requests via interfaces other than lxdbr0
2018-10-17T12:01:41.691097-07:00 WARNING VM(20)[6395]:  dnsmasq[195]: LOUD WARNING: use --bind-dynamic rather than --bind-interfaces to avoid DNS amplification attacks via these interface(s)
2018-10-17T12:01:41.691099-07:00 INFO VM(20)[6395]:  lxd[133]: action=start created=2018-10-10T22:17:06+0000 ephemeral=false lvl=info msg="Started container" name=penguin stateful=false t=2018-10-17T19:01:41+0000 used=2018-10-17T18:24:52+0000#012
2018-10-17T12:01:41.691101-07:00 INFO VM(20)[6395]:  tremplin[200]: 2018/10/17 19:01:41 Received SetUpUser RPC: penguin#012
2018-10-17T12:01:41.691103-07:00 WARNING VM(20)[6395]:  dnsmasq[195]: LOUD WARNING: listening on 100.115.92.193 may accept requests via interfaces other than lxdbr0
2018-10-17T12:01:41.691105-07:00 WARNING VM(20)[6395]:  dnsmasq[195]: LOUD WARNING: use --bind-dynamic rather than --bind-interfaces to avoid DNS amplification attacks via these interface(s)
2018-10-17T12:01:41.692343-07:00 WARNING kernel: [88985.757491] audit_printk_skb: 138 callbacks suppressed
2018-10-17T12:01:41.692352-07:00 NOTICE kernel: [88985.757524] audit: type=1400 audit(1539802901.691:3303): avc:  granted  { execute } for  pid=6546 comm="cros-disks" name="sshfs" dev="nvme0n1p5" ino=92997 scontext=u:r:minijail:s0 tcontext=u:object_r:cros_unconfined_exec:s0 tclass=file
2018-10-17T12:01:41.692354-07:00 NOTICE kernel: [88985.757590] audit: type=1401 audit(1539802901.691:3304): op=security_bounded_transition seresult=denied oldcontext=u:r:minijail:s0 newcontext=u:r:minijailed:s0
2018-10-17T12:01:41.692355-07:00 NOTICE kernel: [88985.757942] audit: type=1400 audit(1539802901.691:3305): avc:  granted  { execute } for  pid=6546 comm="sshfs" path="/usr/bin/sshfs" dev="nvme0n1p5" ino=92997 scontext=u:r:minijail:s0 tcontext=u:object_r:cros_unconfined_exec:s0 tclass=file
2018-10-17T12:01:41.695463-07:00 NOTICE kernel: [88985.760915] audit: type=1400 audit(1539802901.694:3306): avc:  granted  { getattr } for  pid=6546 comm="sshfs" path="/media" dev="tmpfs" ino=1293 scontext=u:r:minijail:s0 tcontext=u:object_r:tmpfs:s0 tclass=dir
2018-10-17T12:01:41.697050-07:00 NOTICE kernel: [88985.762415] audit: type=1400 audit(1539802901.696:3307): avc:  granted  { execute } for  pid=6549 comm="sshfs" name="ssh" dev="nvme0n1p5" ino=92347 scontext=u:r:minijail:s0 tcontext=u:object_r:cros_unconfined_exec:s0 tclass=file
2018-10-17T12:01:41.697063-07:00 NOTICE kernel: [88985.762467] audit: type=1401 audit(1539802901.696:3308): op=security_bounded_transition seresult=denied oldcontext=u:r:minijail:s0 newcontext=u:r:minijailed:s0
2018-10-17T12:01:41.697064-07:00 NOTICE kernel: [88985.762570] audit: type=1400 audit(1539802901.696:3309): avc:  granted  { execute } for  pid=6549 comm="ssh" path="/usr/bin/ssh" dev="nvme0n1p5" ino=92347 scontext=u:r:minijail:s0 tcontext=u:object_r:cros_unconfined_exec:s0 tclass=file
2018-10-17T12:01:41.993345-07:00 INFO cros-disks[2090]: libminijail[2090]: child process 6546 exited with status 1
2018-10-17T12:01:41.993371-07:00 WARNING cros-disks[2090]: FUSE mount program failed with a return code 1
2018-10-17T12:01:41.993389-07:00 ERR cros-disks[2090]: Failed to mount 'narflexnarflex@penguin.termina.linux.test:' to '/media/fuse/crostini_53d63eda33c610d37b44cde8ed06854a05e9cc84_termina_penguin' as filesystem 'sshfs' with options 'UserKnownHostsFile=/run/fuse/.1tcDh0/known_hosts,IdentityFile=/run/fuse/.1tcDh0/id,Port=2222,rw,uid=1000,gid=1001,nodev,noexec,nosuid,KbdInteractiveAuthentication=no,PasswordAuthentication=no,BatchMode=yes,follow_symlinks,allow_other,default_permissions'
2018-10-17T12:01:41.993400-07:00 ERR cros-disks[2090]: Failed to mount path 'sshfs://narflexnarflex@penguin.termina.linux.test:'
2018-10-17T12:01:41.993429-07:00 ERR cros-disks[2090]: Failed to mount 'sshfs://narflexnarflex@penguin.termina.linux.test:'
2018-10-17T12:01:42.398069-07:00 CRIT kernel: [88986.464161] CPU2: Core temperature above threshold, cpu clock throttled (total events = 1429)
2018-10-17T12:01:42.398084-07:00 CRIT kernel: [88986.464162] CPU3: Core temperature above threshold, cpu clock throttled (total events = 1429)
2018-10-17T12:01:42.398086-07:00 CRIT kernel: [88986.464165] CPU3: Package temperature above threshold, cpu clock throttled (total events = 4048)
2018-10-17T12:01:42.398087-07:00 CRIT kernel: [88986.464167] CPU1: Package temperature above threshold, cpu clock throttled (total events = 3541)
2018-10-17T12:01:42.398088-07:00 CRIT kernel: [88986.464167] CPU0: Package temperature above threshold, cpu clock throttled (total events = 3541)
2018-10-17T12:01:42.398088-07:00 CRIT kernel: [88986.464173] CPU2: Package temperature above threshold, cpu clock throttled (total events = 4048)
2018-10-17T12:01:42.400049-07:00 INFO kernel: [88986.466186] CPU2: Core temperature/speed normal
2018-10-17T12:01:42.400058-07:00 INFO kernel: [88986.466187] CPU3: Core temperature/speed normal
2018-10-17T12:01:42.400060-07:00 INFO kernel: [88986.466189] CPU3: Package temperature/speed normal
2018-10-17T12:01:42.400060-07:00 INFO kernel: [88986.466190] CPU0: Package temperature/speed normal
2018-10-17T12:01:42.400061-07:00 INFO kernel: [88986.466191] CPU1: Package temperature/speed normal
2018-10-17T12:01:42.400061-07:00 INFO kernel: [88986.466196] CPU2: Package temperature/speed normal
2018-10-17T12:01:42.452096-07:00 INFO vm_cicerone[6397]: Received LaunchVshd request
2018-10-17T12:01:42.452125-07:00 ERR vm_cicerone[6397]: Requested container does not exist: penguin
2018-10-17T12:01:42.464053-07:00 NOTICE kernel: [88986.530202] audit: type=1401 audit(1539802902.463:3310): op=setxattr invalid_context="u:object_r:cros_shm:s0"
2018-10-17T12:01:42.530072-07:00 ERR kernel: [88986.596005] snd_soc_skl 0000:00:1f.3: ASoC: PRE_PMU: spk_pb_in dsm 0 event failed: -22
2018-10-17T12:01:44.306062-07:00 INFO vm_cicerone[6397]: Startup of container penguin at IP 100.115.92.199 for VM termina completed.
2018-10-17T12:01:44.460932-07:00 INFO vm_concierge[6401]: Received GetContainerSshKeys request
2018-10-17T12:01:46.693297-07:00 INFO VM(20)[6395]:  tremplin[200]: 2018/10/17 19:01:44 Received GetContainerInfo RPC: penguin#012
2018-10-17T12:01:46.693302-07:00 INFO VM(20)[6395]:  tremplin[200]: 2018/10/17 19:01:44 Received GetContainerUsername RPC: penguin#012
2018-10-17T12:01:46.693304-07:00 INFO VM(20)[6395]:  lxd[133]: lvl=info msg="Done updating instance types" t=2018-10-17T19:01:45+0000#012
2018-10-17T12:01:50.628139-07:00 INFO kernel: [88994.693555] Bluetooth: hci_core.c:skip_conditional_cmd()   COND LE cmd (0x200c) is already 0 (chg 0), skip transition to 0
2018-10-17T12:01:50.628173-07:00 INFO kernel: [88994.693569] Bluetooth: hci_core.c:skip_conditional_cmd()   COND call queue_work.
2018-10-17T12:02:30.319998-07:00 NOTICE dbus[603]: [system] Activating service name='org.chromium.ImageLoader' (using servicehelper)
2018-10-17T12:02:30.344883-07:00 NOTICE dbus[603]: [system] Successfully activated service 'org.chromium.ImageLoader'
2018-10-17T12:02:30.349785-07:00 INFO vm_concierge[6401]: Received CreateDiskImage request
2018-10-17T12:02:30.350067-07:00 INFO vm_concierge[6401]: Received StartVm request
2018-10-17T12:02:30.350092-07:00 INFO vm_concierge[6401]: VM with requested name is already running
2018-10-17T12:02:30.350423-07:00 INFO vm_cicerone[6397]: Received CreateLxdContainer request
2018-10-17T12:02:30.369258-07:00 INFO vm_cicerone[6397]: Received StartLxdContainer request
2018-10-17T12:02:30.369422-07:00 INFO vm_concierge[6401]: Received GetContainerSshKeys request
2018-10-17T12:02:30.385840-07:00 INFO vm_cicerone[6397]: Received SetUpLxdContainerUser request
2018-10-17T12:02:30.478828-07:00 INFO vm_concierge[6401]: Received GetContainerSshKeys request
2018-10-17T12:02:30.480095-07:00 NOTICE kernel: [89034.546656] audit: type=1400 audit(1539802950.480:3311): avc:  granted  { execute } for  pid=6647 comm="cros-disks" name="sshfs" dev="nvme0n1p5" ino=92997 scontext=u:r:minijail:s0 tcontext=u:object_r:cros_unconfined_exec:s0 tclass=file
2018-10-17T12:02:30.481050-07:00 NOTICE kernel: [89034.546726] audit: type=1401 audit(1539802950.480:3312): op=security_bounded_transition seresult=denied oldcontext=u:r:minijail:s0 newcontext=u:r:minijailed:s0
2018-10-17T12:02:30.481056-07:00 NOTICE kernel: [89034.546903] audit: type=1400 audit(1539802950.480:3313): avc:  granted  { execute } for  pid=6647 comm="sshfs" path="/usr/bin/sshfs" dev="nvme0n1p5" ino=92997 scontext=u:r:minijail:s0 tcontext=u:object_r:cros_unconfined_exec:s0 tclass=file
2018-10-17T12:02:30.482052-07:00 NOTICE kernel: [89034.548004] audit: type=1400 audit(1539802950.481:3314): avc:  granted  { getattr } for  pid=6647 comm="sshfs" path="/media" dev="tmpfs" ino=1293 scontext=u:r:minijail:s0 tcontext=u:object_r:tmpfs:s0 tclass=dir
2018-10-17T12:02:30.483053-07:00 NOTICE kernel: [89034.548738] audit: type=1400 audit(1539802950.482:3315): avc:  granted  { execute } for  pid=6650 comm="sshfs" name="ssh" dev="nvme0n1p5" ino=92347 scontext=u:r:minijail:s0 tcontext=u:object_r:cros_unconfined_exec:s0 tclass=file
2018-10-17T12:02:30.483060-07:00 NOTICE kernel: [89034.548774] audit: type=1401 audit(1539802950.482:3316): op=security_bounded_transition seresult=denied oldcontext=u:r:minijail:s0 newcontext=u:r:minijailed:s0
2018-10-17T12:02:30.483061-07:00 NOTICE kernel: [89034.548868] audit: type=1400 audit(1539802950.482:3317): avc:  granted  { execute } for  pid=6650 comm="ssh" path="/usr/bin/ssh" dev="nvme0n1p5" ino=92347 scontext=u:r:minijail:s0 tcontext=u:object_r:cros_unconfined_exec:s0 tclass=file
2018-10-17T12:02:31.739485-07:00 INFO VM(20)[6395]:  tremplin[200]: 2018/10/17 19:02:30 Received CreateContainer RPC: penguin#012
2018-10-17T12:02:31.739498-07:00 INFO VM(20)[6395]:  tremplin[200]: 2018/10/17 19:02:30 Received StartContainer RPC: penguin#012
2018-10-17T12:02:31.739502-07:00 INFO VM(20)[6395]:  tremplin[200]: 2018/10/17 19:02:30 Received SetUpUser RPC: penguin#012