Bug#832637: More info

[Till Kamppeter]

On 09/03/2016 07:42 PM, Brian Potkin wrote:


  # DomainSocket /var/run/cups/cups.sock



Thank you. As this line is commented out cups-browsed connects by the 
socket out-of-the-box on your machine.


   Till

Bug#832637: More info

[Brian Potkin]

On Sat 03 Sep 2016 at 19:17:48 -0300, Till Kamppeter wrote:

> Brian, thank you very much for the testing. I will do the next (bug fix)
> release containing also other fixes (version 1.11.3) most probably on
> Monday.
> 
> One question: Did cups-browsed use the socket out-of-the-box or did you need
> to set it in cups-browsed.conf?

If you are referring to the DomainSocket directive I left it exactly as
it came:

  # DomainSocket /var/run/cups/cups.sock

Bug#832637: More info

[Till Kamppeter]

Brian, thank you very much for the testing. I will do the next (bug fix) 
release containing also other fixes (version 1.11.3) most probably on 
Monday.


One question: Did cups-browsed use the socket out-of-the-box or did you 
need to set it in cups-browsed.conf?


   Till

Bug#832637: More info

[Brian Potkin]

On Sat 03 Sep 2016 at 14:12:52 -0300, Till Kamppeter wrote:

> The problem is most probably caused by inconsistency in how cups-browsed
> accesses the local CUPS daemon, for some accesses it uses the domain socket
> (which made it mostly well working in your case) and at other places,
> especially also during shutdown, it accesses localhost:631 (this is why it
> hangs on shutdown), independent of configuration.

I had noticed some asymmetry between startup and shutdown.

> Now I have fixed this in the upstream BZR repository. if you are familiar
> with compiling stuff by yourself and with BZR, load a current BZR snapshot,
> build it, and put its cups-browsed into /usr/sbin/, replacing the distro's
> one. Then check whether it solves the problem.

I'm as familiar with BZR as I am with Swiss train timetables. Designing
and building nuclear power stations seems a lot easier to me. :)

> Do the following commands (relevant source code file is utils/cups-browsed.c
> FYI):
> 
> sudo apt-get build-dep cups-filters
> sudo apt-get install bzr
> bzr branch http://bzr.linuxfoundation.org/openprinting/cups-filters

./autogen.sh was necessary here. The INSTALL file helped.

> cd cups-filters
> ./configure
> make
> sudo systemctl stop cups-browsed
> sudo cp cups-browsed /usr/sbin/
> sudo systemctl start cups-browsed

I end up with a cups-browsed file with size 370820 in the root of
cups-filters.

> Now it should run purely on the domain socket. If not (then it probably runs
> purely on localhost:631) add the line
> 
> DomainSocket /var/run/cups/cups.sock
> 
> to /etc/cups/cups-browsed.conf and restart cups-browsed.
> 
> Does the shutdown now work correctly?

Yes, it does. That's with cups 2.2~rc1-5.

Thank you for your timely response and the fix (and the detailed
instructions).

Cheers,

Brian.

Bug#832637: More info

[Till Kamppeter]

The problem is most probably caused by inconsistency in how cups-browsed 
accesses the local CUPS daemon, for some accesses it uses the domain 
socket (which made it mostly well working in your case) and at other 
places, especially also during shutdown, it accesses localhost:631 (this 
is why it hangs on shutdown), independent of configuration.


Now I have fixed this in the upstream BZR repository. if you are 
familiar with compiling stuff by yourself and with BZR, load a current 
BZR snapshot, build it, and put its cups-browsed into /usr/sbin/, 
replacing the distro's one. Then check whether it solves the problem.


Do the following commands (relevant source code file is 
utils/cups-browsed.c FYI):


sudo apt-get build-dep cups-filters
sudo apt-get install bzr
bzr branch http://bzr.linuxfoundation.org/openprinting/cups-filters
cd cups-filters
./configure
make
sudo systemctl stop cups-browsed
sudo cp cups-browsed /usr/sbin/
sudo systemctl start cups-browsed

Now it should run purely on the domain socket. If not (then it probably 
runs purely on localhost:631) add the line


DomainSocket /var/run/cups/cups.sock

to /etc/cups/cups-browsed.conf and restart cups-browsed.

Does the shutdown now work correctly?

   Till

Bug#832637: More info

[Brian Potkin]

On Tue 30 Aug 2016 at 23:31:55 +0200, Roderich Schupp wrote:

> On Tue, Aug 23, 2016 at 6:55 PM, Brian Potkin 
> wrote:
> 
> > I have no special skills in interpreting strace outputs but this would
> > appear to be confirmation that cups-browsed cannot contact cups when it
> > closes down.
> >
> 
> cupsd _is_ running. The strace fragment simply shows cups-browsed trying to
> connect to
> IPv6 localhost, port 631 (over and over). It can't connect because my cupsd
> doesn't listen
> on localhost:631 (neither IPv4 nor IPv6), only on a domain socket
> (/var/run/cups/cups.sock).

I did what I should have done immediately after Roderich's first mail
and got myself a minimal unstable installation with experimental cups on
it. 'systemctl stop cups-browsed' with cups still running results in a
90 second hang and a strace log essentially the same as Roderich's.

The hang does not happen with 'Listen localhost:631' added to cupsd.conf.
It does happen with 'systemctl stop cups' because cups-browsed is also
stopped as a result of this command.

The only changes I made to the default install were to enable logging
for cups-browsed and comment out Listen localhost:631 in cupsd.conf. A
cups-browsed log is attached.

This behaviour is still unreproducible for me with cups 2.1.4-4.

Cheers,

Brian.
Sat Sep  3 17:33:11 2016 Reading config: BrowseRemoteProtocols dnssd cups
Sat Sep  3 17:33:11 2016 No "Browse..." line at all, accept all servers 
("BrowseOrder Deny,Allow").
Sat Sep  3 17:33:11 2016 network interface at 192.168.7.65
Sat Sep  3 17:33:11 2016 cups-browsed [BrowsePoll localhost:631]: 
IPP-Create-Subscription
Sat Sep  3 17:33:11 2016 cups-browsed [BrowsePoll localhost:631]: subscription 
ID=109
Sat Sep  3 17:33:11 2016 cups-browsed [BrowsePoll localhost:631]: cupsGetDests
Sat Sep  3 17:33:11 2016 Could not determine system default printer!
Sat Sep  3 17:33:11 2016 Using signal handler SIGACTION
Sat Sep  3 17:33:11 2016 Avahi server connection got available, setting up 
service browsers.
Sat Sep  3 17:33:11 2016 listening
Sat Sep  3 17:33:11 2016 Avahi Browser: NEW: service 'HP ENVY 4500 series 
[FAFAC2]' of type '_ipp._tcp' in domain 'local'
Sat Sep  3 17:33:11 2016 Avahi Browser: NEW: service 'HP LaserJet 2200D @ 
desktop' of type '_ipp._tcp' in domain 'local'
Sat Sep  3 17:33:11 2016 Avahi Browser: NEW: service 'laserjet @ desktop' of 
type '_ipp._tcp' in domain 'local'
Sat Sep  3 17:33:11 2016 Avahi Browser: NEW: service 'rawq @ desktop' of type 
'_ipp._tcp' in domain 'local'
Sat Sep  3 17:33:11 2016 Avahi Browser: NEW: service 'Panasonic KX-P1081 (Text 
only) @ desktop' of type '_ipp._tcp' in domain 'local'
Sat Sep  3 17:33:11 2016 Avahi Browser: NEW: service 'Panasonic KX-P1081 (Text 
& graphics) @ desktop' of type '_ipp._tcp' in domain 'local'
Sat Sep  3 17:33:11 2016 Avahi Browser: NEW: service 'Epson Stylus @ desktop' 
of type '_ipp._tcp' in domain 'local'
Sat Sep  3 17:33:11 2016 Avahi Browser: CACHE_EXHAUSTED
Sat Sep  3 17:33:11 2016 Avahi Browser: NEW: service 'Epson Stylus @ desktop' 
of type '_ipps._tcp' in domain 'local'
Sat Sep  3 17:33:11 2016 Avahi Browser: NEW: service 'Panasonic KX-P1081 (Text 
& graphics) @ desktop' of type '_ipps._tcp' in domain 'local'
Sat Sep  3 17:33:11 2016 Avahi Browser: NEW: service 'Panasonic KX-P1081 (Text 
only) @ desktop' of type '_ipps._tcp' in domain 'local'
Sat Sep  3 17:33:11 2016 Avahi Browser: NEW: service 'laserjet @ desktop' of 
type '_ipps._tcp' in domain 'local'
Sat Sep  3 17:33:11 2016 Avahi Browser: NEW: service 'HP LaserJet 2200D @ 
desktop' of type '_ipps._tcp' in domain 'local'
Sat Sep  3 17:33:11 2016 Avahi Browser: NEW: service 'rawq @ desktop' of type 
'_ipps._tcp' in domain 'local'
Sat Sep  3 17:33:11 2016 Avahi Browser: CACHE_EXHAUSTED
Sat Sep  3 17:33:11 2016 Avahi Resolver: Service 'HP LaserJet 2200D @ desktop' 
of type '_ipp._tcp' in domain 'local'.
Sat Sep  3 17:33:11 2016 Found CUPS queue: LaserJet-300 on host desktop.local.
Sat Sep  3 17:33:11 2016 cups-browsed [BrowsePoll localhost:631]: 
IPP-Get-Notifications
Sat Sep  3 17:33:11 2016 cups-browsed [BrowsePoll localhost:631]: no events
Sat Sep  3 17:33:11 2016 Matching printer "LaserJet-300" with properties Host = 
"desktop.local", Port = 631, Service Name = "HP LaserJet 2200D @ desktop", 
Domain = "local" with the BrowseFilter lines in cups-browsed.conf
Sat Sep  3 17:33:11 2016 All BrowseFilter lines matched or skipped, accepting 
printer LaserJet-300
Sat Sep  3 17:33:11 2016 Bonjour IDs: Service name: "HP LaserJet 2200D @ 
desktop", Service type: "_ipp._tcp", Domain: "local"
Sat Sep  3 17:33:11 2016 checking queues in 0s
Sat Sep  3 17:33:11 2016 Avahi Resolver: Service 'rawq @ desktop' of type 
'_ipps._tcp' in domain 'local'.
Sat Sep  3 17:33:11 2016 Found CUPS queue: rawq on host desktop.local.
Sat Sep  3 17:33:11 2016 Remote Bonjour-advertised CUPS queue rawq on host 
desktop.local is raw, ignored.
Sat Sep  3 17:33:11 2016 checking queues in 0s
Sat Sep  3 17:33:11 

Bug#832637: More info

[Brian Potkin]

On Tue 30 Aug 2016 at 23:31:55 +0200, Roderich Schupp wrote:

> On Tue, Aug 23, 2016 at 6:55 PM, Brian Potkin 
> wrote:
> 
> > I have no special skills in interpreting strace outputs but this would
> > appear to be confirmation that cups-browsed cannot contact cups when it
> > closes down.
> >
> 
> cupsd _is_ running. The strace fragment simply shows cups-browsed trying to
> connect to
> IPv6 localhost, port 631 (over and over). It can't connect because my cupsd
> doesn't listen
> on localhost:631 (neither IPv4 nor IPv6), only on a domain socket
> (/var/run/cups/cups.sock).

>From cups-browsed.conf(5):

  If cups-browsed is not able to access the local CUPS daemon
  via a domain socket it accesses it via localhost.

The implication is that cups-browsed will use the domain socket by
default, which is the behaviour I get.

So why does your cups-browsed attempt a connection to localhost when
cupsd is listening on /var/run/cups/cups.sock? What does strace show
when cups-browsed is started? What does 'lpstat-a' give after it has
started?

Please attach your cupsd.conf and cups-browsed.conf to your next mail
here.

Cheers,

Brian.

Bug#832637: More info

[Roderich Schupp]

On Tue, Aug 23, 2016 at 6:55 PM, Brian Potkin 
wrote:

> I have no special skills in interpreting strace outputs but this would
> appear to be confirmation that cups-browsed cannot contact cups when it
> closes down.
>

cupsd _is_ running. The strace fragment simply shows cups-browsed trying to
connect to
IPv6 localhost, port 631 (over and over). It can't connect because my cupsd
doesn't listen
on localhost:631 (neither IPv4 nor IPv6), only on a domain socket
(/var/run/cups/cups.sock).

Cheers, Roderich

Bug#832637: More info

[Brian Potkin]

On Sun 21 Aug 2016 at 17:30:10 +0200, Roderich Schupp wrote:

> On Sun, Aug 21, 2016 at 4:27 PM, Brian Potkin 
> wrote:
> 
> > Are you positive cups.service is still running while cups-browsed is
> > stopping? 'systemctl status cups' in another terminal would tell you.
> >
> 
> Yes
> 
> 
> > If I use the sequence
> >
> >   systemctl start cups cups-browsed.service
> >   systemctl stop cups-browsed.service
> >
> > it stops cups-browsed immediately here.
> >
> 
> I just did:
> 
> # systemctl start cups cups-browsed.service
> # systemctl status cups cups-browsed.service
> cups.service - CUPS Scheduler
>Loaded: loaded (/lib/systemd/system/cups.service; enabled; vendor
> preset: ena
>Active: active (running) since Sun 2016-08-21 09:14:34 CEST; 8h ago
>...
> cups-browsed.service - Make remote CUPS printers available locally
>Loaded: loaded (/lib/systemd/system/cups-browsed.service; enabled;
> vendor pre
>Active: active (running) since Sun 2016-08-21 17:16:33 CEST; 9s ago
>...
> # systemctl stop cups-browsed.service
> (waits 90 sec)
> 
> If I strace the cups-browsed process (all threads) during tese 90 seconds I
> see it repeats the following until it gets killed:
> 
> 19552 connect(10, {sa_family=AF_INET6, sin6_port=htons(631),
> inet_pton(AF_INET6, "::1", _addr), sin6_flowinfo=0, sin6_scope_id=0},
> 28) = -1 EINPROGRESS (Operation now in progress)
> 19552 fcntl(10, F_SETFL, O_RDWR)= 0
> 19552 poll([{fd=10, events=POLLIN|POLLOUT}], 1, 100) = 1 ([{fd=10,
> revents=POLLIN|POLLOUT|POLLERR|POLLHUP}])
> 19552 sendto(10, "POST / HTTP/1.1\r\nContent-Length:"..., 169, 0, NULL, 0)
> = -1 ECONNREFUSED (Connection refused)
> 19552 sendto(10, "POST / HTTP/1.1\r\nContent-Length:"..., 169, 0, NULL, 0)
> = -1 EPIPE (Broken pipe)
> 19552 --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=19552,
> si_uid=0} ---
> 19552 sendto(10, "POST / HTTP/1.1\r\nContent-Length:"..., 169, 0, NULL, 0)
> = -1 EPIPE (Broken pipe)
> 19552 --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=19552,
> si_uid=0} ---
> 19552 close(10) = 0
> 19552 socket(AF_INET6, SOCK_STREAM, IPPROTO_IP) = 10
> 19552 setsockopt(10, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
> 19552 setsockopt(10, SOL_SOCKET, SO_REUSEPORT, [1], 4) = 0
> 19552 setsockopt(10, SOL_TCP, TCP_NODELAY, [1], 4) = 0
> 19552 fcntl(10, F_SETFD, FD_CLOEXEC)= 0
> 19552 fcntl(10, F_GETFL)= 0x2 (flags O_RDWR)
> 19552 fcntl(10, F_SETFL, O_RDWR|O_NONBLOCK) = 0
> 19552 connect(10, {sa_family=AF_INET6, sin6_port=htons(631),
> inet_pton(AF_INET6, "::1", _addr), sin6_flowinfo=0, sin6_scope_id=0},
> 28) = -1 EINPROGRESS (Operation now in progress)
> 19552 fcntl(10, F_SETFL, O_RDWR)= 0
> 19552 poll([{fd=10, events=POLLIN|POLLOUT}], 1, 100) = 1 ([{fd=10,
> revents=POLLIN|POLLOUT|POLLERR|POLLHUP}])
> 19552 sendto(10, "POST / HTTP/1.1\r\nContent-Length:"..., 169, 0, NULL, 0)
> = -1 ECONNREFUSED (Connection refused)
> ...

I have no special skills in interpreting strace outputs but this would
appear to be confirmation that cups-browsed cannot contact cups when it
closes down. But cups is running, so it is beginning to pass through my
mind that your issue is not the same as Heinrich's.

How do you go on with

  systemctl start cups.service cups-browsed.service
  systemctl stop cups.service
  systemctl status cups-browsed.service

Is there a 90 second hang when cups is stopped?

Cheers,

Brian.

Bug#832637: More info

[Roderich Schupp]

On Sun, Aug 21, 2016 at 4:27 PM, Brian Potkin 
wrote:

> Are you positive cups.service is still running while cups-browsed is
> stopping? 'systemctl status cups' in another terminal would tell you.
>

Yes


> If I use the sequence
>
>   systemctl start cups cups-browsed.service
>   systemctl stop cups-browsed.service
>
> it stops cups-browsed immediately here.
>

I just did:

# systemctl start cups cups-browsed.service
# systemctl status cups cups-browsed.service
cups.service - CUPS Scheduler
   Loaded: loaded (/lib/systemd/system/cups.service; enabled; vendor
preset: ena
   Active: active (running) since Sun 2016-08-21 09:14:34 CEST; 8h ago
   ...
cups-browsed.service - Make remote CUPS printers available locally
   Loaded: loaded (/lib/systemd/system/cups-browsed.service; enabled;
vendor pre
   Active: active (running) since Sun 2016-08-21 17:16:33 CEST; 9s ago
   ...
# systemctl stop cups-browsed.service
(waits 90 sec)

If I strace the cups-browsed process (all threads) during tese 90 seconds I
see it repeats the following until it gets killed:

19552 connect(10, {sa_family=AF_INET6, sin6_port=htons(631),
inet_pton(AF_INET6, "::1", _addr), sin6_flowinfo=0, sin6_scope_id=0},
28) = -1 EINPROGRESS (Operation now in progress)
19552 fcntl(10, F_SETFL, O_RDWR)= 0
19552 poll([{fd=10, events=POLLIN|POLLOUT}], 1, 100) = 1 ([{fd=10,
revents=POLLIN|POLLOUT|POLLERR|POLLHUP}])
19552 sendto(10, "POST / HTTP/1.1\r\nContent-Length:"..., 169, 0, NULL, 0)
= -1 ECONNREFUSED (Connection refused)
19552 sendto(10, "POST / HTTP/1.1\r\nContent-Length:"..., 169, 0, NULL, 0)
= -1 EPIPE (Broken pipe)
19552 --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=19552,
si_uid=0} ---
19552 sendto(10, "POST / HTTP/1.1\r\nContent-Length:"..., 169, 0, NULL, 0)
= -1 EPIPE (Broken pipe)
19552 --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=19552,
si_uid=0} ---
19552 close(10) = 0
19552 socket(AF_INET6, SOCK_STREAM, IPPROTO_IP) = 10
19552 setsockopt(10, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
19552 setsockopt(10, SOL_SOCKET, SO_REUSEPORT, [1], 4) = 0
19552 setsockopt(10, SOL_TCP, TCP_NODELAY, [1], 4) = 0
19552 fcntl(10, F_SETFD, FD_CLOEXEC)= 0
19552 fcntl(10, F_GETFL)= 0x2 (flags O_RDWR)
19552 fcntl(10, F_SETFL, O_RDWR|O_NONBLOCK) = 0
19552 connect(10, {sa_family=AF_INET6, sin6_port=htons(631),
inet_pton(AF_INET6, "::1", _addr), sin6_flowinfo=0, sin6_scope_id=0},
28) = -1 EINPROGRESS (Operation now in progress)
19552 fcntl(10, F_SETFL, O_RDWR)= 0
19552 poll([{fd=10, events=POLLIN|POLLOUT}], 1, 100) = 1 ([{fd=10,
revents=POLLIN|POLLOUT|POLLERR|POLLHUP}])
19552 sendto(10, "POST / HTTP/1.1\r\nContent-Length:"..., 169, 0, NULL, 0)
= -1 ECONNREFUSED (Connection refused)
...


Cheers, Roderich

Bug#832637: More info

[Roderich Schupp]

I have the same problem as Heinrich Schuchardt (same version of
cups-browsed, but cups-daemon  2.2~rc1-4 from experimental).

$ sudo systemctl stop cups-browsed.service

takes 90 seconds (while avahi-daemon.service and cups.service are still
running). journalctl shows

Aug 21 14:38:52 macarthur sudo[16227]: pam_unix(sudo:session): session
opened for user root by roderich(uid=0)
Aug 21 14:38:52 macarthur systemd[1]: Stopping Make remote CUPS printers
available locally...
Aug 21 14:40:01 macarthur CRON[16255]: pam_unix(cron:session): session
opened for user root by (uid=0)
Aug 21 14:40:01 macarthur CRON[16260]: (root) CMD ([ -x /usr/sbin/dma ] &&
/usr/sbin/dma -q1)
Aug 21 14:40:01 macarthur CRON[16255]: pam_unix(cron:session): session
closed for user root
Aug 21 14:40:22 macarthur systemd[1]: cups-browsed.service: State
'stop-sigterm' timed out. Killing.
Aug 21 14:40:22 macarthur systemd[1]: cups-browsed.service: Killing process
1630 (cups-browsed) with signal SIGKILL.
Aug 21 14:40:22 macarthur systemd[1]: cups-browsed.service: Main process
exited, code=killed, status=9/KILL
Aug 21 14:40:22 macarthur sudo[16227]: pam_unix(sudo:session): session
closed for user root
Aug 21 14:40:22 macarthur systemd[1]: Stopped Make remote CUPS printers
available locally.
Aug 21 14:40:22 macarthur systemd[1]: cups-browsed.service: Unit entered
failed state.
Aug 21 14:40:22 macarthur systemd[1]: cups-browsed.service: Failed with
result 'signal'.

--- /lib/systemd/system/cups-browsed.service ---
[Unit]
Description=Make remote CUPS printers available locally
Requires=cups.service
After=cups.service avahi-daemon.service
Wants=avahi-daemon.service

[Service]
ExecStart=/usr/sbin/cups-browsed

[Install]
WantedBy=multi-user.target
---

--- /lib/systemd/system/cups.service ---
[Unit]
Description=CUPS Scheduler
Documentation=man:cupsd(8)

[Service]
ExecStart=/usr/sbin/cupsd -l
Type=simple

[Install]
Also=cups.socket cups.path
WantedBy=printer.target
---


Cheers, Roderich