Hallo, das ist mein erster Beitrag in diesem Forum ich bin gerade frisch von Ubuntu auf Arch umgezogen und versuche jetzt das System einzurichten. Ich konnte leider über die Suche nichts finden was mir geholfen hätte. Ich hoffe mit meinem Problem mit CUPS ist hier richtig.
ich habe einen Brother MFC-J245 als Drucker installiert, den Treiber habe ich nach einer Anleitung aus dem WIKI angepasst. wenn ich jetzt allerdings Dokumente oder Testseiten drucken möchte, wird der Auftrag zwar an den Drucker gesendet es passiert aber nichts, auch keine Fehlermeldung und CUPS logt den Auftrag als erledigt.
lpstat -p
gibt folgendes aus:
Drucker Brother ist im Leerlauf. Aktiviert seit Do 11 Apr 2019 20:45:18 CEST
Drucker MFC-J245 ist im Leerlauf. Aktiviert seit Do 11 Apr 2019 18:37:56 CEST
("Brother" ist der gleich Drucker als Netzwerkdrucker über eine Fritzbox, mit gleichem Problem)
CUPS/Drucker und Treiber neu installieren habe ich bereits versucht ohne Erfolg
der Errorlog sieht wie folgt aus:
E [11/Apr/2019:18:17:15 +0200] Unknown directive JobPrivateAccess on line 121 of /etc/cups/cupsd.conf.
E [11/Apr/2019:18:17:15 +0200] Unknown directive JobPrivateValues on line 122 of /etc/cups/cupsd.conf.
E [11/Apr/2019:18:17:15 +0200] Unknown directive SubscriptionPrivateAccess on line 123 of /etc/cups/cupsd.conf.
E [11/Apr/2019:18:17:15 +0200] Unknown directive SubscriptionPrivateValues on line 124 of /etc/cups/cupsd.conf.
E [11/Apr/2019:18:24:20 +0200] [cups-deviced] PID 3529 (cups-brf) stopped with status 13!
W [11/Apr/2019:18:26:59 +0200] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'MFC-J245-Gray..\' already exists
W [11/Apr/2019:18:26:59 +0200] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'MFC-J245-RGB..\' already exists
nach debugging und cups neustart sowie einer erneuten Testseite an den Drucker kommt:
E [11/Apr/2019:18:17:15 +0200] Unknown directive JobPrivateAccess on line 121 of /etc/cups/cupsd.conf.
E [11/Apr/2019:18:17:15 +0200] Unknown directive JobPrivateValues on line 122 of /etc/cups/cupsd.conf.
E [11/Apr/2019:18:17:15 +0200] Unknown directive SubscriptionPrivateAccess on line 123 of /etc/cups/cupsd.conf.
E [11/Apr/2019:18:17:15 +0200] Unknown directive SubscriptionPrivateValues on line 124 of /etc/cups/cupsd.conf.
E [11/Apr/2019:18:24:20 +0200] [cups-deviced] PID 3529 (cups-brf) stopped with status 13!
W [11/Apr/2019:18:26:59 +0200] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'MFC-J245-Gray..\' already exists
W [11/Apr/2019:18:26:59 +0200] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'MFC-J245-RGB..\' already exists
E [11/Apr/2019:20:59:47 +0200] Scheduler shutting down due to program error.
I [11/Apr/2019:21:00:04 +0200] Listening to [v1.::1]:631 (IPv6)
I [11/Apr/2019:21:00:04 +0200] Listening to 127.0.0.1:631 (IPv4)
I [11/Apr/2019:21:00:04 +0200] Listening to /run/cups/cups.sock (Domain)
E [11/Apr/2019:21:00:04 +0200] Unknown directive JobPrivateAccess on line 122 of /etc/cups/cupsd.conf.
E [11/Apr/2019:21:00:04 +0200] Unknown directive JobPrivateValues on line 123 of /etc/cups/cupsd.conf.
E [11/Apr/2019:21:00:04 +0200] Unknown directive SubscriptionPrivateAccess on line 124 of /etc/cups/cupsd.conf.
E [11/Apr/2019:21:00:04 +0200] Unknown directive SubscriptionPrivateValues on line 125 of /etc/cups/cupsd.conf.
I [11/Apr/2019:21:00:04 +0200] Remote access is disabled.
D [11/Apr/2019:21:00:04 +0200] Added auto ServerAlias alf-x
I [11/Apr/2019:21:00:04 +0200] Loaded configuration file "/etc/cups/cupsd.conf"
D [11/Apr/2019:21:00:04 +0200] Using keychain "/etc/cups/ssl" for server name "alf-x".
D [11/Apr/2019:21:00:04 +0200] Repairing access permissions of "/etc/cups/classes.conf"
I [11/Apr/2019:21:00:04 +0200] Using default TempDir of /var/spool/cups/tmp...
I [11/Apr/2019:21:00:04 +0200] Configured for up to 100 clients.
I [11/Apr/2019:21:00:04 +0200] Allowing up to 100 client connections per host.
I [11/Apr/2019:21:00:04 +0200] Using policy "default" as the default.
I [11/Apr/2019:21:00:04 +0200] Full reload is required.
I [11/Apr/2019:21:00:04 +0200] Loaded MIME database from "/usr/share/cups/mime" and "/etc/cups": 78 types, 118 filters...
D [11/Apr/2019:21:00:04 +0200] Loading printer Brother...
D [11/Apr/2019:21:00:04 +0200] load_ppd: Loading /var/cache/cups/Brother.data...
D [11/Apr/2019:21:00:04 +0200] cupsdRegisterPrinter(p=0x55963021df30(Brother))
D [11/Apr/2019:21:00:04 +0200] Loading printer MFC-J245...
D [11/Apr/2019:21:00:04 +0200] load_ppd: Loading /var/cache/cups/MFC-J245.data...
D [11/Apr/2019:21:00:04 +0200] cupsdRegisterPrinter(p=0x559630228d40(MFC-J245))
I [11/Apr/2019:21:00:04 +0200] Loading job cache file "/var/cache/cups/job.cache"...
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
I [11/Apr/2019:21:00:04 +0200] Full reload complete.
D [11/Apr/2019:21:00:04 +0200] cupsdCleanFiles(path="/var/spool/cups/tmp", pattern="(null)")
I [11/Apr/2019:21:00:04 +0200] Cleaning out old files in "/var/spool/cups/tmp".
D [11/Apr/2019:21:00:04 +0200] cupsdCleanFiles(path="/var/spool/cups/tmp/.hplip", pattern="(null)")
I [11/Apr/2019:21:00:04 +0200] Cleaning out old files in "/var/spool/cups/tmp/.hplip".
D [11/Apr/2019:21:00:04 +0200] cupsdCleanFiles(path="/var/spool/cups/tmp/.cache", pattern="(null)")
I [11/Apr/2019:21:00:04 +0200] Cleaning out old files in "/var/spool/cups/tmp/.cache".
D [11/Apr/2019:21:00:04 +0200] cupsdCleanFiles(path="/var/spool/cups/tmp/.cache/fontconfig", pattern="(null)")
I [11/Apr/2019:21:00:04 +0200] Cleaning out old files in "/var/spool/cups/tmp/.cache/fontconfig".
D [11/Apr/2019:21:00:04 +0200] cupsdCleanFiles(path="/var/cache/cups", pattern="*.ipp")
I [11/Apr/2019:21:00:04 +0200] Cleaning out old files in "/var/cache/cups".
D [11/Apr/2019:21:00:04 +0200] service_checkin: pid=17746
D [11/Apr/2019:21:00:04 +0200] service_checkin: 1 listeners.
D [11/Apr/2019:21:00:04 +0200] service_add_listener: Listener #1 at fd 3, "/run/cups/cups.sock".
D [11/Apr/2019:21:00:04 +0200] service_add_listener: Matched existing listener #1 to /run/cups/cups.sock.
D [11/Apr/2019:21:00:04 +0200] Creating KeepAlive/PID file "/var/cache/cups/org.cups.cupsd".
D [11/Apr/2019:21:00:04 +0200] Calling FindDeviceById(cups-Brother)
D [11/Apr/2019:21:00:04 +0200] FindDeviceById failed: org.freedesktop.ColorManager.NotFound:device id \'cups-Brother\' does not exist
D [11/Apr/2019:21:00:04 +0200] Using profile ID "Brother-Gray..".
D [11/Apr/2019:21:00:04 +0200] Calling CreateProfile(Brother-Gray..,temp)
D [11/Apr/2019:21:00:04 +0200] Created profile "/org/freedesktop/ColorManager/profiles/Brother_Gray__".
D [11/Apr/2019:21:00:04 +0200] Using profile ID "Brother-RGB..".
D [11/Apr/2019:21:00:04 +0200] Calling CreateProfile(Brother-RGB..,temp)
D [11/Apr/2019:21:00:04 +0200] Created profile "/org/freedesktop/ColorManager/profiles/Brother_RGB__".
I [11/Apr/2019:21:00:04 +0200] Registering ICC color profiles for "Brother".
D [11/Apr/2019:21:00:04 +0200] Calling CreateDevice(cups-Brother,temp)
D [11/Apr/2019:21:00:04 +0200] Created device "/org/freedesktop/ColorManager/devices/cups_Brother".
D [11/Apr/2019:21:00:04 +0200] Calling /org/freedesktop/ColorManager/devices/cups_Brother:AddProfile(/org/freedesktop/ColorManager/profiles/Brother_Gray__) [soft]
D [11/Apr/2019:21:00:04 +0200] Calling /org/freedesktop/ColorManager/devices/cups_Brother:AddProfile(/org/freedesktop/ColorManager/profiles/Brother_RGB__) [soft]
D [11/Apr/2019:21:00:04 +0200] Calling FindDeviceById(cups-MFC-J245)
D [11/Apr/2019:21:00:04 +0200] FindDeviceById failed: org.freedesktop.ColorManager.NotFound:device id \'cups-MFC-J245\' does not exist
D [11/Apr/2019:21:00:04 +0200] Using profile ID "MFC-J245-Gray..".
D [11/Apr/2019:21:00:04 +0200] Calling CreateProfile(MFC-J245-Gray..,temp)
D [11/Apr/2019:21:00:04 +0200] Created profile "/org/freedesktop/ColorManager/profiles/MFC_J245_Gray__".
D [11/Apr/2019:21:00:04 +0200] Using profile ID "MFC-J245-RGB..".
D [11/Apr/2019:21:00:04 +0200] Calling CreateProfile(MFC-J245-RGB..,temp)
D [11/Apr/2019:21:00:04 +0200] Created profile "/org/freedesktop/ColorManager/profiles/MFC_J245_RGB__".
I [11/Apr/2019:21:00:04 +0200] Registering ICC color profiles for "MFC-J245".
D [11/Apr/2019:21:00:04 +0200] Calling CreateDevice(cups-MFC-J245,temp)
D [11/Apr/2019:21:00:04 +0200] Created device "/org/freedesktop/ColorManager/devices/cups_MFC_J245".
D [11/Apr/2019:21:00:04 +0200] Calling /org/freedesktop/ColorManager/devices/cups_MFC_J245:AddProfile(/org/freedesktop/ColorManager/profiles/MFC_J245_Gray__) [soft]
D [11/Apr/2019:21:00:04 +0200] Calling /org/freedesktop/ColorManager/devices/cups_MFC_J245:AddProfile(/org/freedesktop/ColorManager/profiles/MFC_J245_RGB__) [soft]
I [11/Apr/2019:21:00:04 +0200] Listening to [v1.::1]:631 on fd 8...
I [11/Apr/2019:21:00:04 +0200] Listening to 127.0.0.1:631 on fd 9...
I [11/Apr/2019:21:00:04 +0200] Listening to /run/cups/cups.sock on fd 3...
I [11/Apr/2019:21:00:04 +0200] Resuming new connection processing...
D [11/Apr/2019:21:00:04 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [11/Apr/2019:21:00:04 +0200] cupsdAddCert: Adding certificate for PID 0
D [11/Apr/2019:21:00:04 +0200] Notifier dbus started - PID = 17748
D [11/Apr/2019:21:00:04 +0200] Notifier dbus started - PID = 17749
D [11/Apr/2019:21:00:04 +0200] Notifier dbus started - PID = 17750
D [11/Apr/2019:21:00:04 +0200] Notifier dbus started - PID = 17751
D [11/Apr/2019:21:00:04 +0200] Notifier dbus started - PID = 17752
D [11/Apr/2019:21:00:04 +0200] Notifier dbus started - PID = 17753
D [11/Apr/2019:21:00:04 +0200] Notifier dbus started - PID = 17754
D [11/Apr/2019:21:00:04 +0200] Notifier dbus started - PID = 17755
D [11/Apr/2019:21:00:04 +0200] cupsdMarkDirty(----S)
D [11/Apr/2019:21:00:04 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Not busy"
D [11/Apr/2019:21:00:04 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [11/Apr/2019:21:00:04 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:04 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:04 +0200] [Notifier] Connected to D-BUS
D [11/Apr/2019:21:00:04 +0200] [Notifier] ServerStarted
D [11/Apr/2019:21:00:04 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:04 +0200] [Notifier] Connected to D-BUS
D [11/Apr/2019:21:00:04 +0200] [Notifier] Connected to D-BUS
D [11/Apr/2019:21:00:04 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:04 +0200] [Notifier] Connected to D-BUS
D [11/Apr/2019:21:00:04 +0200] Report: clients=0
D [11/Apr/2019:21:00:04 +0200] Report: jobs=0
D [11/Apr/2019:21:00:04 +0200] Report: jobs-active=0
D [11/Apr/2019:21:00:04 +0200] Report: printers=2
D [11/Apr/2019:21:00:04 +0200] Report: stringpool-string-count=1113
D [11/Apr/2019:21:00:04 +0200] Report: stringpool-alloc-bytes=8920
D [11/Apr/2019:21:00:04 +0200] Report: stringpool-total-bytes=21784
D [11/Apr/2019:21:00:04 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:04 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:04 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [11/Apr/2019:21:00:04 +0200] [Client 1] Server address is "/run/cups/cups.sock".
D [11/Apr/2019:21:00:04 +0200] [Client 1] Accepted from localhost (Domain)
D [11/Apr/2019:21:00:04 +0200] [Client 1] Waiting for request.
D [11/Apr/2019:21:00:04 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:04 +0200] [Notifier] Connected to D-BUS
D [11/Apr/2019:21:00:04 +0200] [Notifier] Connected to D-BUS
D [11/Apr/2019:21:00:04 +0200] [Notifier] Connected to D-BUS
D [11/Apr/2019:21:00:04 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:04 +0200] [Notifier] Connected to D-BUS
D [11/Apr/2019:21:00:04 +0200] [Client 1] POST / HTTP/1.1
D [11/Apr/2019:21:00:04 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:04 +0200] [Client 1] Read: status=200, state=6
D [11/Apr/2019:21:00:04 +0200] [Client 1] No authentication data provided.
D [11/Apr/2019:21:00:04 +0200] [Client 1] 2.0 Create-Printer-Subscriptions 1
D [11/Apr/2019:21:00:04 +0200] Create-Printer-Subscriptions /
D [11/Apr/2019:21:00:04 +0200] create_subscriptions(con=0x5596302d7a10(1), uri="/")
D [11/Apr/2019:21:00:04 +0200] pullmethod="ippget"
D [11/Apr/2019:21:00:04 +0200] notify-lease-duration=86400
D [11/Apr/2019:21:00:04 +0200] notify-time-interval=60
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=7ff, dest=(nil)(), job=(nil)(0), uri="(null)")
D [11/Apr/2019:21:00:04 +0200] Added subscription #47 for server.
D [11/Apr/2019:21:00:04 +0200] cupsdMarkDirty(----S)
D [11/Apr/2019:21:00:04 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:04 +0200] [Client 1] Returning IPP successful-ok for Create-Printer-Subscriptions (/) from localhost.
D [11/Apr/2019:21:00:04 +0200] [Client 1] Content-Length: 107
D [11/Apr/2019:21:00:04 +0200] [Client 1] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [11/Apr/2019:21:00:04 +0200] [Client 1] con->http=0x5596302e3d80
D [11/Apr/2019:21:00:04 +0200] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=107, response=0x5596302b7ec0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [11/Apr/2019:21:00:04 +0200] [Client 1] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [11/Apr/2019:21:00:04 +0200] [Client 1] bytes=0, http_state=0, data_remaining=107
D [11/Apr/2019:21:00:04 +0200] [Client 1] Flushing write buffer.
D [11/Apr/2019:21:00:04 +0200] [Client 1] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:04 +0200] [Client 1] Waiting for request.
D [11/Apr/2019:21:00:04 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:04 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [11/Apr/2019:21:00:04 +0200] [Client 2] Server address is "/run/cups/cups.sock".
D [11/Apr/2019:21:00:04 +0200] [Client 2] Accepted from localhost (Domain)
D [11/Apr/2019:21:00:04 +0200] [Client 2] Waiting for request.
D [11/Apr/2019:21:00:04 +0200] [Client 2] POST / HTTP/1.1
D [11/Apr/2019:21:00:04 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:04 +0200] [Client 2] Read: status=200, state=6
D [11/Apr/2019:21:00:04 +0200] [Client 2] No authentication data provided.
D [11/Apr/2019:21:00:04 +0200] [Client 2] 2.0 CUPS-Get-Printers 2
D [11/Apr/2019:21:00:04 +0200] CUPS-Get-Printers
D [11/Apr/2019:21:00:04 +0200] [Client 2] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost.
D [11/Apr/2019:21:00:04 +0200] [Client 2] Content-Length: 2364
D [11/Apr/2019:21:00:04 +0200] [Client 2] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [11/Apr/2019:21:00:04 +0200] [Client 2] con->http=0x5596302f5e70
D [11/Apr/2019:21:00:04 +0200] [Client 2] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=2364, response=0x5596302f1e30(IPP_STATE_DATA), pipe_pid=0, file=-1
D [11/Apr/2019:21:00:04 +0200] [Client 2] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [11/Apr/2019:21:00:04 +0200] [Client 2] bytes=0, http_state=0, data_remaining=2364
D [11/Apr/2019:21:00:04 +0200] [Client 2] Flushing write buffer.
D [11/Apr/2019:21:00:04 +0200] [Client 2] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:04 +0200] [Client 2] Waiting for request.
D [11/Apr/2019:21:00:04 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:04 +0200] [Client 2] POST / HTTP/1.1
D [11/Apr/2019:21:00:04 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [11/Apr/2019:21:00:04 +0200] [Client 2] Read: status=200, state=6
D [11/Apr/2019:21:00:04 +0200] [Client 2] No authentication data provided.
D [11/Apr/2019:21:00:04 +0200] [Client 2] 2.0 CUPS-Get-Default 3
D [11/Apr/2019:21:00:04 +0200] CUPS-Get-Default
D [11/Apr/2019:21:00:04 +0200] [Client 2] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost.
D [11/Apr/2019:21:00:04 +0200] [Client 2] Content-Length: 9585
D [11/Apr/2019:21:00:04 +0200] [Client 2] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [11/Apr/2019:21:00:04 +0200] [Client 2] con->http=0x5596302f5e70
D [11/Apr/2019:21:00:04 +0200] [Client 2] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=9585, response=0x5596302d7790(IPP_STATE_DATA), pipe_pid=0, file=-1
D [11/Apr/2019:21:00:04 +0200] [Client 2] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [11/Apr/2019:21:00:04 +0200] [Client 2] bytes=0, http_state=0, data_remaining=9585
D [11/Apr/2019:21:00:04 +0200] [Client 2] Flushing write buffer.
D [11/Apr/2019:21:00:04 +0200] [Client 2] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:04 +0200] [Client 2] Waiting for request.
D [11/Apr/2019:21:00:04 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:04 +0200] [Client 1] POST / HTTP/1.1
D [11/Apr/2019:21:00:04 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [11/Apr/2019:21:00:04 +0200] [Client 1] Read: status=200, state=6
D [11/Apr/2019:21:00:04 +0200] [Client 1] No authentication data provided.
D [11/Apr/2019:21:00:04 +0200] [Client 1] 2.0 CUPS-Get-Default 4
D [11/Apr/2019:21:00:04 +0200] CUPS-Get-Default
D [11/Apr/2019:21:00:04 +0200] [Client 1] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost.
D [11/Apr/2019:21:00:04 +0200] [Client 1] Content-Length: 9585
D [11/Apr/2019:21:00:04 +0200] [Client 1] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [11/Apr/2019:21:00:04 +0200] [Client 1] con->http=0x5596302e3d80
D [11/Apr/2019:21:00:04 +0200] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=9585, response=0x5596302da060(IPP_STATE_DATA), pipe_pid=0, file=-1
D [11/Apr/2019:21:00:04 +0200] [Client 1] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [11/Apr/2019:21:00:04 +0200] [Client 1] bytes=0, http_state=0, data_remaining=9585
D [11/Apr/2019:21:00:04 +0200] [Client 1] Flushing write buffer.
D [11/Apr/2019:21:00:04 +0200] [Client 1] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:04 +0200] [Client 1] Waiting for request.
D [11/Apr/2019:21:00:04 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:04 +0200] [Client 1] POST / HTTP/1.1
D [11/Apr/2019:21:00:04 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [11/Apr/2019:21:00:04 +0200] [Client 1] Read: status=200, state=6
D [11/Apr/2019:21:00:04 +0200] [Client 1] No authentication data provided.
D [11/Apr/2019:21:00:04 +0200] [Client 1] 2.0 Create-Printer-Subscriptions 5
D [11/Apr/2019:21:00:04 +0200] Create-Printer-Subscriptions /
D [11/Apr/2019:21:00:04 +0200] create_subscriptions(con=0x5596302d7a10(1), uri="/")
D [11/Apr/2019:21:00:04 +0200] recipient="dbus://"
D [11/Apr/2019:21:00:04 +0200] notify-lease-duration=86400
D [11/Apr/2019:21:00:04 +0200] notify-time-interval=0
D [11/Apr/2019:21:00:04 +0200] cupsdAddSubscription(mask=1fffff, dest=(nil)(), job=(nil)(0), uri="dbus://")
D [11/Apr/2019:21:00:04 +0200] Added subscription #48 for server.
D [11/Apr/2019:21:00:04 +0200] cupsdMarkDirty(----S)
D [11/Apr/2019:21:00:04 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:04 +0200] [Client 1] Returning IPP successful-ok for Create-Printer-Subscriptions (/) from localhost.
D [11/Apr/2019:21:00:04 +0200] [Client 1] Content-Length: 107
D [11/Apr/2019:21:00:04 +0200] [Client 1] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [11/Apr/2019:21:00:04 +0200] [Client 1] con->http=0x5596302e3d80
D [11/Apr/2019:21:00:04 +0200] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=107, response=0x5596302d7790(IPP_STATE_DATA), pipe_pid=0, file=-1
D [11/Apr/2019:21:00:04 +0200] [Client 1] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [11/Apr/2019:21:00:04 +0200] [Client 1] bytes=0, http_state=0, data_remaining=107
D [11/Apr/2019:21:00:04 +0200] [Client 1] Flushing write buffer.
D [11/Apr/2019:21:00:04 +0200] [Client 1] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:04 +0200] [Client 1] Waiting for request.
D [11/Apr/2019:21:00:04 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
I [11/Apr/2019:21:00:05 +0200] Expiring subscriptions...
D [11/Apr/2019:21:00:27 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [11/Apr/2019:21:00:27 +0200] [Client 3] Server address is "[v1.::1]".
D [11/Apr/2019:21:00:27 +0200] [Client 3] Accepted from localhost:41582 (IPv6)
D [11/Apr/2019:21:00:27 +0200] [Client 3] Waiting for request.
I [11/Apr/2019:21:00:27 +0200] Expiring subscriptions...
D [11/Apr/2019:21:00:27 +0200] [Client 3] GET /admin/?OP=redirect HTTP/1.1
D [11/Apr/2019:21:00:27 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:27 +0200] [Client 3] Read: status=200, state=3
D [11/Apr/2019:21:00:27 +0200] [Client 3] Authorized as "alf" using Basic.
D [11/Apr/2019:21:00:27 +0200] [Client 3] Processing GET /admin/?OP=redirect
D [11/Apr/2019:21:00:27 +0200] [CGI] argv[0] = "/usr/lib/cups/cgi-bin/admin.cgi"
D [11/Apr/2019:21:00:27 +0200] [CGI] argv[1] = "OP=redirect"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[0] = "CUPS_CACHEDIR=/var/cache/cups"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[1] = "CUPS_DATADIR=/usr/share/cups"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[2] = "CUPS_DOCROOT=/usr/share/cups/doc"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[3] = "CUPS_FONTPATH=/usr/share/cups/fonts"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[4] = "CUPS_REQUESTROOT=/var/spool/cups"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[5] = "CUPS_SERVERBIN=/usr/lib/cups"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[6] = "CUPS_SERVERROOT=/etc/cups"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[7] = "CUPS_STATEDIR=/run/cups"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[8] = "HOME=/var/spool/cups/tmp"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[9] = "PATH=/usr/lib/cups/filter:/usr/bin:/usr/bin:/bin:/usr/bin"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[10] = "SERVER_ADMIN=root@alf-x"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[11] = "SOFTWARE=CUPS/2.2.11"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[12] = "TMPDIR=/var/spool/cups/tmp"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[13] = "USER=root"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[14] = "CUPS_MAX_MESSAGE=2047"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[15] = "CUPS_SERVER=/run/cups/cups.sock"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[16] = "CUPS_ENCRYPTION=IfRequested"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[17] = "IPP_PORT=631"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[18] = "AUTH_TYPE=Basic"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[19] = "LANG=en_US.UTF8"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[20] = "REDIRECT_STATUS=1"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[21] = "GATEWAY_INTERFACE=CGI/1.1"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[22] = "SERVER_NAME=localhost"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[23] = "SERVER_PORT=631"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[24] = "REMOTE_ADDR=[v1.::1]"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[25] = "REMOTE_HOST=localhost"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[26] = "SCRIPT_NAME=/admin/"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[27] = "SCRIPT_FILENAME=/usr/share/cups/doc/admin/"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[28] = "REMOTE_USER=alf"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[29] = "SERVER_PROTOCOL=HTTP/1.1"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[30] = "HTTP_COOKIE=org.cups.sid=83f03f8ffa47ab8b94585ea5514cb359"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[31] = "HTTP_USER_AGENT=Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[32] = "REQUEST_METHOD=GET"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[33] = "QUERY_STRING=OP=redirect"
D [11/Apr/2019:21:00:27 +0200] cupsdAddCert: Adding certificate for PID 17762
D [11/Apr/2019:21:00:27 +0200] [CGI] Started /usr/lib/cups/cgi-bin/admin.cgi (PID 17762)
I [11/Apr/2019:21:00:27 +0200] [Client 3] Started "/usr/lib/cups/cgi-bin/admin.cgi" (pid=17762, file=26)
D [11/Apr/2019:21:00:27 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:27 +0200] [CGI] admin.cgi started...
D [11/Apr/2019:21:00:27 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:27 +0200] [Client 4] Server address is "/run/cups/cups.sock".
D [11/Apr/2019:21:00:27 +0200] [Client 4] Accepted from localhost (Domain)
D [11/Apr/2019:21:00:27 +0200] [Client 4] Waiting for request.
D [11/Apr/2019:21:00:27 +0200] [CGI] http=0x55960d38c220
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SECTION=\"admin\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REFRESH_PAGE=\"\"
D [11/Apr/2019:21:00:27 +0200] [CGI] org.cups.sid cookie is \"83f03f8ffa47ab8b94585ea5514cb359\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: OP=\"redirect\"
D [11/Apr/2019:21:00:27 +0200] [CGI] redirecting with prefix http://localhost:631!
D [11/Apr/2019:21:00:27 +0200] [Client 4] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [11/Apr/2019:21:00:27 +0200] [Client 4] Closing connection.
D [11/Apr/2019:21:00:27 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:27 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:27 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:27 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=2147483647, response=(nil)(), pipe_pid=17762, file=26
D [11/Apr/2019:21:00:27 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:27 +0200] [Client 3] Script header: Location: http://localhost:631/admin
D [11/Apr/2019:21:00:27 +0200] [Client 3] Script header:
D [11/Apr/2019:21:00:27 +0200] [Client 3] Sending status 303 for CGI.
D [11/Apr/2019:21:00:27 +0200] [Client 3] cupsdSendHeader: code=303, type="(null)", auth_type=0
D [11/Apr/2019:21:00:27 +0200] [Client 3] Flushing write buffer.
D [11/Apr/2019:21:00:27 +0200] [Client 3] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:27 +0200] [Client 3] Waiting for request.
D [11/Apr/2019:21:00:27 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:27 +0200] PID 17762 (/usr/lib/cups/cgi-bin/admin.cgi) exited with no errors.
D [11/Apr/2019:21:00:27 +0200] [Client 3] GET /admin HTTP/1.1
D [11/Apr/2019:21:00:27 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [11/Apr/2019:21:00:27 +0200] [Client 3] Read: status=200, state=3
D [11/Apr/2019:21:00:27 +0200] [Client 3] Authorized as "alf" using Basic.
D [11/Apr/2019:21:00:27 +0200] [Client 3] Processing GET /admin
D [11/Apr/2019:21:00:27 +0200] [CGI] argv[0] = "/usr/lib/cups/cgi-bin/admin.cgi"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[0] = "CUPS_CACHEDIR=/var/cache/cups"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[1] = "CUPS_DATADIR=/usr/share/cups"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[2] = "CUPS_DOCROOT=/usr/share/cups/doc"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[3] = "CUPS_FONTPATH=/usr/share/cups/fonts"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[4] = "CUPS_REQUESTROOT=/var/spool/cups"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[5] = "CUPS_SERVERBIN=/usr/lib/cups"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[6] = "CUPS_SERVERROOT=/etc/cups"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[7] = "CUPS_STATEDIR=/run/cups"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[8] = "HOME=/var/spool/cups/tmp"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[9] = "PATH=/usr/lib/cups/filter:/usr/bin:/usr/bin:/bin:/usr/bin"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[10] = "SERVER_ADMIN=root@alf-x"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[11] = "SOFTWARE=CUPS/2.2.11"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[12] = "TMPDIR=/var/spool/cups/tmp"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[13] = "USER=root"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[14] = "CUPS_MAX_MESSAGE=2047"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[15] = "CUPS_SERVER=/run/cups/cups.sock"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[16] = "CUPS_ENCRYPTION=IfRequested"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[17] = "IPP_PORT=631"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[18] = "AUTH_TYPE=Basic"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[19] = "LANG=en_US.UTF8"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[20] = "REDIRECT_STATUS=1"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[21] = "GATEWAY_INTERFACE=CGI/1.1"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[22] = "SERVER_NAME=localhost"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[23] = "SERVER_PORT=631"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[24] = "REMOTE_ADDR=[v1.::1]"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[25] = "REMOTE_HOST=localhost"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[26] = "SCRIPT_NAME=/admin"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[27] = "SCRIPT_FILENAME=/usr/share/cups/doc/admin"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[28] = "REMOTE_USER=alf"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[29] = "SERVER_PROTOCOL=HTTP/1.1"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[30] = "HTTP_COOKIE=org.cups.sid=83f03f8ffa47ab8b94585ea5514cb359"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[31] = "HTTP_USER_AGENT=Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[32] = "REQUEST_METHOD=GET"
D [11/Apr/2019:21:00:27 +0200] [CGI] envp[33] = "QUERY_STRING="
D [11/Apr/2019:21:00:27 +0200] cupsdAddCert: Adding certificate for PID 17763
D [11/Apr/2019:21:00:27 +0200] [CGI] Started /usr/lib/cups/cgi-bin/admin.cgi (PID 17763)
I [11/Apr/2019:21:00:27 +0200] [Client 3] Started "/usr/lib/cups/cgi-bin/admin.cgi" (pid=17763, file=26)
D [11/Apr/2019:21:00:27 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:27 +0200] [CGI] admin.cgi started...
D [11/Apr/2019:21:00:27 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:27 +0200] [Client 5] Server address is "/run/cups/cups.sock".
D [11/Apr/2019:21:00:27 +0200] [Client 5] Accepted from localhost (Domain)
D [11/Apr/2019:21:00:27 +0200] [Client 5] Waiting for request.
D [11/Apr/2019:21:00:27 +0200] [CGI] http=0x55afba683220
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SECTION=\"admin\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REFRESH_PAGE=\"\"
D [11/Apr/2019:21:00:27 +0200] [CGI] org.cups.sid cookie is \"83f03f8ffa47ab8b94585ea5514cb359\"
D [11/Apr/2019:21:00:27 +0200] [CGI] No form data, showing main menu...
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: DEBUG_LOGGING=\"CHECKED\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: HAVE_GSSAPI=\"1\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: KERBEROS=\"\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: PRESERVE_JOB_HISTORY=\"0\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: PRESERVE_JOB_FILES=\"0\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: MAX_CLIENTS=\"100\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: MAX_JOBS=\"0\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: MAX_LOG_SIZE=\"1m\"
D [11/Apr/2019:21:00:27 +0200] [CGI] /usr/share/cups/drivers/pscript5.dll: No such file or directory
D [11/Apr/2019:21:00:27 +0200] [Client 5] POST / HTTP/1.1
D [11/Apr/2019:21:00:27 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:27 +0200] [Client 5] Read: status=200, state=6
D [11/Apr/2019:21:00:27 +0200] [Client 5] No authentication data provided.
D [11/Apr/2019:21:00:27 +0200] [Client 5] 2.0 Get-Subscriptions 1
D [11/Apr/2019:21:00:27 +0200] Get-Subscriptions ipp://localhost/
I [11/Apr/2019:21:00:27 +0200] Expiring subscriptions...
D [11/Apr/2019:21:00:27 +0200] [Client 5] Returning IPP successful-ok for Get-Subscriptions (ipp://localhost/) from localhost.
D [11/Apr/2019:21:00:27 +0200] [Client 5] Content-Length: 3287
D [11/Apr/2019:21:00:27 +0200] [Client 5] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [11/Apr/2019:21:00:27 +0200] [Client 5] con->http=0x5596302fc870
D [11/Apr/2019:21:00:27 +0200] [Client 5] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=3287, response=0x5596302f2290(IPP_STATE_DATA), pipe_pid=0, file=-1
D [11/Apr/2019:21:00:27 +0200] [Client 5] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [11/Apr/2019:21:00:27 +0200] [Client 5] bytes=0, http_state=0, data_remaining=3287
D [11/Apr/2019:21:00:27 +0200] [Client 5] Flushing write buffer.
D [11/Apr/2019:21:00:27 +0200] [Client 5] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:27 +0200] [Client 5] Waiting for request.
D [11/Apr/2019:21:00:27 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[0]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[0]=\"0\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[0]=\"1\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[1]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[1]=\"0\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[1]=\"2\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[2]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[2]=\"0\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[2]=\"7\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[3]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[3]=\"60\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[3]=\"11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_events[4]=\"all\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[4]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_recipient_uri[4]=\"dbus://\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_recipient_name[4]=\"/\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscriber_user_name[4]=\"anonymous\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[4]=\"0\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[4]=\"12\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[5]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[5]=\"0\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[5]=\"13\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[6]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[6]=\"60\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[6]=\"14\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_events[7]=\"all\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[7]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_recipient_uri[7]=\"dbus://\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_recipient_name[7]=\"/\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscriber_user_name[7]=\"anonymous\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[7]=\"0\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[7]=\"15\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[8]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[8]=\"60\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[8]=\"19\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_events[9]=\"all\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[9]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_recipient_uri[9]=\"dbus://\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_recipient_name[9]=\"/\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscriber_user_name[9]=\"anonymous\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[9]=\"0\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[9]=\"20\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[10]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[10]=\"60\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[10]=\"23\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_events[11]=\"all\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[11]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_recipient_uri[11]=\"dbus://\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_recipient_name[11]=\"/\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscriber_user_name[11]=\"anonymous\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[11]=\"0\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[11]=\"24\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[12]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[12]=\"60\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[12]=\"25\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_events[13]=\"all\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[13]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_recipient_uri[13]=\"dbus://\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_recipient_name[13]=\"/\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscriber_user_name[13]=\"anonymous\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[13]=\"0\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[13]=\"26\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[14]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[14]=\"0\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[14]=\"27\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[15]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[15]=\"60\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[15]=\"30\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_events[16]=\"all\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[16]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_recipient_uri[16]=\"dbus://\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_recipient_name[16]=\"/\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscriber_user_name[16]=\"anonymous\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[16]=\"0\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[16]=\"31\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[17]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[17]=\"0\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[17]=\"32\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[18]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[18]=\"0\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[18]=\"33\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[19]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[19]=\"60\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[19]=\"34\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_events[20]=\"all\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[20]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_recipient_uri[20]=\"dbus://\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_recipient_name[20]=\"/\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscriber_user_name[20]=\"anonymous\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[20]=\"0\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[20]=\"35\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[21]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[21]=\"60\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[21]=\"36\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_events[22]=\"all\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[22]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_recipient_uri[22]=\"dbus://\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_recipient_name[22]=\"/\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscriber_user_name[22]=\"anonymous\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[22]=\"0\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[22]=\"37\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[23]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[23]=\"0\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[23]=\"39\"
D [11/Apr/2019:21:00:27 +0200] [Client 5] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [11/Apr/2019:21:00:27 +0200] [Client 5] Closing connection.
D [11/Apr/2019:21:00:27 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:27 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:27 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=2147483647, response=(nil)(), pipe_pid=17763, file=26
D [11/Apr/2019:21:00:27 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:27 +0200] [Client 3] Script header: Content-Type: text/html;charset=utf-8
D [11/Apr/2019:21:00:27 +0200] [Client 3] Script header:
D [11/Apr/2019:21:00:27 +0200] [Client 3] Sending status 200 for CGI.
D [11/Apr/2019:21:00:27 +0200] [Client 3] cupsdSendHeader: code=200, type="(null)", auth_type=0
D [11/Apr/2019:21:00:27 +0200] PID 17763 (/usr/lib/cups/cgi-bin/admin.cgi) exited with no errors.
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[24]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[24]=\"60\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[24]=\"47\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_events[25]=\"all\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_lease_duration[25]=\"86400\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_recipient_uri[25]=\"dbus://\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_recipient_name[25]=\"/\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscriber_user_name[25]=\"anonymous\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_time_interval[25]=\"0\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetArray: notify_subscription_id[25]=\"48\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: TITLE=\"Administration\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:27 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:27 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:27 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17763, file=26
D [11/Apr/2019:21:00:27 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:27 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:27 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:27 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17763, file=26
D [11/Apr/2019:21:00:27 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:27 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:27 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17763, file=26
D [11/Apr/2019:21:00:27 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:27 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:27 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:27 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17763, file=26
D [11/Apr/2019:21:00:27 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:27 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:27 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17763, file=26
D [11/Apr/2019:21:00:27 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:27 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:27 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:27 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17763, file=26
D [11/Apr/2019:21:00:27 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:27 +0200] [Client 3] Sending 0-length chunk.
D [11/Apr/2019:21:00:27 +0200] [Client 3] Flushing write buffer.
D [11/Apr/2019:21:00:27 +0200] [Client 3] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:27 +0200] [Client 3] Waiting for request.
D [11/Apr/2019:21:00:27 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
I [11/Apr/2019:21:00:28 +0200] Expiring subscriptions...
D [11/Apr/2019:21:00:32 +0200] [Client 3] GET /printers/ HTTP/1.1
D [11/Apr/2019:21:00:32 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [11/Apr/2019:21:00:32 +0200] [Client 3] Read: status=200, state=3
D [11/Apr/2019:21:00:32 +0200] [Client 3] Authorized as "alf" using Basic.
D [11/Apr/2019:21:00:32 +0200] [Client 3] Processing GET /printers/
D [11/Apr/2019:21:00:32 +0200] [CGI] argv[0] = "/usr/lib/cups/cgi-bin/printers.cgi"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[0] = "CUPS_CACHEDIR=/var/cache/cups"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[1] = "CUPS_DATADIR=/usr/share/cups"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[2] = "CUPS_DOCROOT=/usr/share/cups/doc"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[3] = "CUPS_FONTPATH=/usr/share/cups/fonts"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[4] = "CUPS_REQUESTROOT=/var/spool/cups"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[5] = "CUPS_SERVERBIN=/usr/lib/cups"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[6] = "CUPS_SERVERROOT=/etc/cups"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[7] = "CUPS_STATEDIR=/run/cups"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[8] = "HOME=/var/spool/cups/tmp"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[9] = "PATH=/usr/lib/cups/filter:/usr/bin:/usr/bin:/bin:/usr/bin"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[10] = "SERVER_ADMIN=root@alf-x"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[11] = "SOFTWARE=CUPS/2.2.11"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[12] = "TMPDIR=/var/spool/cups/tmp"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[13] = "USER=root"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[14] = "CUPS_MAX_MESSAGE=2047"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[15] = "CUPS_SERVER=/run/cups/cups.sock"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[16] = "CUPS_ENCRYPTION=IfRequested"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[17] = "IPP_PORT=631"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[18] = "AUTH_TYPE=Basic"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[19] = "LANG=en_US.UTF8"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[20] = "REDIRECT_STATUS=1"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[21] = "GATEWAY_INTERFACE=CGI/1.1"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[22] = "SERVER_NAME=localhost"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[23] = "SERVER_PORT=631"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[24] = "REMOTE_ADDR=[v1.::1]"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[25] = "REMOTE_HOST=localhost"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[26] = "SCRIPT_NAME=/printers/"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[27] = "SCRIPT_FILENAME=/usr/share/cups/doc/printers/"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[28] = "REMOTE_USER=alf"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[29] = "SERVER_PROTOCOL=HTTP/1.1"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[30] = "HTTP_COOKIE=org.cups.sid=83f03f8ffa47ab8b94585ea5514cb359"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[31] = "HTTP_USER_AGENT=Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[32] = "HTTP_REFERER=http://localhost:631/admin"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[33] = "REQUEST_METHOD=GET"
D [11/Apr/2019:21:00:32 +0200] [CGI] envp[34] = "QUERY_STRING="
D [11/Apr/2019:21:00:32 +0200] cupsdAddCert: Adding certificate for PID 17765
D [11/Apr/2019:21:00:32 +0200] [CGI] Started /usr/lib/cups/cgi-bin/printers.cgi (PID 17765)
I [11/Apr/2019:21:00:32 +0200] [Client 3] Started "/usr/lib/cups/cgi-bin/printers.cgi" (pid=17765, file=26)
D [11/Apr/2019:21:00:32 +0200] [Client 3] Waiting for CGI data.
I [11/Apr/2019:21:00:32 +0200] Expiring subscriptions...
D [11/Apr/2019:21:00:32 +0200] [CGI] org.cups.sid cookie is \"83f03f8ffa47ab8b94585ea5514cb359\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetVariable: SECTION=\"printers\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetVariable: REFRESH_PAGE=\"\"
D [11/Apr/2019:21:00:32 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:32 +0200] [Client 6] Server address is "/run/cups/cups.sock".
D [11/Apr/2019:21:00:32 +0200] [Client 6] Accepted from localhost (Domain)
D [11/Apr/2019:21:00:32 +0200] [Client 6] Waiting for request.
D [11/Apr/2019:21:00:32 +0200] [Client 6] POST / HTTP/1.1
D [11/Apr/2019:21:00:32 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:32 +0200] [Client 6] Read: status=200, state=6
D [11/Apr/2019:21:00:32 +0200] [Client 6] No authentication data provided.
D [11/Apr/2019:21:00:32 +0200] [Client 6] 2.0 CUPS-Get-Default 1
D [11/Apr/2019:21:00:32 +0200] CUPS-Get-Default
D [11/Apr/2019:21:00:32 +0200] [Client 6] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost.
D [11/Apr/2019:21:00:32 +0200] [Client 6] Content-Length: 160
D [11/Apr/2019:21:00:32 +0200] [Client 6] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [11/Apr/2019:21:00:32 +0200] [Client 6] con->http=0x5596302fc870
D [11/Apr/2019:21:00:32 +0200] [Client 6] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=160, response=0x5596302eeaa0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [11/Apr/2019:21:00:32 +0200] [Client 6] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [11/Apr/2019:21:00:32 +0200] [Client 6] bytes=0, http_state=0, data_remaining=160
D [11/Apr/2019:21:00:32 +0200] [Client 6] Flushing write buffer.
D [11/Apr/2019:21:00:32 +0200] [Client 6] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:32 +0200] [Client 6] Waiting for request.
D [11/Apr/2019:21:00:32 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetVariable: DEFAULT_NAME=\"MFC-J245\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetVariable: DEFAULT_URI=\"/printers/MFC-J245\"
D [11/Apr/2019:21:00:32 +0200] [CGI] show_all_printers(http=0x5582f4c6e4e0, user=\"alf\")
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetVariable: TITLE=\"Printers\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:32 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:32 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:32 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=2147483647, response=(nil)(), pipe_pid=17765, file=26
D [11/Apr/2019:21:00:32 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:32 +0200] [Client 3] Script header: Content-Type: text/html;charset=utf-8
D [11/Apr/2019:21:00:32 +0200] [Client 3] Script header:
D [11/Apr/2019:21:00:32 +0200] [Client 3] Sending status 200 for CGI.
D [11/Apr/2019:21:00:32 +0200] [Client 3] cupsdSendHeader: code=200, type="(null)", auth_type=0
D [11/Apr/2019:21:00:32 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:32 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17765, file=26
D [11/Apr/2019:21:00:32 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:32 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:32 +0200] [Client 6] POST / HTTP/1.1
D [11/Apr/2019:21:00:32 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:32 +0200] [Client 6] Read: status=200, state=6
D [11/Apr/2019:21:00:32 +0200] [Client 6] No authentication data provided.
D [11/Apr/2019:21:00:32 +0200] [Client 6] 2.0 CUPS-Get-Printers 2
D [11/Apr/2019:21:00:32 +0200] CUPS-Get-Printers
D [11/Apr/2019:21:00:32 +0200] [Client 6] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost.
D [11/Apr/2019:21:00:32 +0200] [Client 6] Content-Length: 547
D [11/Apr/2019:21:00:32 +0200] [Client 6] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [11/Apr/2019:21:00:32 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:32 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17765, file=26
D [11/Apr/2019:21:00:32 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:32 +0200] [Client 6] con->http=0x5596302fc870
D [11/Apr/2019:21:00:32 +0200] [Client 6] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=547, response=0x5596302b8090(IPP_STATE_DATA), pipe_pid=0, file=-1
D [11/Apr/2019:21:00:32 +0200] [Client 6] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [11/Apr/2019:21:00:32 +0200] [Client 6] bytes=0, http_state=0, data_remaining=547
D [11/Apr/2019:21:00:32 +0200] [Client 6] Flushing write buffer.
D [11/Apr/2019:21:00:32 +0200] [Client 6] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:32 +0200] [Client 6] Waiting for request.
D [11/Apr/2019:21:00:32 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:32 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:32 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17765, file=26
D [11/Apr/2019:21:00:32 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetVariable: TOTAL=\"2\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetArray: printer_state[0]=\"3\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetArray: printer_state_message[0]=\"\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetArray: admin_uri[0]=\"/admin/\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetArray: printer_uri_supported[0]=\"/printers/Brother\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetArray: printer_name[0]=\"Brother\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetArray: printer_location[0]=\"FritzBox\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetArray: printer_info[0]=\"MFCJ245\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetArray: printer_make_and_model[0]=\"Brother MFC-J245 CUPS\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetArray: printer_state[1]=\"3\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetArray: printer_state_message[1]=\"\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetArray: admin_uri[1]=\"/admin/\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetArray: printer_uri_supported[1]=\"/printers/MFC-J245\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetArray: printer_name[1]=\"MFC-J245\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetArray: printer_location[1]=\"alf-x\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetArray: printer_info[1]=\"Brother MFC-J245\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetArray: printer_make_and_model[1]=\"Brother MFC-J245 CUPS\"
D [11/Apr/2019:21:00:32 +0200] [CGI] cgiSetVariable: THISURL=\"/printers/\"
D [11/Apr/2019:21:00:32 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:32 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:32 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17765, file=26
D [11/Apr/2019:21:00:32 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:32 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:32 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17765, file=26
D [11/Apr/2019:21:00:32 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:32 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:32 +0200] [Client 6] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [11/Apr/2019:21:00:32 +0200] [Client 6] Closing connection.
D [11/Apr/2019:21:00:32 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:32 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:32 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17765, file=26
D [11/Apr/2019:21:00:32 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:32 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:32 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17765, file=26
D [11/Apr/2019:21:00:32 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:32 +0200] PID 17765 (/usr/lib/cups/cgi-bin/printers.cgi) exited with no errors.
D [11/Apr/2019:21:00:32 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:32 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:32 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17765, file=26
D [11/Apr/2019:21:00:32 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:32 +0200] [Client 3] Sending 0-length chunk.
D [11/Apr/2019:21:00:32 +0200] [Client 3] Flushing write buffer.
D [11/Apr/2019:21:00:32 +0200] [Client 3] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:32 +0200] [Client 3] Waiting for request.
D [11/Apr/2019:21:00:32 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
I [11/Apr/2019:21:00:33 +0200] Expiring subscriptions...
I [11/Apr/2019:21:00:35 +0200] Saving subscriptions.conf...
D [11/Apr/2019:21:00:35 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Dirty files"
I [11/Apr/2019:21:00:35 +0200] Expiring subscriptions...
D [11/Apr/2019:21:00:36 +0200] [Client 3] GET /printers/Brother HTTP/1.1
D [11/Apr/2019:21:00:36 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [11/Apr/2019:21:00:36 +0200] [Client 3] Read: status=200, state=3
D [11/Apr/2019:21:00:36 +0200] [Client 3] Authorized as "alf" using Basic.
D [11/Apr/2019:21:00:36 +0200] [Client 3] Processing GET /printers/Brother
D [11/Apr/2019:21:00:36 +0200] [CGI] argv[0] = "/usr/lib/cups/cgi-bin/printers.cgi"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[0] = "CUPS_CACHEDIR=/var/cache/cups"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[1] = "CUPS_DATADIR=/usr/share/cups"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[2] = "CUPS_DOCROOT=/usr/share/cups/doc"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[3] = "CUPS_FONTPATH=/usr/share/cups/fonts"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[4] = "CUPS_REQUESTROOT=/var/spool/cups"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[5] = "CUPS_SERVERBIN=/usr/lib/cups"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[6] = "CUPS_SERVERROOT=/etc/cups"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[7] = "CUPS_STATEDIR=/run/cups"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[8] = "HOME=/var/spool/cups/tmp"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[9] = "PATH=/usr/lib/cups/filter:/usr/bin:/usr/bin:/bin:/usr/bin"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[10] = "SERVER_ADMIN=root@alf-x"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[11] = "SOFTWARE=CUPS/2.2.11"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[12] = "TMPDIR=/var/spool/cups/tmp"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[13] = "USER=root"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[14] = "CUPS_MAX_MESSAGE=2047"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[15] = "CUPS_SERVER=/run/cups/cups.sock"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[16] = "CUPS_ENCRYPTION=IfRequested"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[17] = "IPP_PORT=631"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[18] = "AUTH_TYPE=Basic"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[19] = "LANG=en_US.UTF8"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[20] = "REDIRECT_STATUS=1"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[21] = "GATEWAY_INTERFACE=CGI/1.1"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[22] = "SERVER_NAME=localhost"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[23] = "SERVER_PORT=631"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[24] = "REMOTE_ADDR=[v1.::1]"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[25] = "REMOTE_HOST=localhost"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[26] = "SCRIPT_NAME=/printers/Brother"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[27] = "SCRIPT_FILENAME=/usr/share/cups/doc/printers/Brother"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[28] = "PATH_INFO=/Brother"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[29] = "REMOTE_USER=alf"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[30] = "SERVER_PROTOCOL=HTTP/1.1"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[31] = "HTTP_COOKIE=org.cups.sid=83f03f8ffa47ab8b94585ea5514cb359"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[32] = "HTTP_USER_AGENT=Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[33] = "HTTP_REFERER=http://localhost:631/printers/"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[34] = "REQUEST_METHOD=GET"
D [11/Apr/2019:21:00:36 +0200] [CGI] envp[35] = "QUERY_STRING="
D [11/Apr/2019:21:00:36 +0200] cupsdAddCert: Adding certificate for PID 17766
D [11/Apr/2019:21:00:36 +0200] [CGI] Started /usr/lib/cups/cgi-bin/printers.cgi (PID 17766)
I [11/Apr/2019:21:00:36 +0200] [Client 3] Started "/usr/lib/cups/cgi-bin/printers.cgi" (pid=17766, file=26)
D [11/Apr/2019:21:00:36 +0200] [Client 3] Waiting for CGI data.
I [11/Apr/2019:21:00:36 +0200] Expiring subscriptions...
D [11/Apr/2019:21:00:36 +0200] [CGI] org.cups.sid cookie is \"83f03f8ffa47ab8b94585ea5514cb359\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetVariable: SECTION=\"printers\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetVariable: REFRESH_PAGE=\"\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetVariable: PRINTER_NAME=\"Brother\"
D [11/Apr/2019:21:00:36 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [11/Apr/2019:21:00:36 +0200] [Client 7] Server address is "/run/cups/cups.sock".
D [11/Apr/2019:21:00:36 +0200] [Client 7] Accepted from localhost (Domain)
D [11/Apr/2019:21:00:36 +0200] [Client 7] Waiting for request.
D [11/Apr/2019:21:00:36 +0200] [Client 7] POST / HTTP/1.1
D [11/Apr/2019:21:00:36 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [11/Apr/2019:21:00:36 +0200] [Client 7] Read: status=200, state=6
D [11/Apr/2019:21:00:36 +0200] [Client 7] No authentication data provided.
D [11/Apr/2019:21:00:36 +0200] [Client 7] 2.0 CUPS-Get-Default 1
D [11/Apr/2019:21:00:36 +0200] CUPS-Get-Default
D [11/Apr/2019:21:00:36 +0200] [Client 7] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost.
D [11/Apr/2019:21:00:36 +0200] [Client 7] Content-Length: 160
D [11/Apr/2019:21:00:36 +0200] [Client 7] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [11/Apr/2019:21:00:36 +0200] [Client 7] con->http=0x5596302fc870
D [11/Apr/2019:21:00:36 +0200] [Client 7] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=160, response=0x5596302dae30(IPP_STATE_DATA), pipe_pid=0, file=-1
D [11/Apr/2019:21:00:36 +0200] [Client 7] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [11/Apr/2019:21:00:36 +0200] [Client 7] bytes=0, http_state=0, data_remaining=160
D [11/Apr/2019:21:00:36 +0200] [Client 7] Flushing write buffer.
D [11/Apr/2019:21:00:36 +0200] [Client 7] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:36 +0200] [Client 7] Waiting for request.
D [11/Apr/2019:21:00:36 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetVariable: DEFAULT_NAME=\"MFC-J245\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetVariable: DEFAULT_URI=\"/printers/MFC-J245\"
D [11/Apr/2019:21:00:36 +0200] [CGI] show_printer(http=0x55e51aeb64e0, printer=\"Brother\")
D [11/Apr/2019:21:00:36 +0200] [Client 7] POST / HTTP/1.1
D [11/Apr/2019:21:00:36 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [11/Apr/2019:21:00:36 +0200] [Client 7] Read: status=200, state=6
D [11/Apr/2019:21:00:36 +0200] [Client 7] No authentication data provided.
D [11/Apr/2019:21:00:36 +0200] [Client 7] 2.0 Get-Printer-Attributes 2
D [11/Apr/2019:21:00:36 +0200] Get-Printer-Attributes ipp://localhost/printers/Brother
D [11/Apr/2019:21:00:36 +0200] [Client 7] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost/printers/Brother) from localhost.
D [11/Apr/2019:21:00:36 +0200] [Client 7] Content-Length: 618
D [11/Apr/2019:21:00:36 +0200] [Client 7] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [11/Apr/2019:21:00:36 +0200] [Client 7] con->http=0x5596302fc870
D [11/Apr/2019:21:00:36 +0200] [Client 7] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=618, response=0x55963020bad0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [11/Apr/2019:21:00:36 +0200] [Client 7] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [11/Apr/2019:21:00:36 +0200] [Client 7] bytes=0, http_state=0, data_remaining=618
D [11/Apr/2019:21:00:36 +0200] [Client 7] Flushing write buffer.
D [11/Apr/2019:21:00:36 +0200] [Client 7] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:36 +0200] [Client 7] Waiting for request.
D [11/Apr/2019:21:00:36 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetArray: printer_is_accepting_jobs[0]=\"1\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetArray: printer_is_shared[0]=\"0\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetArray: printer_state[0]=\"3\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetArray: admin_uri[0]=\"/admin/\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetArray: printer_uri_supported[0]=\"/printers/Brother\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetArray: printer_name[0]=\"Brother\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetArray: printer_location[0]=\"FritzBox\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetArray: printer_info[0]=\"MFCJ245\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetArray: job_sheets_default[0]=\"none, none\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetArray: device_uri[0]=\"socket://fritz.box:9100\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetArray: color_supported[0]=\"1\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetArray: printer_make_and_model[0]=\"Brother MFC-J245 CUPS\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetArray: media_default[0]=\"iso_a4_210x297mm\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetArray: sides_supported[0]=\"one-sided\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetArray: sides_default[0]=\"one-sided\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetArray: printer_commands[0]=\"AutoConfigure, Clean, PrintSelfTestPage\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetArray: server_is_sharing_printers[0]=\"0\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetVariable: TITLE=\"Brother\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:36 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:36 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:36 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=2147483647, response=(nil)(), pipe_pid=17766, file=26
D [11/Apr/2019:21:00:36 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:36 +0200] [Client 3] Script header: Content-Type: text/html;charset=utf-8
D [11/Apr/2019:21:00:36 +0200] [Client 3] Script header:
D [11/Apr/2019:21:00:36 +0200] [Client 3] Sending status 200 for CGI.
D [11/Apr/2019:21:00:36 +0200] [Client 3] cupsdSendHeader: code=200, type="(null)", auth_type=0
D [11/Apr/2019:21:00:36 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:36 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17766, file=26
D [11/Apr/2019:21:00:36 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:36 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:36 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:36 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17766, file=26
D [11/Apr/2019:21:00:36 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:36 +0200] [CGI] Regular expression \".*Clean.*\"
D [11/Apr/2019:21:00:36 +0200] [CGI] matches[0].rm_so=0
D [11/Apr/2019:21:00:36 +0200] [CGI] matches[1].rm_so=-1
D [11/Apr/2019:21:00:36 +0200] [CGI] Regular expression \".*PrintSelfTestPage.*\"
D [11/Apr/2019:21:00:36 +0200] [CGI] matches[0].rm_so=0
D [11/Apr/2019:21:00:36 +0200] [CGI] matches[1].rm_so=-1
D [11/Apr/2019:21:00:36 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:36 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17766, file=26
D [11/Apr/2019:21:00:36 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:36 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:36 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:36 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17766, file=26
D [11/Apr/2019:21:00:36 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:36 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:36 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17766, file=26
D [11/Apr/2019:21:00:36 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:36 +0200] [Client 7] POST / HTTP/1.1
D [11/Apr/2019:21:00:36 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [11/Apr/2019:21:00:36 +0200] [Client 7] Read: status=200, state=6
D [11/Apr/2019:21:00:36 +0200] [Client 7] No authentication data provided.
D [11/Apr/2019:21:00:36 +0200] [Client 7] 2.0 Get-Jobs 3
D [11/Apr/2019:21:00:36 +0200] Get-Jobs ipp://localhost:631/printers/Brother
D [11/Apr/2019:21:00:36 +0200] [Client 7] Returning IPP successful-ok for Get-Jobs (ipp://localhost:631/printers/Brother) from localhost.
D [11/Apr/2019:21:00:36 +0200] [Client 7] Content-Length: 75
D [11/Apr/2019:21:00:36 +0200] [Client 7] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [11/Apr/2019:21:00:36 +0200] [Client 7] con->http=0x5596302fc870
D [11/Apr/2019:21:00:36 +0200] [Client 7] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=75, response=0x5596302d6f30(IPP_STATE_DATA), pipe_pid=0, file=-1
D [11/Apr/2019:21:00:36 +0200] [Client 7] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [11/Apr/2019:21:00:36 +0200] [Client 7] bytes=0, http_state=0, data_remaining=75
D [11/Apr/2019:21:00:36 +0200] [Client 7] Flushing write buffer.
D [11/Apr/2019:21:00:36 +0200] [Client 7] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:36 +0200] [Client 7] Waiting for request.
D [11/Apr/2019:21:00:36 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiClearVariables called.
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetVariable: SECTION=\"printers\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetVariable: TOTAL=\"0\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetVariable: PRINTER_NAME=\"Brother\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetVariable: PRINTER_URI_SUPPORTED=\"/printers/Brother\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetVariable: THISURL=\"/printers/Brother\"
D [11/Apr/2019:21:00:36 +0200] [CGI] cgiSetVariable: SEARCH_DEST=\"Brother\"
D [11/Apr/2019:21:00:36 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:36 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:36 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17766, file=26
D [11/Apr/2019:21:00:36 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:36 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:36 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17766, file=26
D [11/Apr/2019:21:00:36 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:36 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:36 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:36 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17766, file=26
D [11/Apr/2019:21:00:36 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:36 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:36 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17766, file=26
D [11/Apr/2019:21:00:36 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:36 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:36 +0200] [Client 7] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [11/Apr/2019:21:00:36 +0200] [Client 7] Closing connection.
D [11/Apr/2019:21:00:36 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [11/Apr/2019:21:00:36 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:36 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17766, file=26
D [11/Apr/2019:21:00:36 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:36 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:36 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17766, file=26
D [11/Apr/2019:21:00:36 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:36 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:36 +0200] PID 17766 (/usr/lib/cups/cgi-bin/printers.cgi) exited with no errors.
D [11/Apr/2019:21:00:36 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:36 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17766, file=26
D [11/Apr/2019:21:00:36 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:36 +0200] [Client 3] Sending 0-length chunk.
D [11/Apr/2019:21:00:36 +0200] [Client 3] Flushing write buffer.
D [11/Apr/2019:21:00:36 +0200] [Client 3] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:36 +0200] [Client 3] Waiting for request.
D [11/Apr/2019:21:00:36 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
I [11/Apr/2019:21:00:37 +0200] Expiring subscriptions...
D [11/Apr/2019:21:00:39 +0200] [Client 3] POST /printers/Brother HTTP/1.1
D [11/Apr/2019:21:00:39 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [11/Apr/2019:21:00:39 +0200] [Client 3] Read: status=200, state=6
D [11/Apr/2019:21:00:39 +0200] [Client 3] Authorized as "alf" using Basic.
D [11/Apr/2019:21:00:39 +0200] [CGI] argv[0] = "/usr/lib/cups/cgi-bin/printers.cgi"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[0] = "CUPS_CACHEDIR=/var/cache/cups"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[1] = "CUPS_DATADIR=/usr/share/cups"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[2] = "CUPS_DOCROOT=/usr/share/cups/doc"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[3] = "CUPS_FONTPATH=/usr/share/cups/fonts"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[4] = "CUPS_REQUESTROOT=/var/spool/cups"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[5] = "CUPS_SERVERBIN=/usr/lib/cups"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[6] = "CUPS_SERVERROOT=/etc/cups"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[7] = "CUPS_STATEDIR=/run/cups"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[8] = "HOME=/var/spool/cups/tmp"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[9] = "PATH=/usr/lib/cups/filter:/usr/bin:/usr/bin:/bin:/usr/bin"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[10] = "SERVER_ADMIN=root@alf-x"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[11] = "SOFTWARE=CUPS/2.2.11"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[12] = "TMPDIR=/var/spool/cups/tmp"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[13] = "USER=root"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[14] = "CUPS_MAX_MESSAGE=2047"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[15] = "CUPS_SERVER=/run/cups/cups.sock"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[16] = "CUPS_ENCRYPTION=IfRequested"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[17] = "IPP_PORT=631"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[18] = "AUTH_TYPE=Basic"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[19] = "LANG=en_US.UTF8"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[20] = "REDIRECT_STATUS=1"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[21] = "GATEWAY_INTERFACE=CGI/1.1"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[22] = "SERVER_NAME=localhost"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[23] = "SERVER_PORT=631"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[24] = "REMOTE_ADDR=[v1.::1]"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[25] = "REMOTE_HOST=localhost"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[26] = "SCRIPT_NAME=/printers/Brother"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[27] = "SCRIPT_FILENAME=/usr/share/cups/doc/printers/Brother"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[28] = "PATH_INFO=/Brother"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[29] = "REMOTE_USER=alf"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[30] = "SERVER_PROTOCOL=HTTP/1.1"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[31] = "HTTP_COOKIE=org.cups.sid=83f03f8ffa47ab8b94585ea5514cb359"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[32] = "HTTP_USER_AGENT=Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[33] = "HTTP_REFERER=http://localhost:631/printers/Brother"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[34] = "REQUEST_METHOD=POST"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[35] = "CONTENT_LENGTH=64"
D [11/Apr/2019:21:00:39 +0200] [CGI] envp[36] = "CONTENT_TYPE=application/x-www-form-urlencoded"
D [11/Apr/2019:21:00:39 +0200] cupsdAddCert: Adding certificate for PID 17767
D [11/Apr/2019:21:00:39 +0200] [CGI] Started /usr/lib/cups/cgi-bin/printers.cgi (PID 17767)
I [11/Apr/2019:21:00:39 +0200] [Client 3] Started "/usr/lib/cups/cgi-bin/printers.cgi" (pid=17767, file=27)
D [11/Apr/2019:21:00:39 +0200] [Client 3] Waiting for CGI data.
I [11/Apr/2019:21:00:39 +0200] Expiring subscriptions...
D [11/Apr/2019:21:00:39 +0200] [CGI] org.cups.sid cookie is \"83f03f8ffa47ab8b94585ea5514cb359\"
D [11/Apr/2019:21:00:39 +0200] [CGI] cgiSetVariable: org.cups.sid=\"83f03f8ffa47ab8b94585ea5514cb359\"
D [11/Apr/2019:21:00:39 +0200] [CGI] cgiSetVariable: OP=\"print-test-page\"
D [11/Apr/2019:21:00:39 +0200] [CGI] cgiSetVariable: SECTION=\"printers\"
D [11/Apr/2019:21:00:39 +0200] [CGI] cgiSetVariable: REFRESH_PAGE=\"\"
D [11/Apr/2019:21:00:39 +0200] [CGI] cgiSetVariable: PRINTER_NAME=\"Brother\"
D [11/Apr/2019:21:00:39 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [11/Apr/2019:21:00:39 +0200] [Client 8] Server address is "/run/cups/cups.sock".
D [11/Apr/2019:21:00:39 +0200] [Client 8] Accepted from localhost (Domain)
D [11/Apr/2019:21:00:39 +0200] [Client 8] Waiting for request.
D [11/Apr/2019:21:00:39 +0200] [Client 8] POST /printers/Brother HTTP/1.1
D [11/Apr/2019:21:00:39 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [11/Apr/2019:21:00:39 +0200] [Client 8] Read: status=200, state=6
D [11/Apr/2019:21:00:39 +0200] [Client 8] No authentication data provided.
D [11/Apr/2019:21:00:39 +0200] [Client 8] 2.0 Print-Job 1
D [11/Apr/2019:21:00:39 +0200] Print-Job ipp://localhost:631/printers/Brother
D [11/Apr/2019:21:00:39 +0200] [Job ???] Auto-typing file...
I [11/Apr/2019:21:00:39 +0200] [Job ???] Request file type is application/vnd.cups-pdf-banner.
D [11/Apr/2019:21:00:39 +0200] cupsdMarkDirty(---J-)
D [11/Apr/2019:21:00:39 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients"
D [11/Apr/2019:21:00:39 +0200] [Job 65] Applying default options...
D [11/Apr/2019:21:00:39 +0200] add_job: requesting-user-name="alf"
D [11/Apr/2019:21:00:39 +0200] Adding default job-sheets values "none,none"...
I [11/Apr/2019:21:00:39 +0200] [Job 65] Adding start banner page "none".
D [11/Apr/2019:21:00:39 +0200] Notifier dbus started - PID = 17768
D [11/Apr/2019:21:00:39 +0200] cupsdMarkDirty(----S)
D [11/Apr/2019:21:00:39 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:39 +0200] cupsdMarkDirty(---J-)
D [11/Apr/2019:21:00:39 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
I [11/Apr/2019:21:00:39 +0200] [Job 65] Adding end banner page "none".
I [11/Apr/2019:21:00:39 +0200] [Job 65] File of type application/vnd.cups-pdf-banner queued by "alf".
D [11/Apr/2019:21:00:39 +0200] [Job 65] hold_until=0
I [11/Apr/2019:21:00:39 +0200] [Job 65] Queued on "Brother" by "alf".
D [11/Apr/2019:21:00:39 +0200] [Job 65] time-at-processing=1555009239
D [11/Apr/2019:21:00:39 +0200] cupsdMarkDirty(---J-)
D [11/Apr/2019:21:00:39 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:39 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:39 +0200] cupsdMarkDirty(----S)
D [11/Apr/2019:21:00:39 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:39 +0200] [Job 65] 4 filters for job:
D [11/Apr/2019:21:00:39 +0200] [Job 65] bannertopdf (application/vnd.cups-pdf-banner to application/pdf, cost 32)
D [11/Apr/2019:21:00:39 +0200] [Job 65] pdftopdf (application/pdf to application/vnd.cups-pdf, cost 66)
D [11/Apr/2019:21:00:39 +0200] [Job 65] pdftops (application/vnd.cups-pdf to application/vnd.cups-postscript, cost 100)
D [11/Apr/2019:21:00:39 +0200] [Job 65] brother_lpdwrapper_mfcj245 (application/vnd.cups-postscript to printer/Brother, cost 0)
D [11/Apr/2019:21:00:39 +0200] [Job 65] job-sheets=none,none
D [11/Apr/2019:21:00:39 +0200] [Job 65] argv[0]="Brother"
D [11/Apr/2019:21:00:39 +0200] [Job 65] argv[1]="65"
D [11/Apr/2019:21:00:39 +0200] [Job 65] argv[2]="alf"
D [11/Apr/2019:21:00:39 +0200] [Job 65] argv[3]="Test Page"
D [11/Apr/2019:21:00:39 +0200] [Job 65] argv[4]="1"
D [11/Apr/2019:21:00:39 +0200] [Job 65] argv[5]="job-uuid=urn:uuid:1567cff3-1c69-316f-5301-7ea3bbf43865 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1555009239 time-at-processing=1555009239"
D [11/Apr/2019:21:00:39 +0200] [Job 65] argv[6]="/var/spool/cups/d00065-001"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[7]="CUPS_STATEDIR=/run/cups"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[8]="HOME=/var/spool/cups/tmp"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/bin:/bin:/usr/bin"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[10]="SERVER_ADMIN=root@alf-x"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[11]="SOFTWARE=CUPS/2.2.11"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[13]="USER=root"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[14]="CUPS_MAX_MESSAGE=2047"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[15]="CUPS_SERVER=/run/cups/cups.sock"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[16]="CUPS_ENCRYPTION=IfRequested"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[17]="IPP_PORT=631"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[18]="CHARSET=utf-8"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[19]="LANG=en_US.UTF-8"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[20]="PPD=/etc/cups/ppd/Brother.ppd"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[21]="RIP_MAX_CACHE=128m"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[22]="CONTENT_TYPE=application/vnd.cups-pdf-banner"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[23]="DEVICE_URI=socket://fritz.box:9100"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[24]="PRINTER_INFO=MFCJ245"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[25]="PRINTER_LOCATION=FritzBox"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[26]="PRINTER=Brother"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[27]="PRINTER_STATE_REASONS=none"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[28]="CUPS_FILETYPE=document"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[29]="FINAL_CONTENT_TYPE=application/vnd.cups-postscript"
D [11/Apr/2019:21:00:39 +0200] [Job 65] envp[30]="AUTH_I****"
I [11/Apr/2019:21:00:39 +0200] [Job 65] Started filter /usr/lib/cups/filter/bannertopdf (PID 17769)
I [11/Apr/2019:21:00:39 +0200] [Job 65] Started filter /usr/lib/cups/filter/pdftopdf (PID 17770)
I [11/Apr/2019:21:00:39 +0200] [Job 65] Started filter /usr/lib/cups/filter/pdftops (PID 17771)
I [11/Apr/2019:21:00:39 +0200] [Job 65] Started filter /usr/lib/cups/filter/brother_lpdwrapper_mfcj245 (PID 17772)
I [11/Apr/2019:21:00:39 +0200] [Job 65] Started backend /usr/lib/cups/backend/socket (PID 17773)
D [11/Apr/2019:21:00:39 +0200] cupsdMarkDirty(----S)
D [11/Apr/2019:21:00:39 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:39 +0200] [Client 8] Returning IPP successful-ok for Print-Job (ipp://localhost:631/printers/Brother) from localhost.
D [11/Apr/2019:21:00:39 +0200] [Client 8] Content-Length: 192
D [11/Apr/2019:21:00:39 +0200] [Client 8] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [11/Apr/2019:21:00:39 +0200] [Client 8] con->http=0x5596302fc870
D [11/Apr/2019:21:00:39 +0200] [Client 8] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=192, response=0x5596302da840(IPP_STATE_IDLE), pipe_pid=0, file=-1
D [11/Apr/2019:21:00:39 +0200] [Client 8] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [11/Apr/2019:21:00:39 +0200] [Client 8] bytes=0, http_state=0, data_remaining=192
D [11/Apr/2019:21:00:39 +0200] [Client 8] Flushing write buffer.
D [11/Apr/2019:21:00:39 +0200] [Client 8] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:39 +0200] [Client 8] Waiting for request.
D [11/Apr/2019:21:00:39 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] JobCreated
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] PrinterStateChanged
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] JobState
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:39 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:39 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:39 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:39 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:39 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:39 +0200] [CGI] cgiSetArray: job_uri[0]=\"/jobs/65\"
D [11/Apr/2019:21:00:39 +0200] [CGI] cgiSetArray: job_id[0]=\"65\"
D [11/Apr/2019:21:00:39 +0200] [CGI] cgiSetArray: job_state[0]=\"3\"
D [11/Apr/2019:21:00:39 +0200] [CGI] cgiSetArray: job_state_message[0]=\"\"
D [11/Apr/2019:21:00:39 +0200] [CGI] cgiSetArray: job_state_reasons[0]=\"none\"
D [11/Apr/2019:21:00:39 +0200] [CGI] cgiSetVariable: refresh_page=\"2;URL=/printers/Brother\"
D [11/Apr/2019:21:00:39 +0200] [CGI] cgiSetVariable: TITLE=\"Print Test Page\"
D [11/Apr/2019:21:00:39 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:39 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:39 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:39 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:39 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=2147483647, response=(nil)(), pipe_pid=17767, file=27
D [11/Apr/2019:21:00:39 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:39 +0200] [Client 3] Script header: Content-Type: text/html;charset=utf-8
D [11/Apr/2019:21:00:39 +0200] [Client 3] Script header:
D [11/Apr/2019:21:00:39 +0200] [Client 3] Sending status 200 for CGI.
D [11/Apr/2019:21:00:39 +0200] [Client 3] cupsdSendHeader: code=200, type="(null)", auth_type=0
D [11/Apr/2019:21:00:39 +0200] [CGI] cgiSetVariable: PRINTER_NAME=\"Brother\"
D [11/Apr/2019:21:00:39 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:39 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17767, file=27
D [11/Apr/2019:21:00:39 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:39 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:39 +0200] [Client 8] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [11/Apr/2019:21:00:39 +0200] [Client 8] Closing connection.
D [11/Apr/2019:21:00:39 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [11/Apr/2019:21:00:39 +0200] PID 17767 (/usr/lib/cups/cgi-bin/printers.cgi) exited with no errors.
D [11/Apr/2019:21:00:39 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:39 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17767, file=27
D [11/Apr/2019:21:00:39 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:39 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17767, file=27
D [11/Apr/2019:21:00:39 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:39 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:39 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:39 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17767, file=27
D [11/Apr/2019:21:00:39 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:39 +0200] [Client 3] Sending 0-length chunk.
D [11/Apr/2019:21:00:39 +0200] [Client 3] Flushing write buffer.
D [11/Apr/2019:21:00:39 +0200] [Client 3] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:39 +0200] [Client 3] Waiting for request.
D [11/Apr/2019:21:00:39 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [11/Apr/2019:21:00:39 +0200] [Job 65] pdftopdf: Last filter determined by the PPD: brother_lpdwrapper_mfcj245; FINAL_CONTENT_TYPE: application/vnd.cups-postscript => pdftopdf will not log pages in page_log.
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Job 65] pdftops - copying to temp print file \"/var/spool/cups/tmp/0456b5cba2b8b\"
D [11/Apr/2019:21:00:39 +0200] [Notifier] Connected to D-BUS
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Job 65] STATE: +connecting-to-device
D [11/Apr/2019:21:00:39 +0200] cupsdMarkDirty(---J-)
D [11/Apr/2019:21:00:39 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Printing jobs and dirty files"
D [11/Apr/2019:21:00:39 +0200] cupsdMarkDirty(----S)
D [11/Apr/2019:21:00:39 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] PrinterStateChanged
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Job 65] Looking up \"fritz.box\"...
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Job 65] PDF template file doesn\'t have form. It\'s okay.
D [11/Apr/2019:21:00:39 +0200] [Job 65] STATE: -connecting-to-device
D [11/Apr/2019:21:00:39 +0200] cupsdMarkDirty(---J-)
D [11/Apr/2019:21:00:39 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Dirty files"
D [11/Apr/2019:21:00:39 +0200] cupsdMarkDirty(----S)
D [11/Apr/2019:21:00:39 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] PrinterStateChanged
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:39 +0200] [Job 65] fritz.box=[v1.2001:16b8:62c4:6b00:3681:c4ff:fe2b:c211]
D [11/Apr/2019:21:00:39 +0200] [Job 65] fritz.box=192.168.178.1
D [11/Apr/2019:21:00:39 +0200] [Job 65] PDF interactive form and annotation flattening done via QPDF
D [11/Apr/2019:21:00:39 +0200] [Job 65] fritz.box=[v1.fd00::3681:c4ff:fe2b:c211]
D [11/Apr/2019:21:00:39 +0200] [Job 65] PID 17769 (/usr/lib/cups/filter/bannertopdf) exited with no errors.
D [11/Apr/2019:21:00:39 +0200] [Job 65] Printer make and model: Brother MFC-J245
D [11/Apr/2019:21:00:39 +0200] [Job 65] Switching to Poppler\'s pdftops instead of Ghostscript for Brother, Minolta, Konica Minolta, Dell, and Apple LaserWriter 16/600, 4/600, 12/640, 12/600, 12/660 to work around bugs in the printer\'s PS interpreters
D [11/Apr/2019:21:00:39 +0200] [Job 65] Running command line for pstops: pstops 65 alf \'Test Page\' 1 \'job-uuid=urn:uuid:1567cff3-1c69-316f-5301-7ea3bbf43865 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1555009239 time-at-processing=1555009239\'
D [11/Apr/2019:21:00:39 +0200] [Job 65] PID 17770 (/usr/lib/cups/filter/pdftopdf) exited with no errors.
D [11/Apr/2019:21:00:39 +0200] [Job 65] No resolution information found in the PPD file.
D [11/Apr/2019:21:00:39 +0200] [Job 65] Using image rendering resolution 300 dpi
D [11/Apr/2019:21:00:39 +0200] [Job 65] Running command line for pdftops: pdftops -level3 -origpagesizes -nocenter -r 300 /var/spool/cups/tmp/0456b5cba2b8b -
D [11/Apr/2019:21:00:39 +0200] [Job 65] Started filter pdftops (PID 17780)
D [11/Apr/2019:21:00:39 +0200] [Job 65] Started filter pstops (PID 17782)
D [11/Apr/2019:21:00:39 +0200] [Job 65] cp: cannot stat \'/opt/brother/Printers/mfcj245/inf/brmfcj245rc\': No such file or directory
D [11/Apr/2019:21:00:39 +0200] [Job 65] chmod: cannot access \'/tmp/brmfcj245rc_17772\': No such file or directory
D [11/Apr/2019:21:00:39 +0200] [Job 65] Page = 595x842; 9,9 to 586,833
D [11/Apr/2019:21:00:39 +0200] [Job 65] slow_collate=0, slow_duplex=0, slow_order=0
D [11/Apr/2019:21:00:39 +0200] [Job 65] Before copy_comments - %!PS-Adobe-3.0
D [11/Apr/2019:21:00:39 +0200] [Job 65] %!PS-Adobe-3.0
D [11/Apr/2019:21:00:39 +0200] [Job 65] %Produced by poppler pdftops version: 0.75.0 (http://poppler.freedesktop.org)
D [11/Apr/2019:21:00:39 +0200] [Job 65] %%Creator: cairo 1.10.2 (http://cairographics.org)
D [11/Apr/2019:21:00:39 +0200] [Job 65] %%LanguageLevel: 3
D [11/Apr/2019:21:00:39 +0200] [Job 65] %%DocumentSuppliedResources: (atend)
D [11/Apr/2019:21:00:39 +0200] [Job 65] %%DocumentMedia: A4 595 842 0 () ()
D [11/Apr/2019:21:00:39 +0200] [Job 65] %%BoundingBox: 0 0 595 842
D [11/Apr/2019:21:00:39 +0200] [Job 65] %%Pages: 1
D [11/Apr/2019:21:00:39 +0200] [Job 65] %%EndComments
D [11/Apr/2019:21:00:39 +0200] [Job 65] Before copy_prolog - %%BeginProlog
D [11/Apr/2019:21:00:39 +0200] [Job 65] Before copy_setup - %%BeginSetup
D [11/Apr/2019:21:00:39 +0200] [Job 65] Before page loop - %%Page: 1 1
D [11/Apr/2019:21:00:39 +0200] [Job 65] Copying page 1...
D [11/Apr/2019:21:00:39 +0200] [Job 65] pagew = 577.0, pagel = 824.0
D [11/Apr/2019:21:00:39 +0200] [Job 65] bboxx = 0, bboxy = 0, bboxw = 595, bboxl = 842
D [11/Apr/2019:21:00:39 +0200] [Job 65] PageLeft = 9.0, PageRight = 586.0
D [11/Apr/2019:21:00:39 +0200] [Job 65] PageTop = 833.0, PageBottom = 9.0
D [11/Apr/2019:21:00:39 +0200] [Job 65] PageWidth = 595.0, PageLength = 842.0
D [11/Apr/2019:21:00:40 +0200] [Job 65] Wrote 1 pages...
I [11/Apr/2019:21:00:40 +0200] Expiring subscriptions...
D [11/Apr/2019:21:00:40 +0200] [Job 65] PID 17782 (pstops) exited with no errors.
D [11/Apr/2019:21:00:40 +0200] [Job 65] PID 17780 (pdftops) exited with no errors.
D [11/Apr/2019:21:00:40 +0200] [Job 65] PID 17771 (/usr/lib/cups/filter/pdftops) exited with no errors.
D [11/Apr/2019:21:00:40 +0200] [Job 65] PID 17772 (/usr/lib/cups/filter/brother_lpdwrapper_mfcj245) exited with no errors.
I [11/Apr/2019:21:00:41 +0200] Expiring subscriptions...
D [11/Apr/2019:21:00:41 +0200] [Client 3] GET /printers/Brother HTTP/1.1
D [11/Apr/2019:21:00:41 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [11/Apr/2019:21:00:41 +0200] [Client 3] Read: status=200, state=3
D [11/Apr/2019:21:00:41 +0200] [Client 3] Authorized as "alf" using Basic.
D [11/Apr/2019:21:00:41 +0200] [Client 3] Processing GET /printers/Brother
D [11/Apr/2019:21:00:41 +0200] [CGI] argv[0] = "/usr/lib/cups/cgi-bin/printers.cgi"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[0] = "CUPS_CACHEDIR=/var/cache/cups"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[1] = "CUPS_DATADIR=/usr/share/cups"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[2] = "CUPS_DOCROOT=/usr/share/cups/doc"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[3] = "CUPS_FONTPATH=/usr/share/cups/fonts"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[4] = "CUPS_REQUESTROOT=/var/spool/cups"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[5] = "CUPS_SERVERBIN=/usr/lib/cups"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[6] = "CUPS_SERVERROOT=/etc/cups"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[7] = "CUPS_STATEDIR=/run/cups"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[8] = "HOME=/var/spool/cups/tmp"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[9] = "PATH=/usr/lib/cups/filter:/usr/bin:/usr/bin:/bin:/usr/bin"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[10] = "SERVER_ADMIN=root@alf-x"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[11] = "SOFTWARE=CUPS/2.2.11"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[12] = "TMPDIR=/var/spool/cups/tmp"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[13] = "USER=root"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[14] = "CUPS_MAX_MESSAGE=2047"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[15] = "CUPS_SERVER=/run/cups/cups.sock"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[16] = "CUPS_ENCRYPTION=IfRequested"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[17] = "IPP_PORT=631"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[18] = "AUTH_TYPE=Basic"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[19] = "LANG=en_US.UTF8"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[20] = "REDIRECT_STATUS=1"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[21] = "GATEWAY_INTERFACE=CGI/1.1"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[22] = "SERVER_NAME=localhost"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[23] = "SERVER_PORT=631"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[24] = "REMOTE_ADDR=[v1.::1]"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[25] = "REMOTE_HOST=localhost"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[26] = "SCRIPT_NAME=/printers/Brother"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[27] = "SCRIPT_FILENAME=/usr/share/cups/doc/printers/Brother"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[28] = "PATH_INFO=/Brother"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[29] = "REMOTE_USER=alf"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[30] = "SERVER_PROTOCOL=HTTP/1.1"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[31] = "HTTP_COOKIE=org.cups.sid=83f03f8ffa47ab8b94585ea5514cb359"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[32] = "HTTP_USER_AGENT=Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[33] = "REQUEST_METHOD=GET"
D [11/Apr/2019:21:00:41 +0200] [CGI] envp[34] = "QUERY_STRING="
D [11/Apr/2019:21:00:41 +0200] cupsdAddCert: Adding certificate for PID 17791
D [11/Apr/2019:21:00:41 +0200] [CGI] Started /usr/lib/cups/cgi-bin/printers.cgi (PID 17791)
I [11/Apr/2019:21:00:41 +0200] [Client 3] Started "/usr/lib/cups/cgi-bin/printers.cgi" (pid=17791, file=26)
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [CGI] org.cups.sid cookie is \"83f03f8ffa47ab8b94585ea5514cb359\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: SECTION=\"printers\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: REFRESH_PAGE=\"\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: PRINTER_NAME=\"Brother\"
D [11/Apr/2019:21:00:41 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [11/Apr/2019:21:00:41 +0200] [Client 9] Server address is "/run/cups/cups.sock".
D [11/Apr/2019:21:00:41 +0200] [Client 9] Accepted from localhost (Domain)
D [11/Apr/2019:21:00:41 +0200] [Client 9] Waiting for request.
D [11/Apr/2019:21:00:41 +0200] [Client 9] POST / HTTP/1.1
D [11/Apr/2019:21:00:41 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [11/Apr/2019:21:00:41 +0200] [Client 9] Read: status=200, state=6
D [11/Apr/2019:21:00:41 +0200] [Client 9] No authentication data provided.
D [11/Apr/2019:21:00:41 +0200] [Client 9] 2.0 CUPS-Get-Default 1
D [11/Apr/2019:21:00:41 +0200] CUPS-Get-Default
D [11/Apr/2019:21:00:41 +0200] [Client 9] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost.
D [11/Apr/2019:21:00:41 +0200] [Client 9] Content-Length: 160
D [11/Apr/2019:21:00:41 +0200] [Client 9] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [11/Apr/2019:21:00:41 +0200] [Client 9] con->http=0x559630312dd0
D [11/Apr/2019:21:00:41 +0200] [Client 9] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=160, response=0x55963030fae0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [11/Apr/2019:21:00:41 +0200] [Client 9] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [11/Apr/2019:21:00:41 +0200] [Client 9] bytes=0, http_state=0, data_remaining=160
D [11/Apr/2019:21:00:41 +0200] [Client 9] Flushing write buffer.
D [11/Apr/2019:21:00:41 +0200] [Client 9] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:41 +0200] [Client 9] Waiting for request.
D [11/Apr/2019:21:00:41 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: DEFAULT_NAME=\"MFC-J245\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: DEFAULT_URI=\"/printers/MFC-J245\"
D [11/Apr/2019:21:00:41 +0200] [CGI] show_printer(http=0x558b9812a4e0, printer=\"Brother\")
D [11/Apr/2019:21:00:41 +0200] [Client 9] POST / HTTP/1.1
D [11/Apr/2019:21:00:41 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [11/Apr/2019:21:00:41 +0200] [Client 9] Read: status=200, state=6
D [11/Apr/2019:21:00:41 +0200] [Client 9] No authentication data provided.
D [11/Apr/2019:21:00:41 +0200] [Client 9] 2.0 Get-Printer-Attributes 2
D [11/Apr/2019:21:00:41 +0200] Get-Printer-Attributes ipp://localhost/printers/Brother
D [11/Apr/2019:21:00:41 +0200] [Client 9] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost/printers/Brother) from localhost.
D [11/Apr/2019:21:00:41 +0200] [Client 9] Content-Length: 618
D [11/Apr/2019:21:00:41 +0200] [Client 9] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [11/Apr/2019:21:00:41 +0200] [Client 9] con->http=0x559630312dd0
D [11/Apr/2019:21:00:41 +0200] [Client 9] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=618, response=0x5596302effe0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [11/Apr/2019:21:00:41 +0200] [Client 9] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [11/Apr/2019:21:00:41 +0200] [Client 9] bytes=0, http_state=0, data_remaining=618
D [11/Apr/2019:21:00:41 +0200] [Client 9] Flushing write buffer.
D [11/Apr/2019:21:00:41 +0200] [Client 9] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:41 +0200] [Client 9] Waiting for request.
D [11/Apr/2019:21:00:41 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: printer_is_accepting_jobs[0]=\"1\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: printer_is_shared[0]=\"0\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: printer_state[0]=\"4\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: admin_uri[0]=\"/admin/\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: printer_uri_supported[0]=\"/printers/Brother\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: printer_name[0]=\"Brother\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: printer_location[0]=\"FritzBox\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: printer_info[0]=\"MFCJ245\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: job_sheets_default[0]=\"none, none\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: device_uri[0]=\"socket://fritz.box:9100\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: color_supported[0]=\"1\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: printer_make_and_model[0]=\"Brother MFC-J245 CUPS\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: media_default[0]=\"iso_a4_210x297mm\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: sides_supported[0]=\"one-sided\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: sides_default[0]=\"one-sided\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: printer_commands[0]=\"AutoConfigure, Clean, PrintSelfTestPage\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: server_is_sharing_printers[0]=\"0\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: refresh_page=\"10;URL=/printers/Brother\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: TITLE=\"Brother\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:41 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=2147483647, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [Client 3] Script header: Content-Type: text/html;charset=utf-8
D [11/Apr/2019:21:00:41 +0200] [Client 3] Script header:
D [11/Apr/2019:21:00:41 +0200] [Client 3] Sending status 200 for CGI.
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdSendHeader: code=200, type="(null)", auth_type=0
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [CGI] Regular expression \".*Clean.*\"
D [11/Apr/2019:21:00:41 +0200] [CGI] matches[0].rm_so=0
D [11/Apr/2019:21:00:41 +0200] [CGI] matches[1].rm_so=-1
D [11/Apr/2019:21:00:41 +0200] [CGI] Regular expression \".*PrintSelfTestPage.*\"
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [CGI] matches[0].rm_so=0
D [11/Apr/2019:21:00:41 +0200] [CGI] matches[1].rm_so=-1
D [11/Apr/2019:21:00:41 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [Client 9] POST / HTTP/1.1
D [11/Apr/2019:21:00:41 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [11/Apr/2019:21:00:41 +0200] [Client 9] Read: status=200, state=6
D [11/Apr/2019:21:00:41 +0200] [Client 9] No authentication data provided.
D [11/Apr/2019:21:00:41 +0200] [Client 9] 2.0 Get-Jobs 3
D [11/Apr/2019:21:00:41 +0200] Get-Jobs ipp://localhost:631/printers/Brother
D [11/Apr/2019:21:00:41 +0200] [Client 9] Returning IPP successful-ok for Get-Jobs (ipp://localhost:631/printers/Brother) from localhost.
D [11/Apr/2019:21:00:41 +0200] [Client 9] Content-Length: 320
D [11/Apr/2019:21:00:41 +0200] [Client 9] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [11/Apr/2019:21:00:41 +0200] [Client 9] con->http=0x559630312dd0
D [11/Apr/2019:21:00:41 +0200] [Client 9] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=320, response=0x55963030fae0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [11/Apr/2019:21:00:41 +0200] [Client 9] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [11/Apr/2019:21:00:41 +0200] [Client 9] bytes=0, http_state=0, data_remaining=320
D [11/Apr/2019:21:00:41 +0200] [Client 9] Flushing write buffer.
D [11/Apr/2019:21:00:41 +0200] [Client 9] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:41 +0200] [Client 9] Waiting for request.
D [11/Apr/2019:21:00:41 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiClearVariables called.
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: SECTION=\"printers\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: TOTAL=\"1\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: job_printer_name[0]=\"Brother\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: job_printer_uri[0]=\"/printers/Brother\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: time_at_completed[0]=\"novalue\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: time_at_creation[0]=\"Thu 11 Apr 2019 09:00:39 PM CEST\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: time_at_processing[0]=\"Thu 11 Apr 2019 09:00:39 PM CEST\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: job_id[0]=\"65\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: job_state[0]=\"5\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: job_impressions_completed[0]=\"0\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: job_k_octets[0]=\"1\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetArray: job_printer_state_message[0]=\"\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: PRINTER_NAME=\"Brother\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: PRINTER_URI_SUPPORTED=\"/printers/Brother\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: THISURL=\"/printers/Brother\"
D [11/Apr/2019:21:00:41 +0200] [CGI] cgiSetVariable: SEARCH_DEST=\"Brother\"
D [11/Apr/2019:21:00:41 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:41 +0200] [Client 9] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [11/Apr/2019:21:00:41 +0200] [Client 9] Closing connection.
D [11/Apr/2019:21:00:41 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [Client 3] CGI data ready to be sent.
D [11/Apr/2019:21:00:41 +0200] PID 17791 (/usr/lib/cups/cgi-bin/printers.cgi) exited with no errors.
D [11/Apr/2019:21:00:41 +0200] [Client 3] con->http=0x5596302f9370
D [11/Apr/2019:21:00:41 +0200] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17791, file=26
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for CGI data.
D [11/Apr/2019:21:00:41 +0200] [Client 3] Sending 0-length chunk.
D [11/Apr/2019:21:00:41 +0200] [Client 3] Flushing write buffer.
D [11/Apr/2019:21:00:41 +0200] [Client 3] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:41 +0200] [Client 3] Waiting for request.
D [11/Apr/2019:21:00:41 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [11/Apr/2019:21:00:42 +0200] [Client 3] GET /cups.css HTTP/1.1
D [11/Apr/2019:21:00:42 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [11/Apr/2019:21:00:42 +0200] [Client 3] Read: status=200, state=3
D [11/Apr/2019:21:00:42 +0200] [Client 3] Authorized as "alf" using Basic.
D [11/Apr/2019:21:00:42 +0200] [Client 3] Processing GET /cups.css
D [11/Apr/2019:21:00:42 +0200] [Client 3] filename="/usr/share/cups/doc/cups.css", type=text/css
D [11/Apr/2019:21:00:42 +0200] [Client 3] cupsdSendHeader: code=304, type="(null)", auth_type=0
D [11/Apr/2019:21:00:42 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
I [11/Apr/2019:21:00:42 +0200] Expiring subscriptions...
I [11/Apr/2019:21:00:43 +0200] Expiring subscriptions...
D [11/Apr/2019:21:00:43 +0200] [Job 65] prtGeneralCurrentLocalization type is 0, expected 2!
D [11/Apr/2019:21:00:43 +0200] [Job 65] backendWaitLoop(snmp_fd=6, addr=0x555ae4059be8, side_cb=0x555ae3665e20)
D [11/Apr/2019:21:00:43 +0200] [Job 65] PID 17773 (/usr/lib/cups/backend/socket) exited with no errors.
D [11/Apr/2019:21:00:43 +0200] [Job 65] time-at-completed=1555009243
D [11/Apr/2019:21:00:43 +0200] cupsdMarkDirty(----S)
D [11/Apr/2019:21:00:43 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
I [11/Apr/2019:21:00:43 +0200] [Job 65] Job completed.
I [11/Apr/2019:21:00:43 +0200] Expiring subscriptions...
D [11/Apr/2019:21:00:43 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [11/Apr/2019:21:00:43 +0200] cupsdMarkDirty(----S)
D [11/Apr/2019:21:00:43 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [11/Apr/2019:21:00:43 +0200] cupsdMarkDirty(---J-)
D [11/Apr/2019:21:00:43 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [11/Apr/2019:21:00:43 +0200] [Job 65] Removing from history.
D [11/Apr/2019:21:00:43 +0200] [Job 65] Unloading...
D [11/Apr/2019:21:00:43 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:43 +0200] [Notifier] JobCompleted
D [11/Apr/2019:21:00:43 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:43 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:43 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:43 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:43 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:43 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:43 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:43 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:43 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:43 +0200] [Notifier] PrinterStateChanged
D [11/Apr/2019:21:00:43 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:43 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:43 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:43 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:43 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:43 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:43 +0200] [Notifier] state=3
D [11/Apr/2019:21:00:43 +0200] [Notifier] state=3
I [11/Apr/2019:21:00:44 +0200] Expiring subscriptions...
D [11/Apr/2019:21:00:52 +0200] [Client 3] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [11/Apr/2019:21:00:52 +0200] [Client 3] Closing connection.
D [11/Apr/2019:21:00:52 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Printing jobs and dirty files"
I [11/Apr/2019:21:00:52 +0200] Expiring subscriptions...
D [11/Apr/2019:21:00:52 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [11/Apr/2019:21:00:52 +0200] [Client 10] Server address is "[v1.::1]".
D [11/Apr/2019:21:00:52 +0200] [Client 10] Accepted from localhost:41584 (IPv6)
D [11/Apr/2019:21:00:52 +0200] [Client 10] Waiting for request.
D [11/Apr/2019:21:00:52 +0200] [Client 10] GET /printers/Brother HTTP/1.1
D [11/Apr/2019:21:00:52 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:52 +0200] [Client 10] Read: status=200, state=3
D [11/Apr/2019:21:00:52 +0200] [Client 10] Authorized as "alf" using Basic.
D [11/Apr/2019:21:00:52 +0200] [Client 10] Processing GET /printers/Brother
D [11/Apr/2019:21:00:52 +0200] [CGI] argv[0] = "/usr/lib/cups/cgi-bin/printers.cgi"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[0] = "CUPS_CACHEDIR=/var/cache/cups"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[1] = "CUPS_DATADIR=/usr/share/cups"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[2] = "CUPS_DOCROOT=/usr/share/cups/doc"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[3] = "CUPS_FONTPATH=/usr/share/cups/fonts"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[4] = "CUPS_REQUESTROOT=/var/spool/cups"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[5] = "CUPS_SERVERBIN=/usr/lib/cups"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[6] = "CUPS_SERVERROOT=/etc/cups"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[7] = "CUPS_STATEDIR=/run/cups"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[8] = "HOME=/var/spool/cups/tmp"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[9] = "PATH=/usr/lib/cups/filter:/usr/bin:/usr/bin:/bin:/usr/bin"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[10] = "SERVER_ADMIN=root@alf-x"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[11] = "SOFTWARE=CUPS/2.2.11"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[12] = "TMPDIR=/var/spool/cups/tmp"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[13] = "USER=root"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[14] = "CUPS_MAX_MESSAGE=2047"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[15] = "CUPS_SERVER=/run/cups/cups.sock"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[16] = "CUPS_ENCRYPTION=IfRequested"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[17] = "IPP_PORT=631"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[18] = "AUTH_TYPE=Basic"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[19] = "LANG=en_US.UTF8"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[20] = "REDIRECT_STATUS=1"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[21] = "GATEWAY_INTERFACE=CGI/1.1"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[22] = "SERVER_NAME=localhost"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[23] = "SERVER_PORT=631"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[24] = "REMOTE_ADDR=[v1.::1]"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[25] = "REMOTE_HOST=localhost"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[26] = "SCRIPT_NAME=/printers/Brother"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[27] = "SCRIPT_FILENAME=/usr/share/cups/doc/printers/Brother"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[28] = "PATH_INFO=/Brother"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[29] = "REMOTE_USER=alf"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[30] = "SERVER_PROTOCOL=HTTP/1.1"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[31] = "HTTP_COOKIE=org.cups.sid=83f03f8ffa47ab8b94585ea5514cb359"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[32] = "HTTP_USER_AGENT=Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[33] = "REQUEST_METHOD=GET"
D [11/Apr/2019:21:00:52 +0200] [CGI] envp[34] = "QUERY_STRING="
D [11/Apr/2019:21:00:52 +0200] cupsdAddCert: Adding certificate for PID 17792
D [11/Apr/2019:21:00:52 +0200] [CGI] Started /usr/lib/cups/cgi-bin/printers.cgi (PID 17792)
I [11/Apr/2019:21:00:52 +0200] [Client 10] Started "/usr/lib/cups/cgi-bin/printers.cgi" (pid=17792, file=27)
D [11/Apr/2019:21:00:52 +0200] [Client 10] Waiting for CGI data.
D [11/Apr/2019:21:00:52 +0200] [CGI] org.cups.sid cookie is \"83f03f8ffa47ab8b94585ea5514cb359\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetVariable: SECTION=\"printers\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetVariable: REFRESH_PAGE=\"\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetVariable: PRINTER_NAME=\"Brother\"
D [11/Apr/2019:21:00:52 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:52 +0200] [Client 11] Server address is "/run/cups/cups.sock".
D [11/Apr/2019:21:00:52 +0200] [Client 11] Accepted from localhost (Domain)
D [11/Apr/2019:21:00:52 +0200] [Client 11] Waiting for request.
D [11/Apr/2019:21:00:52 +0200] [Client 11] POST / HTTP/1.1
D [11/Apr/2019:21:00:52 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:52 +0200] [Client 11] Read: status=200, state=6
D [11/Apr/2019:21:00:52 +0200] [Client 11] No authentication data provided.
D [11/Apr/2019:21:00:52 +0200] [Client 11] 2.0 CUPS-Get-Default 1
D [11/Apr/2019:21:00:52 +0200] CUPS-Get-Default
D [11/Apr/2019:21:00:52 +0200] [Client 11] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost.
D [11/Apr/2019:21:00:52 +0200] [Client 11] Content-Length: 160
D [11/Apr/2019:21:00:52 +0200] [Client 11] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [11/Apr/2019:21:00:52 +0200] [Client 11] con->http=0x55963031d890
D [11/Apr/2019:21:00:52 +0200] [Client 11] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=160, response=0x5596302dae30(IPP_STATE_DATA), pipe_pid=0, file=-1
D [11/Apr/2019:21:00:52 +0200] [Client 11] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [11/Apr/2019:21:00:52 +0200] [Client 11] bytes=0, http_state=0, data_remaining=160
D [11/Apr/2019:21:00:52 +0200] [Client 11] Flushing write buffer.
D [11/Apr/2019:21:00:52 +0200] [Client 11] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:52 +0200] [Client 11] Waiting for request.
D [11/Apr/2019:21:00:52 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetVariable: DEFAULT_NAME=\"MFC-J245\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetVariable: DEFAULT_URI=\"/printers/MFC-J245\"
D [11/Apr/2019:21:00:52 +0200] [CGI] show_printer(http=0x5602b53534e0, printer=\"Brother\")
D [11/Apr/2019:21:00:52 +0200] [Client 11] POST / HTTP/1.1
D [11/Apr/2019:21:00:52 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:52 +0200] [Client 11] Read: status=200, state=6
D [11/Apr/2019:21:00:52 +0200] [Client 11] No authentication data provided.
D [11/Apr/2019:21:00:52 +0200] [Client 11] 2.0 Get-Printer-Attributes 2
D [11/Apr/2019:21:00:52 +0200] Get-Printer-Attributes ipp://localhost/printers/Brother
D [11/Apr/2019:21:00:52 +0200] [Client 11] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost/printers/Brother) from localhost.
D [11/Apr/2019:21:00:52 +0200] [Client 11] Content-Length: 618
D [11/Apr/2019:21:00:52 +0200] [Client 11] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [11/Apr/2019:21:00:52 +0200] [Client 11] con->http=0x55963031d890
D [11/Apr/2019:21:00:52 +0200] [Client 11] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=618, response=0x5596302ef4e0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [11/Apr/2019:21:00:52 +0200] [Client 11] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [11/Apr/2019:21:00:52 +0200] [Client 11] bytes=0, http_state=0, data_remaining=618
D [11/Apr/2019:21:00:52 +0200] [Client 11] Flushing write buffer.
D [11/Apr/2019:21:00:52 +0200] [Client 11] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:52 +0200] [Client 11] Waiting for request.
D [11/Apr/2019:21:00:52 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetArray: printer_is_accepting_jobs[0]=\"1\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetArray: printer_is_shared[0]=\"0\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetArray: printer_state[0]=\"3\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetArray: admin_uri[0]=\"/admin/\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetArray: printer_uri_supported[0]=\"/printers/Brother\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetArray: printer_name[0]=\"Brother\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetArray: printer_location[0]=\"FritzBox\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetArray: printer_info[0]=\"MFCJ245\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetArray: job_sheets_default[0]=\"none, none\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetArray: device_uri[0]=\"socket://fritz.box:9100\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetArray: color_supported[0]=\"1\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetArray: printer_make_and_model[0]=\"Brother MFC-J245 CUPS\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetArray: media_default[0]=\"iso_a4_210x297mm\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetArray: sides_supported[0]=\"one-sided\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetArray: sides_default[0]=\"one-sided\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetArray: printer_commands[0]=\"AutoConfigure, Clean, PrintSelfTestPage\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetArray: server_is_sharing_printers[0]=\"0\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetVariable: TITLE=\"Brother\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:52 +0200] [Client 10] CGI data ready to be sent.
D [11/Apr/2019:21:00:52 +0200] [Client 10] con->http=0x5596302f9370
D [11/Apr/2019:21:00:52 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=2147483647, response=(nil)(), pipe_pid=17792, file=27
D [11/Apr/2019:21:00:52 +0200] [Client 10] Waiting for CGI data.
D [11/Apr/2019:21:00:52 +0200] [Client 10] Script header: Content-Type: text/html;charset=utf-8
D [11/Apr/2019:21:00:52 +0200] [Client 10] Script header:
D [11/Apr/2019:21:00:52 +0200] [Client 10] Sending status 200 for CGI.
D [11/Apr/2019:21:00:52 +0200] [Client 10] cupsdSendHeader: code=200, type="(null)", auth_type=0
D [11/Apr/2019:21:00:52 +0200] [Client 10] con->http=0x5596302f9370
D [11/Apr/2019:21:00:52 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17792, file=27
D [11/Apr/2019:21:00:52 +0200] [Client 10] Waiting for CGI data.
D [11/Apr/2019:21:00:52 +0200] [Client 10] CGI data ready to be sent.
D [11/Apr/2019:21:00:52 +0200] [Client 10] con->http=0x5596302f9370
D [11/Apr/2019:21:00:52 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17792, file=27
D [11/Apr/2019:21:00:52 +0200] [Client 10] Waiting for CGI data.
D [11/Apr/2019:21:00:52 +0200] [CGI] Regular expression \".*Clean.*\"
D [11/Apr/2019:21:00:52 +0200] [CGI] matches[0].rm_so=0
D [11/Apr/2019:21:00:52 +0200] [CGI] matches[1].rm_so=-1
D [11/Apr/2019:21:00:52 +0200] [CGI] Regular expression \".*PrintSelfTestPage.*\"
D [11/Apr/2019:21:00:52 +0200] [Client 10] con->http=0x5596302f9370
D [11/Apr/2019:21:00:52 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17792, file=27
D [11/Apr/2019:21:00:52 +0200] [Client 10] Waiting for CGI data.
D [11/Apr/2019:21:00:52 +0200] [CGI] matches[0].rm_so=0
D [11/Apr/2019:21:00:52 +0200] [CGI] matches[1].rm_so=-1
D [11/Apr/2019:21:00:52 +0200] [Client 10] CGI data ready to be sent.
D [11/Apr/2019:21:00:52 +0200] [Client 10] con->http=0x5596302f9370
D [11/Apr/2019:21:00:52 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17792, file=27
D [11/Apr/2019:21:00:52 +0200] [Client 10] Waiting for CGI data.
D [11/Apr/2019:21:00:52 +0200] [Client 10] con->http=0x5596302f9370
D [11/Apr/2019:21:00:52 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17792, file=27
D [11/Apr/2019:21:00:52 +0200] [Client 10] Waiting for CGI data.
D [11/Apr/2019:21:00:52 +0200] [Client 10] CGI data ready to be sent.
D [11/Apr/2019:21:00:52 +0200] [Client 10] con->http=0x5596302f9370
D [11/Apr/2019:21:00:52 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17792, file=27
D [11/Apr/2019:21:00:52 +0200] [Client 10] Waiting for CGI data.
D [11/Apr/2019:21:00:52 +0200] [Client 10] con->http=0x5596302f9370
D [11/Apr/2019:21:00:52 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17792, file=27
D [11/Apr/2019:21:00:52 +0200] [Client 10] Waiting for CGI data.
D [11/Apr/2019:21:00:52 +0200] [Client 10] CGI data ready to be sent.
D [11/Apr/2019:21:00:52 +0200] [Client 10] con->http=0x5596302f9370
D [11/Apr/2019:21:00:52 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17792, file=27
D [11/Apr/2019:21:00:52 +0200] [Client 10] Waiting for CGI data.
D [11/Apr/2019:21:00:52 +0200] [Client 10] con->http=0x5596302f9370
D [11/Apr/2019:21:00:52 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17792, file=27
D [11/Apr/2019:21:00:52 +0200] [Client 10] Waiting for CGI data.
D [11/Apr/2019:21:00:52 +0200] [Client 11] POST / HTTP/1.1
D [11/Apr/2019:21:00:52 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:52 +0200] [Client 11] Read: status=200, state=6
D [11/Apr/2019:21:00:52 +0200] [Client 11] No authentication data provided.
D [11/Apr/2019:21:00:52 +0200] [Client 11] 2.0 Get-Jobs 3
D [11/Apr/2019:21:00:52 +0200] Get-Jobs ipp://localhost:631/printers/Brother
D [11/Apr/2019:21:00:52 +0200] [Client 11] Returning IPP successful-ok for Get-Jobs (ipp://localhost:631/printers/Brother) from localhost.
D [11/Apr/2019:21:00:52 +0200] [Client 11] Content-Length: 75
D [11/Apr/2019:21:00:52 +0200] [Client 11] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [11/Apr/2019:21:00:52 +0200] [Client 11] con->http=0x55963031d890
D [11/Apr/2019:21:00:52 +0200] [Client 11] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=75, response=0x5596302d9f60(IPP_STATE_DATA), pipe_pid=0, file=-1
D [11/Apr/2019:21:00:52 +0200] [Client 11] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [11/Apr/2019:21:00:52 +0200] [Client 11] bytes=0, http_state=0, data_remaining=75
D [11/Apr/2019:21:00:52 +0200] [Client 11] Flushing write buffer.
D [11/Apr/2019:21:00:52 +0200] [Client 11] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:52 +0200] [Client 11] Waiting for request.
D [11/Apr/2019:21:00:52 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:52 +0200] [Client 11] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [11/Apr/2019:21:00:52 +0200] [Client 11] Closing connection.
D [11/Apr/2019:21:00:52 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiClearVariables called.
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetVariable: SECTION=\"printers\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetVariable: TOTAL=\"0\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetVariable: PRINTER_NAME=\"Brother\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetVariable: PRINTER_URI_SUPPORTED=\"/printers/Brother\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetVariable: THISURL=\"/printers/Brother\"
D [11/Apr/2019:21:00:52 +0200] [CGI] cgiSetVariable: SEARCH_DEST=\"Brother\"
D [11/Apr/2019:21:00:52 +0200] [Client 10] CGI data ready to be sent.
D [11/Apr/2019:21:00:52 +0200] [Client 10] con->http=0x5596302f9370
D [11/Apr/2019:21:00:52 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17792, file=27
D [11/Apr/2019:21:00:52 +0200] [Client 10] Waiting for CGI data.
D [11/Apr/2019:21:00:52 +0200] PID 17792 (/usr/lib/cups/cgi-bin/printers.cgi) exited with no errors.
D [11/Apr/2019:21:00:52 +0200] [Client 10] con->http=0x5596302f9370
D [11/Apr/2019:21:00:52 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17792, file=27
D [11/Apr/2019:21:00:52 +0200] [Client 10] Waiting for CGI data.
D [11/Apr/2019:21:00:52 +0200] [Client 10] CGI data ready to be sent.
D [11/Apr/2019:21:00:52 +0200] [Client 10] con->http=0x5596302f9370
D [11/Apr/2019:21:00:52 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17792, file=27
D [11/Apr/2019:21:00:52 +0200] [Client 10] Waiting for CGI data.
D [11/Apr/2019:21:00:52 +0200] [Client 10] Sending 0-length chunk.
D [11/Apr/2019:21:00:52 +0200] [Client 10] Flushing write buffer.
D [11/Apr/2019:21:00:52 +0200] [Client 10] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:52 +0200] [Client 10] Waiting for request.
D [11/Apr/2019:21:00:52 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:52 +0200] [Client 10] GET /cups.css HTTP/1.1
D [11/Apr/2019:21:00:52 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [11/Apr/2019:21:00:52 +0200] [Client 10] Read: status=200, state=3
D [11/Apr/2019:21:00:52 +0200] [Client 10] Authorized as "alf" using Basic.
D [11/Apr/2019:21:00:52 +0200] [Client 10] Processing GET /cups.css
D [11/Apr/2019:21:00:52 +0200] [Client 10] filename="/usr/share/cups/doc/cups.css", type=text/css
D [11/Apr/2019:21:00:52 +0200] [Client 10] cupsdSendHeader: code=304, type="(null)", auth_type=0
D [11/Apr/2019:21:00:52 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
I [11/Apr/2019:21:00:53 +0200] Expiring subscriptions...
D [11/Apr/2019:21:00:54 +0200] [Client 10] GET /admin HTTP/1.1
D [11/Apr/2019:21:00:54 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [11/Apr/2019:21:00:54 +0200] [Client 10] Read: status=200, state=3
D [11/Apr/2019:21:00:54 +0200] [Client 10] Authorized as "alf" using Basic.
D [11/Apr/2019:21:00:54 +0200] [Client 10] Processing GET /admin
D [11/Apr/2019:21:00:54 +0200] [CGI] argv[0] = "/usr/lib/cups/cgi-bin/admin.cgi"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[0] = "CUPS_CACHEDIR=/var/cache/cups"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[1] = "CUPS_DATADIR=/usr/share/cups"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[2] = "CUPS_DOCROOT=/usr/share/cups/doc"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[3] = "CUPS_FONTPATH=/usr/share/cups/fonts"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[4] = "CUPS_REQUESTROOT=/var/spool/cups"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[5] = "CUPS_SERVERBIN=/usr/lib/cups"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[6] = "CUPS_SERVERROOT=/etc/cups"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[7] = "CUPS_STATEDIR=/run/cups"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[8] = "HOME=/var/spool/cups/tmp"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[9] = "PATH=/usr/lib/cups/filter:/usr/bin:/usr/bin:/bin:/usr/bin"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[10] = "SERVER_ADMIN=root@alf-x"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[11] = "SOFTWARE=CUPS/2.2.11"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[12] = "TMPDIR=/var/spool/cups/tmp"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[13] = "USER=root"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[14] = "CUPS_MAX_MESSAGE=2047"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[15] = "CUPS_SERVER=/run/cups/cups.sock"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[16] = "CUPS_ENCRYPTION=IfRequested"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[17] = "IPP_PORT=631"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[18] = "AUTH_TYPE=Basic"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[19] = "LANG=en_US.UTF8"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[20] = "REDIRECT_STATUS=1"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[21] = "GATEWAY_INTERFACE=CGI/1.1"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[22] = "SERVER_NAME=localhost"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[23] = "SERVER_PORT=631"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[24] = "REMOTE_ADDR=[v1.::1]"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[25] = "REMOTE_HOST=localhost"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[26] = "SCRIPT_NAME=/admin"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[27] = "SCRIPT_FILENAME=/usr/share/cups/doc/admin"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[28] = "REMOTE_USER=alf"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[29] = "SERVER_PROTOCOL=HTTP/1.1"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[30] = "HTTP_COOKIE=org.cups.sid=83f03f8ffa47ab8b94585ea5514cb359"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[31] = "HTTP_USER_AGENT=Mozilla/5.0 (X11; Linux x86_64; rv:66.0) Gecko/20100101 Firefox/66.0"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[32] = "HTTP_REFERER=http://localhost:631/printers/Brother"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[33] = "REQUEST_METHOD=GET"
D [11/Apr/2019:21:00:54 +0200] [CGI] envp[34] = "QUERY_STRING="
D [11/Apr/2019:21:00:54 +0200] cupsdAddCert: Adding certificate for PID 17793
D [11/Apr/2019:21:00:54 +0200] [CGI] Started /usr/lib/cups/cgi-bin/admin.cgi (PID 17793)
I [11/Apr/2019:21:00:54 +0200] [Client 10] Started "/usr/lib/cups/cgi-bin/admin.cgi" (pid=17793, file=27)
D [11/Apr/2019:21:00:54 +0200] [Client 10] Waiting for CGI data.
I [11/Apr/2019:21:00:54 +0200] Expiring subscriptions...
D [11/Apr/2019:21:00:54 +0200] [CGI] admin.cgi started...
D [11/Apr/2019:21:00:54 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:54 +0200] [Client 12] Server address is "/run/cups/cups.sock".
D [11/Apr/2019:21:00:54 +0200] [Client 12] Accepted from localhost (Domain)
D [11/Apr/2019:21:00:54 +0200] [Client 12] Waiting for request.
D [11/Apr/2019:21:00:54 +0200] [CGI] http=0x5564c1481220
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SECTION=\"admin\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REFRESH_PAGE=\"\"
D [11/Apr/2019:21:00:54 +0200] [CGI] org.cups.sid cookie is \"83f03f8ffa47ab8b94585ea5514cb359\"
D [11/Apr/2019:21:00:54 +0200] [CGI] No form data, showing main menu...
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: DEBUG_LOGGING=\"CHECKED\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: HAVE_GSSAPI=\"1\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: KERBEROS=\"\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: PRESERVE_JOB_HISTORY=\"0\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: PRESERVE_JOB_FILES=\"0\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: MAX_CLIENTS=\"100\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: MAX_JOBS=\"0\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: MAX_LOG_SIZE=\"1m\"
D [11/Apr/2019:21:00:54 +0200] [CGI] /usr/share/cups/drivers/pscript5.dll: No such file or directory
D [11/Apr/2019:21:00:54 +0200] [Client 12] POST / HTTP/1.1
D [11/Apr/2019:21:00:54 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:54 +0200] [Client 12] Read: status=200, state=6
D [11/Apr/2019:21:00:54 +0200] [Client 12] No authentication data provided.
D [11/Apr/2019:21:00:54 +0200] [Client 12] 2.0 Get-Subscriptions 1
D [11/Apr/2019:21:00:54 +0200] Get-Subscriptions ipp://localhost/
I [11/Apr/2019:21:00:54 +0200] Expiring subscriptions...
D [11/Apr/2019:21:00:54 +0200] [Client 12] Returning IPP successful-ok for Get-Subscriptions (ipp://localhost/) from localhost.
D [11/Apr/2019:21:00:54 +0200] [Client 12] Content-Length: 3287
D [11/Apr/2019:21:00:54 +0200] [Client 12] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [11/Apr/2019:21:00:54 +0200] [Client 12] con->http=0x55963031d890
D [11/Apr/2019:21:00:54 +0200] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=3287, response=0x5596302dae30(IPP_STATE_DATA), pipe_pid=0, file=-1
D [11/Apr/2019:21:00:54 +0200] [Client 12] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [11/Apr/2019:21:00:54 +0200] [Client 12] bytes=0, http_state=0, data_remaining=3287
D [11/Apr/2019:21:00:54 +0200] [Client 12] Flushing write buffer.
D [11/Apr/2019:21:00:54 +0200] [Client 12] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:54 +0200] [Client 12] Waiting for request.
D [11/Apr/2019:21:00:54 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[0]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[0]=\"0\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[0]=\"1\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[1]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[1]=\"0\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[1]=\"2\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[2]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[2]=\"0\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[2]=\"7\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[3]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[3]=\"60\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[3]=\"11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_events[4]=\"all\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[4]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_recipient_uri[4]=\"dbus://\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_recipient_name[4]=\"/\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscriber_user_name[4]=\"anonymous\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[4]=\"0\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[4]=\"12\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[5]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[5]=\"0\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[5]=\"13\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[6]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[6]=\"60\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[6]=\"14\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_events[7]=\"all\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[7]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_recipient_uri[7]=\"dbus://\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_recipient_name[7]=\"/\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscriber_user_name[7]=\"anonymous\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[7]=\"0\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[7]=\"15\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[8]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[8]=\"60\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[8]=\"19\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_events[9]=\"all\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[9]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_recipient_uri[9]=\"dbus://\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_recipient_name[9]=\"/\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscriber_user_name[9]=\"anonymous\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[9]=\"0\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[9]=\"20\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[10]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[10]=\"60\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[10]=\"23\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_events[11]=\"all\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[11]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_recipient_uri[11]=\"dbus://\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_recipient_name[11]=\"/\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscriber_user_name[11]=\"anonymous\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[11]=\"0\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[11]=\"24\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[12]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[12]=\"60\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[12]=\"25\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_events[13]=\"all\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[13]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_recipient_uri[13]=\"dbus://\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_recipient_name[13]=\"/\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscriber_user_name[13]=\"anonymous\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[13]=\"0\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[13]=\"26\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[14]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[14]=\"0\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[14]=\"27\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[15]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[15]=\"60\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[15]=\"30\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_events[16]=\"all\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[16]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_recipient_uri[16]=\"dbus://\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_recipient_name[16]=\"/\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscriber_user_name[16]=\"anonymous\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[16]=\"0\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[16]=\"31\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[17]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[17]=\"0\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[17]=\"32\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[18]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[18]=\"0\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[18]=\"33\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[19]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[19]=\"60\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[19]=\"34\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [Client 10] CGI data ready to be sent.
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_events[20]=\"all\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[20]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_recipient_uri[20]=\"dbus://\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_recipient_name[20]=\"/\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscriber_user_name[20]=\"anonymous\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[20]=\"0\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[20]=\"35\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[21]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[21]=\"60\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[21]=\"36\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_events[22]=\"all\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[22]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_recipient_uri[22]=\"dbus://\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_recipient_name[22]=\"/\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscriber_user_name[22]=\"anonymous\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[22]=\"0\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[22]=\"37\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [Client 10] con->http=0x5596302f9370
D [11/Apr/2019:21:00:54 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=2147483647, response=(nil)(), pipe_pid=17793, file=27
D [11/Apr/2019:21:00:54 +0200] [Client 10] Waiting for CGI data.
D [11/Apr/2019:21:00:54 +0200] [Client 10] Script header: Content-Type: text/html;charset=utf-8
D [11/Apr/2019:21:00:54 +0200] [Client 10] Script header:
D [11/Apr/2019:21:00:54 +0200] [Client 10] Sending status 200 for CGI.
D [11/Apr/2019:21:00:54 +0200] [Client 10] cupsdSendHeader: code=200, type="(null)", auth_type=0
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[23]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[23]=\"0\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[23]=\"39\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[24]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[24]=\"60\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[24]=\"47\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_events[25]=\"all\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_lease_duration[25]=\"86400\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_recipient_uri[25]=\"dbus://\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_recipient_name[25]=\"/\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscriber_user_name[25]=\"anonymous\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_time_interval[25]=\"0\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetArray: notify_subscription_id[25]=\"48\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: TITLE=\"Administration\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: SERVER_NAME=\"localhost\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: REMOTE_USER=\"alf\"
D [11/Apr/2019:21:00:54 +0200] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.11\"
D [11/Apr/2019:21:00:54 +0200] [Client 10] con->http=0x5596302f9370
D [11/Apr/2019:21:00:54 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17793, file=27
D [11/Apr/2019:21:00:54 +0200] [Client 10] Waiting for CGI data.
D [11/Apr/2019:21:00:54 +0200] [Client 12] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [11/Apr/2019:21:00:54 +0200] [Client 12] Closing connection.
D [11/Apr/2019:21:00:54 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [11/Apr/2019:21:00:54 +0200] [Client 10] CGI data ready to be sent.
D [11/Apr/2019:21:00:54 +0200] [Client 10] con->http=0x5596302f9370
D [11/Apr/2019:21:00:54 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17793, file=27
D [11/Apr/2019:21:00:54 +0200] [Client 10] Waiting for CGI data.
D [11/Apr/2019:21:00:54 +0200] [Client 10] con->http=0x5596302f9370
D [11/Apr/2019:21:00:54 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17793, file=27
D [11/Apr/2019:21:00:54 +0200] [Client 10] Waiting for CGI data.
D [11/Apr/2019:21:00:54 +0200] [Client 10] CGI data ready to be sent.
D [11/Apr/2019:21:00:54 +0200] [Client 10] con->http=0x5596302f9370
D [11/Apr/2019:21:00:54 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17793, file=27
D [11/Apr/2019:21:00:54 +0200] [Client 10] Waiting for CGI data.
D [11/Apr/2019:21:00:54 +0200] [Client 10] con->http=0x5596302f9370
D [11/Apr/2019:21:00:54 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17793, file=27
D [11/Apr/2019:21:00:54 +0200] [Client 10] Waiting for CGI data.
D [11/Apr/2019:21:00:54 +0200] [Client 10] CGI data ready to be sent.
D [11/Apr/2019:21:00:54 +0200] PID 17793 (/usr/lib/cups/cgi-bin/admin.cgi) exited with no errors.
D [11/Apr/2019:21:00:54 +0200] [Client 10] con->http=0x5596302f9370
D [11/Apr/2019:21:00:54 +0200] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=17793, file=27
D [11/Apr/2019:21:00:54 +0200] [Client 10] Waiting for CGI data.
D [11/Apr/2019:21:00:54 +0200] [Client 10] Sending 0-length chunk.
D [11/Apr/2019:21:00:54 +0200] [Client 10] Flushing write buffer.
D [11/Apr/2019:21:00:54 +0200] [Client 10] New state is HTTP_STATE_WAITING
D [11/Apr/2019:21:00:54 +0200] [Client 10] Waiting for request.
D [11/Apr/2019:21:00:54 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
I [11/Apr/2019:21:00:55 +0200] Expiring subscriptions...
D [11/Apr/2019:21:00:56 +0200] [Client 10] GET /admin/log/error_log HTTP/1.1
D [11/Apr/2019:21:00:56 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [11/Apr/2019:21:00:56 +0200] [Client 10] Read: status=200, state=3
D [11/Apr/2019:21:00:56 +0200] [Client 10] Authorized as "alf" using Basic.
D [11/Apr/2019:21:00:56 +0200] cupsdIsAuthorized: username="alf"
D [11/Apr/2019:21:00:56 +0200] [Client 10] Processing GET /admin/log/error_log
und das Configfile:
MaxLogSize 1m
# Show troubleshooting information in error_log.
LogLevel debug
Listen localhost:631
Listen /run/cups/cups.sock
Browsing On
BrowseLocalProtocols dnssd
DefaultAuthType Basic
WebInterface Yes
<Location />
Order allow,deny
</Location>
<Location /admin>
Order allow,deny
</Location>
<Location /admin/conf>
AuthType Default
Require user @SYSTEM
Order allow,deny
</Location>
<Location /admin/log>
AuthType Default
Require user @SYSTEM
Order allow,deny
</Location>
<Policy default>
JobPrivateAccess default
JobPrivateValues default
SubscriptionPrivateAccess default
SubscriptionPrivateValues default
<Limit Create-Job Print-Job Print-URI Validate-Job>
Order deny,allow
</Limit>
<Limit Send-Document Send-URI Hold-Job Release-Job Restart-Job Purge-Jobs Set-Job-Attributes Create-Job-Subscription Renew-Subscription Cancel-Subscription Get-Notifications Reprocess-Job Cancel-Current-Job Suspend-Current-Job Resume-Job Cancel-My-Jobs Close-Job CUPS-Move-Job CUPS-Get-Document>
Require user @OWNER @SYSTEM
Order deny,allow
</Limit>
<Limit CUPS-Add-Modify-Printer CUPS-Delete-Printer CUPS-Add-Modify-Class CUPS-Delete-Class CUPS-Set-Default CUPS-Get-Devices>
AuthType Default
Require user @SYSTEM
Order deny,allow
</Limit>
<Limit Pause-Printer Resume-Printer Enable-Printer Disable-Printer Pause-Printer-After-Current-Job Hold-New-Jobs Release-Held-New-Jobs Deactivate-Printer Activate-Printer Restart-Printer Shutdown-Printer Startup-Printer Promote-Job Schedule-Job-After Cancel-Jobs CUPS-Accept-Jobs CUPS-Reject-Jobs>
AuthType Default
Require user @SYSTEM
Order deny,allow
</Limit>
<Limit Cancel-Job CUPS-Authenticate-Job>
Require user @OWNER @SYSTEM
Order deny,allow
</Limit>
<Limit All>
Order deny,allow
</Limit>
</Policy>
<Policy authenticated>
JobPrivateAccess default
JobPrivateValues default
SubscriptionPrivateAccess default
SubscriptionPrivateValues default
<Limit Create-Job Print-Job Print-URI Validate-Job>
AuthType Default
Order deny,allow
</Limit>
<Limit Send-Document Send-URI Hold-Job Release-Job Restart-Job Purge-Jobs Set-Job-Attributes Create-Job-Subscription Renew-Subscription Cancel-Subscription Get-Notifications Reprocess-Job Cancel-Current-Job Suspend-Current-Job Resume-Job Cancel-My-Jobs Close-Job CUPS-Move-Job CUPS-Get-Document>
AuthType Default
Require user @OWNER @SYSTEM
Order deny,allow
</Limit>
<Limit CUPS-Add-Modify-Printer CUPS-Delete-Printer CUPS-Add-Modify-Class CUPS-Delete-Class CUPS-Set-Default>
AuthType Default
Require user @SYSTEM
Order deny,allow
</Limit>
<Limit Pause-Printer Resume-Printer Enable-Printer Disable-Printer Pause-Printer-After-Current-Job Hold-New-Jobs Release-Held-New-Jobs Deactivate-Printer Activate-Printer Restart-Printer Shutdown-Printer Startup-Printer Promote-Job Schedule-Job-After Cancel-Jobs CUPS-Accept-Jobs CUPS-Reject-Jobs>
AuthType Default
Require user @SYSTEM
Order deny,allow
</Limit>
<Limit Cancel-Job CUPS-Authenticate-Job>
AuthType Default
Require user @OWNER @SYSTEM
Order deny,allow
</Limit>
<Limit All>
Order deny,allow
</Limit>
</Policy>
<Policy kerberos>
JobPrivateAccess default
JobPrivateValues default
SubscriptionPrivateAccess default
SubscriptionPrivateValues default
<Limit Create-Job Print-Job Print-URI Validate-Job>
AuthType Negotiate
Order deny,allow
</Limit>
<Limit Send-Document Send-URI Hold-Job Release-Job Restart-Job Purge-Jobs Set-Job-Attributes Create-Job-Subscription Renew-Subscription Cancel-Subscription Get-Notifications Reprocess-Job Cancel-Current-Job Suspend-Current-Job Resume-Job Cancel-My-Jobs Close-Job CUPS-Move-Job CUPS-Get-Document>
AuthType Negotiate
Require user @OWNER @SYSTEM
Order deny,allow
</Limit>
<Limit CUPS-Add-Modify-Printer CUPS-Delete-Printer CUPS-Add-Modify-Class CUPS-Delete-Class CUPS-Set-Default>
AuthType Default
Require user @SYSTEM
Order deny,allow
</Limit>
<Limit Pause-Printer Resume-Printer Enable-Printer Disable-Printer Pause-Printer-After-Current-Job Hold-New-Jobs Release-Held-New-Jobs Deactivate-Printer Activate-Printer Restart-Printer Shutdown-Printer Startup-Printer Promote-Job Schedule-Job-After Cancel-Jobs CUPS-Accept-Jobs CUPS-Reject-Jobs>
AuthType Default
Require user @SYSTEM
Order deny,allow
</Limit>
<Limit Cancel-Job CUPS-Authenticate-Job>
AuthType Negotiate
Require user @OWNER @SYSTEM
Order deny,allow
</Limit>
<Limit All>
Order deny,allow
</Limit>
</Policy>
JobPrivateAccess default
JobPrivateValues default
SubscriptionPrivateAccess default
SubscriptionPrivateValues default
MaxJobs 0
PreserveJobFiles No
PreserveJobHistory No
falls ich hier mit dem Beitrag falsch sein sollte, sagt mir gerne bescheid, ansonsten bitte sehr genau erklähren was ich machen muss, da ich noch neu bin und mir erst die befehle und Programmnamen von Arch aneignen muss.
beste Grüße
edit:
Der Drucker wird bei einstecken des USB kabels automatisch erkannt und als USB Drucker eingerichtet mit dem gleichen Fehler.