Bug 2166842

Hi Benny,

thank you for contacting us with the issue!

The message itself is not exactly CUPS error, but an access log message - log of a request from a different source to CUPS daemon and the result of the request. It says there was a request for cancelling subscription, but the subscription ID the client provided doesn't exist.

According to logs there seems to be two daemons who ask for printer subscription:

Fingerprint Authentication Daemon:
Feb 03 00:32:38 localhost.localdomain systemd[1]: Starting Fingerprint Authentication Daemon...
Feb 03 00:32:38 localhost.localdomain cupsd[1311]: REQUEST localhost - - "POST / HTTP/1.1" 200 359 Create-Printer-Subscriptions successful-ok
Feb 03 00:32:38 localhost.localdomain wireplumber[2072]: <WpSiAudioAdapter:0x5561d4226080> Object activation aborted: proxy destroyed
Feb 03 00:32:38 localhost.localdomain wireplumber[2072]: <WpSiAudioAdapter:0x5561d4226080> failed to activate item: Object activation aborted: proxy destroyed
Feb 03 00:32:38 localhost.localdomain systemd[1]: Started Fingerprint Authentication Daemon.

GNOME printer notification daemon:
Feb 03 00:37:36 localhost.localdomain cupsd[1311]: REQUEST localhost - - "POST / HTTP/1.1" 200 360 Create-Printer-Subscriptions successful-ok
Feb 03 00:37:36 localhost.localdomain systemd[2487]: Started GNOME printer notifications service.
Feb 03 00:37:36 localhost.localdomain systemd[2487]: Reached target GNOME printer notifications target.

The cancellation of the same subscription happens when gnome-shell is not able to bring up xwayland:

Feb 03 00:37:37 localhost.localdomain systemd[2487]: Reached target GNOME Session.
Feb 03 00:37:37 localhost.localdomain systemd[2487]: Reached target GNOME Wayland Session (session: gnome).
Feb 03 00:37:37 localhost.localdomain systemd[2487]: Reached target Current graphical user session.
Feb 03 00:37:37 localhost.localdomain systemd[2487]: GNOME Initial Setup was skipped because of an unmet condition check (ConditionPathExists=!/home/dell/.config/gnome-initial-setup-done).
Feb 03 00:37:38 localhost.localdomain gnome-shell[2639]: GNOME Shell started at Fri Feb 03 2023 00:37:36 GMT-0500 (Eastern Standard Time)
Feb 03 00:37:38 localhost.localdomain gnome-shell[2639]: Registering session with GDM
Feb 03 00:37:38 localhost.localdomain gnome-shell[1718]: Connection to xwayland lost
Feb 03 00:37:38 localhost.localdomain cupsd[1311]: REQUEST localhost - - "POST / HTTP/1.1" 200 151 Cancel-Subscription successful-ok
Feb 03 00:37:38 localhost.localdomain gdm-wayland-session[1632]: GLib: Source ID 2 was not found when attempting to remove it
Feb 03 00:37:38 localhost.localdomain cupsd[1311]: REQUEST localhost - - "POST / HTTP/1.1" 200 151 Cancel-Subscription client-error-not-found
Feb 03 00:37:38 localhost.localdomain gdm-launch-environment][1463]: pam_unix(gdm-launch-environment:session): session closed for user gdm
Feb 03 00:37:38 localhost.localdomain gdm-launch-environment][1463]: GLib-GObject: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Feb 03 00:37:38 localhost.localdomain systemd-logind[1109]: Session c1 logged out. Waiting for processes to exit.

I see two possible turns of events - 

1) two different apps want to cancel the same subscription - this is not a bug in CUPS, but a fix should be pursued in the application which sends the request

or

2) there is a CUPS bug, which results into providing the same subscription number to the two different subscribers


To rule the 2) out I will need a CUPS debug log.

Benny, it would be great if you followed the following steps:


1) enable CUPS debug logging by:

$ cupsctl LogLevel=debug2

2) reproduce the issue

3) if the issue is shown, generate a new sosreport and attach it here to the ticket


Thank you in advance!

Hello,

I got the error message just after reboot the system. 
So maybe need the boot parameter to enable debug logging.

And I would like to know if is not a bug in CUPS, is it normal for us to get the messgae.

Thanks,
Benny.

Hi Benny,

(In reply to BennyBao from comment #2)
> Hello,
> 
> I got the error message just after reboot the system. 
> So maybe need the boot parameter to enable debug logging.

As a CUPS maintainer and for investigation from CUPS view, I need CUPS debug logs, which can be obtained by turning on debug logging in CUPS daemon. This can be achieved by entering 'cupsctl LogLevel=debug2' in terminal before reboot - there is no need for a boot parameter.

> 
> And I would like to know if is not a bug in CUPS, is it normal for us to get
> the messgae.

I cannot make a decision from the sosreport you've provided - CUPS LogLevel is not sufficient in the sosreport (the default log level is 'warn', I need 'debug2'). It would be great if you followed the steps I've written in my previous comment (comment #1) and provided the requested information.

The steps are:

1) enable CUPS debug logging before reboot:

$ cupsctl LogLevel=debug2

2) reproduce the issue - so reboot in your case:

$ reboot

3) if the issue appeared (you check this by 'journalctl -b0' and looking for 'Cancel-Subscription client-error-not-found'), generate sosreport and attach it to the bugzilla ticket


The most verbose CUPS log will tell me if all is well on CUPS side - if not, I can dig deeper, otherwise the Cancel Request is triggered gnome-shell losing connection to xwayland, which looks suspicious and can be a bug. Once I'll verify everything is fine on CUPS side, I'll pass this issue to gnome-shell for further investigation.

> 
> Thanks,
> Benny.

Created attachment 1943853 [details]
sosreport log with cups debug

Hi Dohnal,

Upload the sosreport with debug2 cups log.

Thanks,
Benny.

Thank you for the sosreport, Benny!

Now I have CUPS debug logs where I can see both requests:

1.
 985 Feb 13 07:43:31 localhost.localdomain cupsd[1310]: [Client 5] 2.0 Cancel-Subscription 4
 986 Feb 13 07:43:31 localhost.localdomain cupsd[1310]: cupsdProcessIPPRequest(0x55f883e6e820[5]): operation_id=001b(Cancel-Subscription)
 987 Feb 13 07:43:31 localhost.localdomain cupsd[1310]: cupsdProcessIPPRequest: operation-attributes-tag
 988 Feb 13 07:43:31 localhost.localdomain cupsd[1310]: cupsdProcessIPPRequest: attributes-charset charset 'utf-8'
 989 Feb 13 07:43:31 localhost.localdomain cupsd[1310]: cupsdProcessIPPRequest: attributes-natural-language naturalLanguage 'en-us'
 990 Feb 13 07:43:31 localhost.localdomain cupsd[1310]: cupsdProcessIPPRequest: printer-uri uri '/'
 991 Feb 13 07:43:31 localhost.localdomain cupsd[1310]: cupsdProcessIPPRequest: requesting-user-name nameWithoutLanguage 'gdm'
 992 Feb 13 07:43:31 localhost.localdomain cupsd[1310]: cupsdProcessIPPRequest: notify-subscription-id integer '23'
...
1006 Feb 13 07:43:31 localhost.localdomain cupsd[1310]: [Client 5] Returning IPP successful-ok for Cancel-Subscription (/) from localhost.


2.
1051 Feb 13 07:43:31 localhost.localdomain cupsd[1310]: [Client 6] 2.0 Cancel-Subscription 5
1052 Feb 13 07:43:31 localhost.localdomain cupsd[1310]: cupsdProcessIPPRequest(0x55f883e6e820[6]): operation_id=001b(Cancel-Subscription)
1053 Feb 13 07:43:31 localhost.localdomain cupsd[1310]: cupsdProcessIPPRequest: operation-attributes-tag
1054 Feb 13 07:43:31 localhost.localdomain cupsd[1310]: cupsdProcessIPPRequest: attributes-charset charset 'utf-8'
1055 Feb 13 07:43:31 localhost.localdomain cupsd[1310]: cupsdProcessIPPRequest: attributes-natural-language naturalLanguage 'en-us'
1056 Feb 13 07:43:31 localhost.localdomain cupsd[1310]: cupsdProcessIPPRequest: printer-uri uri '/'
1057 Feb 13 07:43:31 localhost.localdomain cupsd[1310]: cupsdProcessIPPRequest: requesting-user-name nameWithoutLanguage 'gdm'
1058 Feb 13 07:43:31 localhost.localdomain cupsd[1310]: cupsdProcessIPPRequest: notify-subscription-id integer '23'
...
1061 Feb 13 07:43:31 localhost.localdomain cupsd[1310]: Cancel-Subscription client-error-not-found: Subscription #23 does not exist.

I see the user 'gdm' sent two different requests to cancel a subscription with the same ID - 23. So the CUPS behavior is expected and the message is not indicating any error in CUPS.

I'll switch the bug to gdm component for their investigation why it sends duplicated IPP requests and why there are errors regarding your Wayland sessions, which causes this behavior.

===============================================================

To GDM maintainer:

RH partner Dell requests information whether the situation with GDM, which results into duplicated IPP request to cancel the same subscription, is a bug or not.

From /var/log/messages I see there are xwayland/glib errors before CUPS receives the requests, f.e.:


32667 Feb 13 07:37:42 localhost journal[2624]: Registering session with GDM
32668 Feb 13 07:37:42 localhost gdm-wayland-session[1634]: GLib: Source ID 2 was not found when attempting to remove it
32669 Feb 13 07:37:42 localhost cupsd[1314]: REQUEST localhost - - "POST / HTTP/1.1" 200 151 Cancel-Subscription successful-ok
32670 Feb 13 07:37:42 localhost cupsd[1314]: REQUEST localhost - - "POST / HTTP/1.1" 200 151 Cancel-Subscription client-error-not-found
32671 Feb 13 07:37:42 localhost journal[2349]: GChildWatchSource: Exit status of a child process was requested but ECHILD was received by waitpid(). See the documentation of g_child_watch_source_new() for possible causes.
32672 Feb 13 07:37:42 localhost gdm-launch-environment][1453]: GLib-GObject: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
32673 Feb 13 07:37:42 localhost systemd-logind[1119]: Session c1 logged out. Waiting for processes to exit.
32674 Feb 13 07:37:42 localhost journal[2924]: failed to connect to device: Failed to connect to missing device /org/freedesktop/ColorManager/devices/xrandr_LG_Display_gdm_42

36173 Feb 13 07:39:28 localhost journal[1960]: Connection to xwayland lost
36174 Feb 13 07:39:28 localhost gnome-session[1902]: gnome-session-binary[1902]: WARNING: Lost name on bus: org.gnome.SessionManager
36175 Feb 13 07:39:28 localhost gnome-session-binary[1902]: WARNING: Lost name on bus: org.gnome.SessionManager
36176 Feb 13 07:39:28 localhost cupsd[1305]: REQUEST localhost - - "POST / HTTP/1.1" 200 151 Cancel-Subscription successful-ok
36177 Feb 13 07:39:28 localhost cupsd[1305]: REQUEST localhost - - "POST / HTTP/1.1" 200 151 Cancel-Subscription client-error-not-found
36178 Feb 13 07:39:28 localhost journal[2411]: Error releasing name org.gnome.SettingsDaemon.Rfkill: The connection is closed 
36179 Feb 13 07:39:28 localhost journal[2408]: Error releasing name org.gnome.SettingsDaemon.PrintNotifications: The connection is closed
36180 Feb 13 07:39:28 localhost journal[2413]: Error releasing name org.gnome.SettingsDaemon.Smartcard: The connection is closed
36181 Feb 13 07:39:28 localhost journal[2418]: Error releasing name org.freedesktop.ScreenSaver: The connection is closed
36182 Feb 13 07:39:28 localhost journal[2424]: Error releasing name org.gnome.SettingsDaemon.A11ySettings: The connection is closed
36183 Feb 13 07:39:28 localhost journal[2421]: Error releasing name org.gnome.SettingsDaemon.Sound: The connection is closed
36184 Feb 13 07:39:28 localhost journal[2414]: Error releasing name org.gnome.SettingsDaemon.Datetime: The connection is closed
36185 Feb 13 07:39:29 localhost journal[3184]: failed to connect to device: Failed to connect to missing device /org/freedesktop/ColorManager/devices/xrandr_LG_Display_gdm_42
36186 Feb 13 07:39:29 localhost journal[3525]: Cannot open display:

43734 Feb 13 07:43:31 localhost gdm-wayland-session[1879]: GLib: Source ID 2 was not found when attempting to remove it
43735 Feb 13 07:43:31 localhost gnome-session[1886]: gnome-session-binary[1886]: WARNING: Lost name on bus: org.gnome.SessionManager
43736 Feb 13 07:43:31 localhost gnome-session-binary[1886]: WARNING: Lost name on bus: org.gnome.SessionManager
43737 Feb 13 07:43:31 localhost cupsd[1310]: REQUEST localhost - - "POST / HTTP/1.1" 200 151 Cancel-Subscription successful-ok
43738 Feb 13 07:43:31 localhost cupsd[1310]: REQUEST localhost - - "POST / HTTP/1.1" 200 151 Cancel-Subscription client-error-not-found
43739 Feb 13 07:43:31 localhost gdm-launch-environment][1712]: GLib-GObject: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
43740 Feb 13 07:43:31 localhost systemd-logind[1114]: Session c1 logged out. Waiting for processes to exit.
43741 Feb 13 07:43:31 localhost journal[3183]: failed to connect to device: Failed to connect to missing device /org/freedesktop/ColorManager/devices/xrandr_LG_Display_gdm_42

So my understanding of the situation is, the login screen listens to printer notifications, I guess so that it can show them to the user. I guess for "ink low" messages ? That behavior is a bit dubious in and of itself, but for now, let's call it designed behavior.

Now the bug is here:

void•                                                                         
gsd_print_notifications_manager_stop (GsdPrintNotificationsManager *manager)• 
{•                                                                            
...
        if (manager->subscription_id >= 0)•                       
                cancel_subscription (manager->subscription_id);•  
...
}• 

You see, the "stop" function is not idempotent. If it gets called more than once it will cancel the one subscription it has more than once.

The printer-notification daemon calls stop twice though: once in main.c during early teardown and once again later during manager finalization.

The fix should be trivial, just adding

manager->subscription_id = -1;

inside the above referenced if statement.  In fact it may be prudent to add a new state variable "is_started" that gets set to TRUE in "start", and FALSE in "stop" and make "stop" return early if is_started is FALSE.

Thank you for your suggestion Ray. I've reset all the internal variables in the stop() method and it fixes the issue.

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (gnome-settings-daemon bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2023:2446