Bug 34562

Summary:	quick closing & opening of Print dialog makes a CUPS printer disappear (be not found/displayed)
Product:	Sisyphus	Reporter:	Ivan Zakharyaschev <imz>
Component:	libgtk+2	Assignee:	Yuri N. Sedunov <aris>
Status:	NEW ---	QA Contact:	qa-sisyphus
Severity:	normal
Priority:	P3	CC:	aris
Version:	unstable
Hardware:	all
OS:	Linux
URL:	https://gitlab.gnome.org/GNOME/gtk/issues/39
Bug Depends on:	34570
Bug Blocks:

Description

Ivan Zakharyaschev 2018-02-18 13:20:45 MSK

2.24.32-alt1

(x-post: https://gitlab.gnome.org/GNOME/gtk/issues/39 , https://bugzilla.gnome.org/show_bug.cgi?id=793529 .)

Let me describe a way how we can reproduce this bug:

0. Install cups-pdf. (This will be the CUPS printer that will be used to test the appearance of a CUPS printer in the Print dialog.)

1. Press Ctrl-P (in atril built with libgtk+2-2.24.32; this has also been reproduced in firefox; and with 2.24.21; and probably with libgtk+3-3.22.26), select CUPS-PDF, print a page.

2. Press Ctrl-P.

3. Press Esc (to close the Print dialog).

Repeat 2 and 3 quickly many times. (Sometimes 3 times is enough, sometimes 20.) 

Result: in the last Print dialog, CUPS-PDF is not in the list anymore.

Expected result: CUPS-PDF is in the listand can be printed to.

In the invocation of the Print dialog before the last one, before one presses Esc, CUPS-PDF is usually listed, but the "Print" button is not active (yet). It looks as if the Print dialog is still getting some information from the printer.

(We have learned of this bug from people who have been using the Print dialog in a virtual machine, so as for now, we tried to reproduce this in similar conditions only, i.e., in a VirtualBox inside a kvm virtual machine, and I'm not sure whether it is easy to get this on real hardware.)

Of course, this looks like a race or a collision in the connections from Gtk to CUPS. (I have compared this to the behavior of the Qt Print dialog, and there was no such problem with Qt, so I believe the cups server probably works well accepting connections through cups.sock.)

I have compiled libgtk+2-2.24.32 with --enable-debug=yes , and I'll show below the debugging messages when this bug appears.

(As for libgtk+2-2.24.21 compiled with --enable-debug=yes , surprizingly, the Print dialog was not usable at all: already on the first invocation, CUPS-PDF never became ready to print, even when no environment variables to output the debugging messages were set, i.e.: no debugging information was output to the terminal, but the dialog was not usable.)

Debugging:

I ran it like this:

```
G_MESSAGES_DEBUG=printing GTK_DEBUG=printing atril /usr/share/doc/dia/en/dia.pdf &>atril.debug.0
```

Here is some interesting stuff:

First, do:

```
sed -i -re 's:ignored:&\n:' atril.debug.0
```

because of a missing newline in one of the debugging messages (a minor bug I've created the pull request <https://gitlab.gnome.org/GNOME/gtk/merge_requests/23> for).

```
[user@prodesk0 ~]$ egrep 'request_exec|finaliz|dispose' atril.debug.0 
CUPS Backend: cups_request_execute <source 0x9efb90> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_request_execute <source 0xa36380> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/printers/Cups-PDF.ppd'
CUPS Backend: cups_dispatch_watch_finalize <source 0x9efb90>
CUPS Backend: cups_dispatch_watch_finalize <source 0xa36380>
CUPS Backend: cups_request_execute <source 0x9ec840> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0x9ec840>
CUPS Backend: cups_request_execute <source 0xa72c00> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa72c00>
CUPS Backend: cups_request_execute <source 0xa72050> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa72050>
CUPS Backend: cups_request_execute <source 0xa72320> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa72320>
CUPS Backend: cups_request_execute <source 0xa72320> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa72320>
CUPS Backend: cups_request_execute <source 0xa72fc0> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa72fc0>
CUPS Backend: cups_request_execute <source 0xa73000> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa73000>
CUPS Backend: cups_request_execute <source 0xa72340> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa72340>
CUPS Backend: cups_request_execute <source 0xa72320> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa72320>
CUPS Backend: cups_request_execute <source 0xa73470> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa73470>
CUPS Backend: cups_request_execute <source 0xa72320> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa72320>
CUPS Backend: cups_request_execute <source 0xa73390> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa73390>
CUPS Backend: cups_request_execute <source 0xa73350> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa73350>
CUPS Backend: cups_request_execute <source 0xa73390> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa73390>
CUPS Backend: cups_request_execute <source 0xa73390> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa73390>
CUPS Backend: gtk_print_backend_cups_dispose
CUPS Backend: cups_request_execute <source 0xa4a900> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_request_execute <source 0x9b5bf0> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/printers/Cups-PDF.ppd'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa4a900>
CUPS Backend: cups_dispatch_watch_finalize <source 0x9b5bf0>
CUPS Backend: cups_request_execute <source 0xa55810> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa55810>
CUPS Backend: cups_request_execute <source 0xa87600> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa87600>
CUPS Backend: cups_request_execute <source 0xa876c0> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa876c0>
CUPS Backend: cups_request_execute <source 0xa87360> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa87360>
CUPS Backend: cups_request_execute <source 0xa879d0> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa879d0>
CUPS Backend: gtk_print_backend_cups_dispose
CUPS Backend: cups_request_execute <source 0x9b21d0> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_request_execute <source 0xa22900> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/printers/Cups-PDF.ppd'
CUPS Backend: cups_dispatch_watch_finalize <source 0x9b21d0>
CUPS Backend: cups_dispatch_watch_finalize <source 0xa22900>
CUPS Backend: cups_request_execute <source 0xa658c0> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa658c0>
CUPS Backend: cups_request_execute <source 0xa9c610> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa9c610>
CUPS Backend: cups_request_execute <source 0xa9c000> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa9c000>
CUPS Backend: cups_request_execute <source 0xa9c0c0> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa9c0c0>
CUPS Backend: cups_request_execute <source 0xa9c0a0> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa9c0a0>
CUPS Backend: gtk_print_backend_cups_dispose
CUPS Backend: cups_request_execute <source 0xa359e0> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_request_execute <source 0xa20f20> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/printers/Cups-PDF.ppd'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa359e0>
CUPS Backend: cups_dispatch_watch_finalize <source 0xa20f20>
CUPS Backend: cups_request_execute <source 0xaa2a90> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xaa2a90>
CUPS Backend: cups_request_execute <source 0xaa29b0> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xaa29b0>
CUPS Backend: cups_request_execute <source 0xaa29e0> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xaa29e0>
CUPS Backend: cups_request_execute <source 0xaa29e0> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xaa29e0>
CUPS Backend: gtk_print_backend_cups_dispose
CUPS Backend: cups_request_execute <source 0x98a730> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_request_execute <source 0xa67d90> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/printers/Cups-PDF.ppd'
CUPS Backend: cups_dispatch_watch_finalize <source 0x98a730>
CUPS Backend: gtk_print_backend_cups_dispose
CUPS Backend: cups_request_execute <source 0xa33710> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
CUPS Backend: cups_dispatch_watch_finalize <source 0xa67d90>
[user@prodesk0 ~]$ 
```

Note above that each `cups_request_execute` is followed by a corresponding `cups_dispatch_watch_finalize`. (And a pair of `cups_request_execute` is always followed by a pair of corresponding `cups_dispatch_watch_finalize`.) But the one before the last one:

```
CUPS Backend: cups_request_execute <source 0xa67d90> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/printers/Cups-PDF.ppd'
```

is not matched by a corresponding `cups_dispatch_watch_finalize`, and the the next one is executed:

```
CUPS Backend: cups_request_execute <source 0xa33710> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/'
````

and after that a non-corresponding `cups_dispatch_watch_finalize` occurs. The the Print dialog is being displayed without CUPS-PDF ever appearing in the list. (After a while, I terminated the process.)

The output is huge (attached [atril.debug.0.xz](/uploads/5bc7b0df5402b875f8fc9c4b4060e14c/atril.debug.0.xz)):

```
$ wc -l atril.debug.0 
494422 atril.debug.0
```

and the tail is all about the last request:

```
[user@prodesk0 ~]$ tail atril.debug.0 
CUPS Backend: cups_dispatch_watch_prepare <source 0xa33710>
CUPS Backend: cups_dispatch_watch_check <source 0xa33710>
CUPS Backend: cups_dispatch_watch_prepare <source 0xa33710>
CUPS Backend: cups_dispatch_watch_check <source 0xa33710>
CUPS Backend: cups_dispatch_watch_prepare <source 0xa33710>
CUPS Backend: cups_dispatch_watch_check <source 0xa33710>
CUPS Backend: cups_dispatch_watch_prepare <source 0xa33710>
CUPS Backend: cups_dispatch_watch_check <source 0xa33710>
CUPS Backend: cups_dispatch_watch_prepare <source 0xa33710>
CUPS Backend: cups_dispatch_watch_check <source 0xa33710>
```

Here is the piece concerning the last request:

```
CUPS Backend: cups_dispatch_watch_dispatch <source 0x98a730>
CUPS Backend: cups_request_printer_list_cb
CUPS Backend: Attribute number-up-default ignored
CUPS Backend: Found printer ipp://localhost:631/printers/Cups-PDF
CUPS Backend: Setting ppd name 'Cups-PDF' for printer/class 'Cups-PDF'
CUPS Backend: cups_request_ppd
CUPS Backend: Requesting resource /printers/Cups-PDF.ppd to be written to temp file /tmp/.private/test/gtkprint_ppd_0MFJEZ
CUPS Backend: cups_request_execute <source 0xa67d90> - Executing cups request on server '/var/run/cups/cups.sock' and resource '/printers/Cups-PDF.ppd'
CUPS Backend: cups_dispatch_watch_finalize <source 0x98a730>
CUPS Backend: cups_dispatch_watch_prepare <source 0xa67d90>
CUPS Backend: cups_dispatch_watch_check <source 0xa67d90>
CUPS Backend: _get_send
CUPS Backend: _get_check
CUPS Backend: cups_dispatch_watch_prepare <source 0xa67d90>
CUPS Backend: cups_dispatch_watch_check <source 0xa67d90>
CUPS Backend: cups_dispatch_watch_prepare <source 0xa67d90>
CUPS Backend: cups_dispatch_watch_check <source 0xa67d90>
CUPS Backend: cups_dispatch_watch_prepare <source 0xa67d90>
```

Comment 1

Ivan Zakharyaschev 2018-02-20 13:03:31 MSK

I've got an understanding how this bug happens because of a "race" between a close and a connect syscall associated with cups.sock. I'll describe the details later.

(Not really a race, but rather a wrong assumption/buggy code about fd numbers)