Sudo enter-chroot takes unusually long

[jazzgroove]

Please paste the output of the following command here: sudo edit-chroot -all

name: buster
encrypted: no
Entering /mnt/stateful_partition/crouton/chroots/buster...
crouton: version 1-20180709160044~master:193dcfd0
release: buster
architecture: amd64
xmethod: xiwi
targets: audio,core,extension,lxde,xiwi
host: version 10718.34.0 (Official Build) beta-channel samus
kernel: Linux localhost 3.14.0 #1 SMP PREEMPT Mon Jun 25 22:22:50 PDT 2018 x86_64 GNU/Linux
freon: yes

Please describe your issue:

My longtime Buster chroot all of the sudden has been taking an extremely longtime to load(sudo startlxde or enter-chroot from the CLI). After the chroot is up and running things seem to be fine except that any sudo commands (ex. sudo apt-get install) also take a long time.

If known, describe the steps to reproduce the issue:

1. From a shell sudo enter-chroot -n buster

--or--

2. Inside a chroot execute any command that uses sudo (ex. sudo su)

Result - takes roughly a minute before entering the chroot.

[DennisLfromGA]

@jazzgroove,

You may be able to pin down where it's slowing down by tracing the execution and watching for the delay, using something like this:

• sudo sh -x /usr/local/bin/enter-chroot -n buster 2>&1

Hope this helps,
-DennisLfromGA

[kapilhp]

Same problem after update of a "buster" chroot. Will check with tracing.

[kapilhp]

The command adduser is slow as well.

After running strace -t -o sudo.strace sudo -s -u test the attached file was the output of the trace. It seems to indicate that the ppoll to fd4 is getting stuck. Not adept at reading these traces, but perhaps this fd4 is the socket for communication with dbus.

strace.txt

[jazzgroove]

Thanks for the tip @DennisLfromGA - I ran your suggested command and I've captured in the output where the pauses occur:

• env -i chroot /var/run/crouton/mnt/stateful_partition/crouton/chroots/buster su -s /bin/sh -c
  if ! hash dbus-daemon 2>/dev/null; then
  exit 0
  fi
  dbususer=''
  pidfile="/var/run/dbus/pid"
  if [ -f "$pidfile" ]; then
  if grep -q "^dbus-daemon" "/proc/cat "$pidfile"/cmdline"
  2>/dev/null; then
  exit 0
  fi
  rm -f "$pidfile"
  fi
  mkdir -p /var/run/dbus
  dbususer="id -un "$dbususer" 2>/dev/null || echo "messagebus""
  dbusgrp="id -gn "$dbususer" 2>/dev/null || echo "messagebus""
  chown "$dbususer:$dbusgrp" /var/run/dbus
  exec dbus-daemon --system --fork - root

SUPER Long Pause***

• local pid=
• [ -n ]
• TRAP=sh -e '/usr/local/bin/unmount-chroot' -yc '/mnt/stateful_partition/crouton/chroots' -- 'buster';stty echo 2>/dev/null;
• return 0
• [ 0 != 0 ]
• fixabslinks /run/systemd
• local p=/var/run/crouton/mnt/stateful_partition/crouton/chroots/buster//run/systemd c
• readlink -m -- /var/run/crouton/mnt/stateful_partition/crouton/chroots/buster//run/systemd
• c=/var/run/crouton/mnt/stateful_partition/crouton/chroots/buster/run/systemd
• [ /var/run/crouton/mnt/stateful_partition/crouton/chroots/buster/run/systemd != /var/run/crouton/mnt/stateful_partition/crouton/chroots/buster//run/systemd ]
• p=/var/run/crouton/mnt/stateful_partition/crouton/chroots/buster/run/systemd
• readlink -m -- /var/run/crouton/mnt/stateful_partition/crouton/chroots/buster/run/systemd
• c=/var/run/crouton/mnt/stateful_partition/crouton/chroots/buster/run/systemd
• [ /var/run/crouton/mnt/stateful_partition/crouton/chroots/buster/run/systemd != /var/run/crouton/mnt/stateful_partition/crouton/chroots/buster/run/systemd ]
• echo /var/run/crouton/mnt/stateful_partition/crouton/chroots/buster/run/systemd
• systemd_dir=/var/run/crouton/mnt/stateful_partition/crouton/chroots/buster/run/systemd
• [ -x /var/run/crouton/mnt/stateful_partition/crouton/chroots/buster/lib/systemd/systemd-logind ]
• [ ! -d /var/run/crouton/mnt/stateful_partition/crouton/chroots/buster/run/systemd ]
• [ buster = saucy -o buster = trusty ]
• chrootcmd /usr/local/bin/croutonfindnacld >/dev/null 2>&1 </dev/null &
• local ret=0 oldtrap=sh -e '/usr/local/bin/unmount-chroot' -yc '/mnt/stateful_partition/crouton/chroots' -- 'buster';stty echo 2>/dev/null;
• TRAP=
• env -i chroot /var/run/crouton/mnt/stateful_partition/crouton/chroots/buster su -s /bin/sh -c /usr/local/bin/croutonfindnacld >/dev/null 2>&1 </dev/null & - root

SUPER Long Pause*****

• local pid=
• [ -n ]
• TRAP=sh -e '/usr/local/bin/unmount-chroot' -yc '/mnt/stateful_partition/crouton/chroots' -- 'buster';stty echo 2>/dev/null;
• return 0
• [ -n ]
• [ -n y -a -x /var/run/crouton/mnt/stateful_partition/crouton/chroots/buster/etc/rc.local ]
• [ 0 = 0 -o -n ]
• env -i TERM=xterm-256color chroot /var/run/crouton/mnt/stateful_partition/crouton/chroots/buster su - username

[DennisLfromGA]

Thanx for the feedback, hopefully, someone looking at this will be able to narrow down the delay.

-DennisLfromGA

[kapilhp]

A fresh install of "buster" does not seem to give the problem! Investigating further, I ran the following commands:

1. sudo crouton -r buster -t core -n test -e
2. sudo enter-chroot -n test

There was no delay this time!

[kapilhp]

Narrowed it down to the installation of pulseaudio. As soon as it is installed the enter-chroot command takes a long time. Once it is removed, the problem disappears!

[DennisLfromGA]

@kapilhp,

Thanx for that feedback and /workaround/resolution.
Maybe @jazzgroove could try removing pulseaudio to see if it eliminates the delay.

Hope this helps,
-DennisLfromGA

[kapilhp]

Since pulseaudio is a dependency for a number of packages and is generally required for many programs (for example, the most recent Firefox binaries appear to depend on it if they are to give audio output), I tried to see if there is a way out.

For the moment, the pulseaudio from sid (which is version 12+) appears to work without causing this problem.

[jazzgroove]

Thx @kapilhp and @DennisLfromGA

I removed the pulseaudio package and still see the delay. I'm not sure where to go from here. I'm wondering if policy.d could be part of the issue. Looking in the Crouton X.org log I see:

Error org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken

[kapilhp]

Perhaps also removedbus-x11. I have a working buster chroot for the last 10 odd days now after removing dbus-x11 and installing the pulseaudio packages from sid.

[jazzgroove]

Thanks @kapilhp I removed dbus-x11 too and still have the delay. I'm thinking I might need to start over completely or restore an old backup and try to compare.

[dnschneid]

This happened to me as well. Since this sid chroot was non-graphical, I found that apt-get remove systemd only had minor package impact:

The following packages will be REMOVED:
  libnss-systemd libpam-systemd policykit-1 systemd systemd-sysv
The following NEW packages will be installed:
  sysvinit-core

and fixed the login speed issues for me. I guess something changed recently in the systemd packages on sid/testing that is causing this issue, but I haven't looked into it much further. YMMV; make a backup first.

[kapilhp]

I do have systemd installed. So, it's not the problematic package. However, I do not have policykit-1 installed. Since my premature mail 13 days ago blaming pulseaudio I have not faced any problem. I am attaching
out.txt
the list of installed packages on my system (along with versions) which may help in diagnosing the problem.
If it turns out that I have some time this weekend (unlikely!), then I will test this out by creating a new chroot.

[kapilhp]

Unable to replicate!

1. Created a new chroot with sudo crouton -t core -r buster -n test.

2. Installed dbus-X11 in this chroot (which already had systemd installed). This did not affect the capacity to do sudo normally; i.e. there was no slow down.

3. Installed pulseaudio in this chroot. This did not affect the capacity to do sudo.

4. Installed policykit-1 in this chroot. This did not affect the capacity to do sudo.

So now this is (as one of my former colleagues would say) "a mystery wrapped in an enigma wrapped in a riddle!" 😄

Perhaps whatever was causing the problem has disappeared from "buster" which has a high churn since it is a rolling distribution.

[dcecile]

This happened to me too (running Debian Sid, updated yesterday) -- slow sudo as well as slow starting/exiting the chroot, and slow starting X via xinit. (I also verified with strace that it was the same /run/dbus/system_bus_socket 24-second timeout that was causing the delay in sudo.)

The fix to apt-get remove systemd seems to be working fine for me so far. No more slowdowns, no problems starting the chroot or running X.

[jazzgroove]

@kapilhp - thanks for the list of packages. Did you use apt-show-versions? I'm going to generate a list too and compare.

[dbaynard]

I think I've just encountered this issue — I have many of the same symptoms. I'm fairly sure it's related to dbus, and began when I used croutonpowerd.

I'm running arch on a fork of crouton, which has been working fine. I ran croutonpowerd -i sudo pacman -Su (to any arch people: I'd already run -Syuw) and it failed (deleting the package manager in the process).

Both arch and sid use dbus version 1.12.10. The changelog is on github (the website is on the 1.13 branch). Nothing jumps out, to me. I believe I was using 1.12.8 successfully, beforehand.

My errors with croutonpowerd correspond to the following call, last touched by #3378 (the line number 303 in the error corresponds to 52 in the source). Oddly I see references to the same issue in the strace from sudo commands (even without croutonpowerd).

crouton/chroot-bin/croutonpowerd

Lines 52 to 57 in 5d4c301

	pingpowerd() {
	$hostdbus dbus-send --system --dest=org.chromium.PowerManager \
	--type=method_call /org/chromium/PowerManager \
	org.chromium.PowerManager.HandleUserActivity \
	int32:0 || true
	}

/usr/local/bin/croutonpowerd: line 303:  8008 Bus error               (core dumped) $hostdbus dbus-send --system --dest=org.chromium.PowerManager --type=method_call /org/chromium/PowerManager org.chromium.PowerManager.HandleUserActivity int32:0
/usr/local/bin/croutonpowerd: line 303:  8185 Bus error               (core dumped) $hostdbus dbus-send --system --dest=org.chromium.PowerManager --type=method_call /org/chromium/PowerManager org.chromium.PowerManager.HandleUserActivity int32:0
/usr/local/bin/croutonpowerd: line 303:  8227 Bus error               (core dumped) $hostdbus dbus-send --system --dest=org.chromium.PowerManager --type=method_call /org/chromium/PowerManager org.chromium.PowerManager.HandleUserActivity int32:0

I'm trying to fix it for me — when (if?) I do, I'll respond here with details. Meanwhile, I hope this report helps.

[dbaynard]

I bisected my arch install; below are the packages that changed and broke the chroot (note; they are fine on a non-crouton system). Looks like systemd was probably the change.

There are various network interface changes in systemd-239; the error could well be here.

---

• apr-util: 1.6.1-2 ⇒ 1.6.1-3
• avahi: 0.7+4+gd8d8c67-1 ⇒ 0.7+16+g1cc2b8e-1
• gdbm: 1.14.1-1 ⇒ 1.16-1
• imagemagick: 7.0.8.4-1 ⇒ 7.0.8.5-1
• libmagick: 7.0.8.4-1 ⇒ 7.0.8.5-1
• libmagick6: 6.9.10.4-1 ⇒ 6.9.10.5-1
• libsasl: 2.1.26-12 ⇒ 2.1.26-13
• libsystemd: 238.133-4 ⇒ 239.0-2
• man-db: 2.8.3-1 ⇒ 2.8.3-2
• perl: 5.26.2-1 ⇒ 5.26.2-2
• python: 3.6.5-3 ⇒ 3.6.6-1
• python2: 2.7.15-1 ⇒ 2.7.15-2
• ruby: 2.5.1-1 ⇒ 2.5.1-2
• systemd: 238.133-4 ⇒ 239.0-2
• systemd-sysvcompat: 238.133-4 ⇒ 239.0-2
• zsh: 5.5.1-1 ⇒ 5.5.1-2
• zstd: 1.3.4-1 ⇒ 1.3.5-1

---

[jazzgroove]

Great info @dbaynard. I reverted back to an earlier backup of systemd.
State: installed (238-4), upgrade available (239-7). Version 238-4 doesn't have the lag and sudo actions are nice and quick.

[kapilhp]

It is probably some combination of dbus and systemd and (possibly) pam. Here are the versions on my system: pam is version 1.1.8-3.7, systemd is version 239-7, dbus is version 1.12.10-1. (The number after the hyphen is the internal Debian version.)

In my case, with these packages, I see no lag in sudo within the chroot or in enter-chroot from Chrome OS.

Just in case it is relevant: Google Chrome version is 68.0.3440.87 (Official Build) (64-bit) and
Platform version is 10718.71.2 (Official Build).

-- Kapil.

[eyqs]

Thanks, @dbaynard. I reverted systemd and libsystemd from 239.0-2 to 238.133-4 and sudo no longer hangs in my arch chroot anymore.

[dbaynard]

@eyqs I've only just encountered your chroagh-dev repo — we should collaborate!

Also, I wonder if running crouton with functional systemd (with merged #2474 by @sn0e) would help, here.

It seems like there's something going on with systemd 239.0, and nothing jumped out on the bug tracker. We could report — but they often punt distro specific issues back to the distribution. So if crouton maintainers thinks it should go upstream, let's do it.

[eyqs]

+1 on reporting.

By the way, I think the currently active repo is @mediocregopher's, not mine, so let's help them out!

[mediocregopher]

Oh wow, I was having this exact issue. If it helps to narrow down some more, I first downgraded just systemd to 238.76-1.1 with no effect, but then downgrading libsystemd fixed the problem immediately.

[davidgiven]

Is there any news on a fix for this?

[jazzgroove]

@davidgiven I only see a commit to the chroagh repo. I don't think anything has been patched in crouton for this.

[nehalem501]

I have the same issue after upgrading my ubuntu chroot to cosmic.
Downgrading systemd, libsystemd, dbus, or pam didn't have any effect.

It stays stuck there for a while before entering the chroot

+ TRAP=
+ env -i chroot /var/run/crouton/mnt/stateful_partition/crouton/chroots/cosmic su -s /bin/sh -c 
        if ! hash dbus-daemon 2>/dev/null; then
            exit 0
        fi
        dbususer=''
        pidfile="/var/run/dbus/pid"
        if [ -f "$pidfile" ]; then
            if grep -q "^dbus-daemon" "/proc/`cat "$pidfile"`/cmdline" \
                    2>/dev/null; then
                exit 0
            fi
            rm -f "$pidfile"
        fi
        mkdir -p /var/run/dbus
        dbususer="`id -un "$dbususer" 2>/dev/null || echo "messagebus"`"
        dbusgrp="`id -gn "$dbususer" 2>/dev/null || echo "messagebus"`"
        chown "$dbususer:$dbusgrp" /var/run/dbus
        exec dbus-daemon --system --fork - root

[mediocregopher]

Update: I fixed this in chroagh (the archlinux fork of crouton which barely works) in this commit.

I diagnosed the problem by using strace and saw sudo seemed to be hanging while waiting for some dbus-related behavior. I took out the code where chroagh was starting its own dbus-daemon and instead mounted /var/run/dbus into the chroot, so any dbus needs are handled by the host, and this fixed sudo. I have no idea what other side-effects this might have, but things seem to be going well for me so far.

[ellbur]

I took out the code where chroagh was starting its own dbus-daemon and instead mounted /var/run/dbus into the chroot, so any dbus needs are handled by the host, and this fixed sudo.

This is a very good idea. I have also noted this problem with Ubuntu Eoan, and it seemed to be related to waiting for a reply from DBus with a long timeout. This actually happens if you install with eoan right away with crouton -r eoan; every so often it waits forever for a DBus reply that never comes.

Pointing the chroot to the host DBus seems like a good idea for many reasons so long as it doesn't break anything else, which who knows, it might. For example, the host DBus runs the "system" bus but not the "session" bus, whatever that means.