[Date Prev][Date Next] [Thread Prev][Thread Next] [Date Index] [Thread Index]

Windows client doesn't print after successful GetPrinterAttributes

Hi,

in my overengineered home network, I have

- a VLAN with my Laser Printer and an Inkjet.
- another VLAN with my CUPS server, parada, running Debian stable
- two Windows 10 computers in two different VLANs, one ("twist")
  belonging to me, and the other ("eb840") belonging to a client.
- a router/firewall, barrida, running a packet filter and avahi-daemon
  in reflector configuration.

The printer is configured to do avahi/zeroconf, parada has 
avahi-daemon and cups-browsed installed and running.

Please see the thread starting with
https://lists.debian.org/debian-printing/2019/01/msg00035.html for a
more in-depth discussion of what I have tried so far, successful up to
the current point.

On both Windows machines, I have connected
http://parada:631/printers/c534-ka51 and am using the same "Lexmark C534
Class Driver". twist prints the test page and application data just
fine, while eb840 doesn't even print the test page. In both cases, the
firewall doesn't log any denies.

Both machines will connect and issue a Get-Printer-Attributes call. When
it's twist connecting, I see log lines like cupsdSetBusyState:
newbusy="Active clients", busy="Not busy", when it's eb840, the log says
cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty
files". In other regards, the log entries seem identical.

After the Get-Printer-Attributes call, twist will issue a Print-Job and
actually print, while eb840 will issue a "Get-Jobs" call and then
claiming that it has successfully printed the test page, which is
obviously not the case.

Full logs are below. As I am used to picking error messages from CUPS
straces, I have also straced the daemon, but this time it seems to be
the client that is not willing to print. The most obvious difference on
the CUPS side is the "Active clients and dirty files" that appears only
when CUPS is talking to eb840. Do we have some leftovers that are
confusing CUPS and Windows?

Any hints will be appreciated.

Greetings
Marc

This is the log of twist printing a successful test page:

D [01/Feb/2019:17:18:39 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Dirty files"
D [01/Feb/2019:17:18:40 +0100] [Client 23] Server address is "192.168.181.165".
D [01/Feb/2019:17:18:40 +0100] [Client 23] Accepted from 192.168.182.240:61968 (IPv4)
D [01/Feb/2019:17:18:40 +0100] [Client 23] Waiting for request.
D [01/Feb/2019:17:18:40 +0100] [Client 23] POST /printers/c534-ka51 HTTP/1.1
D [01/Feb/2019:17:18:40 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [01/Feb/2019:17:18:40 +0100] [Client 23] Read: status=200
D [01/Feb/2019:17:18:40 +0100] [Client 23] No authentication data provided.
D [01/Feb/2019:17:18:40 +0100] [Client 23] 1.0 Get-Printer-Attributes 11
D [01/Feb/2019:17:18:40 +0100] Get-Printer-Attributes http://parada.ka51.zugschlus.de:631/printers/c534-ka51
D [01/Feb/2019:17:18:40 +0100] [Client 23] Returning IPP successful-ok for Get-Printer-Attributes (http://parada.ka51.zugschlus.de:631/printers/c534-ka51) from 192.168.182.240
D [01/Feb/2019:17:18:40 +0100] [Client 23] Content-Length: 10507
D [01/Feb/2019:17:18:40 +0100] [Client 23] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [01/Feb/2019:17:18:40 +0100] [Client 23] con->http=0x562b0990ef30
D [01/Feb/2019:17:18:40 +0100] [Client 23] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=10507, response=0x562b0990bc70(IPP_STATE_DATA), pipe_pid=0, file=-1
D [01/Feb/2019:17:18:40 +0100] [Client 23] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [01/Feb/2019:17:18:40 +0100] [Client 23] bytes=0, http_state=0, data_remaining=10507
D [01/Feb/2019:17:18:40 +0100] [Client 23] Flushing write buffer.
D [01/Feb/2019:17:18:40 +0100] [Client 23] New state is HTTP_STATE_WAITING
D [01/Feb/2019:17:18:40 +0100] [Client 23] Waiting for request.
D [01/Feb/2019:17:18:40 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [01/Feb/2019:17:18:40 +0100] [Client 24] Server address is "192.168.181.165".
D [01/Feb/2019:17:18:40 +0100] [Client 24] Accepted from 192.168.182.240:61969 (IPv4)
D [01/Feb/2019:17:18:40 +0100] [Client 24] Waiting for request.
D [01/Feb/2019:17:18:40 +0100] [Client 24] POST /printers/c534-ka51 HTTP/1.1
D [01/Feb/2019:17:18:40 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [01/Feb/2019:17:18:40 +0100] [Client 24] Read: status=200
D [01/Feb/2019:17:18:40 +0100] [Client 24] No authentication data provided.
D [01/Feb/2019:17:18:40 +0100] [Client 24] 1.0 Get-Printer-Attributes 11
D [01/Feb/2019:17:18:40 +0100] Get-Printer-Attributes http://parada.ka51.zugschlus.de:631/printers/c534-ka51
D [01/Feb/2019:17:18:40 +0100] [Client 24] Returning IPP successful-ok for Get-Printer-Attributes (http://parada.ka51.zugschlus.de:631/printers/c534-ka51) from 192.168.182.240
D [01/Feb/2019:17:18:40 +0100] [Client 24] Content-Length: 10507
D [01/Feb/2019:17:18:40 +0100] [Client 24] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [01/Feb/2019:17:18:40 +0100] [Client 24] con->http=0x562b0992d480
D [01/Feb/2019:17:18:40 +0100] [Client 24] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=10507, response=0x562b09922b60(IPP_STATE_DATA), pipe_pid=0, file=-1
D [01/Feb/2019:17:18:40 +0100] [Client 24] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [01/Feb/2019:17:18:40 +0100] [Client 24] bytes=0, http_state=0, data_remaining=10507
D [01/Feb/2019:17:18:40 +0100] [Client 24] Flushing write buffer.
D [01/Feb/2019:17:18:40 +0100] [Client 24] New state is HTTP_STATE_WAITING
D [01/Feb/2019:17:18:40 +0100] [Client 24] Waiting for request.
D [01/Feb/2019:17:18:40 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [01/Feb/2019:17:18:40 +0100] [Client 25] Server address is "192.168.181.165".
D [01/Feb/2019:17:18:40 +0100] [Client 25] Accepted from 192.168.182.240:61970 (IPv4)
D [01/Feb/2019:17:18:40 +0100] [Client 25] Waiting for request.
D [01/Feb/2019:17:18:40 +0100] [Client 25] POST /printers/c534-ka51 HTTP/1.1
D [01/Feb/2019:17:18:40 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [01/Feb/2019:17:18:40 +0100] [Client 25] Read: status=200
D [01/Feb/2019:17:18:40 +0100] [Client 25] No authentication data provided.
D [01/Feb/2019:17:18:40 +0100] [Client 25] 1.0 Print-Job 2
D [01/Feb/2019:17:18:40 +0100] [Client 25] Read: status=100
D [01/Feb/2019:17:18:40 +0100] [Client 25] Read: status=100
(Duplicate lines removed)
D [01/Feb/2019:17:18:40 +0100] [Client 25] Read: status=100
D [01/Feb/2019:17:18:40 +0100] [Client 25] Read: status=100
D [01/Feb/2019:17:18:40 +0100] Print-Job http://parada.ka51.zugschlus.de:631/printers/c534-ka51
D [01/Feb/2019:17:18:40 +0100] [Job ???] Auto-typing file...
I [01/Feb/2019:17:18:40 +0100] [Job ???] Request file type is application/vnd.cups-raw.
D [01/Feb/2019:17:18:40 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:40 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients"
D [01/Feb/2019:17:18:40 +0100] add_job: requesting-user-name="mh"
D [01/Feb/2019:17:18:40 +0100] Adding default job-sheets values "none,none"...
I [01/Feb/2019:17:18:40 +0100] [Job 2408] Adding start banner page "none".
D [01/Feb/2019:17:18:40 +0100] Discarding unused job-created event...
D [01/Feb/2019:17:18:40 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:40 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
I [01/Feb/2019:17:18:40 +0100] [Job 2408] Adding end banner page "none".
I [01/Feb/2019:17:18:40 +0100] [Job 2408] File of type application/vnd.cups-raw queued by "mh".
D [01/Feb/2019:17:18:40 +0100] [Job 2408] hold_until=0
I [01/Feb/2019:17:18:40 +0100] [Job 2408] Queued on "c534-ka51" by "mh".
D [01/Feb/2019:17:18:40 +0100] [Job 2408] time-at-processing=1549037920
D [01/Feb/2019:17:18:40 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:40 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [01/Feb/2019:17:18:40 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [01/Feb/2019:17:18:40 +0100] Discarding unused printer-state-changed event...
D [01/Feb/2019:17:18:40 +0100] [Job 2408] 2 filters for job:
D [01/Feb/2019:17:18:40 +0100] [Job 2408] - (application/vnd.cups-raw to printer/c534-ka51/application/octet-stream, cost 0)
D [01/Feb/2019:17:18:40 +0100] [Job 2408] - (printer/c534-ka51/application/octet-stream to printer/c534-ka51, cost 0)
D [01/Feb/2019:17:18:40 +0100] [Job 2408] job-sheets=none,none
D [01/Feb/2019:17:18:40 +0100] [Job 2408] argv[0]="c534-ka51"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] argv[1]="2408"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] argv[2]="mh"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] argv[3]="Testseite"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] argv[4]="1"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] argv[5]="job-uuid=urn:uuid:62d95b15-2a48-321c-40eb-5dac4d48970f job-originating-host-name=192.168.182.240 date-time-at-creation= date-time-at-processing= time-at-creation=1549037920 time-at-processing=1549037920"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] argv[6]="/var/spool/cups/d02408-001"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc-root"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[7]="CUPS_STATEDIR=/var/run/cups"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[8]="HOME=/var/spool/cups/tmp"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[10]="SERVER_ADMIN=root@parada"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[11]="SOFTWARE=CUPS/2.2.1"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[13]="USER=root"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[14]="CUPS_MAX_MESSAGE=2047"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[15]="CUPS_SERVER=/var/run/cups/cups.sock"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[16]="CUPS_ENCRYPTION=IfRequested"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[17]="IPP_PORT=631"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[18]="CHARSET=utf-8"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[19]="LANG=en_US.UTF-8"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[20]="PPD=/etc/cups/ppd/c534-ka51.ppd"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[21]="RIP_MAX_CACHE=128m"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[22]="CONTENT_TYPE=application/vnd.cups-raw"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[23]="DEVICE_URI=dnssd://c534-ka51._pdl-datastream._tcp.local/"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[24]="PRINTER_INFO=Lexmark C534"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[25]="PRINTER_LOCATION=KA51 KE"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[26]="PRINTER=c534-ka51"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[27]="PRINTER_STATE_REASONS=none"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[28]="CUPS_FILETYPE=document"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[29]="FINAL_CONTENT_TYPE=application/octet-stream"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] envp[30]="AUTH_I****"
I [01/Feb/2019:17:18:40 +0100] [Job 2408] Started backend /usr/lib/cups/backend/dnssd (PID 30187)
D [01/Feb/2019:17:18:40 +0100] Discarding unused job-state-changed event...
D [01/Feb/2019:17:18:40 +0100] [Client 25] Returning IPP successful-ok for Print-Job (http://parada.ka51.zugschlus.de:631/printers/c534-ka51) from 192.168.182.240
D [01/Feb/2019:17:18:40 +0100] [Client 25] Content-Length: 213
D [01/Feb/2019:17:18:40 +0100] [Client 25] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [01/Feb/2019:17:18:40 +0100] [Client 25] con->http=0x562b09930690
D [01/Feb/2019:17:18:40 +0100] [Client 25] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=213, response=0x562b09915a10(IPP_STATE_IDLE), pipe_pid=0, file=-1
D [01/Feb/2019:17:18:40 +0100] [Client 25] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [01/Feb/2019:17:18:40 +0100] [Client 25] bytes=0, http_state=0, data_remaining=213
D [01/Feb/2019:17:18:40 +0100] [Client 25] Flushing write buffer.
D [01/Feb/2019:17:18:40 +0100] [Client 25] New state is HTTP_STATE_WAITING
D [01/Feb/2019:17:18:40 +0100] [Client 25] Waiting for request.
D [01/Feb/2019:17:18:40 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients and dirty files"
D [01/Feb/2019:17:18:40 +0100] [Job 2408] Resolving \"c534-ka51._pdl-datastream._tcp.local\"...
D [01/Feb/2019:17:18:40 +0100] [Job 2408] STATE: +connecting-to-device
D [01/Feb/2019:17:18:40 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:40 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Printing jobs and dirty files"
D [01/Feb/2019:17:18:40 +0100] Discarding unused printer-state-changed event...
D [01/Feb/2019:17:18:40 +0100] [Job 2408] Resolving \"c534-ka51\", regtype=\"_pdl-datastream._tcp\", domain=\"local.\"...
D [01/Feb/2019:17:18:44 +0100] [Job 2408] Resolved as \"socket://c534-ka51.local:9100/\"...
D [01/Feb/2019:17:18:44 +0100] [Job 2408] STATE: -connecting-to-device,offline-report
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2408] Executing backend \"/usr/lib/cups/backend/socket\"...
D [01/Feb/2019:17:18:44 +0100] Discarding unused printer-state-changed event...
D [01/Feb/2019:17:18:44 +0100] [Job 2408] STATE: +connecting-to-device
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Printing jobs and dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2408] Looking up \"c534-ka51.local\"...
D [01/Feb/2019:17:18:44 +0100] Discarding unused printer-state-changed event...
D [01/Feb/2019:17:18:44 +0100] [Job 2408] ATTR: marker-colors=#00FFFF,#FF00FF,#FFFF00,#000000,none,none,none,none,none,none,none
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(P----)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2408] ATTR: marker-names=\'\"Cyan Toner\"\',\'\"Magenta Toner\"\',\'\"Yellow Toner\"\',\'\"Black Toner\"\',\'\"Photo Drum:Cyan\"\',\'\"Photo Drum:Magenta\"\',\'\"Photo Drum:Yellow\"\',\'\"Photo Drum:Black\"\',\'\"Waste Toner Box\"\',\'\"Fuser\"\',\'\"Transfer Belt\"\'
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(P----)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2408] ATTR: marker-types=toner,toner,toner,toner,opc,opc,opc,opc,waste-toner,other,other
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(P----)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2408] ATTR: marker-levels=54,100,97,89,69,95,92,49,0,-1,-1
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(P----)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2408] new_supply_state=0, change_state=ffff
D [01/Feb/2019:17:18:44 +0100] [Job 2408] STATE: -developer-low-report
D [01/Feb/2019:17:18:44 +0100] [Job 2408] STATE: -developer-empty-warning
D [01/Feb/2019:17:18:44 +0100] [Job 2408] STATE: -marker-supply-low-report
D [01/Feb/2019:17:18:44 +0100] [Job 2408] STATE: -marker-supply-empty-warning
D [01/Feb/2019:17:18:44 +0100] [Job 2408] STATE: -opc-near-eol-report
D [01/Feb/2019:17:18:44 +0100] [Job 2408] STATE: -opc-life-over-warning
D [01/Feb/2019:17:18:44 +0100] [Job 2408] STATE: -toner-low-report
D [01/Feb/2019:17:18:44 +0100] [Job 2408] STATE: -toner-empty-warning
D [01/Feb/2019:17:18:44 +0100] [Job 2408] STATE: -waste-receptacle-almost-full-report
D [01/Feb/2019:17:18:44 +0100] [Job 2408] STATE: -waste-receptacle-full-warning
D [01/Feb/2019:17:18:44 +0100] [Job 2408] STATE: -cleaner-life-almost-over-report
D [01/Feb/2019:17:18:44 +0100] [Job 2408] STATE: -cleaner-life-over-warning
D [01/Feb/2019:17:18:44 +0100] Discarding unused printer-state-changed event...
D [01/Feb/2019:17:18:44 +0100] [Job 2408] new_state=0, change_state=ffff
D [01/Feb/2019:17:18:44 +0100] [Job 2408] STATE: -media-empty-warning
D [01/Feb/2019:17:18:44 +0100] [Job 2408] STATE: -door-open-report
D [01/Feb/2019:17:18:44 +0100] [Job 2408] STATE: -media-jam-warning
D [01/Feb/2019:17:18:44 +0100] [Job 2408] STATE: -input-tray-missing-warning
D [01/Feb/2019:17:18:44 +0100] [Job 2408] STATE: -output-tray-missing-warning
D [01/Feb/2019:17:18:44 +0100] [Job 2408] STATE: -marker-supply-missing-warning
D [01/Feb/2019:17:18:44 +0100] [Job 2408] STATE: -output-area-almost-full-report
D [01/Feb/2019:17:18:44 +0100] [Job 2408] STATE: -output-area-full-warning
D [01/Feb/2019:17:18:44 +0100] [Job 2408] Connecting to c534-ka51.local:9100
D [01/Feb/2019:17:18:44 +0100] [Job 2408] Connecting to printer.
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2408] Set job-printer-state-message to "Connecting to printer.", current level=INFO
D [01/Feb/2019:17:18:44 +0100] Discarding unused job-progress event...
D [01/Feb/2019:17:18:44 +0100] Discarding unused printer-state-changed event...
D [01/Feb/2019:17:18:44 +0100] [Job 2408] STATE: -connecting-to-device
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2408] Connected to printer.
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2408] Set job-printer-state-message to "Connected to printer.", current level=INFO
D [01/Feb/2019:17:18:44 +0100] [Job 2408] Connected to 192.168.183.240:9100...
D [01/Feb/2019:17:18:44 +0100] [Job 2408] PAGE: 1 1D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [01/Feb/2019:17:18:44 +0100] Discarding unused job-progress event...
D [01/Feb/2019:17:18:44 +0100] [Job 2408] backendRunLoop(print_fd=5, device_fd=7, snmp_fd=6, addr=0x55b90cafba68, use_bc=1, side_cb=0x55b90c8cc000)
D [01/Feb/2019:17:18:44 +0100] [Job 2408] Read 8192 bytes of print data...
D [01/Feb/2019:17:18:44 +0100] Discarding unused job-progress event...
D [01/Feb/2019:17:18:44 +0100] Discarding unused printer-state-changed event...
D [01/Feb/2019:17:18:44 +0100] [Job 2408] ATTR: marker-levels=51,98,94,86,66,92,89,46,0,-1,-1
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(P----)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2408] new_supply_state=0, change_state=0
D [01/Feb/2019:17:18:44 +0100] Discarding unused printer-state-changed event...
D [01/Feb/2019:17:18:44 +0100] [Job 2408] new_state=0, change_state=0
D [01/Feb/2019:17:18:44 +0100] [Job 2408] Wrote 8192 bytes of print data...
D [01/Feb/2019:17:18:44 +0100] [Job 2408] Read 8192 bytes of print data...
D [01/Feb/2019:17:18:44 +0100] [Job 2408] Wrote 8192 bytes of print data...
D [01/Feb/2019:17:18:44 +0100] [Job 2408] Read 8192 bytes of print data...
D [01/Feb/2019:17:18:44 +0100] [Job 2408] Wrote 8192 bytes of print data...
(Duplicates removed)
D [01/Feb/2019:17:18:44 +0100] [Job 2408] Wrote 4981 bytes of print data...
D [01/Feb/2019:17:18:44 +0100] [Job 2408] Print file sent.
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2408] Set job-printer-state-message to "Print file sent.", current level=INFO
D [01/Feb/2019:17:18:44 +0100] [Job 2408] STATE: +cups-waiting-for-job-completed
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(P----)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2408] Waiting for printer to finish.
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2408] Set job-printer-state-message to "Waiting for printer to finish.", current level=INFO
D [01/Feb/2019:17:18:44 +0100] Discarding unused job-progress event...
D [01/Feb/2019:17:18:44 +0100] Discarding unused printer-state-changed event...
D [01/Feb/2019:17:18:44 +0100] [Job 2408] ATTR: marker-levels=51,98,94,86,66,92,89,46,0,-1,-1
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(P----)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2408] new_supply_state=0, change_state=0
D [01/Feb/2019:17:18:44 +0100] Discarding unused printer-state-changed event...
D [01/Feb/2019:17:18:44 +0100] [Job 2408] new_state=0, change_state=0
D [01/Feb/2019:17:18:44 +0100] [Job 2408] PID 30187 (/usr/lib/cups/backend/dnssd) exited with no errors.
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(P----)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2408] time-at-completed=1549037924
D [01/Feb/2019:17:18:44 +0100] Discarding unused job-completed event...
I [01/Feb/2019:17:18:44 +0100] [Job 2408] Job completed.
I [01/Feb/2019:17:18:44 +0100] Expiring subscriptions...
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [01/Feb/2019:17:18:44 +0100] Discarding unused printer-state-changed event...
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2397] Removing document files.
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Printing jobs and dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2398] Removing document files.
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2399] Removing document files.
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2400] Removing document files.
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2401] Removing document files.
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2402] Removing document files.
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2403] Removing document files.
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2404] Removing document files.
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2405] Removing document files.
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [01/Feb/2019:17:18:44 +0100] [Job 2408] Removing document files.
D [01/Feb/2019:17:18:44 +0100] cupsdMarkDirty(---J-)
D [01/Feb/2019:17:18:44 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [01/Feb/2019:17:18:46 +0100] [Job 2408] Unloading...

And this is the log of eb840 trying to print a test page:
D [01/Feb/2019:17:18:50 +0100] [Client 26] Server address is "[v1.2a01:238:4071:3281::a5:100]".
D [01/Feb/2019:17:18:50 +0100] [Client 26] Accepted from [v1.2a01:238:4071:3289:13f:55cd:4f35:d4d7]:51545 (IPv6)
D [01/Feb/2019:17:18:50 +0100] [Client 26] Waiting for request.
D [01/Feb/2019:17:18:50 +0100] [Client 26] POST /printers/c534-ka51 HTTP/1.1
D [01/Feb/2019:17:18:50 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [01/Feb/2019:17:18:50 +0100] [Client 26] Read: status=200
D [01/Feb/2019:17:18:50 +0100] [Client 26] No authentication data provided.
D [01/Feb/2019:17:18:50 +0100] [Client 26] 1.0 Get-Printer-Attributes 11
D [01/Feb/2019:17:18:50 +0100] Get-Printer-Attributes http://parada.ka51.zugschlus.de:631/printers/c534-ka51
D [01/Feb/2019:17:18:50 +0100] [Client 26] Returning IPP successful-ok for Get-Printer-Attributes (http://parada.ka51.zugschlus.de:631/printers/c534-ka51) from [v1.2a01:238:4071:3289:13f:55cd:4f35:d4d7]
D [01/Feb/2019:17:18:50 +0100] [Client 26] Content-Length: 10733
D [01/Feb/2019:17:18:50 +0100] [Client 26] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [01/Feb/2019:17:18:50 +0100] [Client 26] con->http=0x562b099338a0
D [01/Feb/2019:17:18:50 +0100] [Client 26] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=10733, response=0x562b09915ff0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [01/Feb/2019:17:18:50 +0100] [Client 26] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [01/Feb/2019:17:18:50 +0100] [Client 26] bytes=0, http_state=0, data_remaining=10733
D [01/Feb/2019:17:18:50 +0100] [Client 26] Flushing write buffer.
D [01/Feb/2019:17:18:50 +0100] [Client 26] New state is HTTP_STATE_WAITING
D [01/Feb/2019:17:18:50 +0100] [Client 26] Waiting for request.
D [01/Feb/2019:17:18:50 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [01/Feb/2019:17:18:50 +0100] [Client 27] Server address is "[v1.2a01:238:4071:3281::a5:100]".
D [01/Feb/2019:17:18:50 +0100] [Client 27] Accepted from [v1.2a01:238:4071:3289:13f:55cd:4f35:d4d7]:51546 (IPv6)
D [01/Feb/2019:17:18:51 +0100] [Client 27] Waiting for request.
D [01/Feb/2019:17:18:51 +0100] [Client 27] POST /printers/c534-ka51 HTTP/1.1
D [01/Feb/2019:17:18:51 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [01/Feb/2019:17:18:51 +0100] [Client 27] Read: status=200
D [01/Feb/2019:17:18:51 +0100] [Client 27] No authentication data provided.
D [01/Feb/2019:17:18:51 +0100] [Client 27] 1.0 Get-Printer-Attributes 11
D [01/Feb/2019:17:18:51 +0100] Get-Printer-Attributes http://parada.ka51.zugschlus.de:631/printers/c534-ka51
D [01/Feb/2019:17:18:51 +0100] [Client 27] Returning IPP successful-ok for Get-Printer-Attributes (http://parada.ka51.zugschlus.de:631/printers/c534-ka51) from [v1.2a01:238:4071:3289:13f:55cd:4f35:d4d7]
D [01/Feb/2019:17:18:51 +0100] [Client 27] Content-Length: 10733
D [01/Feb/2019:17:18:51 +0100] [Client 27] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [01/Feb/2019:17:18:51 +0100] [Client 27] con->http=0x562b09936ab0
D [01/Feb/2019:17:18:51 +0100] [Client 27] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=10733, response=0x562b09904280(IPP_STATE_DATA), pipe_pid=0, file=-1
D [01/Feb/2019:17:18:51 +0100] [Client 27] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [01/Feb/2019:17:18:51 +0100] [Client 27] bytes=0, http_state=0, data_remaining=10733
D [01/Feb/2019:17:18:51 +0100] [Client 27] Flushing write buffer.
D [01/Feb/2019:17:18:51 +0100] [Client 27] New state is HTTP_STATE_WAITING
D [01/Feb/2019:17:18:51 +0100] [Client 27] Waiting for request.
D [01/Feb/2019:17:18:51 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [01/Feb/2019:17:18:51 +0100] [Client 28] Server address is "[v1.2a01:238:4071:3281::a5:100]".
D [01/Feb/2019:17:18:51 +0100] [Client 28] Accepted from [v1.2a01:238:4071:3289:13f:55cd:4f35:d4d7]:51547 (IPv6)
D [01/Feb/2019:17:18:51 +0100] [Client 28] Waiting for request.
D [01/Feb/2019:17:18:51 +0100] [Client 28] POST /printers/c534-ka51 HTTP/1.1
D [01/Feb/2019:17:18:51 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [01/Feb/2019:17:18:51 +0100] [Client 28] Read: status=200
D [01/Feb/2019:17:18:51 +0100] [Client 28] No authentication data provided.
D [01/Feb/2019:17:18:51 +0100] [Client 28] 1.0 Get-Jobs 10
D [01/Feb/2019:17:18:51 +0100] Get-Jobs http://parada.ka51.zugschlus.de:631/printers/c534-ka51
D [01/Feb/2019:17:18:51 +0100] [Client 28] Returning IPP successful-ok for Get-Jobs (http://parada.ka51.zugschlus.de:631/printers/c534-ka51) from [v1.2a01:238:4071:3289:13f:55cd:4f35:d4d7]
D [01/Feb/2019:17:18:51 +0100] [Client 28] Content-Length: 75
D [01/Feb/2019:17:18:51 +0100] [Client 28] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [01/Feb/2019:17:18:51 +0100] [Client 28] con->http=0x562b09939cc0
D [01/Feb/2019:17:18:51 +0100] [Client 28] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=75, response=0x562b09915a10(IPP_STATE_DATA), pipe_pid=0, file=-1
D [01/Feb/2019:17:18:51 +0100] [Client 28] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [01/Feb/2019:17:18:51 +0100] [Client 28] bytes=0, http_state=0, data_remaining=75
D [01/Feb/2019:17:18:51 +0100] [Client 28] Flushing write buffer.
D [01/Feb/2019:17:18:51 +0100] [Client 28] New state is HTTP_STATE_WAITING
D [01/Feb/2019:17:18:51 +0100] [Client 28] Waiting for request.
D [01/Feb/2019:17:18:51 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"



-- 
-----------------------------------------------------------------------------
Marc Haber         | "I don't trust Computers. They | Mailadresse im Header
Leimen, Germany    |  lose things."    Winona Ryder | Fon: *49 6224 1600402
Nordisch by Nature |  How to make an American Quilt | Fax: *49 6224 1600421
Reply to: