manager: print status text of the service when waiting for a job

This does two semi-independent but interleaved things: firstly, the manager now
prints the status text (if available) of a service when we have a job running
for that service and it is slow. Because it's hard to fit enough info on the
line, we only do this if the output mode uses unit names. The format of the
line "… job is running for …" is changed to be shorter. This way we can
somewhat reasonably fit two status messages on one line.

Secondly, the manager now sends more information using sd_notify. This mostly
matters for in case of the user manager. In particular, we notify when starting
one of the special units. Without this, when the system manager would display a
line about waiting for the user manager, it would show status like "Ready.",
which is confusing. Now it'll either show something like "Started special unit
shutdown.target", or the line about waiting for a user job.

Also, the timeouts for the user manager are lowered: the user manager usually
(always?) has status disabled, so we would wait for 25 seconds before showing
job progress. Normally we don't expect to have any jobs that take more than a
second. So let's start the progress output fairly quickly, like we would if
status showing was enabled. This obviously makes the output in the system
manager about the user manager more useful. The timeouts are "desynchronized"
by a fraction so if there are multiple jobs running, we'll cycle through
showing all combinations.

Example output:

         Stopping user@1000.service...
[  OK  ] Stopped dracut-shutdown.service.
[  OK  ] Stopped systemd-logind.service.
[  OK  ] Stopped systemd-logind.service - User Login Management.
[*     ] Job user@1000.service/stop running (2s / 2min): (1 of 2) User job slowstop.service/stop running (1s / 1min 30s)...
[***   ] Job user@1000.service/stop running (3s / 2min): (2 of 2) User job slowstop2.service/stop running (2s / 1min 30s)...
[   ***] Job user@1000.service/stop running (4s / 2min): (1 of 2) User job slowstop.service/stop running (4s / 1min 30s)...
[     *] Job user@1000.service/stop running (5s / 2min): (1 of 2) User job slowstop.service/stop running (5s / 1min 30s)...
[   ***] Job user@1000.service/stop running (6s / 2min): (2 of 2) User job slowstop2.service/stop running (6s / 1min 30s)...
[***   ] Job user@1000.service/stop running (8s / 2min): (1 of 2) User job slowstop.service/stop running (7s / 1min 30s)...
[***   ] Job user@1000.service/stop running (10s / 2min): (2 of 2) User job slowstop2.service/stop running (9s / 1min 30s)...
[  *** ] Job user@1000.service/stop running (11s / 2min): (1 of 2) User job slowstop.service/stop running (10s / 1min 30s)...
[     *] Job user@1000.service/stop running (12s / 2min): (2 of 2) User job slowstop2.service/stop running (12s / 1min 30s)...
[   ***] Job user@1000.service/stop running (13s / 2min): (1 of 2) User job slowstop.service/stop running (13s / 1min 30s)...
[***   ] Job user@1000.service/stop running (15s / 2min): (2 of 2) User job slowstop2.service/stop running (14s / 1min 30s)...
[*     ] Job user@1000.service/stop running (15s / 2min): (2 of 2) User job slowstop2.service/stop running (14s / 1min 30s)...
[***   ] Job user@1000.service/stop running (16s / 2min): User job slowstop.service/stop running (16s / 1min 30s)...
[   ***] Job user@1000.service/stop running (18s / 2min): User job slowstop.service/stop running (17s / 1min 30s)...
[     *] Job user@1000.service/stop running (19s / 2min): User job slowstop.service/stop running (18s / 1min 30s)...
[   ***] Job user@1000.service/stop running (20s / 2min): User job slowstop.service/stop running (19s / 1min 30s)...
[*     ] Job user@1000.service/stop running (22s / 2min): User job slowstop.service/stop running (22s / 1min 30s)...
[**    ] Job user@1000.service/stop running (30s / 2min): User job slowstop.service/stop running (29s / 1min 30s)...
[   ***] Job user@1000.service/stop running (32s / 2min): User job slowstop.service/stop running (31s / 1min 30s)...
[     *] Job user@1000.service/stop running (33s / 2min): User job slowstop.service/stop running (32s / 1min 30s)...
[   ***] Job user@1000.service/stop running (34s / 2min): User job slowstop.service/stop running (33s / 1min 30s)...
[**    ] Job user@1000.service/stop running (37s / 2min): User job slowstop.service/stop running (36s / 1min 30s)...
[  *** ] Job user@1000.service/stop running (41s / 2min): User job slowstop.service/stop running (41s / 1min 30s)...
[  OK  ] Stopped user@1000.service - User Manager for UID 1000.
         Stopping user-runtime-dir@1000.service - User Runtime Directory /run/user/1000...
[  OK  ] Unmounted run-user-1000.mount - /run/user/1000.
[  OK  ] Stopped user-runtime-dir@1000.service - User Runtime Directory /run/user/1000.

If the output width is lower than approximately 100 columns, the output stops
being very useful. No idea what to do about that.

1 files changed, 52 insertions, 13 deletions

diff --git a/src/core/manager.c b/src/core/manager.c
index efa0efcb0c..a3607ea44f 100644
--- a/src/core/manager.c
+++ b/src/core/manager.c
@@ -117,9 +117,19 @@ static int manager_run_generators(Manager *m);
 static void manager_vacuum(Manager *m);
 
 static usec_t manager_watch_jobs_next_time(Manager *m) {
-        return usec_add(now(CLOCK_MONOTONIC),
-                        show_status_on(m->show_status) ? JOBS_IN_PROGRESS_WAIT_USEC :
-                                                         JOBS_IN_PROGRESS_QUIET_WAIT_USEC);
+        usec_t timeout;
+
+        if (MANAGER_IS_USER(m))
+                /* Let the user manager without a timeout show status quickly, so the system manager can make
+                 * use of it, if it wants to. */
+                timeout = JOBS_IN_PROGRESS_WAIT_USEC * 2 / 3;
+        else if (show_status_on(m->show_status))
+                /* When status is on, just use the usual timeout. */
+                timeout = JOBS_IN_PROGRESS_WAIT_USEC;
+        else
+                timeout = JOBS_IN_PROGRESS_QUIET_WAIT_USEC;
+
+        return usec_add(now(CLOCK_MONOTONIC), timeout);
 }
 
 static void manager_watch_jobs_in_progress(Manager *m) {
@@ -199,7 +209,6 @@ static void manager_flip_auto_status(Manager *m, bool enable, const char *reason
 }
 
 static void manager_print_jobs_in_progress(Manager *m) {
-        _cleanup_free_ char *job_of_n = NULL;
         Job *j;
         unsigned counter = 0, print_nr;
         char cylon[6 + CYLON_BUFFER_EXTRA + 1];
@@ -229,25 +238,51 @@ static void manager_print_jobs_in_progress(Manager *m) {
 
         m->jobs_in_progress_iteration++;
 
+        char job_of_n[STRLEN("( of ) ") + DECIMAL_STR_MAX(unsigned)*2] = "";
         if (m->n_running_jobs > 1)
-                (void) asprintf(&job_of_n, "(%u of %u) ", counter, m->n_running_jobs);
+                xsprintf(job_of_n, "(%u of %u) ", counter, m->n_running_jobs);
 
         bool have_timeout = job_get_timeout(j, &x) > 0;
 
         /* We want to use enough information for the user to identify previous lines talking about the same
          * unit, but keep the message as short as possible. So if 'Starting foo.service' or 'Starting
-         * foo.service (Description)' were used, 'foo.service' is enough here. On the other hand, if we used
+         * foo.service - Description' were used, 'foo.service' is enough here. On the other hand, if we used
          * 'Starting Description' before, then we shall also use 'Description' here. So we pass NULL as the
          * second argument to unit_status_string(). */
         const char *ident = unit_status_string(j->unit, NULL);
 
-        manager_status_printf(m, STATUS_TYPE_EPHEMERAL, cylon,
-                              "%sA %s job is running for %s (%s / %s)",
-                              strempty(job_of_n),
-                              job_type_to_string(j->type),
-                              ident,
-                              FORMAT_TIMESPAN(now(CLOCK_MONOTONIC) - j->begin_usec, 1*USEC_PER_SEC),
-                              have_timeout ? FORMAT_TIMESPAN(x - j->begin_usec, 1*USEC_PER_SEC) : "no limit");
+        const char *time = FORMAT_TIMESPAN(now(CLOCK_MONOTONIC) - j->begin_usec, 1*USEC_PER_SEC);
+        const char *limit = have_timeout ? FORMAT_TIMESPAN(x - j->begin_usec, 1*USEC_PER_SEC) : "no limit";
+
+        if (m->status_unit_format == STATUS_UNIT_FORMAT_DESCRIPTION)
+                /* When using 'Description', we effectively don't have enough space to show the nested status
+                 * without ellipsization, so let's not even try. */
+                manager_status_printf(m, STATUS_TYPE_EPHEMERAL, cylon,
+                                      "%sA %s job is running for %s (%s / %s)",
+                                      job_of_n,
+                                      job_type_to_string(j->type),
+                                      ident,
+                                      time, limit);
+        else {
+                const char *status_text = unit_status_text(j->unit);
+
+                manager_status_printf(m, STATUS_TYPE_EPHEMERAL, cylon,
+                                      "%sJob %s/%s running (%s / %s)%s%s",
+                                      job_of_n,
+                                      ident,
+                                      job_type_to_string(j->type),
+                                      time, limit,
+                                      status_text ? ": " : "",
+                                      strempty(status_text));
+        }
+
+        sd_notifyf(false,
+                   "STATUS=%sUser job %s/%s running (%s / %s)...",
+                   job_of_n,
+                   ident,
+                   job_type_to_string(j->type),
+                   time, limit);
+        m->status_ready = false;
 }
 
 static int have_ask_password(void) {
@@ -2621,6 +2656,10 @@ static void manager_start_special(Manager *m, const char *name, JobMode mode) {
         const char *s = unit_status_string(job->unit, NULL);
 
         log_info("Activating special unit %s...", s);
+
+        sd_notifyf(false,
+                   "STATUS=Activating special unit %s...", s);
+        m->status_ready = false;
 }
 
 static void manager_handle_ctrl_alt_del(Manager *m) {