Rendering completed - Stuck

[balasankarc]

Sometimes, the printing get stuck with the message "Rendering completed". Sometimes it can be fixed by turning the printer off and on. Sometimes, it can be fixed by disabling the printer and enabling it. Often both of them has to be done sequentially to fix the issue.

Ubuntu 14.04
Canon LBP 2900B

[twd2]

I have the same problem.

[is-cs]

First of all thanks for this driver. Its for the first time i was able to setup Google Cloud Print. I'm using Canon-LBP-2900B on my Raspberry Pi running Raspbian Jessie 8. But I'm facing a strange issue, as people have mentioned above. In my case, I'm able to print only once. After i see the "Rendering Complete", further print jobs just dont print, they go from "Processing page 1..." to "Rendering Complete", but printing does not happen. I have to turn off and on the printer again, to fire one more print job, and it becomes useless again. Request you to please fix this issue.

[agalakhov]

Hi,
the problem is, I cannot identify the cause. This is not an usual bug in the driver. This is some misinterpretation of the CAPT command set which we don't really know (it is reverse-engineered). Unfortunately I don't have enough information about the CAPT protocol right now to tell why it happens.

I do not own the printer anymore. Hopefully one of the printer owners could do some debugging.

[is-cs]

Hi Galakhov

Its great to hear back from you. I hope the owners will take a look at it.
I am a developer myself, and was trying to make sense of the driver code. I
could not find WHO is sending this message "Rendering Completed". Its not
in the driver code. Although i spotted a couple of messages in the driver
code like " bad reply from printer" that i saw on the CUPS webpage a couple
times.
On Apr 2, 2016 11:45 PM, "Alexey Galakhov" notifications@github.com wrote:

Hi,
the problem is, I cannot identify the cause. This is not an usual bug in
the driver. This is some misinterpretation of the CAPT command set which we
don't really know (it is reverse-engineered). Unfortunately I don't have
enough information about the CAPT protocol right now to tell why it happens.

I do not own the printer anymore. Hopefully one of the printer owners
could do some debugging.

—
You are receiving this because you commented.
Reply to this email directly or view it on GitHub
#7 (comment)

[missla]

Hi is-cs,
have you experienced ant freeze after latest changes of the code? In case could you report the printer state reply.

The message "Rendering Completed" is by CUPS. Keep in mind captdriver is a CUPS filter so it is launched and handle by CUPS.

[Goshik92]

Hi @is-cs ,

How did you manage to run LBP2900 on your Raspberry Pi? I used this guide to install the driver on my Cubieboard 2 with Debian 9, but the printer didn't work at all showing the message "Rendering completed". No manipulations with my printer or driver lead to printing a single page. Did you do anything that is not in the guide above (added compiler options etc)?

[mounaiban]

@agalakhov:

Hi,
the problem is, I cannot identify the cause. This is not an usual bug in the driver. This is some misinterpretation of the CAPT command set which we don't really know (it is reverse-engineered).

Don't sweat it, not even Canon has gotten it 100%. The proprietary driver froze frequently (like once out of four jobs) when I was using it on macOS 10.12, and I had to restart or reconnect the printer (LBP 3000) to keep printing. Anyone who manages to solve this problem would have outdone the boss.

[mounaiban]

I just found this today on the CUPS repo: apple/cups#5310

Long story short, someone had the same problem with an HP printer, and found that disabling usblp reattachment in CUPS for the printer solves the stuck printer problem.

I have repeated the same workaround with my LBP3000, and now it takes on job after job without the need to restart or reconnect the printer. This is what you do:

First, identify the vendor-product id of your printer with lsusb or any other capable tool. Let's say my printer has an id of 04a9:1337, as seen on my system:

$ lsusb
...
Bus 001 Device 099: ID 04a9:1337 Canon, Inc. CAPT Device

I would then add the following two lines to $(cups-config --datadir)/usb/org.cups.usb-quirks:

# LBP 3000
0x04a9 0x1337 no-reattach

Remember to su or sudo before editing that file!

Save your edits, and restart or reconnect your printer. The printer should take on additional print jobs without needing more restarts! 😎

I have personally tested this with great success on Xubuntu 18.04.1 (CUPS 2.2.7) and CentOS 8.1.1911 (CUPS 2.2.6) [*2].

As far as my needs are concerned, I think at this point I am getting an experience that rivals or even exceeds what I got out of macOS. Honestly, I haven't got a clue why it worked for me, but I had to try this trick because it sounded like it would work.

Note 1: on most of my systems, $(cups-config --datadir) == /usr/share/cups/
just writing it in that style just in case the directories are different for you...

Note 2: on CUPS 2.2.6, captdriver only works for the LBP 3000 with a previous version of the operations and job preparation routines, prn_lbp2900.c, specifically commit 216fddb

[mounaiban]

Could we have this issue closed now? After some more testing, I think the problem has been largely fixed in 94b2bf2 for LBP2900, or my edit 1106978 for LBP3000. If anyone is using these versions or later, please respond to confirm with your printer model if your printer works (also, please ignore my message above and leave the no-reattach USB quirk off).

@Goshik92: if you follow the instructions on https://brain.cdauth.eu/2014/01/16/canon-lbp2900-printer-on-linux/ you might get an error if you compiled captdriver as a normal user. You should see error messages in /var/log/cups/error_log about "insecure filters".

This is because CUPS only runs filters that are owned by root and are read-and-execute-only to everyone else (mode 0755). See https://askubuntu.com/questions/456918/cups-insecure-filter-error-for-lexmark-printer-on-trusty#511351 for details.

[uncleeugene]

Just pulled latest captdriver yesterday to make my LBP2900 work. Same issue, one job printed. I have set no-reattach thing up, not yet tested.

[sbn001]

Just pulled latest captdriver yesterday to make my LBP2900 work. Same issue, one job printed. I have set no-reattach thing up, not yet tested.

Which Linux system / arch are you using? I could get my LPB2900 printer to print multiple pages repeatedly without problems on my Raspberry Pi 3 running Ubuntu server (19.10.1 armhf) and CUPS 2.2.12. I tried with the latest commit b2948ba from @mounaiban and it worked without requiring to restart the printer or adding anything to org.cups.usb-quirks.

However, I could not get the same thing to work on a Pi running Raspbian. I am still unable to identify why it did not work in Raspbian. The macs on my home network can now print to LBP2900 via the CUPS running on the Pi (Ubuntu) but I have not been able print from my Windows devices yet. There might be some other issues with communication between CUPS and the Windows system.

Please try compiling the captdriver from https://github.com/mounaiban/captdriver and check if it can print more than once.

[uncleeugene]

I am running Manjaro on x86_64. Thank you for the link, i'll give it a try and report my progress.

[fresun78]

Hi, I have a LBP2900 printer. Have it connected to a rpi 3a+. Installed Raspbian lite today (Raspbian GNU/Linux 10), installed CUPS 2.2.10. Tried install both agalakhov and mounaiban capt driver, also tried editing /usr/share/cups/usb/org.cups.usb-quirks, restarting printer, pause/resume all ended up with same result, "Rendering completed" and nothing printed.

I tried to enable error logging via cupsctl --debug-logging and looked at /var/log/cups/error_log
Not really sure what to look for regarding the "Rendering completed" problem.
I found where the "Rendering completed" gets sent:

D [25/Jun/2020:19:00:02 +0100] [CGI] cgiSetArray: job_printer_name[0]="Canon_LBP2900"
D [25/Jun/2020:19:00:02 +0100] [CGI] cgiSetArray: job_printer_uri[0]="/printers/Canon_LBP2900"
D [25/Jun/2020:19:00:02 +0100] [CGI] cgiSetArray: time_at_completed[0]="novalue"
D [25/Jun/2020:19:00:02 +0100] [CGI] cgiSetArray: time_at_creation[0]="Thu Jun 25 18:59:57 2020"
D [25/Jun/2020:19:00:02 +0100] [CGI] cgiSetArray: time_at_processing[0]="Thu Jun 25 18:59:57 2020"
D [25/Jun/2020:19:00:02 +0100] [CGI] cgiSetArray: job_id[0]="8"
D [25/Jun/2020:19:00:02 +0100] [CGI] cgiSetArray: job_state[0]="5"
D [25/Jun/2020:19:00:02 +0100] [CGI] cgiSetArray: job_impressions_completed[0]="0"
D [25/Jun/2020:19:00:02 +0100] [CGI] cgiSetArray: job_k_octets[0]="1"
D [25/Jun/2020:19:00:02 +0100] [CGI] cgiSetArray: job_printer_state_message[0]="Rendering completed"
D [25/Jun/2020:19:00:02 +0100] [CGI] cgiSetVariable: THISURL="/jobs/"
D [25/Jun/2020:19:00:02 +0100] [Client 1] CGI data ready to be sent.
D [25/Jun/2020:19:00:02 +0100] [Client 1] con->http=0x16f9da8
D [25/Jun/2020:19:00:02 +0100] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, dat
a_remaining=0, response=(nil)(), pipe_pid=10890, file=21
D [25/Jun/2020:19:00:02 +0100] [Client 1] Waiting for CGI data.
D [25/Jun/2020:19:00:02 +0100] [Client 1] con->http=0x16f9da8
D [25/Jun/2020:19:00:02 +0100] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, dat
a_remaining=0, response=(nil)(), pipe_pid=10890, file=21
D [25/Jun/2020:19:00:02 +0100] [Client 1] Waiting for CGI data.
D [25/Jun/2020:19:00:02 +0100] [Client 1] CGI data ready to be sent.
D [25/Jun/2020:19:00:02 +0100] [Client 1] con->http=0x16f9da8
D [25/Jun/2020:19:00:02 +0100] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, dat
a_remaining=0, response=(nil)(), pipe_pid=10890, file=21
D [25/Jun/2020:19:00:02 +0100] [Client 1] Waiting for CGI data.
D [25/Jun/2020:19:00:02 +0100] [Client 1] con->http=0x16f9da8
D [25/Jun/2020:19:00:02 +0100] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=10890, file=21
D [25/Jun/2020:19:00:02 +0100] [Client 1] Waiting for CGI data.
D [25/Jun/2020:19:00:02 +0100] [Client 4] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [25/Jun/2020:19:00:02 +0100] [Client 4] Closing connection.
D [25/Jun/2020:19:00:02 +0100] cupsdSetBusyState: newbusy="Active clients and printing jobs", busy="Active clients and printing jobs"
D [25/Jun/2020:19:00:02 +0100] PID 10890 (/usr/lib/cups/cgi-bin/jobs.cgi) exited with no errors.
D [25/Jun/2020:19:00:02 +0100] [Client 1] CGI data ready to be sent.
D [25/Jun/2020:19:00:02 +0100] [Client 1] con->http=0x16f9da8
D [25/Jun/2020:19:00:02 +0100] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=10890, file=21
D [25/Jun/2020:19:00:02 +0100] [Client 1] Waiting for CGI data.
D [25/Jun/2020:19:00:02 +0100] [Client 1] Sending 0-length chunk.
D [25/Jun/2020:19:00:02 +0100] [Client 1] Flushing write buffer.
D [25/Jun/2020:19:00:02 +0100] [Client 1] New state is HTTP_STATE_WAITING
D [25/Jun/2020:19:00:02 +0100] [Client 1] Waiting for request.
D [25/Jun/2020:19:00:02 +0100] cupsdSetBusyState: newbusy="Printing jobs", busy="Active clients and printing jobs"

After that I had a lot of repeated messages (identical as below)

I [25/Jun/2020:19:00:07 +0100] Expiring subscriptions...
D [25/Jun/2020:19:00:07 +0100] [Job 8] CAPT: send A0 E0 04 00
D [25/Jun/2020:19:00:07 +0100] [Job 8] CUPS_SC_CMD_DRAIN_OUTPUT received from driver...
D [25/Jun/2020:19:00:07 +0100] [Job 8] Read 4 bytes of print data...
D [25/Jun/2020:19:00:07 +0100] [Job 8] Wrote 4 bytes of print data...
D [25/Jun/2020:19:00:07 +0100] [Job 8] CAPT: waiting for 6 bytes
D [25/Jun/2020:19:00:07 +0100] [Job 8] Read 6 bytes of back-channel data...
D [25/Jun/2020:19:00:07 +0100] [Job 8] CAPT: recv A0 E0 06 00 88 00

I also checked

dmesg | grep usblp
[ 4.758896] usblp 1-1:1.0: usblp0: USB Bidirectional printer dev 2 if 0 alt 0 proto 2 vid 0x04A9 pid 0x2676
[ 4.759180] usbcore: registered new interface driver usblp
[ 14.653722] usblp0: removed
[ 111.207228] usblp 1-1:1.0: usblp0: USB Bidirectional printer dev 3 if 0 alt 0 proto 2 vid 0x04A9 pid 0x2676
[ 177.112430] usblp0: removed

So it turns out the /dev/usb/lp0 appears for a very short time and then gets removed again.
I tried lpadmin -p Canon_LBP2900 -o usb-no-reattach-default=true
Now the /dev/usb/lp0 device appears (and remains).

Now trying to print again moves past the "Rendering completed", but halts with a new error.

lpstat -p
printer Canon_LBP2900 is idle. enabled since Thu Jun 25 20:43:20 2020
CAPT: bad reply from printer, expected A0 E0 xx xx xx xx, got A1 A1 38 00 00 0B

From /var/log/cups/error_log

D [25/Jun/2020:20:43:20 +0100] [Job 12] CAPT: rastertocapt: start job
D [25/Jun/2020:20:43:20 +0100] [Job 12] CAPT: send A1 A1 04 00
D [25/Jun/2020:20:43:20 +0100] [Job 12] Read 4 bytes of print data...
D [25/Jun/2020:20:43:20 +0100] [Job 12] Wrote 4 bytes of print data...
D [25/Jun/2020:20:43:20 +0100] [Job 12] CUPS_SC_CMD_DRAIN_OUTPUT received from driver...
D [25/Jun/2020:20:43:20 +0100] [Job 12] Read 6 bytes of back-channel data...
D [25/Jun/2020:20:43:20 +0100] [Job 12] Read 50 bytes of back-channel data...
D [25/Jun/2020:20:43:20 +0100] [Job 12] Rendering completed
D [25/Jun/2020:20:43:20 +0100] [Job 12] PID 1795 (/usr/lib/cups/filter/gstoraster) exited with no errors.
D [25/Jun/2020:20:43:20 +0100] [Job 12] CAPT: output already empty, not drained
D [25/Jun/2020:20:43:20 +0100] [Job 12] CAPT: waiting for 6 bytes
D [25/Jun/2020:20:43:20 +0100] [Job 12] CAPT: waiting for 50 bytes
D [25/Jun/2020:20:43:20 +0100] [Job 12] CAPT: recv A1 A1 38 00 00 0B 31 2A 01 01 F0 FF 40 00 04 00
D [25/Jun/2020:20:43:20 +0100] [Job 12] CAPT: 41 00 01 00 D0 02 00 00 6F 08 00 00 E4 0D 00 00
D [25/Jun/2020:20:43:20 +0100] [Job 12] CAPT: 00 00 00 00 FA 02 00 00 F6 04 00 00 28 3C 32 32
D [25/Jun/2020:20:43:20 +0100] [Job 12] CAPT: 58 02 58 02 15 03 02 02
D [25/Jun/2020:20:43:20 +0100] [Job 12] CAPT: send A0 E0 04 00
D [25/Jun/2020:20:43:20 +0100] [Job 12] Read 4 bytes of print data...
D [25/Jun/2020:20:43:20 +0100] [Job 12] CUPS_SC_CMD_DRAIN_OUTPUT received from driver...
D [25/Jun/2020:20:43:20 +0100] [Job 12] Wrote 4 bytes of print data...
D [25/Jun/2020:20:43:20 +0100] [Job 12] CAPT: waiting for 6 bytes
D [25/Jun/2020:20:43:20 +0100] [Job 12] Set job-printer-state-message to "CAPT: bad reply from printer, expected A0 E0 xx xx xx xx, got A1 A1 38 00 00 0B", current level=ERROR

After this the /dev/usb/lp0 got removed again

[ 1263.347568] usblp 1-1:1.0: usblp0: USB Bidirectional printer dev 6 if 0 alt 0 proto 2 vid 0x04A9 pid 0x2676
[ 1411.672350] usblp0: removed

And restarting the print job gets stuck at "Rendering completed".

[mounaiban]

@fresun78 thanks for your feedback. Try reverting to 216fddb with git checkout, and see if you can print.

Please note that printing support was a lot less complete at the time of the commit; while it was the last commit known to work on Raspbian with the LBP2900, at that stage you had to restart the printer between jobs (among other limitations).

At time of writing, I believe this issue is due to a failure to correctly communicate with the LBP2900 to obtain a job number (see lbp_2900_job_prologue() in prn_lbp2900.c). I have mentioned this earlier in the issue tracker in my fork: mounaiban#3 (comment)

I suspect that the CAPT_JOB_BEGIN command has been incorrectly issued due to a lack of understanding of the printer's behaviour. You can also have a look at capt-status.c to see how the status checks are done. If you notice anything we are doing wrong, please let us know.

In the meantime, I am thinking of overriding the job number with the one provided by CUPS. This is a return to how things were done in 216fddb, except that the job number will be allowed to move beyond 1. Hopefully, this would allow you to work around the bug that has been preventing the LBP2900 from printing.