xpra icon
Bug tracker and wiki

This bug tracker and wiki are being discontinued
please use https://github.com/Xpra-org/xpra instead.


Opened 12 months ago

Closed 12 months ago

Last modified 5 months ago

#2821 closed defect (fixed)

cups printing from html client not working

Reported by: Dušan Vejnovič Owned by: Dušan Vejnovič
Priority: major Milestone: 4.1
Component: printing Version: 3.0.x
Keywords: Cc:

Description

I want to print documnt from Libreoffice Writer. When from printers select HTML5-client and print the document, I cannot get PDF file.
I'm running Debian 10 with Xpra 3.0.10 (server and client).

My locale settings (with command 'locale -a'):

C
C.UTF-8
POSIX
sl_SI.utf8

With command 'sudo journalctl -f -t xpraforwarder' I got:

-- Logs begin at Sat 2020-06-27 16:34:25 CEST. --
jun 27 17:17:59 demo2 xpraforwarder[7627]: '/usr/lib/cups/backend/xpraforwarder' '89' 'dusan' 'Neimenovano 1' '1' 'PageSize=A4 job-uuid=urn:uuid:0139ff4e-e72d-3c65-6500-65ce038c6ccc job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1593271079 time-at-processing=1593271079 document-name-supplied=Iiz6EA'
jun 27 17:17:59 demo2 xpraforwarder[7627]: version 3.0.10, username: dusan, title: Neimenovano 1, filename: -, job_id: 89
jun 27 17:17:59 demo2 xpraforwarder[7627]: uid=(0, 0, 0), gid=(7, 7, 7)
jun 27 17:17:59 demo2 xpraforwarder[7627]: DEVICE_URI=xpraforwarder:/tmp?display=%3A51255&source=99e56d0f77ab41b581e1316f30b3b465&socket-path=%2Frun%2Fxpra%2Fdemo2-51255&remote-printer=HTML5-client&remote-device-uri=None&mimetype=application%2Fpdf
jun 27 17:17:59 demo2 xpraforwarder[7627]: parsed attributes={'mimetype': ['application/pdf'], 'socket-path': ['/run/xpra/demo2-51255'], 'remote-printer': ['HTML5-client'], 'remote-device-uri': ['None'], 'source': ['99e56d0f77ab41b581e1316f30b3b465'], 'display': [':51255']}
jun 27 17:17:59 demo2 xpraforwarder[7627]: xpra display: :51255, socket-path: /run/xpra/demo2-51255
jun 27 17:17:59 demo2 xpraforwarder[7627]: running: ['xpra', 'print', 'socket:/run/xpra/demo2-51255', '-', 'application/pdf', '99e56d0f77ab41b581e1316f30b3b465', 'Neimenovano 1', 'HTML5-client', '1', 'PageSize=A4 job-uuid=urn:uuid:0139ff4e-e72d-3c65-6500-65ce038c6ccc job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1593271079 time-at-processing=1593271079 document-name-supplied=Iiz6EA']
jun 27 17:17:59 demo2 xpraforwarder[7627]: returncode=1
jun 27 17:17:59 demo2 xpraforwarder[7627]: stdout=
jun 27 17:17:59 demo2 xpraforwarder[7627]: stderr=xpra main error:
                                           Traceback (most recent call last):
                                             File "/usr/lib/python3/dist-packages/xpra/scripts/main.py", line 121, in main
                                               return run_mode(script_file, err, options, args, mode, defaults)
                                             File "/usr/lib/python3/dist-packages/xpra/scripts/main.py", line 462, in run_mode
                                               return run_client(error_cb, options, args, mode)
                                             File "/usr/lib/python3/dist-packages/xpra/scripts/main.py", line 1526, in run_client
                                               app = get_client_app(error_cb, opts, extra_args, mode)
                                             File "/usr/lib/python3/dist-packages/xpra/scripts/main.py", line 1589, in get_client_app
                                               app.set_command_args(args)
                                             File "/usr/lib/python3/dist-packages/xpra/client/gobject_client_base.py", line 430, in set_command_args
                                               self.file_data = sys.stdin.read()
                                             File "/usr/lib/python3.7/codecs.py", line 322, in decode
                                               (result, consumed) = self._buffer_decode(data, self.errors, final)
                                           UnicodeDecodeError: 'utf-8' codec can't decode byte 0xbf in position 410: invalid start byte

Change History (11)

comment:1 Changed 12 months ago by Antoine Martin

Owner: changed from Antoine Martin to Dušan Vejnovič

Please try r26827. (trivial change which you can apply by hand to your installation)

The solution was found here: How to prevent “UnicodeDecodeError” when reading piped input from sys.stdin?

Last edited 12 months ago by Antoine Martin (previous) (diff)

comment:2 Changed 12 months ago by Dušan Vejnovič

Not working, nothing happend.

comment:3 Changed 12 months ago by Antoine Martin

Not working, nothing happend.

What about the logs?
FYI: with the html5 client, the file is supposed to open for printing - you may have to accept the event.

comment:4 Changed 12 months ago by Dušan Vejnovič

I'm select HTML5-client printer for printing and print the document. After printing there is no window for saving the printed document.

Command 'sudo journalctl -f -t xpraforwarder' show:

jun 28 08:44:12 test xpraforwarder[5896]: '/usr/lib/cups/backend/xpraforwarder' '17' 'root' 'Untitled 1' '1' 'PageSize=A4 job-uuid=urn:uuid:1f44b6d0-4cb3-34db-5c99-78d24158134c job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1593326652 time-at-processing=1593326652 document-name-supplied=afwtO8'
jun 28 08:44:12 test xpraforwarder[5896]: version 3.0.10, username: root, title: Untitled 1, filename: -, job_id: 17
jun 28 08:44:12 test xpraforwarder[5896]: uid=(0, 0, 0), gid=(7, 7, 7)
jun 28 08:44:12 test xpraforwarder[5896]: DEVICE_URI=xpraforwarder:/tmp?source=324125a9-8de4-93a2-cf59-2003fe522a1b&remote-device-uri=None&display=%3A10000&remote-printer=HTML5+client&mimetype=application%2Fpdf&socket-path=%2Frun%2Fuser%2F0%2Fxpra%2Ftest-10000
jun 28 08:44:12 test xpraforwarder[5896]: parsed attributes={'mimetype': ['application/pdf'], 'socket-path': ['/run/user/0/xpra/test-10000'], 'remote-printer': ['HTML5 client'], 'remote-device-uri': ['None'], 'source': ['324125a9-8de4-93a2-cf59-2003fe522a1b'], 'display': [':10000']}
jun 28 08:44:12 test xpraforwarder[5896]: xpra display: :10000, socket-path: /run/user/0/xpra/test-10000
jun 28 08:44:12 test xpraforwarder[5896]: running: ['xpra', 'print', 'socket:/run/user/0/xpra/test-10000', '-', 'application/pdf', '324125a9-8de4-93a2-cf59-2003fe522a1b', 'Untitled 1', 'HTML5 client', '1', 'PageSize=A4 job-uuid=urn:uuid:1f44b6d0-4cb3-34db-5c99-78d24158134c job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1593326652 time-at-processing=1593326652 document-name-supplied=afwtO8']
jun 28 08:44:12 test xpraforwarder[5896]: returncode=0
jun 28 08:44:40 test xpraforwarder[5922]: '/usr/lib/cups/backend/xpraforwarder' '16' 'root' 'Untitled 1' '1' 'Duplex=None PageSize=A4 job-uuid=urn:uuid:a3375aba-895f-3367-4cf5-cf53cf2f1bbc job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1593326377 time-at-processing=1593326679 document-name-supplied=QwJ18F'
jun 28 08:44:40 test xpraforwarder[5922]: version 3.0.10, username: root, title: Untitled 1, filename: -, job_id: 16
jun 28 08:44:40 test xpraforwarder[5922]: uid=(0, 0, 0), gid=(7, 7, 7)
jun 28 08:44:40 test xpraforwarder[5922]: DEVICE_URI=xpraforwarder:/tmp?source=324125a9-8de4-93a2-cf59-2003fe522a1b&remote-device-uri=None&display=%3A10000&remote-printer=HTML5+client&mimetype=application%2Fpdf&socket-path=%2Frun%2Fuser%2F0%2Fxpra%2Ftest-10000
jun 28 08:44:40 test xpraforwarder[5922]: parsed attributes={'mimetype': ['application/pdf'], 'socket-path': ['/run/user/0/xpra/test-10000'], 'remote-printer': ['HTML5 client'], 'remote-device-uri': ['None'], 'source': ['324125a9-8de4-93a2-cf59-2003fe522a1b'], 'display': [':10000']}
jun 28 08:44:40 test xpraforwarder[5922]: xpra display: :10000, socket-path: /run/user/0/xpra/test-10000
jun 28 08:44:40 test xpraforwarder[5922]: running: ['xpra', 'print', 'socket:/run/user/0/xpra/test-10000', '-', 'application/pdf', '324125a9-8de4-93a2-cf59-2003fe522a1b', 'Untitled 1', 'HTML5 client', '1', 'Duplex=None PageSize=A4 job-uuid=urn:uuid:a3375aba-895f-3367-4cf5-cf53cf2f1bbc job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1593326377 time-at-processing=1593326679 document-name-supplied=QwJ18F']
jun 28 08:44:40 test xpraforwarder[5922]: returncode=0

Cups access_log:

localhost - - [28/Jun/2020:08:44:12 +0200] "POST /printers/HTML5-client HTTP/1.1" 200 196 Create-Job successful-ok
localhost - - [28/Jun/2020:08:44:12 +0200] "POST /printers/HTML5-client HTTP/1.1" 200 7178 Send-Document successful-ok

Cups error_log:

D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [28/Jun/2020:08:44:12 +0200] [Client 16] Server address is "/var/run/cups/cups.sock".
D [28/Jun/2020:08:44:12 +0200] [Client 16] Accepted from localhost (Domain)
D [28/Jun/2020:08:44:12 +0200] [Client 16] Waiting for request.
I [28/Jun/2020:08:44:12 +0200] Expiring subscriptions...
D [28/Jun/2020:08:44:12 +0200] [Client 16] POST / HTTP/1.1
D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=200, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] No authentication data provided.
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] 2.0 Get-Printer-Attributes 7
D [28/Jun/2020:08:44:12 +0200] Get-Printer-Attributes ipp://localhost:631/printers/HTML5-client
D [28/Jun/2020:08:44:12 +0200] [Client 16] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost:631/printers/HTML5-client) from localhost.
D [28/Jun/2020:08:44:12 +0200] [Client 16] Content-Length: 1380
D [28/Jun/2020:08:44:12 +0200] [Client 16] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [28/Jun/2020:08:44:12 +0200] [Client 16] con->http=0x560d624f5400
D [28/Jun/2020:08:44:12 +0200] [Client 16] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1380, response=0x560d6250a5f0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [28/Jun/2020:08:44:12 +0200] [Client 16] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [28/Jun/2020:08:44:12 +0200] [Client 16] bytes=0, http_state=0, data_remaining=1380
D [28/Jun/2020:08:44:12 +0200] [Client 16] Flushing write buffer.
D [28/Jun/2020:08:44:12 +0200] [Client 16] New state is HTTP_STATE_WAITING
D [28/Jun/2020:08:44:12 +0200] [Client 16] Waiting for request.
D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [28/Jun/2020:08:44:12 +0200] [Client 16] POST /printers/HTML5-client HTTP/1.1
D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=200, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] No authentication data provided.
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] 2.0 Get-Printer-Attributes 8
D [28/Jun/2020:08:44:12 +0200] Get-Printer-Attributes ipp://localhost/printers/HTML5-client
D [28/Jun/2020:08:44:12 +0200] [Client 16] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost/printers/HTML5-client) from localhost.
D [28/Jun/2020:08:44:12 +0200] [Client 16] Content-Length: 12253
D [28/Jun/2020:08:44:12 +0200] [Client 16] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [28/Jun/2020:08:44:12 +0200] [Client 16] con->http=0x560d624f5400
D [28/Jun/2020:08:44:12 +0200] [Client 16] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=12253, response=0x560d6250a680(IPP_STATE_DATA), pipe_pid=0, file=-1
D [28/Jun/2020:08:44:12 +0200] [Client 16] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [28/Jun/2020:08:44:12 +0200] [Client 16] bytes=0, http_state=0, data_remaining=12253
D [28/Jun/2020:08:44:12 +0200] [Client 16] Flushing write buffer.
D [28/Jun/2020:08:44:12 +0200] [Client 16] New state is HTTP_STATE_WAITING
D [28/Jun/2020:08:44:12 +0200] [Client 16] Waiting for request.
D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [28/Jun/2020:08:44:12 +0200] [Client 16] POST /printers/HTML5-client HTTP/1.1
D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=200, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] No authentication data provided.
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] 2.0 Create-Job 9
D [28/Jun/2020:08:44:12 +0200] Create-Job ipp://localhost/printers/HTML5-client
D [28/Jun/2020:08:44:12 +0200] cupsdMarkDirty(---J-)
D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients"
D [28/Jun/2020:08:44:12 +0200] [Job 17] Applying default options...
D [28/Jun/2020:08:44:12 +0200] add_job: requesting-user-name="root"
D [28/Jun/2020:08:44:12 +0200] Adding default job-sheets values "none,none"...
I [28/Jun/2020:08:44:12 +0200] [Job 17] Adding start banner page "none".
D [28/Jun/2020:08:44:12 +0200] cupsdMarkDirty(----S)
D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
I [28/Jun/2020:08:44:12 +0200] [Job 17] Queued on "HTML5-client" by "root".
D [28/Jun/2020:08:44:12 +0200] [Client 16] Returning IPP successful-ok for Create-Job (ipp://localhost/printers/HTML5-client) from localhost.
D [28/Jun/2020:08:44:12 +0200] [Client 16] Content-Length: 200
D [28/Jun/2020:08:44:12 +0200] [Client 16] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [28/Jun/2020:08:44:12 +0200] [Client 16] con->http=0x560d624f5400
D [28/Jun/2020:08:44:12 +0200] [Client 16] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=200, response=0x560d6250a750(IPP_STATE_IDLE), pipe_pid=0, file=-1
D [28/Jun/2020:08:44:12 +0200] [Client 16] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [28/Jun/2020:08:44:12 +0200] [Client 16] bytes=0, http_state=0, data_remaining=200
D [28/Jun/2020:08:44:12 +0200] [Client 16] Flushing write buffer.
D [28/Jun/2020:08:44:12 +0200] [Client 16] New state is HTTP_STATE_WAITING
D [28/Jun/2020:08:44:12 +0200] [Client 16] Waiting for request.
D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [28/Jun/2020:08:44:12 +0200] [Notifier] state=3
D [28/Jun/2020:08:44:12 +0200] [Notifier] JobCreated
D [28/Jun/2020:08:44:12 +0200] [Client 16] POST /printers/HTML5-client HTTP/1.1
D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=200, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] No authentication data provided.
D [28/Jun/2020:08:44:12 +0200] [Client 16] 2.0 Send-Document 10
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] [Client 16] Read: status=100, state=6
D [28/Jun/2020:08:44:12 +0200] Send-Document ipp://localhost:631/printers/HTML5-client
D [28/Jun/2020:08:44:12 +0200] cupsdIsAuthorized: requesting-user-name="root"
D [28/Jun/2020:08:44:12 +0200] [Job 17] Auto-typing file...
D [28/Jun/2020:08:44:12 +0200] [Job 17] Request file type is application/pdf.
D [28/Jun/2020:08:44:12 +0200] cupsdMarkDirty(---J-)
D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
I [28/Jun/2020:08:44:12 +0200] [Job 17] File of type application/pdf queued by "root".
I [28/Jun/2020:08:44:12 +0200] [Job 17] Adding end banner page "none".
D [28/Jun/2020:08:44:12 +0200] cupsdMarkDirty(---J-)
D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [28/Jun/2020:08:44:12 +0200] [Job 17] time-at-processing=1593326652
D [28/Jun/2020:08:44:12 +0200] cupsdMarkDirty(---J-)
D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [28/Jun/2020:08:44:12 +0200] cupsdMarkDirty(----S)
D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [28/Jun/2020:08:44:12 +0200] [Job 17] 2 filters for job:
D [28/Jun/2020:08:44:12 +0200] [Job 17] pdftopdf (application/pdf to printer/HTML5-client/application/vnd.cups-pdf, cost 0)
D [28/Jun/2020:08:44:12 +0200] [Job 17] - (printer/HTML5-client/application/vnd.cups-pdf to printer/HTML5-client, cost 0)
D [28/Jun/2020:08:44:12 +0200] [Job 17] job-sheets=none,none
D [28/Jun/2020:08:44:12 +0200] [Job 17] argv[0]="HTML5-client"
D [28/Jun/2020:08:44:12 +0200] [Job 17] argv[1]="17"
D [28/Jun/2020:08:44:12 +0200] [Job 17] argv[2]="root"
D [28/Jun/2020:08:44:12 +0200] [Job 17] argv[3]="Untitled 1"
D [28/Jun/2020:08:44:12 +0200] [Job 17] argv[4]="1"
D [28/Jun/2020:08:44:12 +0200] [Job 17] argv[5]="PageSize=A4 job-uuid=urn:uuid:1f44b6d0-4cb3-34db-5c99-78d24158134c job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1593326652 time-at-processing=1593326652 document-name-supplied=afwtO8"
D [28/Jun/2020:08:44:12 +0200] [Job 17] argv[6]="/var/spool/cups/d00017-001"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc-root"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[7]="CUPS_STATEDIR=/run/cups"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[8]="HOME=/var/spool/cups/tmp"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[10]="SERVER_ADMIN=root@test"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[11]="SOFTWARE=CUPS/2.2.10"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[13]="USER=root"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[14]="CUPS_MAX_MESSAGE=2047"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[15]="CUPS_SERVER=/var/run/cups/cups.sock"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[16]="CUPS_ENCRYPTION=IfRequested"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[17]="IPP_PORT=631"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[18]="CHARSET=utf-8"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[19]="LANG=sl_SI.UTF-8"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[20]="PPD=/etc/cups/ppd/HTML5-client.ppd"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[21]="RIP_MAX_CACHE=128m"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[22]="CONTENT_TYPE=application/pdf"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[23]="DEVICE_URI=xpraforwarder:/tmp?source=324125a9-8de4-93a2-cf59-2003fe522a1b&remote-device-uri=None&display=%3A10000&remote-printer=HTML5+client&mimetype=application%2Fpdf&socket-path=%2Frun%2Fuser%2F0%2Fxpra%2Ftest-10000"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[24]="PRINTER_INFO=Print to PDF in client browser"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[25]="PRINTER_LOCATION=via xpra"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[26]="PRINTER=HTML5-client"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[27]="PRINTER_STATE_REASONS=none"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[28]="CUPS_FILETYPE=document"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[29]="FINAL_CONTENT_TYPE=application/vnd.cups-pdf"
D [28/Jun/2020:08:44:12 +0200] [Job 17] envp[30]="AUTH_I****"
I [28/Jun/2020:08:44:12 +0200] [Job 17] Started filter /usr/lib/cups/filter/pdftopdf (PID 5895)
I [28/Jun/2020:08:44:12 +0200] [Job 17] Started backend /usr/lib/cups/backend/xpraforwarder (PID 5896)
D [28/Jun/2020:08:44:12 +0200] cupsdMarkDirty(----S)
D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients and dirty files"
D [28/Jun/2020:08:44:12 +0200] [Client 16] Content-Length: 170
D [28/Jun/2020:08:44:12 +0200] [Client 16] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [28/Jun/2020:08:44:12 +0200] [Client 16] con->http=0x560d624f5400
D [28/Jun/2020:08:44:12 +0200] [Client 16] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=170, response=0x560d6250a5c0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [28/Jun/2020:08:44:12 +0200] [Client 16] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [28/Jun/2020:08:44:12 +0200] [Client 16] bytes=0, http_state=0, data_remaining=170
D [28/Jun/2020:08:44:12 +0200] [Client 16] Flushing write buffer.
D [28/Jun/2020:08:44:12 +0200] [Client 16] New state is HTTP_STATE_WAITING
D [28/Jun/2020:08:44:12 +0200] [Client 16] Waiting for request.
D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [28/Jun/2020:08:44:12 +0200] [Notifier] state=3
D [28/Jun/2020:08:44:12 +0200] [Notifier] PrinterStateChanged
D [28/Jun/2020:08:44:12 +0200] [Notifier] state=3
D [28/Jun/2020:08:44:12 +0200] [Notifier] JobState
D [28/Jun/2020:08:44:12 +0200] [Job 17] pdftopdf: Last filter determined by the PPD: pdftopdf; FINAL_CONTENT_TYPE: application/vnd.cups-pdf => pdftopdf will log pages in page_log.
D [28/Jun/2020:08:44:12 +0200] [Job 17] PAGE: 1 1
D [28/Jun/2020:08:44:12 +0200] cupsdMarkDirty(----S)
D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [28/Jun/2020:08:44:12 +0200] cupsdMarkDirty(---J-)
D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [28/Jun/2020:08:44:12 +0200] [Notifier] state=3
D [28/Jun/2020:08:44:12 +0200] [Notifier] JobProgress
D [28/Jun/2020:08:44:12 +0200] [Job 17] PID 5895 (/usr/lib/cups/filter/pdftopdf) exited with no errors.
D [28/Jun/2020:08:44:12 +0200] [Job 17] PID 5896 (/usr/lib/cups/backend/xpraforwarder) exited with no errors.
D [28/Jun/2020:08:44:12 +0200] [Job 17] time-at-completed=1593326652
D [28/Jun/2020:08:44:12 +0200] cupsdMarkDirty(----S)
D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
I [28/Jun/2020:08:44:12 +0200] [Job 17] Job completed.
I [28/Jun/2020:08:44:12 +0200] Expiring subscriptions...
D [28/Jun/2020:08:44:12 +0200] cupsdMarkDirty(---J-)
D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [28/Jun/2020:08:44:12 +0200] cupsdMarkDirty(----S)
D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [28/Jun/2020:08:44:12 +0200] cupsdMarkDirty(---J-)
D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [28/Jun/2020:08:44:12 +0200] cupsdMarkDirty(---J-)
D [28/Jun/2020:08:44:12 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [28/Jun/2020:08:44:12 +0200] [Notifier] state=3
D [28/Jun/2020:08:44:12 +0200] [Notifier] JobCompleted
D [28/Jun/2020:08:44:12 +0200] [Notifier] state=3
D [28/Jun/2020:08:44:12 +0200] [Notifier] PrinterStateChanged
I [28/Jun/2020:08:44:13 +0200] Expiring subscriptions...
D [28/Jun/2020:08:44:13 +0200] [Job 17] Unloading...
I [28/Jun/2020:08:44:39 +0200] Expiring subscriptions...
D [28/Jun/2020:08:44:39 +0200] cupsdAddCert: Adding certificate for PID 0
D [28/Jun/2020:08:44:39 +0200] cupsdMarkDirty(----S)
D [28/Jun/2020:08:44:39 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Printing jobs and dirty files"
I [28/Jun/2020:08:44:39 +0200] [Job 16] Job submission timed out.
D [28/Jun/2020:08:44:39 +0200] cupsdMarkDirty(---J-)
D [28/Jun/2020:08:44:39 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [28/Jun/2020:08:44:39 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [28/Jun/2020:08:44:39 +0200] [Job 16] time-at-processing=1593326679
D [28/Jun/2020:08:44:39 +0200] cupsdMarkDirty(---J-)
D [28/Jun/2020:08:44:39 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [28/Jun/2020:08:44:39 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [28/Jun/2020:08:44:39 +0200] cupsdMarkDirty(----S)
D [28/Jun/2020:08:44:39 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [28/Jun/2020:08:44:39 +0200] [Job 16] 2 filters for job:
D [28/Jun/2020:08:44:39 +0200] [Job 16] pdftopdf (application/pdf to printer/HTML5-client/application/vnd.cups-pdf, cost 0)
D [28/Jun/2020:08:44:39 +0200] [Job 16] - (printer/HTML5-client/application/vnd.cups-pdf to printer/HTML5-client, cost 0)
D [28/Jun/2020:08:44:39 +0200] [Job 16] job-sheets=none,none
D [28/Jun/2020:08:44:39 +0200] [Job 16] argv[0]="HTML5-client"
D [28/Jun/2020:08:44:39 +0200] [Job 16] argv[1]="16"
D [28/Jun/2020:08:44:39 +0200] [Job 16] argv[2]="root"
D [28/Jun/2020:08:44:39 +0200] [Job 16] argv[3]="Untitled 1"
D [28/Jun/2020:08:44:39 +0200] [Job 16] argv[4]="1"
D [28/Jun/2020:08:44:39 +0200] [Job 16] argv[5]="Duplex=None PageSize=A4 job-uuid=urn:uuid:a3375aba-895f-3367-4cf5-cf53cf2f1bbc job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1593326377 time-at-processing=1593326679 document-name-supplied=QwJ18F"
D [28/Jun/2020:08:44:39 +0200] [Job 16] argv[6]="/var/spool/cups/d00016-001"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc-root"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[7]="CUPS_STATEDIR=/run/cups"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[8]="HOME=/var/spool/cups/tmp"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[10]="SERVER_ADMIN=root@test"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[11]="SOFTWARE=CUPS/2.2.10"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[13]="USER=root"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[14]="CUPS_MAX_MESSAGE=2047"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[15]="CUPS_SERVER=/var/run/cups/cups.sock"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[16]="CUPS_ENCRYPTION=IfRequested"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[17]="IPP_PORT=631"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[18]="CHARSET=utf-8"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[19]="LANG=sl_SI.UTF-8"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[20]="PPD=/etc/cups/ppd/HTML5-client.ppd"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[21]="RIP_MAX_CACHE=128m"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[22]="CONTENT_TYPE=application/pdf"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[23]="DEVICE_URI=xpraforwarder:/tmp?source=324125a9-8de4-93a2-cf59-2003fe522a1b&remote-device-uri=None&display=%3A10000&remote-printer=HTML5+client&mimetype=application%2Fpdf&socket-path=%2Frun%2Fuser%2F0%2Fxpra%2Ftest-10000"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[24]="PRINTER_INFO=Print to PDF in client browser"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[25]="PRINTER_LOCATION=via xpra"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[26]="PRINTER=HTML5-client"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[27]="PRINTER_STATE_REASONS=none"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[28]="CUPS_FILETYPE=document"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[29]="FINAL_CONTENT_TYPE=application/vnd.cups-pdf"
D [28/Jun/2020:08:44:39 +0200] [Job 16] envp[30]="AUTH_I****"
I [28/Jun/2020:08:44:39 +0200] [Job 16] Started filter /usr/lib/cups/filter/pdftopdf (PID 5921)
I [28/Jun/2020:08:44:39 +0200] [Job 16] Started backend /usr/lib/cups/backend/xpraforwarder (PID 5922)
D [28/Jun/2020:08:44:39 +0200] cupsdMarkDirty(----S)
D [28/Jun/2020:08:44:39 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Dirty files"
D [28/Jun/2020:08:44:39 +0200] Report: clients=1
D [28/Jun/2020:08:44:39 +0200] Report: jobs=17
D [28/Jun/2020:08:44:39 +0200] Report: jobs-active=1
D [28/Jun/2020:08:44:39 +0200] Report: printers=2
D [28/Jun/2020:08:44:39 +0200] Report: stringpool-string-count=2563
D [28/Jun/2020:08:44:39 +0200] Report: stringpool-alloc-bytes=13376
D [28/Jun/2020:08:44:39 +0200] Report: stringpool-total-bytes=52408
D [28/Jun/2020:08:44:39 +0200] [Notifier] state=3
D [28/Jun/2020:08:44:39 +0200] [Notifier] JobState
D [28/Jun/2020:08:44:39 +0200] [Notifier] state=3
D [28/Jun/2020:08:44:39 +0200] [Notifier] PrinterStateChanged
D [28/Jun/2020:08:44:39 +0200] [Notifier] state=3
D [28/Jun/2020:08:44:39 +0200] [Notifier] JobState
D [28/Jun/2020:08:44:40 +0200] [Job 16] pdftopdf: Last filter determined by the PPD: pdftopdf; FINAL_CONTENT_TYPE: application/vnd.cups-pdf => pdftopdf will log pages in page_log.
D [28/Jun/2020:08:44:40 +0200] [Job 16] PAGE: 1 1
D [28/Jun/2020:08:44:40 +0200] cupsdMarkDirty(----S)
D [28/Jun/2020:08:44:40 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [28/Jun/2020:08:44:40 +0200] cupsdMarkDirty(---J-)
D [28/Jun/2020:08:44:40 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [28/Jun/2020:08:44:40 +0200] [Notifier] state=3
D [28/Jun/2020:08:44:40 +0200] [Notifier] JobProgress
D [28/Jun/2020:08:44:40 +0200] [Job 16] PID 5921 (/usr/lib/cups/filter/pdftopdf) exited with no errors.
I [28/Jun/2020:08:44:40 +0200] Expiring subscriptions...
D [28/Jun/2020:08:44:40 +0200] [Job 16] PID 5922 (/usr/lib/cups/backend/xpraforwarder) exited with no errors.
D [28/Jun/2020:08:44:40 +0200] [Job 16] time-at-completed=1593326680
D [28/Jun/2020:08:44:40 +0200] cupsdMarkDirty(----S)
D [28/Jun/2020:08:44:40 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
I [28/Jun/2020:08:44:40 +0200] [Job 16] Job completed.
I [28/Jun/2020:08:44:40 +0200] Expiring subscriptions...
D [28/Jun/2020:08:44:40 +0200] cupsdMarkDirty(---J-)
D [28/Jun/2020:08:44:40 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [28/Jun/2020:08:44:40 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [28/Jun/2020:08:44:40 +0200] cupsdMarkDirty(----S)
D [28/Jun/2020:08:44:40 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [28/Jun/2020:08:44:40 +0200] cupsdMarkDirty(---J-)
D [28/Jun/2020:08:44:40 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [28/Jun/2020:08:44:40 +0200] [Notifier] state=3
D [28/Jun/2020:08:44:40 +0200] [Notifier] JobCompleted
D [28/Jun/2020:08:44:40 +0200] [Notifier] state=3
D [28/Jun/2020:08:44:40 +0200] [Notifier] PrinterStateChanged
I [28/Jun/2020:08:44:41 +0200] Expiring subscriptions...
D [28/Jun/2020:08:44:41 +0200] [Job 16] Unloading...
I [28/Jun/2020:08:44:43 +0200] Saving job.cache...
I [28/Jun/2020:08:44:43 +0200] Saving subscriptions.conf...
D [28/Jun/2020:08:44:43 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Printing jobs and dirty files"
I [28/Jun/2020:08:44:43 +0200] Expiring subscriptions...
I [28/Jun/2020:08:49:13 +0200] Expiring subscriptions...
D [28/Jun/2020:08:49:13 +0200] Closing client 16 after 300 seconds of inactivity.
D [28/Jun/2020:08:49:13 +0200] [Client 16] Closing connection.
D [28/Jun/2020:08:49:13 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [28/Jun/2020:08:49:13 +0200] Report: clients=0
D [28/Jun/2020:08:49:13 +0200] Report: jobs=17
D [28/Jun/2020:08:49:13 +0200] Report: jobs-active=0
D [28/Jun/2020:08:49:13 +0200] Report: printers=2
D [28/Jun/2020:08:49:13 +0200] Report: stringpool-string-count=2600
D [28/Jun/2020:08:49:13 +0200] Report: stringpool-alloc-bytes=12344
D [28/Jun/2020:08:49:13 +0200] Report: stringpool-total-bytes=53184

comment:5 Changed 12 months ago by Antoine Martin

The problem must be elsewhere now because the xpra print command worked correctly this time:

running: ['xpra', 'print', 'socket:/run/user/0/xpra/test-10000', '-', 'application/pdf', '324125a9-8de4-93a2-cf59-2003fe522a1b', 'Untitled 1', 'HTML5 client', '1', '...']
xpraforwarder[5922]: returncode=0

Maybe there's a regression in the server or the html5 client.
You could run your xpra server with -d file,printing and post the log. And also keep an eye on the javascript console of your browser.

comment:6 Changed 12 months ago by Dušan Vejnovič

No error messages in the In Firefox Javascipt Console.

File /run/user/0/xpra/:10000.log

2020-06-28 11:23:38,916 Missing property or wrong property type WM_TRANSIENT_FOR (window)
2020-06-28 11:23:38,917  no such window
2020-06-28 11:23:39,222 New unix-domain connection received
2020-06-28 11:23:39,222  on '/run/user/0/xpra/test-10000'
2020-06-28 11:23:39,225 Handshake complete; enabling connection
2020-06-28 11:23:39,226 file transfer: init_attributes('no', 10, 'no', 'no', 'no', None, True)
2020-06-28 11:23:39,226 file transfer attributes={'file-transfer': False, 'file-transfer-ask': False, 'file-size-limit': 10, 'file-chunks': 65536, 'open-files': False, 'open-files-ask': False, 'printing': False, 'printing-ask': False, 'open-url': False, 'open-url-ask': False, 'file-ask-timeout': 3600}
2020-06-28 11:23:39,226 file transfer: init_attributes('no', 10, 'no', 'no', 'no', None, True)
2020-06-28 11:23:39,226 file transfer attributes={'file-transfer': False, 'file-transfer-ask': False, 'file-size-limit': 10, 'file-chunks': 65536, 'open-files': False, 'open-files-ask': False, 'printing': False, 'printing-ask': False, 'open-url': False, 'open-url-ask': False, 'file-ask-timeout': 3600}
2020-06-28 11:23:39,227 file transfer remote caps: file-transfer=False   (ask=True)
2020-06-28 11:23:39,228 file transfer remote caps: printing=False        (ask=False)
2020-06-28 11:23:39,228 file transfer remote caps: open-files=True      (ask=True)
2020-06-28 11:23:39,228 file transfer remote caps: open-url=True        (ask=True)
2020-06-28 11:23:39,228 Python/GObject/Print client version 3.0.10-r26630 64-bit
2020-06-28 11:23:39,228  connected from 'test' as 'root'
2020-06-28 11:23:39,231 Error parsing xdg menu data:
2020-06-28 11:23:39,231  ParsingError in file '/etc/xdg/menus/kde-debian-menu.menu', File not found
2020-06-28 11:23:39,231  this is either a bug in python-xdg,
2020-06-28 11:23:39,231  or an invalid system menu configuration
2020-06-28 11:23:39,235 Error parsing xdg menu data:
2020-06-28 11:23:39,235  ParsingError in file '/etc/xdg/menus/kde-debian-menu.menu', File not found
2020-06-28 11:23:39,235  this is either a bug in python-xdg,
2020-06-28 11:23:39,235  or an invalid system menu configuration
2020-06-28 11:23:39,239 process_print: (b'324125a9-8de4-93a2-cf59-2003fe522a1b', b'application/pdf', '7346 bytes', '324125a9-8de4-93a2-cf59-2003fe522a1b', b'Untitled 1', b'HTML5 client', 1, {'Duplex': 'None', 'PageSize': 'A4', 'job-uuid': 'urn:uuid:721387e7-cb44-3439-6b4b-e97dd5b3970c', 'job-originating-host-name': 'localhost', 'date-time-at-creation': '', 'date-time-at-proce
ssing': '', 'time-at-creation': '1593336218', 'time-at-processing': '1593336218', 'document-name-supplied': 'QvcceM'})
2020-06-28 11:23:39,239 process_print: got 7346 bytes for file b'324125a9-8de4-93a2-cf59-2003fe522a1b'
2020-06-28 11:23:39,239 sha1 digest: da3a380362a27b76ec1d966f5523c6859e404395
2020-06-28 11:23:39,239 parsed printer options: {'printer': b'HTML5 client', 'title': b'Untitled 1', 'copies': 1, 'options': {'Duplex': 'None', 'PageSize': 'A4', 'job-uuid': 'urn:uuid:721387e7-cb44-3439-6b4b-e97dd5b3970c', 'job-originating-host-name': 'localhost', 'date-time-at-creation': '', 'date-time-at-processing': '', 'time-at-creation': '1593336218', 'time-at-processing
': '1593336218', 'document-name-supplied': 'QvcceM'}, 'sha1': 'da3a380362a27b76ec1d966f5523c6859e404395'}
2020-06-28 11:23:39,239 will try to send to 2 clients: (ClientConnection(1 : WebSocket(ws socket: 192.168.0.50:10000 <- 192.168.0.3:54838)), ClientConnection(5 : Protocol(unix-domain socket:/run/user/0/xpra/test-10000)))
2020-06-28 11:23:39,240 not sending to ClientConnection(1 : WebSocket(ws socket: 192.168.0.50:10000 <- 192.168.0.3:54838)) (uuid=33eb35ec-d28b-1db7-d757-eb3ea09e18bd, wanted uuid=324125a9-8de4-93a2-cf59-2003fe522a1b)
2020-06-28 11:23:39,240 not sending to ClientConnection(5 : Protocol(unix-domain socket:/run/user/0/xpra/test-10000)) (uuid=27b6fd3c98e34649d9a26a271cc83eaace4eaf58, wanted uuid=324125a9-8de4-93a2-cf59-2003fe522a1b)
2020-06-28 11:23:39,240 'b'Untitled 1'' (7KB) sent to 0 clients for printing
2020-06-28 11:23:39,240 client Protocol(unix-domain socket:/run/user/0/xpra/test-10000) has requested disconnection: done (detaching)
2020-06-28 11:23:39,240 Disconnecting client /run/user/0/xpra/test-10000:
2020-06-28 11:23:39,240  client request
2020-06-28 11:23:39,243 xpra client 5 disconnected.

Cups access_log:

localhost - - [28/Jun/2020:11:23:38 +0200] "POST /printers/HTML5-client HTTP/1.1" 200 211 Create-Job successful-ok
localhost - - [28/Jun/2020:11:23:38 +0200] "POST /printers/HTML5-client HTTP/1.1" 200 7162 Send-Document successful-ok

Cups error_log

D [28/Jun/2020:11:23:36 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [28/Jun/2020:11:23:36 +0200] [Client 25] Server address is "/var/run/cups/cups.sock".
D [28/Jun/2020:11:23:36 +0200] [Client 25] Accepted from localhost (Domain)
D [28/Jun/2020:11:23:36 +0200] [Client 25] Waiting for request.
I [28/Jun/2020:11:23:36 +0200] Expiring subscriptions...
D [28/Jun/2020:11:23:36 +0200] cupsdAddCert: Adding certificate for PID 0
D [28/Jun/2020:11:23:36 +0200] Report: clients=2
D [28/Jun/2020:11:23:36 +0200] Report: jobs=20
D [28/Jun/2020:11:23:36 +0200] Report: jobs-active=0
D [28/Jun/2020:11:23:36 +0200] Report: printers=2
D [28/Jun/2020:11:23:36 +0200] Report: stringpool-string-count=3142
D [28/Jun/2020:11:23:36 +0200] Report: stringpool-alloc-bytes=12504
D [28/Jun/2020:11:23:36 +0200] Report: stringpool-total-bytes=64392
D [28/Jun/2020:11:23:36 +0200] [Client 25] POST / HTTP/1.1
D [28/Jun/2020:11:23:36 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=200, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] No authentication data provided.
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] 2.0 CUPS-Get-Printers 25
D [28/Jun/2020:11:23:36 +0200] CUPS-Get-Printers
D [28/Jun/2020:11:23:36 +0200] [Client 25] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost.
D [28/Jun/2020:11:23:36 +0200] [Client 25] Content-Length: 2481
D [28/Jun/2020:11:23:36 +0200] [Client 25] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [28/Jun/2020:11:23:36 +0200] [Client 25] con->http=0x560d6251b5e0
D [28/Jun/2020:11:23:36 +0200] [Client 25] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=2481, response=0x560d62514850(IPP_STATE_DATA), pipe_pid=0, file=-1
D [28/Jun/2020:11:23:36 +0200] [Client 25] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [28/Jun/2020:11:23:36 +0200] [Client 25] bytes=0, http_state=0, data_remaining=2481
D [28/Jun/2020:11:23:36 +0200] [Client 25] Flushing write buffer.
D [28/Jun/2020:11:23:36 +0200] [Client 25] New state is HTTP_STATE_WAITING
D [28/Jun/2020:11:23:36 +0200] [Client 25] Waiting for request.
D [28/Jun/2020:11:23:36 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [28/Jun/2020:11:23:36 +0200] [Client 25] POST / HTTP/1.1
D [28/Jun/2020:11:23:36 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=200, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] No authentication data provided.
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=100, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] 2.0 CUPS-Get-Default 26
D [28/Jun/2020:11:23:36 +0200] CUPS-Get-Default
D [28/Jun/2020:11:23:36 +0200] [Client 25] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost.
D [28/Jun/2020:11:23:36 +0200] [Client 25] Content-Length: 13206
D [28/Jun/2020:11:23:36 +0200] [Client 25] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [28/Jun/2020:11:23:36 +0200] [Client 25] con->http=0x560d6251b5e0
D [28/Jun/2020:11:23:36 +0200] [Client 25] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=13206, response=0x560d62512f90(IPP_STATE_DATA), pipe_pid=0, file=-1
D [28/Jun/2020:11:23:36 +0200] [Client 25] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [28/Jun/2020:11:23:36 +0200] [Client 25] bytes=0, http_state=0, data_remaining=13206
D [28/Jun/2020:11:23:36 +0200] [Client 25] Flushing write buffer.
D [28/Jun/2020:11:23:36 +0200] [Client 25] New state is HTTP_STATE_WAITING
D [28/Jun/2020:11:23:36 +0200] [Client 25] Waiting for request.
D [28/Jun/2020:11:23:36 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [28/Jun/2020:11:23:36 +0200] [Client 25] POST / HTTP/1.1
D [28/Jun/2020:11:23:36 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [28/Jun/2020:11:23:36 +0200] [Client 25] Read: status=200, state=6
D [28/Jun/2020:11:23:36 +0200] [Client 25] No authentication data provided.
D [28/Jun/2020:11:23:36 +0200] [Client 25] 2.0 CUPS-Get-Default 27
D [28/Jun/2020:11:23:36 +0200] CUPS-Get-Default
D [28/Jun/2020:11:23:36 +0200] [Client 25] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost.
D [28/Jun/2020:11:23:36 +0200] [Client 25] Content-Length: 13206
D [28/Jun/2020:11:23:36 +0200] [Client 25] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [28/Jun/2020:11:23:36 +0200] [Client 25] con->http=0x560d6251b5e0
D [28/Jun/2020:11:23:36 +0200] [Client 25] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=13206, response=0x560d6251b540(IPP_STATE_DATA), pipe_pid=0, file=-1
D [28/Jun/2020:11:23:36 +0200] [Client 25] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [28/Jun/2020:11:23:36 +0200] [Client 25] bytes=0, http_state=0, data_remaining=13206
D [28/Jun/2020:11:23:36 +0200] [Client 25] Flushing write buffer.
D [28/Jun/2020:11:23:36 +0200] [Client 25] New state is HTTP_STATE_WAITING
D [28/Jun/2020:11:23:36 +0200] [Client 25] Waiting for request.
D [28/Jun/2020:11:23:36 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [28/Jun/2020:11:23:36 +0200] [Client 25] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [28/Jun/2020:11:23:36 +0200] [Client 25] Closing connection.
D [28/Jun/2020:11:23:36 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
I [28/Jun/2020:11:23:37 +0200] Expiring subscriptions...
D [28/Jun/2020:11:23:38 +0200] [Client 23] POST / HTTP/1.1
D [28/Jun/2020:11:23:38 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [28/Jun/2020:11:23:38 +0200] [Client 23] Read: status=200, state=6
D [28/Jun/2020:11:23:38 +0200] [Client 23] No authentication data provided.
D [28/Jun/2020:11:23:38 +0200] [Client 23] 2.0 Get-Printer-Attributes 28
D [28/Jun/2020:11:23:38 +0200] Get-Printer-Attributes ipp://localhost:631/printers/HTML5-client
D [28/Jun/2020:11:23:38 +0200] [Client 23] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost:631/printers/HTML5-client) from localhost.
D [28/Jun/2020:11:23:38 +0200] [Client 23] Content-Length: 1380
D [28/Jun/2020:11:23:38 +0200] [Client 23] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
I [28/Jun/2020:11:23:38 +0200] Expiring subscriptions...
D [28/Jun/2020:11:23:38 +0200] [Client 23] con->http=0x560d624f5400
D [28/Jun/2020:11:23:38 +0200] [Client 23] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1380, response=0x560d62510de0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [28/Jun/2020:11:23:38 +0200] [Client 23] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [28/Jun/2020:11:23:38 +0200] [Client 23] bytes=0, http_state=0, data_remaining=1380
D [28/Jun/2020:11:23:38 +0200] [Client 23] Flushing write buffer.
D [28/Jun/2020:11:23:38 +0200] [Client 23] New state is HTTP_STATE_WAITING
D [28/Jun/2020:11:23:38 +0200] [Client 23] Waiting for request.
D [28/Jun/2020:11:23:38 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [28/Jun/2020:11:23:38 +0200] [Client 23] POST /printers/HTML5-client HTTP/1.1
D [28/Jun/2020:11:23:38 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [28/Jun/2020:11:23:38 +0200] [Client 23] Read: status=200, state=6
D [28/Jun/2020:11:23:38 +0200] [Client 23] No authentication data provided.
D [28/Jun/2020:11:23:38 +0200] [Client 23] Read: status=100, state=6
D [28/Jun/2020:11:23:38 +0200] [Client 23] Read: status=100, state=6
D [28/Jun/2020:11:23:38 +0200] [Client 23] Read: status=100, state=6
D [28/Jun/2020:11:23:38 +0200] [Client 23] Read: status=100, state=6
D [28/Jun/2020:11:23:38 +0200] [Client 23] Read: status=100, state=6
D [28/Jun/2020:11:23:38 +0200] [Client 23] Read: status=100, state=6
D [28/Jun/2020:11:23:38 +0200] [Client 23] Read: status=100, state=6
D [28/Jun/2020:11:23:38 +0200] [Client 23] Read: status=100, state=6
D [28/Jun/2020:11:23:38 +0200] [Client 23] Read: status=100, state=6
D [28/Jun/2020:11:23:38 +0200] [Client 23] 2.0 Get-Printer-Attributes 29
D [28/Jun/2020:11:23:38 +0200] Get-Printer-Attributes ipp://localhost/printers/HTML5-client
D [28/Jun/2020:11:23:38 +0200] [Client 23] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost/printers/HTML5-client) from localhost.
D [28/Jun/2020:11:23:38 +0200] [Client 23] Content-Length: 12253
D [28/Jun/2020:11:23:38 +0200] [Client 23] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [28/Jun/2020:11:23:38 +0200] [Client 23] con->http=0x560d624f5400
D [28/Jun/2020:11:23:38 +0200] [Client 23] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=12253, response=0x560d6251b540(IPP_STATE_DATA), pipe_pid=0, file=-1
D [28/Jun/2020:11:23:38 +0200] [Client 23] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [28/Jun/2020:11:23:38 +0200] [Client 23] bytes=0, http_state=0, data_remaining=12253
D [28/Jun/2020:11:23:38 +0200] [Client 23] Flushing write buffer.
D [28/Jun/2020:11:23:38 +0200] [Client 23] New state is HTTP_STATE_WAITING
D [28/Jun/2020:11:23:38 +0200] [Client 23] Waiting for request.
D [28/Jun/2020:11:23:38 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [28/Jun/2020:11:23:38 +0200] [Client 23] POST /printers/HTML5-client HTTP/1.1
D [28/Jun/2020:11:23:38 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [28/Jun/2020:11:23:38 +0200] [Client 23] Read: status=200, state=6
D [28/Jun/2020:11:23:38 +0200] [Client 23] No authentication data provided.
D [28/Jun/2020:11:23:38 +0200] [Client 23] Read: status=100, state=6
D [28/Jun/2020:11:23:38 +0200] [Client 23] Read: status=100, state=6
D [28/Jun/2020:11:23:38 +0200] [Client 23] Read: status=100, state=6
D [28/Jun/2020:11:23:38 +0200] [Client 23] Read: status=100, state=6
D [28/Jun/2020:11:23:38 +0200] [Client 23] Read: status=100, state=6
D [28/Jun/2020:11:23:38 +0200] [Client 23] Read: status=100, state=6
D [28/Jun/2020:11:23:38 +0200] [Client 23] Read: status=100, state=6
D [28/Jun/2020:11:23:38 +0200] [Client 23] Read: status=100, state=6
D [28/Jun/2020:11:23:38 +0200] [Client 23] Read: status=100, state=6
D [28/Jun/2020:11:23:38 +0200] [Client 23] 2.0 Create-Job 30
D [28/Jun/2020:11:23:38 +0200] Create-Job ipp://localhost/printers/HTML5-client
D [28/Jun/2020:11:23:38 +0200] cupsdMarkDirty(---J-)
D [28/Jun/2020:11:23:38 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients"
D [28/Jun/2020:11:23:38 +0200] [Job 21] Applying default options...
D [28/Jun/2020:11:23:38 +0200] add_job: requesting-user-name="root"
D [28/Jun/2020:11:23:38 +0200] Adding default job-sheets values "none,none"...
I [28/Jun/2020:11:23:38 +0200] [Job 21] Adding start banner page "none".
D [28/Jun/2020:11:23:38 +0200] cupsdMarkDirty(----S)
D [28/Jun/2020:11:23:38 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
I [28/Jun/2020:11:23:38 +0200] [Job 21] Queued on "HTML5-client" by "root".
D [28/Jun/2020:11:23:38 +0200] [Client 23] Returning IPP successful-ok for Create-Job (ipp://localhost/printers/HTML5-client) from localhost.
D [28/Jun/2020:11:23:38 +0200] [Client 23] Content-Length: 200
D [28/Jun/2020:11:23:38 +0200] [Client 23] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [28/Jun/2020:11:23:38 +0200] [Client 23] con->http=0x560d624f5400
D [28/Jun/2020:11:23:38 +0200] [Client 23] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=200, response=0x560d62510de0(IPP_STATE_IDLE), pipe_pid=0, file=-1
D [28/Jun/2020:11:23:38 +0200] [Client 23] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [28/Jun/2020:11:23:38 +0200] [Client 23] bytes=0, http_state=0, data_remaining=200
D [28/Jun/2020:11:23:38 +0200] [Client 23] Flushing write buffer.
D [28/Jun/2020:11:23:38 +0200] [Client 23] New state is HTTP_STATE_WAITING
D [28/Jun/2020:11:23:38 +0200] [Client 23] Waiting for request.
D [28/Jun/2020:11:23:38 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [28/Jun/2020:11:23:38 +0200] [Notifier] state=3
D [28/Jun/2020:11:23:38 +0200] [Notifier] JobCreated
D [28/Jun/2020:11:23:38 +0200] [Client 23] POST /printers/HTML5-client HTTP/1.1
D [28/Jun/2020:11:23:38 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [28/Jun/2020:11:23:38 +0200] [Client 23] Read: status=200, state=6
D [28/Jun/2020:11:23:38 +0200] [Client 23] No authentication data provided.
D [28/Jun/2020:11:23:38 +0200] [Client 23] 2.0 Send-Document 31
D [28/Jun/2020:11:23:38 +0200] [Client 23] Read: status=100, state=6
D [28/Jun/2020:11:23:38 +0200] [Client 23] Read: status=100, state=6
D [28/Jun/2020:11:23:38 +0200] Send-Document ipp://localhost:631/printers/HTML5-client
D [28/Jun/2020:11:23:38 +0200] cupsdIsAuthorized: requesting-user-name="root"
D [28/Jun/2020:11:23:38 +0200] [Job 21] Auto-typing file...
D [28/Jun/2020:11:23:38 +0200] [Job 21] Request file type is application/pdf.
D [28/Jun/2020:11:23:38 +0200] cupsdMarkDirty(---J-)
D [28/Jun/2020:11:23:38 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
I [28/Jun/2020:11:23:38 +0200] [Job 21] File of type application/pdf queued by "root".
I [28/Jun/2020:11:23:38 +0200] [Job 21] Adding end banner page "none".
D [28/Jun/2020:11:23:38 +0200] cupsdMarkDirty(---J-)
D [28/Jun/2020:11:23:38 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [28/Jun/2020:11:23:38 +0200] [Job 21] time-at-processing=1593336218
D [28/Jun/2020:11:23:38 +0200] cupsdMarkDirty(---J-)
D [28/Jun/2020:11:23:38 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [28/Jun/2020:11:23:38 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [28/Jun/2020:11:23:38 +0200] cupsdMarkDirty(----S)
D [28/Jun/2020:11:23:38 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [28/Jun/2020:11:23:38 +0200] [Job 21] 2 filters for job:
D [28/Jun/2020:11:23:38 +0200] [Job 21] pdftopdf (application/pdf to printer/HTML5-client/application/vnd.cups-pdf, cost 0)
D [28/Jun/2020:11:23:38 +0200] [Job 21] - (printer/HTML5-client/application/vnd.cups-pdf to printer/HTML5-client, cost 0)
D [28/Jun/2020:11:23:38 +0200] [Job 21] job-sheets=none,none
D [28/Jun/2020:11:23:38 +0200] [Job 21] argv[0]="HTML5-client"
D [28/Jun/2020:11:23:38 +0200] [Job 21] argv[1]="21"
D [28/Jun/2020:11:23:38 +0200] [Job 21] argv[2]="root"
D [28/Jun/2020:11:23:38 +0200] [Job 21] argv[3]="Untitled 1"
D [28/Jun/2020:11:23:38 +0200] [Job 21] argv[4]="1"
D [28/Jun/2020:11:23:38 +0200] [Job 21] argv[5]="Duplex=None PageSize=A4 job-uuid=urn:uuid:721387e7-cb44-3439-6b4b-e97dd5b3970c job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1593336218 time-at-processing=1593336218 document-name-supplied=QvcceM"
D [28/Jun/2020:11:23:38 +0200] [Job 21] argv[6]="/var/spool/cups/d00021-001"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc-root"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[7]="CUPS_STATEDIR=/run/cups"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[8]="HOME=/var/spool/cups/tmp"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[10]="SERVER_ADMIN=root@test"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[11]="SOFTWARE=CUPS/2.2.10"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[13]="USER=root"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[14]="CUPS_MAX_MESSAGE=2047"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[15]="CUPS_SERVER=/var/run/cups/cups.sock"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[16]="CUPS_ENCRYPTION=IfRequested"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[17]="IPP_PORT=631"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[18]="CHARSET=utf-8"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[19]="LANG=sl_SI.UTF-8"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[20]="PPD=/etc/cups/ppd/HTML5-client.ppd"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[21]="RIP_MAX_CACHE=128m"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[22]="CONTENT_TYPE=application/pdf"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[23]="DEVICE_URI=xpraforwarder:/tmp?source=324125a9-8de4-93a2-cf59-2003fe522a1b&remote-device-uri=None&display=%3A10000&remote-printer=HTML5+client&mimetype=application%2Fpdf&socket-path=%2Frun%2Fuser%2F0%2Fxpra%2Ftest-10000"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[24]="PRINTER_INFO=Print to PDF in client browser"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[25]="PRINTER_LOCATION=via xpra"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[26]="PRINTER=HTML5-client"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[27]="PRINTER_STATE_REASONS=none"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[28]="CUPS_FILETYPE=document"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[29]="FINAL_CONTENT_TYPE=application/vnd.cups-pdf"
D [28/Jun/2020:11:23:38 +0200] [Job 21] envp[30]="AUTH_I****"
I [28/Jun/2020:11:23:38 +0200] [Job 21] Started filter /usr/lib/cups/filter/pdftopdf (PID 6612)
I [28/Jun/2020:11:23:38 +0200] [Job 21] Started backend /usr/lib/cups/backend/xpraforwarder (PID 6613)
D [28/Jun/2020:11:23:38 +0200] cupsdMarkDirty(----S)
D [28/Jun/2020:11:23:38 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients and dirty files"
D [28/Jun/2020:11:23:38 +0200] [Client 23] Returning IPP successful-ok for Send-Document (ipp://localhost:631/printers/HTML5-client) from localhost.
D [28/Jun/2020:11:23:38 +0200] [Client 23] Content-Length: 170
D [28/Jun/2020:11:23:38 +0200] [Client 23] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [28/Jun/2020:11:23:38 +0200] [Client 23] con->http=0x560d624f5400
D [28/Jun/2020:11:23:38 +0200] [Client 23] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=170, response=0x560d62517880(IPP_STATE_DATA), pipe_pid=0, file=-1
D [28/Jun/2020:11:23:38 +0200] [Client 23] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [28/Jun/2020:11:23:38 +0200] [Client 23] bytes=0, http_state=0, data_remaining=170
D [28/Jun/2020:11:23:38 +0200] [Client 23] Flushing write buffer.
D [28/Jun/2020:11:23:38 +0200] [Client 23] New state is HTTP_STATE_WAITING
D [28/Jun/2020:11:23:38 +0200] [Client 23] Waiting for request.
D [28/Jun/2020:11:23:38 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [28/Jun/2020:11:23:38 +0200] [Notifier] state=3
D [28/Jun/2020:11:23:38 +0200] [Notifier] PrinterStateChanged
D [28/Jun/2020:11:23:38 +0200] [Notifier] state=3
D [28/Jun/2020:11:23:38 +0200] [Notifier] JobState
D [28/Jun/2020:11:23:38 +0200] [Job 21] pdftopdf: Last filter determined by the PPD: pdftopdf; FINAL_CONTENT_TYPE: application/vnd.cups-pdf => pdftopdf will log pages in page_log.
D [28/Jun/2020:11:23:38 +0200] [Job 21] PAGE: 1 1
D [28/Jun/2020:11:23:38 +0200] cupsdMarkDirty(----S)
D [28/Jun/2020:11:23:38 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [28/Jun/2020:11:23:38 +0200] cupsdMarkDirty(---J-)
D [28/Jun/2020:11:23:38 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [28/Jun/2020:11:23:38 +0200] [Job 21] PID 6612 (/usr/lib/cups/filter/pdftopdf) exited with no errors.
D [28/Jun/2020:11:23:38 +0200] [Notifier] state=3
D [28/Jun/2020:11:23:38 +0200] [Notifier] JobProgress
I [28/Jun/2020:11:23:39 +0200] Expiring subscriptions...
D [28/Jun/2020:11:23:39 +0200] [Job 21] PID 6613 (/usr/lib/cups/backend/xpraforwarder) exited with no errors.
D [28/Jun/2020:11:23:39 +0200] [Job 21] time-at-completed=1593336219
D [28/Jun/2020:11:23:39 +0200] cupsdMarkDirty(----S)
D [28/Jun/2020:11:23:39 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
I [28/Jun/2020:11:23:39 +0200] [Job 21] Job completed.
I [28/Jun/2020:11:23:39 +0200] Expiring subscriptions...
D [28/Jun/2020:11:23:39 +0200] cupsdMarkDirty(---J-)
D [28/Jun/2020:11:23:39 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [28/Jun/2020:11:23:39 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [28/Jun/2020:11:23:39 +0200] cupsdMarkDirty(----S)
D [28/Jun/2020:11:23:39 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [28/Jun/2020:11:23:39 +0200] cupsdMarkDirty(---J-)
D [28/Jun/2020:11:23:39 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [28/Jun/2020:11:23:39 +0200] cupsdMarkDirty(---J-)
D [28/Jun/2020:11:23:39 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [28/Jun/2020:11:23:39 +0200] [Notifier] state=3
D [28/Jun/2020:11:23:39 +0200] [Notifier] JobCompleted
D [28/Jun/2020:11:23:39 +0200] [Notifier] state=3
D [28/Jun/2020:11:23:39 +0200] [Notifier] PrinterStateChanged
I [28/Jun/2020:11:23:40 +0200] Expiring subscriptions...
D [28/Jun/2020:11:23:40 +0200] [Job 21] Unloading...
I [28/Jun/2020:11:24:09 +0200] Saving job.cache...
I [28/Jun/2020:11:24:09 +0200] Saving subscriptions.conf...
D [28/Jun/2020:11:24:09 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Printing jobs and dirty files"
I [28/Jun/2020:11:24:09 +0200] Expiring subscriptions...
I [28/Jun/2020:11:28:39 +0200] Expiring subscriptions...
D [28/Jun/2020:11:28:39 +0200] cupsdAddCert: Adding certificate for PID 0
D [28/Jun/2020:11:28:39 +0200] Closing client 23 after 300 seconds of inactivity.
D [28/Jun/2020:11:28:39 +0200] [Client 23] Closing connection.
D [28/Jun/2020:11:28:39 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [28/Jun/2020:11:28:39 +0200] Report: clients=0
D [28/Jun/2020:11:28:39 +0200] Report: jobs=21
D [28/Jun/2020:11:28:39 +0200] Report: jobs-active=0
D [28/Jun/2020:11:28:39 +0200] Report: printers=2
D [28/Jun/2020:11:28:39 +0200] Report: stringpool-string-count=3320
D [28/Jun/2020:11:28:39 +0200] Report: stringpool-alloc-bytes=12472
D [28/Jun/2020:11:28:39 +0200] Report: stringpool-total-bytes=68064

comment:7 Changed 12 months ago by Antoine Martin

I've managed to reproduce more unicode errors, r26831 fixes those.

This may be why you were seeing these messages in your xpra server log:

not sending to ClientConnection(1 : WebSocket(ws socket: 192.168.0.50:10000 <- 192.168.0.3:54838)) (uuid=33eb35ec-d28b-1db7-d757-eb3ea09e18bd, wanted uuid=324125a9-8de4-93a2-cf59-2003fe522a1b)
not sending to ClientConnection(5 : Protocol(unix-domain socket:/run/user/0/xpra/test-10000)) (uuid=27b6fd3c98e34649d9a26a271cc83eaace4eaf58, wanted uuid=324125a9-8de4-93a2-cf59-2003fe522a1b)
'b'Untitled 1'' (7KB) sent to 0 clients for printing

Though I don't understand why your connection uuid is completely different there.

Printing works for me with Firefox, with chrome I think that the popup gets blocked silently now (this definitely used to work).

FYI: you may also need to disable SELinux if you get AVCs.

comment:8 Changed 12 months ago by Dušan Vejnovič

I was restarting the server, still not working: cannot get window for saving printed document. SELinux is disabled, connection uuid is still different.

comment:9 Changed 12 months ago by Antoine Martin

connection uuid is still different.

It should match.
Maybe the printer you selected was created by a different connection / user / session?
The uuid is stored as source in the DEVICE_URI of the printer.
It is unique per client connection.

comment:10 Changed 12 months ago by Dušan Vejnovič

Resolution: fixed
Status: newclosed

I have manually delete printer from CUPS. Now I can get printed document. Thank you.
I will close this ticket for now.

comment:11 Changed 5 months ago by migration script

this ticket has been moved to: https://github.com/Xpra-org/xpra/issues/2821

Note: See TracTickets for help on using tickets.