The 12-Second Login: How a Backup File Slowed My Matrix Banner

I built a Matrix-themed login banner for no better reason than that I wanted one. Green text, a white rabbit in ASCII, a typewriter greeting, a status panel. It lives in a public repo (MichealGarner/matrix-banner) and I put it on a Raspberry Pi 3 last week.

It looked exactly as intended. It also made me wait. Between the first thing appearing on screen and the animation starting there was a pause long enough to make me wonder whether SSH had stalled. I didn’t mind the animation’s own sleep calls, since those are the point. It was the dead gap before it that bothered me.

This post is about finding that gap. The banner is the excuse; the useful part is how Debian builds a login, and what you can do when you can’t tell which part of it is slow.

What actually runs when you log in

I’d written the banner as three separate pieces without thinking much about how they fit together. On Debian they run at three different points:

1. Pre-authentication banner. sshd sends the contents of /etc/ssh/banner.txt before you’ve authenticated, via the Banner directive. This is the legal notice.
2. The MOTD. After you authenticate, PAM’s pam_motd module runs every executable in /etc/update-motd.d/ and prints whatever they output. My dynamic MOTD, 10-matrix-motd, lives here and shows hostname, load, disk and pending updates.
3. The login shell. Once the shell starts, it sources /etc/profile.d/*.sh. My animated banner, 00-matrix-banner.sh, lives here.

So an interactive SSH login goes: legal notice, authenticate, MOTD, animation. The delay I was seeing sat between the MOTD and the animation, which is the gap between steps 2 and 3. Nothing in my animation script was obviously slow, so the question was what ran in between.

Measuring instead of guessing

My first instinct was to time the banner script on its own. That told me very little, because the script wasn’t the slow part. (A tip if you try this: run sudo -v first. My first time included typing my sudo password, which made everything look slower than it was.)

What worked was putting timestamped markers into the login path and reading them back. I added logger calls to the banner script at the points I suspected:

logger -t mb "banner start"
# ... existing script ...
logger -t mb "before clear"

Then I logged in, and pulled the markers out of the journal with microsecond timestamps:

sudo journalctl -o short-precise --since "5 minutes ago" | grep 'mb\['

One detail cost me a few minutes. logger -t mb records the tag as mb[pid]:, not mb:, so a grep for ' mb:' matches nothing. Escape the bracket and it works.

The markers showed that my script started promptly. The time was being lost before it ever ran, so the slow part was upstream of my animation entirely.

Watching every process the login starts

To see what ran in that window I attached strace to the SSH daemon and followed its children, logging only execve calls with timestamps:

sudo strace -f -tt -e trace=execve -o /tmp/login.trace -p "$(pgrep -o -x sshd)"

Then I logged in from a second terminal and read the trace. Two things stood out: a large number of apt-get invocations, and a clear gap of roughly 12 seconds between the PAM session opening and my shell starting. The apt-get calls came from the MOTD script, which was checking for pending updates at every login.

That explained a lot. On a Raspberry Pi 3 with an SD card, apt-get --just-print upgrade takes about six seconds. My MOTD ran it every single login. Six seconds is annoying. Twelve is what I was actually seeing, so something was running it twice.

The cause: a backup that was also a MOTD

run-parts, which pam_motd uses, doesn’t care about intent. It runs every executable file in the directory. You can ask it what it would run without running anything:

sudo run-parts --test /etc/update-motd.d

It listed two entries where there should have been one: the real 10-matrix-motd, and a backup of it. I’d copied the script aside with cp -a before editing it. That preserves permissions, including the execute bit, and I’d left the copy in the same directory. So on every login, PAM ran my MOTD, then ran the backup of my MOTD, and each one spent about six seconds asking apt what was waiting to be upgraded.

I moved the backup out of the directory and the gap disappeared. The login went from slow to fast in one mv.

The lesson is general, and I’d have missed it without the trace: a .d directory runs everything in it. Anything that is executable and lives there is part of the login, whatever its name says. Backups don’t belong in the directory they back up. If you want to disable a script in one of these directories, chmod -x it rather than renaming it to .bak.

My installer had the same flaw in its backup step, so that’s fixed in the repo as well. It now backs files up to /var/backups/matrix-banner/ with the execute bit stripped, and it clears out stale backups it finds in /etc/update-motd.d/.

Fixing the underlying slowness

Removing the duplicate halved the delay, but it left the real problem in place: the MOTD was still running a slow apt simulation on every login. That doesn’t belong in the login path at all.

The fix is to compute the update counts when they change, not when someone logs in. A small helper script writes the counts to a cache file, and apt runs it automatically after anything that could change them:

# /etc/apt/apt.conf.d/99matrix-banner
DPkg::Post-Invoke { "/usr/local/sbin/matrix-update-cache || true"; };
APT::Update::Post-Invoke-Success { "/usr/local/sbin/matrix-update-cache || true"; };

The helper, /usr/local/sbin/matrix-update-cache, does the slow work once and writes <total> <security> to /var/cache/matrix-banner-updates. It writes to a temporary file and moves it into place, so a login can never read a half-written file. The MOTD then just reads that file:

UPDATES=0; SEC_UPDATES=0
if [ -r /var/cache/matrix-banner-updates ]; then
    read -r UPDATES SEC_UPDATES < /var/cache/matrix-banner-updates || true
fi
[[ "$UPDATES" =~ ^[0-9]+$ ]] || UPDATES=0

Reading a one-line file takes effectively no time. The counts can be slightly stale between apt runs, but for a number on a login banner that’s a fair trade.

An unexpected side effect

With the delay gone, I had the opposite problem. The MOTD now flashed past so quickly that I could hardly read it before the animation cleared the screen. For about twelve seconds I’d had plenty of time to read it. That wasn’t a feature.

It also made something else obvious. On an interactive login, the MOTD and the animated banner show much the same information. You see the hostname, the panel and the warning twice, once in the MOTD and then again after the screen clears. Since the animation is the one I actually care about, I added an installer option to skip the MOTD entirely:

sudo bash install.sh --no-motd

That installs the animated banner and the pre-auth notice, skips the MOTD and the update cache, and disables an existing 10-matrix-motd if there is one. Running the installer again without the flag turns the MOTD back on. If you want to keep the MOTD but make it readable, adding sleep 1.5 on the line before clear in 00-matrix-banner.sh gives you a moment to look at it.

One thing to be aware of if you go the --no-motd route: the pre-auth SSH banner then becomes the only legal notice on SSH logins, because the warning box inside my animation is commented out in my version of the script. You can uncomment it if you want it back.

The same problem on a server, and a banner that picked the wrong IP

Once the Pi was sorted I put the banner on Herald, the Debian server that hosts this site and doubles as my NTP server. It had the same pause. The cause was simpler this time: there was no stray backup, just the MOTD running apt-get on every login. Timing the MOTD directly showed it:

time sudo run-parts /etc/update-motd.d

That took 8.65 seconds. After installing with --no-motd and the update cache, the same check took 0.055 seconds. Different cause from the Pi, same shape of problem: slow work sitting in the login path.

Herald also exposed a flaw in the banner itself. The status panel showed 10.10.0.2, which is my Fortinet lab interface, rather than the address I actually SSH to. The script took the first address from hostname -I, and that command lists addresses in the kernel’s interface order, so on a machine with several interfaces “first” is arbitrary. A server with a lab network, a management network and a couple of spare ports is exactly where that goes wrong.

The banner now lists every global IPv4 address on interfaces that are up, one row per interface, using:

ip -o -4 addr show scope global up | awk '{print $2, $4}'

On Herald the panel now reads:

  │  IP Address:        10.10.0.2/24 (enp1s0)                   │
  │                     192.168.11.20/24 (ens1)                 │

Loopback, link-local, IPv6 and interfaces that are down are left out. Docker, bridge, veth, libvirt and Kubernetes CNI interfaces are skipped as well, since on a container host they would bury the real addresses. The list is capped at six rows with a (+N more) line after that, and it shows none if there is nothing to display. The skipped interface names and the row limit are easy to change near the top of the script, and the README covers both.

What I took from it

• Measure before you guess. logger markers plus journalctl -o short-precise will tell you where the time goes in a login. strace -f -tt -e trace=execve will tell you what ran.
• .d directories run everything. Check with run-parts --test before assuming a directory contains what you think it does.
• Move slow work out of the login path. If something takes seconds on weak hardware, do it when the data changes and cache the answer.
• Don’t back up into the directory you’re backing up. Or at least strip the execute bit.
• Test on more than one machine. The banner worked perfectly on a Pi with one network interface. A server with four showed up a flaw I would never have seen otherwise.

The banner is still a silly thing to have on a Pi, but now it appears when I log in rather than a while after.

The code, including the installer, the --no-motd option and the per-interface IP rows, is in the matrix-banner repo. The values in the animation above (IP address, kernel version and memory figures) are examples, not from a real host.