scripts in /etc/update-motd.d/ run even on login via non-interactive scp and sftp sessions

Hello Thomas,

Thanks for reporting this and making Ubuntu better.

about your statement on lsb-release, in 00-header:

""""
[ -r /etc/lsb-release ] && . /etc/lsb-release

if [ -z "$DISTRIB_DESCRIPTION" ] && [ -x /usr/bin/lsb_release ]; then
        # Fall back to using the very slow lsb_release utility
        DISTRIB_DESCRIPTION=$(lsb_release -s -d)
fi

# cat /etc/lsb-release
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=16.04
DISTRIB_CODENAME=xenial
DISTRIB_DESCRIPTION="Ubuntu 16.04.7 LTS"
""""

the slowpath is only executed if the DISTRIB_DESCRIPTION variable is not set, at least in my tests.

In regards to your statement:

"""
The content of /etc/update-motd.d/* really, really, really shouldn't be executed if the session in question is not interactive, as it provides no value at all. Unfortunately, to disable it for these non-interactive sessions, we also have to disable it for the interactive ones as well where it has some value (though not enough to make spiking the load on this server through the roof an acceptable tradeoff).
"""

Considering there IS a way of disabling the dynamic motd contents currently by commenting only the line containing the /run/motd.dynamic wording:

# Print the message of the day upon successful login.
# This includes a dynamically generated part from /run/motd.dynamic
# and a static (admin-editable) part from /etc/motd.
# session optional pam_motd.so motd=/run/motd.dynamic
session optional pam_motd.so noupdate

I'm flagging this bug as a whishlist priority.

The landscape-sysinfo executions also come from the 50-landscape-sysinfo script. So the root nature of the issue is the same, and I think keeping it under update-motd.d package is better than involving the landscape team for tuning a single script.

As currently we may have many things in front of this particular issue, it is part of a whishlist AND the use case is not something affecting a big number of users for now, I cannot guarantee this will be addressed very soon. Do feel free to suggest a "fix" for this issue, by already having something a code change to commit, and a sponsorship of your change (or not) is likely to happen sooner.

Thanks

-rafaeldtinoco

I found this bug while searching for cases forgotten for too long - sorry to all of you.
And after reading into the case I feel even worse that it was forgotten so long :-/

I know it is just a config file and one could just remove some of the /etc/update-motd.d files to adapt. Also pam config can be changed. All that will stay true, but I think this is worth improving the default experience a bit.

The following is mostly a log of thoughts on the case that I had while re-triaging this:

The net is full of suggestions e.g. https://unix.stackexchange.com/questions/26676/how-to-check-if-a-shell-is-login-interactive-batch
With that:
  [[ $- == *i* ]] && echo 'Interactive' || echo 'Not interactive' >> /tmp/update-motd-test
  shopt -q login_shell && echo 'Login shell' || echo 'Not login shell' >> /tmp/update-motd-test
In a test like:
  ssh testuser1@10.253.194.246 "ls ~/"
It will detect:
  Not interactive
  Not login shell

If not in libpam we could clearly use this in the script snippets to fast-pass most of them.
Sadly above checks seem trivial I've found that they always report non-interactive/non-login even when being such. It seems the way this is executed prevents proper detection.

Slow operations are recommended in motd to use caching and here I think this should be done as well.

Just like other operations using slow calls or network they should cache it and only run every few seconds. That will already cut down any mistaken "run on non-interactive" by an order of magnitude and generally it doesn't matter too much for this output if it is current or 5 seconds old as long as it isn't from yesteryear.

So even if all else fails this should - as a fallback - help a bit right?

I must re-state that agree one might expect (I did) that on non-interactive shells these motd content would not execute at all.
... but it does ... why?

Nowadays this is all from libpam which has pam_mount (man page) and is enabled by default here:

root@j:~# grep -Hrn motd /etc/pam*
/etc/pam.d/login:31:# This includes a dynamically generated part from /run/motd.dynamic
/etc/pam.d/login:32:# and a static (admin-editable) part from /etc/motd.
/etc/pam.d/login:33:session optional pam_motd.so motd=/run/motd.dynamic
/etc/pam.d/login:34:session optional pam_motd.so noupdate
/etc/pam.d/sshd:31:# This includes a dynamically generated part from /run/motd.dynamic
/etc/pam.d/sshd:32:# and a static (admin-editable) part from /etc/motd.
/etc/pam.d/sshd:33:session optional pam_motd.so motd=/run/motd.dynamic
/etc/pam.d/sshd:34:session optional pam_motd.so noupdate

Ok on a login shell (/etc/pam.d/login) it makes sense, but on ssh I'd expect (just like the reporter) to be only shown if interactive.

At least that is a great place to disable this manually if needed,
but sadly disabling this in only /etc/pam.d/sshd also removes it for an ssh-based login shells.
So an ssh based login shell will not be configured by /etc/pam.d/login :-/
Pam is trying to outsmart us ... :-/

After all [1] says "... which is displayed by the pam_motd(8) module on interactive shell logins." which should, but isn't true.

One can debate if it is good or not in the first place to log in for every command as there will be a lot more every time (e.g. audit entries, syslog entries, the env being spawned, ...), overall this is only one of the things that makes this conceptually wrong.

But still I find it embarrassing to see this trivial test to be so bad:

$ time for i in $(seq 1 100); do ssh -i /tmp/id-rsa-test testuser1@10.253.194.246 "ls ~"; done

- With pam_motd.so enabled in /etc/pam.d/sshd => 0m59,709s
- With pam_motd.so disabled in /etc/pam.d/sshd => 16,159s

On any cloud or hipervisor that scales a lot not only the expired time but also the cycles will add up to quite a lot. So either way it comes to slowdown as well as unnecessary price or power consumption

I'm tempted to suggest a discussion to disable it in /etc/pam.d/sshd unless we find a way to make it only happen on interactive logins.

P.S. I have the feeling we had this discussion, maybe others will remember better - I need to talk to a few people ...

[1]: http://manpages.ubuntu.com/manpages/bionic/man5/update-motd.5.html

BTW I also wanted to confirm that this runs (as reported) on any sftp connect and therefore (imagine serving a bunch of small files fetched every now and then) adding overhead there as well.

There are tasks for /etc/pam.d/common-session-noninteractive but those have no detection logic.
They are just included from several non-intactive pam types: samba, sudo, polkit, cron.

The upstream feature is static:
https://github.com/allisonkarlitskaya/linux-pam/commit/acd50bf7b6dd78e3185a57368f8568fb7be11d39

While "only static" it can't be disabled either.
Yet without anything to display it to it renders as mostly a no-op.

The dynamic parts are Ubuntu delta due to bug 399071.
And updated since a long while to do the very same.

Due to this overall situation upstream has no interest/need to fix something, this is IMHO on Ubuntu.

The only current interactivity detection code in pam is part of a pam.conf -> pam.d conversion tool that won't be useful here.

The pam_motd code emits content via things like try_to_display_fd.
A message is created and then printed via pam_info.
Which is actually pam_prompt which wraps pam_vprompt

This gets the conversation function via
  retval = pam_get_item (pamh, PAM_CONV, &convp);
and on that it then emits the message
  retval = conv->conv (1, &pmsg, &pam_resp, conv->appdata_ptr);

Either via this PAM_CONV and then attributes of that channel (as it is what we'd print on) OR via something like pam_get_item(pamh, PAM_TTY, &tty); we might get access from pam_motd to something that we can work out if it is interactive.

I'm busy with other things now (for the rest of today), but I want ton continue tomorrow.
I want this at least to get into a clear state that is sure if:
a) this is as important as I think
b) the steps needed from here are clear

I wanted to get a better feeling about this before jumping to action.
Therefore I have created three 1G/1vcpu KVM guests Bionic/Focal/Jammy to test and compare this on.

I do not need hot-loop analysis or anything down to instructions, so no debug symbols needed.
For now I only want to know:
1. how much time a bunch of low effort logins take (we measure only the overhead)
2. how much cpu is utilized while doing that
3. how that work is spread across programs (disable them one by one and look at data)

The two I see most are:
- /usr/lib/update-notifier/update-motd-hwe-eol
    apt-config shell SourceList Dir::Etc::sourcelist
- /etc/update-motd.d/50-landscape-sysinfo
    /usr/bin/python3 /usr/bin/landscape-sysinfo

Very non-pro data gathering:

$ cat tracestart.sh
#!/bin/bash
sudo rm perf.data perf.log log.vmstat
nohup vmstat -wt 5 &> log.vmstat &
nohup perf record --event cpu-clock --all-cpus &> perf.log &
sleep 5

$ cat traceend.sh
#!/bin/bash
killall perf
killall vmstat
cat perf.log
cat log.vmstat
#perf report --sort comm --stdio

Most simple load involving those helpers.
for sys in login-bionic login-focal login-jammy; do ssh $sys "sudo ~/tracestart.sh"; time for i in $(seq 1 100); do ssh $sys "/bin/true"; done; ssh $sys "sudo ~/traceend.sh"; done

I'll get those numbers for Bionic/Focal/Jammy and enabling/disabling it all and/or individual elements.

Time and CPU consumption (results are rather consistent BTW):

Bionic
real 1m11.714s

us sy id wa st UTC
68 19 13 0 0 2022-03-29 13:13:25
67 19 14 0 0 2022-03-29 13:13:30
68 17 14 0 0 2022-03-29 13:13:35

    59.56% landscape-sysin
    16.38% swapper
     7.35% lsb_release
     3.77% sshd
     3.22% apt-config
     1.20% dpkg
     0.56% dbus-daemon
     0.52% systemd

Focal
real 0m44.742s

us sy id wa st UTC
67 24 8 0 0 2022-03-29 13:14:13
65 25 10 0 0 2022-03-29 13:14:18
67 24 9 0 0 2022-03-29 13:14:23

    23.12% landscape-sysin
    17.36% swapper
    13.38% systemd-udevd
    10.91% lsb_release
     7.64% sshd
     5.37% apt-config
     1.97% dpkg
     1.73% snapd
     1.54% dbus-daemon
     1.23% systemd
     0.95% systemd-detect-
     0.93% systemd-logind
     0.92% gdbus
     0.73% update-motd-hwe
     0.69% run-parts
     0.65% grep
     0.61% systemd-journal
     0.58% bash
     0.54% find
     0.52% id

Jammy
real 1m8.010s

us sy id wa st UTC
68 20 11 0 0 2022-03-29 13:15:20
68 20 11 0 0 2022-03-29 13:15:25
67 22 12 0 0 2022-03-29 13:15:30

    58.52% landscape-sysin
    14.82% swapper
     6.28% sshd
     5.72% lsb_release
     3.32% apt-config
     0.91% dbus-daemon
     0.81% systemd
     0.62% gdbus
     0.54% dpkg

So in terms of latency/delay
- Bionic->Focal improved here
- Focal->Jammy degraded as much as we gained before

In terms of cpu cycles spent things are pretty similar per time, but that means it increased linearly with the delay which means we are slower AND consume more cpu cycles.

The programs listed with the highest consumption we see match the assumption of landscape-sysinfo and the update-motd-hwe-eol (which does the apt-config call) are the top scorer. This is based on the perf data across the full runtime which is usually pretty reliable.

pam_motd completely disabled in /etc/pam.d/sshd

Bionic
real 0m15.540s
us sy id wa st
18 14 68 0 0

Focal
real 0m16.937s
us sy id wa st
43 40 17 0 0

Jammy
real 0m16.260s
us sy id wa st
36 19 45 0 0

The remaining difference of those is in the noise-range.
Some difference in the cycles consumed though, but not too bad.

pam_motd enabled, but 50-landscape-sysinfo and 95-hwe-eol disabled

Bionic
real 0m25.952s
us sy id wa st
41 22 37 0 0

Focal
real 0m30.592s
us sy id wa st
49 33 19 0 0

Jammy
real 0m25.395s
us sy id wa st
44 28 29 0 0

That is still quite some overhead (~+60% to no motd) but clearly those are the two worst contributors.

Analysis has spotted 91-release-upgrade as the most likely expensive remainder.
pam_motd enabled, but disabled:
- 50-landscape-sysinfo
- 91-release-upgrade
- 95-hwe-eol disabled

Bionic
real 0m18.669s
us sy id wa st
22 23 55 0 0

Focal
real 0m23.821s
us sy id wa st
40 39 21 0 0

Jammy
real 0m19.616s
us sy id wa st
33 30 37 0 0

This is pretty close to "no-motd" and has no single spike left.
The next ones I found in the list are now low and already use caching.
The improvement for those would be a (slower and more complex) modification to pam_motd to detect and skip on non-interactive sessions.

Summarizing the low hanging fruits here:
- Add caching to 50-landscape-sysinfo
- Add caching to 95-hwe-eol
- /usr/lib/update-notifier/update-motd-hwe-eol calls apt-config multiple times.
  consider reducing those calls
- 91-release-upgrade unconditionally calls lsb_release which is expensive.
  Use the same check others use

The rest already uses caching AND/OR is small, fast and simple.

The follow on of making pam_motd truly not do anything on non-interactive can then be a follow on case and would no more be that important.

For these fixes three packages need to be touched:
Source: ubuntu-release-upgrader
Source: update-notifier
Source: landscape-client

Collecting snippets:

This one worked, proven by eliminating lsb_release on the consumption charts.

#1 Caching for 91-release-upgrade:

--- orig/91-release-upgrade 2022-03-30 07:53:26.560515795 +0000
+++ /etc/update-motd.d/91-release-upgrade 2022-03-30 07:59:05.819971148 +0000
@@ -1,7 +1,12 @@
 #!/bin/sh

 # if the current release is under development there won't be a new one
-if [ "$(lsb_release -sd | cut -d' ' -f4)" = "(development" ]; then
+[ -r /etc/lsb-release ] && . /etc/lsb-release
+if [ -z "$DISTRIB_DESCRIPTION" ] && [ -x /usr/bin/lsb_release ]; then
+ DISTRIB_DESCRIPTION=$(lsb_release -s -d)
+fi
+
+if [ "$(echo "$DISTRIB_DESCRIPTION" | cut -d' ' -f4)" = "(development" ]; then
     exit 0
 fi

#2 95-hwe-eol / update-motd-hwe-eol

Sadly this already does some caching in update-motd-hwe-eol by checking if the last of these checks is older than an update to the source lists. But to do so it has already executed the - relatively - rather expensive apt-config calls.

Since it comes down to checking new sources.lists there is no need to update this more often than once every few minutes or hours. Could be even slower without loosing most of its value, but we already achieve most of what we need with a delay of ~1h.

We started with:
     5.37% apt-config
Now:
     -- no more present

--- orig/95-hwe-eol 2022-03-30 07:53:18.396529018 +0000
+++ /etc/update-motd.d/95-hwe-eol 2022-03-30 09:13:16.160985148 +0000
@@ -1,5 +1,11 @@
 #!/bin/sh

+# this stamp is created and updated by /usr/lib/update-notifier/update-motd-hwe-eol
+stamp="/var/lib/update-notifier/hwe-eol"
+
+# do not try to refresh this more than once per hour
+find $stamp -newermt 'now-1 hours' 2> /dev/null | grep -m 1 '.' && exit 0
+
 if [ -x /usr/lib/update-notifier/update-motd-hwe-eol ]; then
     exec /usr/lib/update-notifier/update-motd-hwe-eol
 fi

No big need left to reduce the apt-config usage in update-motd-hwe-eol after this change.

#3 50-landscape-sysinfo

The landscape part already has a statement about "when it is from" as it is not re-executed on high load. This is handy as it will also ensure there is no confusion "from when" this info is if we skip for too frequent invocations.

Since it has an alternate less useful output I've added checks to replace this more often and not replace a good output with a bad one.

--- orig/50-landscape-sysinfo 2022-03-30 07:53:04.320551811 +0000
+++ /etc/update-motd.d/50-landscape-sysinfo 2022-03-30 10:04:00.536053398 +0000
@@ -1,17 +1,39 @@
 #!/bin/sh
-# pam_motd does not carry the environment
-[ -f /etc/default/locale ] && . /etc/default/locale
-export LANG
-cores=$(grep -c ^processor /proc/cpuinfo 2>/dev/null)
-[ "$cores" -eq "0" ] && cores=1
-threshold="${cores:-1}.0"
-if [ $(echo "`cut -f1 -d ' ' /proc/loadavg` < $threshold" | bc) -eq 1 ]; then
- echo
- echo -n " System information as of "
- /bin/date
- echo
- /usr/bin/landscape-sysinfo
-else
- echo
- echo " System information disabled due to load higher than $threshold"
+
+# do try refresh this more than once per minute
+# Due to cpu consumption and login delays (LP: #1893716)
+stamp="/var/lib/landscape/landscape-sysinfo.cache"
+NEED_UPDATE="FALSE"
+find $stamp -newermt 'now-1 minutes' 2> /dev/null | grep -q -m 1 '.' || NEED_UPDATE="TRUE"
+# If the last report in cache wasn't useful (load was too high) still wait at least 5 seconds
+if grep -q "System information disabled" $stamp 2> /dev/null; then
+ find $stamp -newermt 'now-5 seconds' 2> /dev/null | grep -q -m 1 '.' || NEED_UPDATE="TRUE"
 fi
+
+if [ "$NEED_UPDATE" = "TRUE" ]; then
+ # pam_motd does not carry the environment
+ [ -f /etc/default/locale ] && . /etc/default/locale
+ export LANG
+ cores=$(grep -c ^processor /proc/cpuinfo 2>/dev/null)
+ [ "$cores" -eq "0" ] && cores=1
+ threshold="${cores:-1}.0"
+ if [ $(echo "`cut -f1 -d ' ' /proc/loadavg` < $threshold" | bc) -eq 1 ]; then
+ (
+ echo
+ echo -n " System information as of "
+ /bin/date
+ echo
+ /usr/bin/landscape-sysinfo
+ ) > $stamp
+ else
+ # do not replace a formerly good result due to load
+ if ! grep -q "System information as of" $stamp 2> /dev/null; then
+ (
+ echo
+ echo " System information disabled due to load higher than $threshold"
+ ) > $stamp
+ fi
+ fi
+fi
+
+[ ! -r "$stamp" ] || cat "$stamp"

# Info:
It might be worth to note, the optimizations to 95-hwe-eol and 91-release-upgrade save CPU cycles (which is good and worth on its own), but do not improve the delay much.
The optimization to

P.S. I'll need some minor updates for style and avoiding errors (e.g. the && exit 0 was working but could be bad)

With the three combined I get down to:

real 0m20.900s
us sy id wa st
32 33 35 0 0

    43.88% swapper
    21.48% sshd
     3.07% dbus-daemon
     2.78% systemd
     2.10% gdbus
     1.96% grep
     1.80% run-parts
     1.68% systemd-logind
     1.38% find
     1.24% systemd-journal
     1.23% bash
     1.12% update-motd-fsc
     1.10% cat
     0.95% awk
     0.85% 50-motd-news
     0.76% uname
     0.70% 00-header
     0.69% 91-release-upgr
     0.67% 97-overlayroot
     0.67% 50-landscape-sy
     0.62% date
     0.61% 90-updates-avai
     0.56% 95-hwe-eol
     0.54% cut

None of the remaining big contributions to consumption is from the MOTD efforts (all <2%).

That is reasonable, nice time gain as well as reduced cpu consumption.

I re-installed the former package content, rebooted the system and gave it some more memory to get rid of any concerns in that regard (from the perf data).

The diff of the actual content before/after was all reasonable (new times, different package counts, but otherwise the same)

Consumption wise we have:

# Before fixes
real 1m11.731s
us sy id wa st
71 20 9 0 0

    59.16% landscape-sysin
    14.23% swapper
     6.16% sshd
     5.78% lsb_release
     3.35% apt-config
     0.86% dbus-daemon
     0.80% systemd
     0.59% gdbus
     0.56% dpkg
     0.48% systemd-logind

# After fixes

real 0m21.257s
us sy id wa st
32 34 34 0 0

    42.00% swapper
    22.45% sshd
     2.94% dbus-daemon
     2.79% systemd
     2.08% gdbus
     2.07% grep
     1.88% run-parts
     1.58% systemd-logind
     1.46% find
     1.23% bash
     1.22% update-motd-fsc
     1.18% systemd-journal
     1.13% cat

That is good.
Ready to open MRs for this.

At a very high summary:
- delay cut down by 2/3 of the initial duration
- consumption reduced by 71% (duration) and by 26% (consumption while running).
  This is multiplicative so for the example we have an saving of ~81.27% of cpu cycles

This bug was fixed in the package ubuntu-release-upgrader - 1:22.04.8

---------------
ubuntu-release-upgrader (1:22.04.8) jammy; urgency=medium

  [ Brian Murray ]
  * Update the firefox deb2snap entry so that it includes Ubuntu Studio.
  * Modify the ubuntu-release-upgrader apport package hook to also gather
    recent messages in journalctl and a list of crashes in /var/crash as one
    of those may have negatively affected the upgrade process.

  [ Christian Ehrhardt ]
  * d/91-release-upgrade: try to use the less expensive /etc/lsb-release
    to check if we are in a devel release (LP: #1893716)

 -- Brian Murray <email address hidden> Thu, 31 Mar 2022 14:23:13 -0700

This bug was fixed in the package landscape-client - 19.12-0ubuntu13

---------------
landscape-client (19.12-0ubuntu13) jammy; urgency=medium

  * d/landscape-sysinfo.wrapper, d/landscape-common.postrm: avoid too
    frequent expensive operations (LP: #1893716)
    - use a cache file and refresh it only once per minute
    - use a single printf to format output
    - if the former info was useful and we'd replace it with "sorry, load to
      high" skip that update
    - remove the cache file on purge

 -- Christian Ehrhardt <email address hidden> Wed, 30 Mar 2022 12:32:38 +0200

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

---------------
update-notifier (3.192.54) jammy; urgency=medium

  * d/95-hwe-eol: do not update eol data more than once per day (LP: #1893716)

 -- Christian Ehrhardt <email address hidden> Wed, 30 Mar 2022 12:20:47 +0200

Overall the majority of this is now fixed and mitigated with the combination of:
 ubuntu-release-upgrader | 1:22.04.8 | jammy | source
 landscape-client | 19.12-0ubuntu13 | jammy | source, amd64, arm64, armhf, ppc64el, riscv64, s390x
 update-notifier | 3.192.54 | jammy | source, amd64, arm64, armhf, ppc64el, riscv64, s390x

There is still the IMHO valid feature request to pam_motd to not run at all in non-interactive sessions which I'll need to file upstream.

But already in a system with these updates:
ubuntu@login-jammy:~$ dpkg -l ubuntu-release-upgrader-core landscape-common update-notifier-common
Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend
|/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
||/ Name Version Architecture Description
+++-============================-===============-============-=======================================================
ii landscape-common 19.12-0ubuntu13 amd64 Landscape administration system client - Common files
ii ubuntu-release-upgrader-core 1:22.04.8 all manage release upgrades
ii update-notifier-common 3.192.54 all Files shared between update-notifier and other packages

I now get reasonable results.
Down from 70-80 seconds to ~20-25 => almost down to 1/4 of the time.
At the same time the system is ~16% less busy, so other things running won't stall it that much either and vice versa.

What is left looks as in the test sessions.
This now mostly comes down to the fact that logging in for every command will in general have overhead to spawn the session. For another gain pam_motd can be disabled as shown above, but that does not reduce it to zero overhead - so as explained any mutli-command submitting solution should still - even with the fix - try to use one login for all of them.

# Overhead Command
# ........ ...............
#
    32.50% swapper
    26.67% sshd
     3.53% dbus-daemon
     3.37% systemd
     2.36% run-parts
     2.02% systemd-logind
     1.87% find
     1.85% gdbus
     1.48% cat
     1.47% update-motd-fsc
     1.22% 50-motd-news
     1.17% awk
     1.15% systemd-journal
     1.11% grep
     1.10% bash
     1.05% uname
     0.98% 00-header
     0.93% 91-release-upgr
     0.92% 97-overlayroot
     0.81% 90-updates-avai
     0.80% date
     0.72% cut
     0.68% 50-landscape-sy
     0.62% env
     0.59% ksoftirqd/0
     0.58% 95-hwe-eol
     0.53% stat
     0.51% id

FYI: Filed upstream at https://github.com/linux-pam/linux-pam/issues/452