apt-check hangs, preventing login via SSH

[Martin-Éric Racine]

Binary package hint: update-notifier

While investigating protracted hangs in the remote login process, I noticed that apt-check is called to update the list of available updates and print the number of updatable packages in the MOTD. As it so happens, apt-check often hangs in mid-update, which effectively prevents remote login via SSH from taking place.

Related bugs:
 * bug 525674: apt-check hangs, preventing login via SSH
 * bug 1527710: apt-get update triggers asynchronous task
 * bug 1533243: preseeded installation fails on critical question: partman/unmount_active DISKS /dev/vda

ProblemType: Bug
Architecture: i386
Date: Mon Feb 22 12:20:16 2010
DistroRelease: Ubuntu 10.04
Package: update-notifier-common 0.96
PackageArchitecture: all
ProcEnviron:
 LANGUAGE=fi_FI.UTF-8
 PATH=(custom, user)
 LANG=fi_FI.UTF-8
 SHELL=/bin/bash
ProcVersionSignature: Ubuntu 2.6.32-14.20-generic
SourcePackage: update-notifier
Uname: Linux 2.6.32-14-generic i686

[Martin-Éric Racine (q-funk)]

Subscribed Ubuntu Server Team as this is an issue that prevents remote servicing of Lucid hosts.

[Scott Moser (smoser)]

I was about to file this bug, so I'll confirm it. I have not seen the apt-check hang entirely, but it is very slow to run, and blocks initial.

Note, you may have seen what appeared to be a hang due to the very bad performance of security.ubuntu.com in the past few days. That performance was due to it being slammed by openoffice.org security update.

This is quite an annoyance on a newly booted ec2 instance.

[Dan Muresan (danmbox)]

What connects loging in to running update-notifier? I'd like to disable that (especially for SSH logins) without removing update-notifier completely.

[Dan Muresan (danmbox)]

To answer self, there are pam_motd references in /etc/pam.d/{login,ssh} (!). 'Cause hey, you never know when you need that important ssh session or CONSOLE login delayed for a while...

And since the very same friendly developers will be in charge of the next release (and the next one after that), there's no telling how many more pleasant surprises like this one we will have the next time we upgrade. Of course they never tell you how to disable these "surprises" in the RELEASE NOTES -- that would spoil the fun. They like you spending time treasure-hunting the goodies they hide in various dark corners of the distro.

[RichardNeill (ubuntu-richardneill)]

This is really painful - although I don't experience complete hangs, I do experience 12-second+ delays while
the script "90-updates-available" grinds slowly though. So login via SSH is unpleasantly slow. Furthermore, bash completion for tab completion on scp commands is also very slow.

The workaround is: chmod -x /etc/update-motd.d/*

However, it seems to me that this should be a cron-job which runs once an hour (and @reboot). There's no need for it to happen at the precise moment where I log in.

[RichardNeill (ubuntu-richardneill)]

(P.S. Even worse is connecting via a stack of SSH tunnels, eg behind a firewall. It takes almost 30 seconds to get a prompt, and ssh -vvv doesn't help identify the issue).

[RichardNeill (ubuntu-richardneill)]

Interestingly, 14.04 seems to be much better at this than 12.04, takling around 1.5 sec rather than 12.
However, it's interesting how much faster it can still be without this.

Here is a measurement I made. This is 14.04 server on the LAN, with ssh-key authentication, and I repeated serveral times:
   time ssh server_on_lan true

With the /etc/update-motd.d/* files unaltered, this takes ~ 1.13 sec
After chmod -x, this takes ~ 0.15 sec.

I hope that helps,

[ChristianEhrhardt (paelzer)]

Other MOTD plugins use caching, for example /usr/lib/update-notifier/update-motd-reboot-required does:
if [ -f /var/run/reboot-required ]; then
        cat /var/run/reboot-required
fi

Actually /usr/lib/update-notifier/update-motd-updates-available already uses "caching" like the others.
It stores its result in:
  /var/lib/update-notifier/updates-available
This is what the call to "/usr/lib/update-notifier/apt-check --human-readable" writes into

But it executes slow commands like find apt-check synchronously.
Yes a cron job might be nice, but it is rather "invasive" in changing the general behaviour maybe more than required.

Why not just executing the "slow parts" like find and apt-check asynchronously.
One can still evolve that approach later on an move (instead or additionally) the async part into a cron job if required.

It comes at "the risk" of having one outdated info on login.
But since updates don't change every second anyway it is probably better than waiting on each login.
Especially with all the examples made like scp tabbing, slow network and so on.

The atomicity issue with updating the temporary file already exists in todays code with regards to concurrent logins. But we can improve that as well by using a temporary file and mv.

The following are suggestions to fix it in trusty, vivid, wily and upstream.

[Ubuntu Foundations Team Bug Bot (crichton)]

The attachment "Fix for trusty" seems to be a debdiff. The ubuntu-sponsors team has been subscribed to the bug report so that they can review and hopefully sponsor the debdiff. If the attachment isn't a patch, please remove the "patch" flag from the attachment, remove the "patch" tag, and if you are member of the ~ubuntu-sponsors, unsubscribe the team.

[This is an automated message performed by a Launchpad user owned by ~brian-murray, for any issue please contact him.]

[ChristianEhrhardt (paelzer)]

FYI - After a discussion I'll likely revamp the patches for wily and upstream the next days.
Until then we will also decide if this is worth SRUs for trusty/vivid.

[ChristianEhrhardt (paelzer)]

Here the bigger, but more architecturally complete solution for wily&upstream (which is actually identical at this time).

Summary:
- move the actual updating part out of the pam based trigger completely (avoids slowdown)
- pam based motd now only prints the cached info (if existing)
- hook into apt with APT::Update::Post-Invoke-Success to update the cached file (thanks mvo and pitti for that good IRC discussion)
- removed one level of indirection (apt hook -> stamp file -> on pam login check stamp -> update) to the more separate
  (apt hook -> update cached info) (on pam login -> print cached info)
- while the chance of a concurrent update is now (almost) impossible it keeps the atomic cache update and cleanup to be sure

It was working find in all my builds and tests on wily.
Attaching for review ...

[Martin Pitt (pitti)]

Thanks Christian! Some remarks:

 - The introduction of data/get-motd-updates-available seems like an unnecessary indirection to me. Instead of checking the executability of that and run it, debian/90-updates-available could just directly do

  cat /var/lib/update-notifier/updates-available 2>/dev/null || true

or

  [ ! -r /var/lib/update-notifier/updates-available ] || cat /var/lib/update-notifier/updates-available

if you prefer that. This would be simpler IMHO.

 - changelog should point out that data/update-motd-updates-available now runs in the background, to avoid blocking "apt-get update" unnecessarily long.

These are just nitpicks, this looks fine by and large. Thanks for working on this!

[Michael Vogt (mvo)]

Thanks for working on this! Diff looks good (pitti pointed some minor things out already).

One more thing, please keep the part:
  "DPkg::Post-Invoke {"if [ -d /var/lib/update-notifier ]; then touch /var/lib/update-notifier/dpkg-run-stamp; fi; "
the part of update-notifier that displays a icon (used in xfce iirc) will depend on this file, it uses inotify to know reliable when apt was finished.

[Scott Moser (smoser)]

hey. saw this in my inbox, and very happy! thank you for working on this.

one note, in update-notifier-3.164/data/update-motd-updates-available

+ trap cleanup EXIT
+ tmpfile=$(mktemp)

if tmpfile was set in the environment prior to this program running, and you exited for some reason between those two, then you'd rm the previously set 'tmpfile'.

the easy fix is to just declare 'tmpfile=' before trapping cleanup.

[ChristianEhrhardt (paelzer)]

Martin:
- I already removed one indirection with my former patch and love to remove one more.
  Simple code = good code - thanks for the good hint.
- I changed it slightly to use the existing variable so people recognize from which code
  it came and to avoid issues if one ever changes only one occurrence of that file name.
- changelog now contains the original intention (no stall to logins) and the avoidance of
  stalling apt-get update along with all other minor fixes that came up along the way

Michael:
- Good catch, I didn't realize that this were two totally independent pieces.

Scott:
- Another good catch, of a potentially rare but nasty to track down issue

Overall I want to thank all reviewers a lot - I highly appreciate this real community feeling.
The patch got way better and smaller at once.
Thank You!

[Scott Moser (smoser)]

looks good to me.

[Martin Pitt (pitti)]

Thank you! Uploaded.

[Launchpad Janitor (janitor)]

This bug was fixed in the package update-notifier - 3.164

---------------
update-notifier (3.164) xenial; urgency=medium

  * debian/90-updates-available
    - Now directly prints the cached info if available
      => avoid login stalls due to motd updates (LP: #525674)
    - Also fixes a former potential issue of existing but not readable cached
      info by changing the test from -e to -r
  * debian/99update-notifier:
    - Now additionally triggers the an asynchronous background update of the
      cached info via update-motd-updates-available hooking into
      APT::Update::Post-Invoke-Success.
  * data/update-motd-updates-available:
    - This now only contains the slow part of actually 'updating the cached
      info'.
    - It executes asynchronously to avoid stalling apt-get update.
    - The file is no more called by pam to avoid login stalls.
    - It also fixes an issue with concurrent updates clobbering the
      cached file via mv being atomic

 -- Christian Ehrhardt <email address hidden> Fri, 13 Nov 2015 12:28:25 +0100