Bug 1540180

Summary:	there is some strange error about dbus, avahi when printing
Product:	[Fedora] Fedora	Reporter:	Petr Sklenar <psklenar>
Component:	avahi	Assignee:	Rex Dieter <rdieter>
Status:	NEW ---	QA Contact:	Fedora Extras Quality Assurance <extras-qa>
Severity:	unspecified	Docs Contact:
Priority:	unspecified
Version:	rawhide	CC:	david.vantyghem, john.j5live, lpoetter, msekleta, qe-baseos-daemons, rdieter
Target Milestone:	---	Keywords:	FutureFeature, Patch, Upstream
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:	1534489	Environment:
Last Closed:		Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Petr Sklenar 2018-01-30 12:38:42 UTC

+++ This bug was initially created as a clone of Bug #1534489 +++

Description of problem:
there is some strange error about avahi? dbus? when printing, no idea why its connected

Version-Release number of selected component (if applicable):
firefox-52.5.1-1.el7_4.x86_64
dbus-1.10.24-3.el7.x86_64
avahi-0.6.31-19.el7.x86_64
cups-1.6.3-35.el7.x86_64


How reproducible:
tried once, and its always there

Steps to Reproduce:
1. rhe75 nightly, server with GUI, all default
2. add usb printer
3. firefox + print whatever page
4, I did no setup of avahi, its all by default

Actual results:
log shows some error:

Jan 15 11:06:31 localhost dbus[689]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.2" (uid=70 pid=686 comm="avahi-daemon: starting up ") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.434" (uid=0 pid=3762 comm="/usr/lib64/firefox/firefox ")
Jan 15 11:06:31 localhost dbus[689]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.2" (uid=70 pid=686 comm="avahi-daemon: starting up ") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.434" (uid=0 pid=3762 comm="/usr/lib64/firefox/firefox ")

Expected results:
log is without error in case of default installation


--- Additional comment from Michal Sekletar on 2018-01-25 17:03:15 CET ---

I was able to figure out the root cause. Problem is that avahi client (GNOME print dialog -- the issue is not specific to Firefox, evince and gedit have the same problem) calls Free() method on ServerBrowser object and in the method_call message it sets NO_REPLY_EXPECTED flag. However, avahi didn't respect the flag (avahi was written around the same time when dbus-daemon and NO_REPLY_EXPECTED flag was a newer addition to the dbus spec and daemon) and sent method_reply (OK) anyway. Our new dbus-daemon (rebased in RHEL-7.5) doesn't like that so it dropped the message and logged an error.

This is not the new problem, also Fedora has the same issue.

--- Additional comment from Michal Sekletar on 2018-01-29 17:11:50 CET ---

Patch posted upstream,

https://github.com/lathiat/avahi/pull/165

--- Additional comment from Michal Sekletar on 2018-01-29 17:13:30 CET ---

Issue was always present in avahi. This isn't a regression.

Comment 1 InfoLibre 2020-07-18 13:29:22 UTC

I've got the same error message.

I updated a computer from Linux Mint MATE 19.3 to Linux Mint MATE 20. This computer prints on a Brother-HL-3170CDW, it works.
I installed Linux Mint MATE 20 on another computer in the same network, with the same 2 packages hl3170cdwlpr-1.1.2-1.i386.deb and hl3170cdwcupswrapper-1.1.4-0.i386.deb. This computer prints on the same printer, with the same protocol (ipps://192.168.1.2:443) but it doesn't work, no paper is going out of the printer, the printer LED doesn't even blink. In /var/spool/cups, 2 files d000... and c000... are created each time I'm printing :

-rw-r-----  1 root     lp           234 16 juil. 14:08 d00030-001
-rw-r-----  1 root     lp            27 16 juil. 14:06 d00029-001
-rw-r-----  1 root     lp            32 16 juil. 14:05 d00028-001
-rw-r-----  1 root     lp            27 16 juil. 13:59 d00027-001
-rw-r-----  1 root     lp            27 16 juil. 13:59 d00026-001
-rw-r-----  1 root     lp         45830 16 juil. 13:27 d00025-001
-rw-------  1 root     lp           970 16 juil. 14:08 c00030
-rw-------  1 root     lp           964 16 juil. 14:06 c00029
-rw-------  1 root     lp          1006 16 juil. 14:05 c00028
-rw-------  1 root     lp           964 16 juil. 14:00 c00027
-rw-------  1 root     lp           964 16 juil. 13:59 c00026
-rw-------  1 root     lp          1395 16 juil. 13:53 c00025

In /var/log/cups/access_log/ :

localhost - - [16/Jul/2020:13:20:41 +0200] "POST /printers/Brother-HL-3170CDW HTTP/1.1" 200 46523 Print-Job successful-ok
localhost - - [16/Jul/2020:13:25:33 +0200] "POST /printers/Brother-HL-3170CDW HTTP/1.1" 200 94388 Print-Job successful-ok
localhost - - [16/Jul/2020:13:27:20 +0200] "POST /printers/Brother-HL-3170CDW HTTP/1.1" 200 46523 Print-Job successful-ok
localhost - - [16/Jul/2020:13:59:20 +0200] "POST /printers/Brother-HL-3170CDW HTTP/1.1" 200 262 Print-Job successful-ok
localhost - - [16/Jul/2020:13:59:53 +0200] "POST /printers/Brother-HL-3170CDW HTTP/1.1" 200 262 Print-Job successful-ok
localhost - - [16/Jul/2020:14:05:30 +0200] "POST /printers/Brother-HL-3170CDW HTTP/1.1" 200 267 Print-Job successful-ok
localhost - - [16/Jul/2020:14:06:24 +0200] "POST /printers/Brother-HL-3170CDW HTTP/1.1" 200 262 Print-Job successful-ok
localhost - - [16/Jul/2020:14:08:03 +0200] "POST /printers/Brother-HL-3170CDW HTTP/1.1" 200 420 Print-Job successful-ok

In /var/log/auth.log :

    Jul 17 11:20:35 Ordinateur-David dbus-daemon[895]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.4" (uid=119 pid=892 comm="avahi-daemon: starting up " label="unconfined") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.194" (uid=1000 pid=12700 comm="xed " label="unconfined")

If I print with Firefox, comm="/usr/lib/firefox/firefox " instead of comm="xed " etc.


    $ lpstat -t -v
    scheduler is running
    system default destination: Brother-HL-3170CDW
    matériel pour Brother-HL-3170CDW : ipps://192.168.1.2:443
    matériel pour PDF : cups-pdf:/
    Brother-HL-3170CDW accepte des requêtes depuis ven. 17 juil. 2020 11:56:21
    PDF accepte des requêtes depuis ven. 10 juil. 2020 22:08:15
    printer Brother-HL-3170CDW is idle. enabled since ven. 17 juil. 2020 11:56:21
    printer PDF is idle. enabled since ven. 10 juil. 2020 22:08:15
    matériel pour Brother-HL-3170CDW : ipps://192.168.1.2:443
    matériel pour PDF : cups-pdf:/

    $ ls /etc/cups/ppd
    Brother-HL-3170CDW.ppd PDF.ppd PDF.ppd.O

    $ lpstat -l -e
    Brother-HL-3170CDW permanent ipp://localhost/printers/Brother-HL-3170CDW ipps://192.168.1.2:443
    PDF permanent ipp://localhost/printers/PDF cups-pdf:/

Anyone could help me to know where is the problem ?