#984692 cups-daemon: "dbus" notifier stays hanging after showing the notification

Package:
cups-daemon
Source:
cups
Description:
Common UNIX Printing System(tm) - daemon
Submitter:
Igor Liferenko
Date:
2021-09-28 05:15:02 UTC
Severity:
normal
#984692#5
Date:
2021-03-07 08:57:00 UTC
From:
To:
Dear Maintainer,

After printing a file I get notification that document is sent to printer
and then that printing is finished.

The problem is that dbus notifier process stays alive after having done
its job. Most probably the reason is that the process which calls
the notifier does not close the pipe and the dbus notifier process
keeps waiting for data to be read instead of getting EOF.

Following are the outputs of "systemctl status cups" before and after
printing a document. Notice the process list in the end of each.

● cups.service - CUPS Scheduler
     Loaded: loaded (/lib/systemd/system/cups.service; enabled; vendor preset: enabled)
     Active: active (running) since Sun 2021-03-07 15:44:27 +07; 12s ago
TriggeredBy: ● cups.path
             ● cups.socket
       Docs: man:cupsd(8)
   Main PID: 5019 (cupsd)
     Status: "Scheduler is running..."
      Tasks: 1 (limit: 2142)
     Memory: 3.4M
        CPU: 18ms
     CGroup: /system.slice/cups.service
             └─5019 /usr/sbin/cupsd -l
---------------

● cups.service - CUPS Scheduler
     Loaded: loaded (/lib/systemd/system/cups.service; enabled; vendor preset: enabled)
     Active: active (running) since Sun 2021-03-07 15:44:27 +07; 19s ago
TriggeredBy: ● cups.path
             ● cups.socket
       Docs: man:cupsd(8)
   Main PID: 5019 (cupsd)
     Status: "Scheduler is running..."
      Tasks: 2 (limit: 2142)
     Memory: 4.8M
        CPU: 123ms
     CGroup: /system.slice/cups.service
             ├─5019 /usr/sbin/cupsd -l
             └─5025 /usr/lib/cups/notifier/dbus dbus://

Thanks,
Igor

P.S.
This may be relevant:
https://bugzilla.redhat.com/show_bug.cgi?id=1026949
#984692#10
Date:
2021-03-07 09:27:09 UTC
From:
To:
If I copy testnotify (testnotify.c in cups source) over
/usr/lib/cups/notifier/dbus the result is the same.
#984692#15
Date:
2021-03-07 09:59:21 UTC
From:
To:
Indeed, strace shows that the dbus notifier process is blocked while
waiting for input from cupsd on stdin:

$ strace -p 5025
strace: Process 5025 attached
read(0,
#984692#20
Date:
2021-03-07 10:35:44 UTC
From:
To:
The dbus notifier process stays opened and on subsequent notifications cups-exec
is not done for it. Now it's clear to me that this is done for efficiency.

One thing that still troubles me, though, is that sometimes there are
two and sometimes even three dbus notifier processes in "systemctl
status cups" list. But I can't reliably reproduce these scenarios. Why
can that be?
#984692#25
Date:
2021-09-28 05:10:47 UTC
From:
To:
I tried to understand why two dbus processes are started.
First, I replaced /usr/lib/cups/notifier/dbus with this program:

    #include <unistd.h>
    int main(void)
    {
      char buf[8192];
      while (read(STDIN_FILENO, buf, sizeof buf) > 0) ;
      return 0;
    }

Then I printed a file, after which two dbus processes appeared in
"systemctl status cups". Then I did "strace" on both these processes
and printed another job. The output of strace showed what data is
received by these dbus processes. It is in attachment.

Note, that data is almost identical - do "diff cups1 cups2" to see the
differences.

So, the question is - why two dbus processes are started instead of one?