Corrupt output on Epson TM-T20II

[zoomyboy]

We're using this driver to print receipts from a WooCommerce shop. The document we're trying to print is actually a PDF file which is generated beforehand and then given to the printer. We're using a raspbery pi 4. The printer is connected via USB.

But sometimes in rather rare cases (like 1 in 15), the printer just prints nonsense. You can find an image attached to this issue to see the output. The printer also just prints like half of the document correctly and then just stops in between.

I configured the printer to cut automatically when the printing is finished. Even that isn't working anymore when the printer prints those random characters. It just stops and doesnt cut at all.
Also it's very difficult to test this properly because right now we have no clue where the issue comes from.

You also find the cups logs attached. I compared the cups logs of a "good-looking" print with a "bad-looking" but cannot find any issues which look like an error. So I assume that this is related to how the driver / printer initially functions. On the other hand, if the driver doesnt render the document properly, it should error out and doesnt print anything at all. But that's not the case.

Do you have any solutions for this?
We're really struggling with this as this is sometimes working and sometimes not.

D [15/Apr/2021:17:02:13 +0200] [Notifier] JobCreated
D [15/Apr/2021:17:02:13 +0200] [Client 14] POST /printers/EPSON_TM-T20III HTTP/1.1
D [15/Apr/2021:17:02:13 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [15/Apr/2021:17:02:13 +0200] [Client 14] Read: status=200, state=6
D [15/Apr/2021:17:02:13 +0200] [Client 14] No authentication data provided.
D [15/Apr/2021:17:02:13 +0200] [Client 14] 2.0 Send-Document 5
D [15/Apr/2021:17:02:13 +0200] [Client 14] Read: status=100, state=6
D [15/Apr/2021:17:02:13 +0200] [Client 14] Read: status=100, state=6
D [15/Apr/2021:17:02:13 +0200] [Client 14] Read: status=100, state=6
D [15/Apr/2021:17:02:13 +0200] [Client 14] Read: status=100, state=6
D [15/Apr/2021:17:02:13 +0200] [Client 14] Read: status=100, state=6
D [15/Apr/2021:17:02:13 +0200] [Client 14] Read: status=100, state=6
D [15/Apr/2021:17:02:13 +0200] [Client 14] Read: status=100, state=6
D [15/Apr/2021:17:02:13 +0200] [Client 14] Read: status=100, state=6
D [15/Apr/2021:17:02:13 +0200] [Client 14] Read: status=100, state=6
D [15/Apr/2021:17:02:13 +0200] [Client 14] Read: status=100, state=6
D [15/Apr/2021:17:02:13 +0200] [Client 14] Read: status=100, state=6
I [15/Apr/2021:17:02:14 +0200] Expiring subscriptions...
D [15/Apr/2021:17:02:14 +0200] [Client 14] Read: status=100, state=6
D [15/Apr/2021:17:02:14 +0200] [Client 14] Read: status=100, state=6
D [15/Apr/2021:17:02:14 +0200] Send-Document ipp://localhost:631/printers/EPSON_TM-T20III
D [15/Apr/2021:17:02:14 +0200] cupsdIsAuthorized: requesting-user-name="pi"
D [15/Apr/2021:17:02:14 +0200] [Job 577] Auto-typing file...
D [15/Apr/2021:17:02:14 +0200] [Job 577] Request file type is application/pdf.
D [15/Apr/2021:17:02:14 +0200] cupsdMarkDirty(---J-)
D [15/Apr/2021:17:02:14 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
I [15/Apr/2021:17:02:14 +0200] [Job 577] File of type application/pdf queued by "pi".
I [15/Apr/2021:17:02:14 +0200] [Job 577] Adding end banner page "none".
D [15/Apr/2021:17:02:14 +0200] cupsdMarkDirty(---J-)
D [15/Apr/2021:17:02:14 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [15/Apr/2021:17:02:14 +0200] [Job 577] time-at-processing=1618498934
D [15/Apr/2021:17:02:14 +0200] cupsdMarkDirty(---J-)
D [15/Apr/2021:17:02:14 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [15/Apr/2021:17:02:14 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [15/Apr/2021:17:02:14 +0200] cupsdMarkDirty(----S)
D [15/Apr/2021:17:02:14 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [15/Apr/2021:17:02:14 +0200] [Job 577] 3 filters for job:
D [15/Apr/2021:17:02:14 +0200] [Job 577] pdftopdf (application/pdf to application/vnd.cups-pdf, cost 66)
D [15/Apr/2021:17:02:14 +0200] [Job 577] gstoraster (application/vnd.cups-pdf to application/vnd.cups-raster, cost 99)
D [15/Apr/2021:17:02:14 +0200] [Job 577] rastertoepsonsimple (application/vnd.cups-raster to printer/EPSON_TM-T20III, cost 0)
D [15/Apr/2021:17:02:14 +0200] [Job 577] job-sheets=none,none
D [15/Apr/2021:17:02:14 +0200] [Job 577] argv[0]="EPSON_TM-T20III"
D [15/Apr/2021:17:02:14 +0200] [Job 577] argv[1]="577"
D [15/Apr/2021:17:02:14 +0200] [Job 577] argv[2]="pi"
D [15/Apr/2021:17:02:14 +0200] [Job 577] argv[3]="55525.pdf"
D [15/Apr/2021:17:02:14 +0200] [Job 577] argv[4]="1"
D [15/Apr/2021:17:02:14 +0200] [Job 577] argv[5]="finishings=3 number-up=1 job-uuid=urn:uuid:6b28dbc5-0a62-3831-60b5-0fa8de45fd01 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1618498933 time-at-processing=1618498934 document-name-supplied=55525.pdf"
D [15/Apr/2021:17:02:14 +0200] [Job 577] argv[6]="/var/spool/cups/d00577-001"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc-root"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[7]="CUPS_STATEDIR=/run/cups"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[8]="HOME=/var/spool/cups/tmp"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[10]="SERVER_ADMIN=root@hostname"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[11]="SOFTWARE=CUPS/2.2.10"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[13]="USER=root"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[14]="CUPS_MAX_MESSAGE=2047"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[15]="CUPS_SERVER=/run/cups/cups.sock"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[16]="CUPS_ENCRYPTION=IfRequested"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[17]="IPP_PORT=631"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[18]="CHARSET=utf-8"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[19]="LANG=de_DE.UTF-8"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[20]="PPD=/etc/cups/ppd/EPSON_TM-T20III.ppd"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[21]="RIP_MAX_CACHE=128m"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[22]="CONTENT_TYPE=application/pdf"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[23]="DEVICE_URI=usb://EPSON/TM-T20III?serial=583741560601890000"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[24]="PRINTER_INFO=EPSON TM-T20III"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[25]="PRINTER_LOCATION="
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[26]="PRINTER=EPSON_TM-T20III"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[27]="PRINTER_STATE_REASONS=none"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[28]="CUPS_FILETYPE=document"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[29]="FINAL_CONTENT_TYPE=application/vnd.cups-raster"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[30]="AUTH_I****"
I [15/Apr/2021:17:02:14 +0200] [Job 577] Started filter /usr/lib/cups/filter/pdftopdf (PID 789)
I [15/Apr/2021:17:02:14 +0200] [Job 577] Started filter /usr/lib/cups/filter/gstoraster (PID 790)
I [15/Apr/2021:17:02:14 +0200] [Job 577] Started filter /usr/lib/cups/filter/rastertoepsonsimple (PID 791)
I [15/Apr/2021:17:02:14 +0200] [Job 577] Started backend /usr/lib/cups/backend/usb (PID 792)
D [15/Apr/2021:17:02:14 +0200] cupsdMarkDirty(----S)
D [15/Apr/2021:17:02:14 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients and dirty files"
D [15/Apr/2021:17:02:14 +0200] [Client 14] Returning IPP successful-ok for Send-Document (ipp://localhost:631/printers/EPSON_TM-T20III) from localhost.
D [15/Apr/2021:17:02:14 +0200] [Client 14] Content-Length: 171
D [15/Apr/2021:17:02:14 +0200] [Client 14] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [15/Apr/2021:17:02:14 +0200] [Client 14] con->http=0xe569b0
D [15/Apr/2021:17:02:14 +0200] [Client 14] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=171, response=0xe3d218(IPP_STATE_DATA), pipe_pid=0, file=-1
D [15/Apr/2021:17:02:14 +0200] [Client 14] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [15/Apr/2021:17:02:14 +0200] [Client 14] bytes=0, http_state=0, data_remaining=171
D [15/Apr/2021:17:02:14 +0200] [Client 14] Flushing write buffer.
D [15/Apr/2021:17:02:14 +0200] [Client 14] New state is HTTP_STATE_WAITING
D [15/Apr/2021:17:02:14 +0200] [Client 14] Waiting for request.
D [15/Apr/2021:17:02:14 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [15/Apr/2021:17:02:14 +0200] [Notifier] state=3
D [15/Apr/2021:17:02:14 +0200] [Notifier] PrinterStateChanged
D [15/Apr/2021:17:02:14 +0200] [Notifier] state=3
D [15/Apr/2021:17:02:14 +0200] [Notifier] JobState
D [15/Apr/2021:17:02:14 +0200] [Client 14] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [15/Apr/2021:17:02:14 +0200] [Client 14] Closing connection.
D [15/Apr/2021:17:02:14 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [15/Apr/2021:17:02:14 +0200] [Job 577] Loading USB quirks from \"/usr/share/cups/usb\".
D [15/Apr/2021:17:02:14 +0200] [Job 577] Loaded 172 quirks.
D [15/Apr/2021:17:02:14 +0200] [Job 577] Printing on printer with URI: usb://EPSON/TM-T20III?serial=583741560601890000
D [15/Apr/2021:17:02:14 +0200] [Job 577] pageCutType = 0
D [15/Apr/2021:17:02:14 +0200] [Job 577] docCutType = 1
D [15/Apr/2021:17:02:14 +0200] [Job 577] bytesPerScanLine = 80
D [15/Apr/2021:17:02:14 +0200] [Job 577] doubleMode = 0
D [15/Apr/2021:17:02:14 +0200] [Job 577] OUTFORMAT=\"(null)\", so output format will be CUPS/PWG Raster
D [15/Apr/2021:17:02:14 +0200] [Job 577] libusb_get_device_list=4
D [15/Apr/2021:17:02:14 +0200] [Job 577] STATE: +connecting-to-device
D [15/Apr/2021:17:02:14 +0200] cupsdMarkDirty(---J-)
D [15/Apr/2021:17:02:14 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Printing jobs and dirty files"
D [15/Apr/2021:17:02:14 +0200] cupsdMarkDirty(----S)
D [15/Apr/2021:17:02:14 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [15/Apr/2021:17:02:14 +0200] [Notifier] state=3
D [15/Apr/2021:17:02:14 +0200] [Notifier] PrinterStateChanged
D [15/Apr/2021:17:02:14 +0200] [Job 577] STATE: -connecting-to-device
D [15/Apr/2021:17:02:14 +0200] cupsdMarkDirty(---J-)
D [15/Apr/2021:17:02:14 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Dirty files"
D [15/Apr/2021:17:02:14 +0200] cupsdMarkDirty(----S)
D [15/Apr/2021:17:02:14 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [15/Apr/2021:17:02:14 +0200] [Notifier] state=3
D [15/Apr/2021:17:02:14 +0200] [Notifier] PrinterStateChanged
D [15/Apr/2021:17:02:14 +0200] [Job 577] Device protocol: 2
D [15/Apr/2021:17:02:14 +0200] [Job 577] Sende Daten zum Drucker.
D [15/Apr/2021:17:02:14 +0200] cupsdMarkDirty(---J-)
D [15/Apr/2021:17:02:14 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [15/Apr/2021:17:02:14 +0200] [Job 577] Set job-printer-state-message to "Sende Daten zum Drucker.", current level=INFO
D [15/Apr/2021:17:02:14 +0200] cupsdMarkDirty(----S)
D [15/Apr/2021:17:02:14 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [15/Apr/2021:17:02:14 +0200] cupsdMarkDirty(----S)
D [15/Apr/2021:17:02:14 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [15/Apr/2021:17:02:14 +0200] [Job 577] pdftopdf: Last filter determined by the PPD: rastertoepsonsimple; FINAL_CONTENT_TYPE: application/vnd.cups-raster => pdftopdf will not log pages in page_log.
D [15/Apr/2021:17:02:14 +0200] [Notifier] state=3
D [15/Apr/2021:17:02:14 +0200] [Notifier] JobProgress
D [15/Apr/2021:17:02:14 +0200] [Notifier] state=3
D [15/Apr/2021:17:02:14 +0200] [Notifier] PrinterStateChanged
D [15/Apr/2021:17:02:14 +0200] [Job 577] Color Manager: Calibration Mode/Off
D [15/Apr/2021:17:02:14 +0200] [Job 577] PID 789 (/usr/lib/cups/filter/pdftopdf) exited with no errors.
D [15/Apr/2021:17:02:14 +0200] [Job 577] Calling FindDeviceById(cups-EPSON_TM-T20III)
D [15/Apr/2021:17:02:14 +0200] [Job 577] Found device /org/freedesktop/ColorManager/devices/cups_EPSON_TM_T20III
D [15/Apr/2021:17:02:14 +0200] [Job 577] Calling org.freedesktop.ColorManager.Device.Get(ProfilingInhibitors)
D [15/Apr/2021:17:02:14 +0200] [Job 577] Calling FindDeviceById(cups-EPSON_TM-T20III)
D [15/Apr/2021:17:02:14 +0200] [Job 577] Found device /org/freedesktop/ColorManager/devices/cups_EPSON_TM_T20III
D [15/Apr/2021:17:02:14 +0200] [Job 577] Calling GetProfileForQualifiers(Gray.....)
D [15/Apr/2021:17:02:14 +0200] [Job 577] Found profile /org/freedesktop/ColorManager/profiles/EPSON_TM_T20III_Gray__
D [15/Apr/2021:17:02:14 +0200] [Job 577] Calling org.freedesktop.ColorManager.Profile.Get(Filename)
D [15/Apr/2021:17:02:14 +0200] [Job 577] Use profile filename: \'\'
D [15/Apr/2021:17:02:14 +0200] [Job 577] Color Manager: ICC Profile: 
D [15/Apr/2021:17:02:14 +0200] [Job 577] Ghostscript using Any-Part-of-Pixel method to fill paths.
D [15/Apr/2021:17:02:14 +0200] [Job 577] Ghostscript command line: gs -dQUIET -dPARANOIDSAFER -dNOPAUSE -dBATCH -dNOINTERPOLATE -dNOMEDIAATTRS -dShowAcroForm -sstdout=%stderr -sOutputFile=%stdout -sDEVICE=cups -r203x203 -dDEVICEWIDTHPOINTS=226 -dDEVICEHEIGHTPOINTS=566 -dcupsBitsPerColor=1 -dcupsColorOrder=0 -dcupsColorSpace=3 -scupsPageSizeName=X80MMY200MM -I/usr/share/cups/fonts -c \'<</.HWMargins[0.000000 0.000000 0.000000 0.000000] /Margins[0 0]>>setpagedevice\' -f -_
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[0]=\"CUPS_CACHEDIR=/var/cache/cups\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[1]=\"CUPS_DATADIR=/usr/share/cups\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[2]=\"CUPS_DOCROOT=/usr/share/cups/doc-root\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[3]=\"CUPS_FONTPATH=/usr/share/cups/fonts\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[4]=\"CUPS_REQUESTROOT=/var/spool/cups\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[5]=\"CUPS_SERVERBIN=/usr/lib/cups\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[6]=\"CUPS_SERVERROOT=/etc/cups\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[7]=\"CUPS_STATEDIR=/run/cups\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[8]=\"HOME=/var/spool/cups/tmp\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[9]=\"PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[10]=\"SERVER_ADMIN=root@hostname\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[11]=\"SOFTWARE=CUPS/2.2.10\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[12]=\"TMPDIR=/var/spool/cups/tmp\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[13]=\"USER=root\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[14]=\"CUPS_MAX_MESSAGE=2047\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[15]=\"CUPS_SERVER=/run/cups/cups.sock\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[16]=\"CUPS_ENCRYPTION=IfRequested\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[17]=\"IPP_PORT=631\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[18]=\"CHARSET=utf-8\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[19]=\"LANG=de_DE.UTF-8\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[20]=\"PPD=/etc/cups/ppd/EPSON_TM-T20III.ppd\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[21]=\"RIP_MAX_CACHE=128m\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[22]=\"CONTENT_TYPE=application/pdf\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[23]=\"DEVICE_URI=usb://EPSON/TM-T20III?serial=583741560601890000\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[24]=\"PRINTER_INFO=EPSON TM-T20III\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[25]=\"PRINTER_LOCATION=\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[26]=\"PRINTER=EPSON_TM-T20III\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[27]=\"PRINTER_STATE_REASONS=none\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[28]=\"CUPS_FILETYPE=document\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[29]=\"FINAL_CONTENT_TYPE=application/vnd.cups-raster\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] envp[30]=\"AUTH_INFO_REQUIRED=none\"
D [15/Apr/2021:17:02:14 +0200] [Job 577] Start rendering...
D [15/Apr/2021:17:02:14 +0200] cupsdMarkDirty(---J-)
D [15/Apr/2021:17:02:14 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [15/Apr/2021:17:02:14 +0200] [Job 577] Set job-printer-state-message to "Start rendering...", current level=INFO
D [15/Apr/2021:17:02:14 +0200] [Job 577] Processing page 1...
D [15/Apr/2021:17:02:14 +0200] cupsdMarkDirty(---J-)
D [15/Apr/2021:17:02:14 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [15/Apr/2021:17:02:14 +0200] [Job 577] Set job-printer-state-message to "Processing page 1...", current level=INFO
D [15/Apr/2021:17:02:14 +0200] cupsdMarkDirty(----S)
D [15/Apr/2021:17:02:14 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [15/Apr/2021:17:02:14 +0200] cupsdMarkDirty(----S)
D [15/Apr/2021:17:02:14 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [15/Apr/2021:17:02:14 +0200] [Notifier] state=3
D [15/Apr/2021:17:02:14 +0200] [Notifier] JobProgress
D [15/Apr/2021:17:02:14 +0200] [Notifier] state=3
D [15/Apr/2021:17:02:14 +0200] [Notifier] PrinterStateChanged
D [15/Apr/2021:17:02:15 +0200] [Job 577] PAGE: 1 1
D [15/Apr/2021:17:02:15 +0200] cupsdMarkDirty(----S)
D [15/Apr/2021:17:02:15 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [15/Apr/2021:17:02:15 +0200] cupsdMarkDirty(---J-)
D [15/Apr/2021:17:02:15 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [15/Apr/2021:17:02:15 +0200] [Job 577] Read 8192 bytes of print data...
D [15/Apr/2021:17:02:15 +0200] [Job 577] Processing page 2...
D [15/Apr/2021:17:02:15 +0200] cupsdMarkDirty(---J-)
D [15/Apr/2021:17:02:15 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [15/Apr/2021:17:02:15 +0200] [Job 577] Set job-printer-state-message to "Processing page 2...", current level=INFO
D [15/Apr/2021:17:02:15 +0200] cupsdMarkDirty(----S)
D [15/Apr/2021:17:02:15 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [15/Apr/2021:17:02:15 +0200] cupsdMarkDirty(----S)
D [15/Apr/2021:17:02:15 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
I [15/Apr/2021:17:02:15 +0200] Expiring subscriptions...
D [15/Apr/2021:17:02:15 +0200] [Notifier] state=3
D [15/Apr/2021:17:02:15 +0200] [Notifier] JobProgress
D [15/Apr/2021:17:02:15 +0200] [Notifier] state=3
D [15/Apr/2021:17:02:15 +0200] [Notifier] JobProgress
D [15/Apr/2021:17:02:15 +0200] [Notifier] state=3
D [15/Apr/2021:17:02:15 +0200] [Notifier] PrinterStateChanged
D [15/Apr/2021:17:02:15 +0200] [Job 577] Rendering completed
D [15/Apr/2021:17:02:15 +0200] cupsdMarkDirty(---J-)
D [15/Apr/2021:17:02:15 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [15/Apr/2021:17:02:15 +0200] [Job 577] Set job-printer-state-message to "Rendering completed", current level=INFO
D [15/Apr/2021:17:02:15 +0200] cupsdMarkDirty(----S)
D [15/Apr/2021:17:02:15 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [15/Apr/2021:17:02:15 +0200] cupsdMarkDirty(----S)
D [15/Apr/2021:17:02:15 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [15/Apr/2021:17:02:15 +0200] [Notifier] state=3
D [15/Apr/2021:17:02:15 +0200] [Notifier] JobProgress
D [15/Apr/2021:17:02:15 +0200] [Notifier] state=3
D [15/Apr/2021:17:02:15 +0200] [Notifier] PrinterStateChanged
D [15/Apr/2021:17:02:15 +0200] [Job 577] Ready to print.
D [15/Apr/2021:17:02:15 +0200] cupsdMarkDirty(---J-)
D [15/Apr/2021:17:02:15 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [15/Apr/2021:17:02:15 +0200] [Job 577] Set job-printer-state-message to "Ready to print.", current level=INFO
D [15/Apr/2021:17:02:15 +0200] cupsdMarkDirty(----S)
D [15/Apr/2021:17:02:15 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [15/Apr/2021:17:02:15 +0200] cupsdMarkDirty(----S)
D [15/Apr/2021:17:02:15 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [15/Apr/2021:17:02:15 +0200] [Job 577] PID 790 (/usr/lib/cups/filter/gstoraster) exited with no errors.
D [15/Apr/2021:17:02:15 +0200] [Notifier] state=3
D [15/Apr/2021:17:02:15 +0200] [Notifier] JobProgress
D [15/Apr/2021:17:02:15 +0200] [Notifier] state=3
D [15/Apr/2021:17:02:15 +0200] [Notifier] PrinterStateChanged
D [15/Apr/2021:17:02:15 +0200] [Job 577] Wrote 8192 bytes of print data...
D [15/Apr/2021:17:02:15 +0200] [Job 577] Read 8192 bytes of print data...
D [15/Apr/2021:17:02:15 +0200] [Job 577] PID 791 (/usr/lib/cups/filter/rastertoepsonsimple) exited with no errors.
D [15/Apr/2021:17:02:16 +0200] [Job 577] Wrote 8192 bytes of print data...
I [15/Apr/2021:17:02:16 +0200] Expiring subscriptions...
D [15/Apr/2021:17:02:16 +0200] [Job 577] Read 8192 bytes of print data...
D [15/Apr/2021:17:02:16 +0200] [Job 577] Wrote 8192 bytes of print data...
D [15/Apr/2021:17:02:16 +0200] [Job 577] Read 8192 bytes of print data...
D [15/Apr/2021:17:02:17 +0200] [Job 577] Wrote 8192 bytes of print data...
I [15/Apr/2021:17:02:17 +0200] Expiring subscriptions...
D [15/Apr/2021:17:02:17 +0200] [Job 577] Read 8192 bytes of print data...
D [15/Apr/2021:17:02:18 +0200] [Job 577] Wrote 8192 bytes of print data...
I [15/Apr/2021:17:02:18 +0200] Expiring subscriptions...
D [15/Apr/2021:17:02:18 +0200] [Job 577] Read 8192 bytes of print data...
D [15/Apr/2021:17:02:18 +0200] [Job 577] Wrote 8192 bytes of print data...
D [15/Apr/2021:17:02:18 +0200] [Job 577] Read 8192 bytes of print data...
D [15/Apr/2021:17:02:32 +0200] [Job 577] Wrote 8192 bytes of print data...
I [15/Apr/2021:17:02:32 +0200] Expiring subscriptions...
D [15/Apr/2021:17:02:32 +0200] [Job 577] Read 8192 bytes of print data...
D [15/Apr/2021:17:02:32 +0200] [Job 577] Wrote 8192 bytes of print data...
D [15/Apr/2021:17:02:32 +0200] [Job 577] Read 8192 bytes of print data...
D [15/Apr/2021:17:02:33 +0200] [Job 577] Wrote 8192 bytes of print data...
I [15/Apr/2021:17:02:33 +0200] Expiring subscriptions...
D [15/Apr/2021:17:02:33 +0200] [Job 577] Read 3094 bytes of print data...
D [15/Apr/2021:17:02:33 +0200] [Job 577] Wrote 3094 bytes of print data...
D [15/Apr/2021:17:02:33 +0200] [Job 577] Sent 76822 bytes...
D [15/Apr/2021:17:02:33 +0200] [Job 577] Waiting for read thread to exit...
D [15/Apr/2021:17:02:33 +0200] [Job 577] PID 792 (/usr/lib/cups/backend/usb) exited with no errors.
D [15/Apr/2021:17:02:33 +0200] [Job 577] time-at-completed=1618498953
D [15/Apr/2021:17:02:33 +0200] cupsdMarkDirty(----S)
D [15/Apr/2021:17:02:33 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
I [15/Apr/2021:17:02:33 +0200] [Job 577] Job completed.
I [15/Apr/2021:17:02:33 +0200] Expiring subscriptions...
D [15/Apr/2021:17:02:33 +0200] cupsdMarkDirty(---J-)
D [15/Apr/2021:17:02:33 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [15/Apr/2021:17:02:33 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [15/Apr/2021:17:02:33 +0200] cupsdMarkDirty(----S)
D [15/Apr/2021:17:02:33 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [15/Apr/2021:17:02:33 +0200] cupsdMarkDirty(---J-)
D [15/Apr/2021:17:02:33 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [15/Apr/2021:17:02:33 +0200] [Notifier] state=3
D [15/Apr/2021:17:02:33 +0200] [Notifier] JobCompleted
D [15/Apr/2021:17:02:33 +0200] [Notifier] state=3
D [15/Apr/2021:17:02:33 +0200] [Notifier] PrinterStateChanged
I [15/Apr/2021:17:02:34 +0200] Expiring subscriptions...
D [15/Apr/2021:17:02:34 +0200] [Job 577] Unloading...
I [15/Apr/2021:17:02:44 +0200] Saving job.cache...
I [15/Apr/2021:17:02:44 +0200] Saving subscriptions.conf...
D [15/Apr/2021:17:02:44 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Printing jobs and dirty files"
I [15/Apr/2021:17:02:44 +0200] Expiring subscriptions...
D [15/Apr/2021:17:02:44 +0200] Report: clients=3
D [15/Apr/2021:17:02:44 +0200] Report: jobs=122
D [15/Apr/2021:17:02:44 +0200] Report: jobs-active=0
D [15/Apr/2021:17:02:44 +0200] Report: printers=2
D [15/Apr/2021:17:02:44 +0200] Report: stringpool-string-count=6291
D [15/Apr/2021:17:02:44 +0200] Report: stringpool-alloc-bytes=18976
D [15/Apr/2021:17:02:44 +0200] Report: stringpool-total-bytes=124672
I [15/Apr/2021:17:06:42 +0200] Expiring subscriptions...
D [15/Apr/2021:17:06:42 +0200] cupsdAddCert: Adding certificate for PID 0
D [15/Apr/2021:17:06:42 +0200] Closing client 2 after 300 seconds of inactivity.
D [15/Apr/2021:17:06:42 +0200] [Client 2] Closing connection.
D [15/Apr/2021:17:06:42 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"

[gajdusek]

Hello, I had similar problem. I am copy pasting my old notes here. The OS was Raspbian based on Debian wheezy.

In my case it seemed to be caused by interfering or outputting something to USB port while printing, confusing the printer and switching it to TEXT mode (resulting in garbage printed and unability to cut off the role) usually until the printer was turned off and on again.

The issue disappeared after black-listing usblp kernel module. This removed /dev/usb/lp0.

Kernel module usblp (USB Printer Device Class driver) is loaded by default but is not needed by CUPS. Each time a job is to be printed, device file /dev/usb/lp0 (provided by kernel module usblp) is removed to avoid interfering with ongoing print job, and re-enabled after the job is finished. However, this seemed to be not enough to prevent interfering in my case.

/var/log/syslog:

Nov 29 10:53:32 CZLCRIMP1 kernel: [1112671.364278] usblp0: removed
Nov 29 10:53:39 CZLCRIMP1 kernel: [1112678.123601] usblp 1-1.2:1.0: usblp0: USB Bidirectional printer dev 15 if 0 alt 0 proto 2 vid 0x04B8 pid 0x0E15

Therefore it may be good idea to prevent usblp module from being loaded, as it is not needed by CUPS at all.

/etc/modprobe.d/local-printer-blacklist.conf:

# Blacklist usblp to attempt of fixing printing issues
blacklist usblp

I also blacklisted the RPi sound card (module snd-bcm2835), but that was probably not needed.

[zoomyboy]

Okay. Thanks for your solution. I will give this a try.

[plinth666]

Maybe we should put this into the readme?On Apr 16, 2021 9:07 AM, Philipp Lang ***@***.***> wrote: Okay. Thanks for your solution. I will give this a try. —You are receiving this because you are subscribed to this thread.Reply to this email directly, view it on GitHub, or unsubscribe.