LBP2900 cannot print from Raspbian 10 armhf (32-bit)

[mounaiban]

When trying to print with an LBP2900 from Raspbian 10 armhf, the printer gets stuck in a loop. Other versions of Raspbian may be affected as well.

CUPS debug logs reveal that the loop is a status check command (code 0xE0A0) gone wrong, with endlessly-repeating entries like:

D [24/Apr/2020:16:29:19 ] [Job 4] CAPT: send A0 E0 04 00
D [24/Apr/2020:16:29:19 ] [Job 4] Read 4 bytes of print data...
D [24/Apr/2020:16:29:19 ] [Job 4] CUPS_SC_CMD_DRAIN_OUTPUT received from driver...
D [24/Apr/2020:16:29:19 ] [Job 4] Wrote 4 bytes of print data...
D [24/Apr/2020:16:29:19 ] [Job 4] CAPT: waiting for 6 bytes
D [24/Apr/2020:16:29:19 ] [Job 4] Read 6 bytes of back-channel data...
D [24/Apr/2020:16:29:19 ] [Job 4] CAPT: waiting for 6 bytes
D [24/Apr/2020:16:29:19 ] [Job 4] Read 6 bytes of back-channel data...
D [24/Apr/2020:16:29:19 ] [Job 4] CAPT: recv A0 E0 0C 00 00 8A 00 00 0F 00 00 00
I [24/Apr/2020:16:29:20 ] Expiring subscriptions...

See this comment (https://github.com/mounaiban/captdriver/commit/18797c4c8edf916add31c09a2c527cf284021e14#r38716893) in the original conversation for details.

[mounaiban]

An experimental fix 66667a2e13fb7b0a2273a941708535d6c9d44581 has been pushed into the 0.1.4-wait-for-fl-processing branch. The driver is set to wait for a different flag to clear (CAPT_FL_PROCESSING instead of CAPT_FL_BUSY) before sending the first page of the job.

[sbn001]

I tried printing with 0.1.4-wait-for-fl-processing branch but I am still getting the same error from CUPS erro_log. Still unable to print on LBP2900 from Raspbian.

D [30/Apr/2020:14:52:06 ] [Job 6] CAPT: send  A0 E0 04 00
D [30/Apr/2020:14:52:06 ] [Job 6] CUPS_SC_CMD_DRAIN_OUTPUT received from driver...
D [30/Apr/2020:14:52:06 ] [Job 6] Read 4 bytes of print data...
D [30/Apr/2020:14:52:06 ] [Job 6] Wrote 4 bytes of print data...
D [30/Apr/2020:14:52:06 ] [Job 6] CAPT: waiting for 6 bytes
D [30/Apr/2020:14:52:06 ] [Job 6] Read 6 bytes of back-channel data...
D [30/Apr/2020:14:52:06 ] [Job 6] Read 6 bytes of back-channel data...
D [30/Apr/2020:14:52:06 ] [Job 6] CAPT: waiting for 6 bytes
D [30/Apr/2020:14:52:06 ] [Job 6] CAPT: recv  A0 E0 0C 00 00 8A 00 00 0F 00 00 00
I [30/Apr/2020:14:52:07 ] Expiring subscriptions...

[mounaiban]

I have pushed another branch, 0.1.4-alt-dummy-job-details, please try it and see if it solves the problem. It contains changes to send_job_start() which attempts to reproduce the effects of its 216fddb version. The size of the command requested by this function is brought back to 116 bytes.

[sbn001]

Thank you for your tireless efforts to get the driver working. I tried printing with branch 0.1.4-alt-dummy-job-details but still unable to print on Raspbian and getting the same error log from /var/log/cups/error_log

# Unsuccessful print with new driver 
D [04/May/2020:11:19:13 ] [Job 7] CAPT: send  A0 E0 04 00
D [04/May/2020:11:19:13 ] [Job 7] Read 4 bytes of print data...
D [04/May/2020:11:19:13 ] [Job 7] CUPS_SC_CMD_DRAIN_OUTPUT received from driver...
D [04/May/2020:11:19:13 ] [Job 7] Wrote 4 bytes of print data...
D [04/May/2020:11:19:13 ] [Job 7] CAPT: waiting for 6 bytes
D [04/May/2020:11:19:13 ] [Job 7] Read 6 bytes of back-channel data...
D [04/May/2020:11:19:13 ] [Job 7] CAPT: waiting for 6 bytes
D [04/May/2020:11:19:13 ] [Job 7] Read 6 bytes of back-channel data...
D [04/May/2020:11:19:13 ] [Job 7] CAPT: recv  A0 E0 0C 00 00 8A 00 00 0F 00 00 00
I [04/May/2020:11:19:14 ] Expiring subscriptions...

I rechecked if I could print from 216fddba1616546eff73802bab3f12967301dc86 and it worked but as usual only once after each restart of the printer. I have attached below the excerpt from the log while printing successfully using the old filter.

# Successful print with first print job after restarting printer
D [04/May/2020:11:35:08 ] [Job 11] CAPT: send  A7 E0 06 00 01 00
D [04/May/2020:11:35:08 ] [Job 11] Read 6 bytes of print data...
D [04/May/2020:11:35:08 ] [Job 11] CUPS_SC_CMD_DRAIN_OUTPUT received from driver...
D [04/May/2020:11:35:08 ] [Job 11] Wrote 6 bytes of print data...
D [04/May/2020:11:35:08 ] [Job 11] CAPT: waiting for 6 bytes
D [04/May/2020:11:35:08 ] [Job 11] Read 6 bytes of back-channel data...
D [04/May/2020:11:35:08 ] [Job 11] CAPT: recv  A7 E0 06 00 00 00
D [04/May/2020:11:35:08 ] [Job 11] CAPT: send  A0 E0 04 00
D [04/May/2020:11:35:08 ] [Job 11] Read 4 bytes of print data...
D [04/May/2020:11:35:08 ] [Job 11] CUPS_SC_CMD_DRAIN_OUTPUT received from driver...
D [04/May/2020:11:35:08 ] [Job 11] Wrote 4 bytes of print data...
D [04/May/2020:11:35:08 ] [Job 11] CAPT: waiting for 6 bytes
D [04/May/2020:11:35:08 ] [Job 11] Read 6 bytes of back-channel data...
D [04/May/2020:11:35:08 ] [Job 11] CAPT: waiting for 6 bytes
D [04/May/2020:11:35:08 ] [Job 11] Read 6 bytes of back-channel data...
D [04/May/2020:11:35:08 ] [Job 11] CAPT: recv  A0 E0 0C 00 00 8B 00 00 0F 00 00 00
D [04/May/2020:11:35:08 ] [Job 11] CAPT: send  A0 E0 04 00
D [04/May/2020:11:35:08 ] [Job 11] Read 4 bytes of print data...
D [04/May/2020:11:35:08 ] [Job 11] CUPS_SC_CMD_DRAIN_OUTPUT received from driver...
D [04/May/2020:11:35:08 ] [Job 11] Wrote 4 bytes of print data...
D [04/May/2020:11:35:08 ] [Job 11] CAPT: waiting for 6 bytes
D [04/May/2020:11:35:08 ] [Job 11] Read 6 bytes of back-channel data...
D [04/May/2020:11:35:08 ] [Job 11] CAPT: waiting for 6 bytes
D [04/May/2020:11:35:08 ] [Job 11] Read 6 bytes of back-channel data...
D [04/May/2020:11:35:08 ] [Job 11] CAPT: recv  A0 E0 0C 00 00 8B 00 00 0F 00 00 00
D [04/May/2020:11:35:08 ] [Job 11] CAPT: send  A8 A0 04 00
D [04/May/2020:11:35:08 ] [Job 11] Read 4 bytes of print data...
D [04/May/2020:11:35:08 ] [Job 11] CUPS_SC_CMD_DRAIN_OUTPUT received from driver...
D [04/May/2020:11:35:08 ] [Job 11] Wrote 4 bytes of print data...
D [04/May/2020:11:35:08 ] [Job 11] CAPT: waiting for 6 bytes
D [04/May/2020:11:35:08 ] [Job 11] Read 6 bytes of back-channel data...
D [04/May/2020:11:35:08 ] [Job 11] CAPT: waiting for 50 bytes
D [04/May/2020:11:35:08 ] [Job 11] Read 50 bytes of back-channel data...
D [04/May/2020:11:35:08 ] [Job 11] CAPT: recv  A8 A0 38 00 00 8A 00 00 0F 00 00 00 80 00 80 00
D [04/May/2020:11:35:08 ] [Job 11] CAPT: 00 00 01 00 00 00 00 00 00 00 00 00 57 00 00 00
D [04/May/2020:11:35:08 ] [Job 11] CAPT: 01 00 00 00 00 02 01 00 00 00 00 00 01 00 00 00
D [04/May/2020:11:35:08 ] [Job 11] CAPT: 00 00 00 00 00 00 00 00
D [04/May/2020:11:35:08 ] [Job 11] CAPT: printer status P1=0 P2=0 B=0 B1=0 nE=1
D [04/May/2020:11:35:08 ] [Job 11] CAPT: pages 1/0/0/0
...skipping...
D [04/May/2020:11:35:09 ] [Job 11] CAPT: waiting for 6 bytes
D [04/May/2020:11:35:09 ] [Job 11] Read 6 bytes of back-channel data...
D [04/May/2020:11:35:09 ] [Job 11] CAPT: waiting for 6 bytes
D [04/May/2020:11:35:09 ] [Job 11] Read 6 bytes of back-channel data...
D [04/May/2020:11:35:09 ] [Job 11] CAPT: recv  A0 E0 0C 00 00 8B 00 00 0F 00 00 00
D [04/May/2020:11:35:09 ] [Job 11] CAPT: send  A8 A0 04 00
D [04/May/2020:11:35:09 ] [Job 11] Read 4 bytes of print data...
D [04/May/2020:11:35:09 ] [Job 11] CUPS_SC_CMD_DRAIN_OUTPUT received from driver...
D [04/May/2020:11:35:09 ] [Job 11] Wrote 4 bytes of print data...
D [04/May/2020:11:35:09 ] [Job 11] CAPT: waiting for 6 bytes
D [04/May/2020:11:35:09 ] [Job 11] Read 6 bytes of back-channel data...
D [04/May/2020:11:35:09 ] [Job 11] CAPT: waiting for 50 bytes
D [04/May/2020:11:35:09 ] [Job 11] Read 50 bytes of back-channel data...
D [04/May/2020:11:35:09 ] [Job 11] CAPT: recv  A8 A0 38 00 00 8A 00 00 0F 00 00 00 84 00 80 00
D [04/May/2020:11:35:09 ] [Job 11] CAPT: 00 00 01 00 00 00 00 00 00 00 00 00 57 00 00 00
D [04/May/2020:11:35:09 ] [Job 11] CAPT: 01 00 00 00 00 02 01 00 00 00 00 00 01 00 00 00
D [04/May/2020:11:35:09 ] [Job 11] CAPT: 00 00 00 00 00 00 00 00
D [04/May/2020:11:35:09 ] [Job 11] CAPT: printer status P1=0 P2=0 B=0 B1=0 nE=1
D [04/May/2020:11:35:09 ] [Job 11] CAPT: pages 1/0/0/0
I [04/May/2020:11:35:10 ] Expiring subscriptions...
D [04/May/2020:11:35:10 ] [Job 11] CAPT: send  A0 E0 04 00
D [04/May/2020:11:35:10 ] [Job 11] Read 4 bytes of print data...
D [04/May/2020:11:35:10 ] [Job 11] CUPS_SC_CMD_DRAIN_OUTPUT received from driver...
D [04/May/2020:11:35:10 ] [Job 11] Wrote 4 bytes of print data...
D [04/May/2020:11:35:10 ] [Job 11] CAPT: waiting for 6 bytes
D [04/May/2020:11:35:10 ] [Job 11] Read 6 bytes of back-channel data...
D [04/May/2020:11:35:10 ] [Job 11] CAPT: waiting for 6 bytes
D [04/May/2020:11:35:10 ] [Job 11] Read 6 bytes of back-channel data...
D [04/May/2020:11:35:10 ] [Job 11] CAPT: recv  A0 E0 0C 00 00 8A 00 00 0F 00 00 00

The printer status returned to normal after printing the first job.

pi@raspberrypi:~/captdriver $ lpstat -a
Canon_LBP2900 accepting requests since Mon 04 May 2020 11:35:26

The next print job after this was unsuccessful and result in the following log.

# Unsuccessful print with old driver after suceessfully printing the first print job
D [04/May/2020:11:42:50 ] [Job 12] CAPT: B6 BC D5 B9 BC 88 3E 3C A6 FD FC B1 9C 1C BA 2C
D [04/May/2020:11:42:50 ] [Job 12] CAPT: EC BF F4 94 BD 18 A8 BC 6E B6 BC D5 B9 BC 88 3E
D [04/May/2020:11:42:50 ] [Job 12] CAPT: 3C A6 FD FC B1 9C 1C BA 2C EC BF F4 94 BD 18 A8... (108 more)
D [04/May/2020:11:42:50 ] [Job 12] Read 236 bytes of print data...
D [04/May/2020:11:42:50 ] [Job 12] Wrote 236 bytes of print data...
D [04/May/2020:11:42:50 ] [Job 12] CUPS_SC_CMD_DRAIN_OUTPUT received from driver...
D [04/May/2020:11:42:51 ] [Job 12] CAPT: output already empty, not drained
I [04/May/2020:11:42:51 ] Expiring subscriptions...
D [04/May/2020:11:42:51 ] [Job 12] CAPT: send  A0 C0 D0 00 93 BE BB BE BF FD B8 2E 44 9C 8F 3C
D [04/May/2020:11:42:51 ] [Job 12] CAPT: D4 DC 1C BA 2C EC BF F4 94 BD 18 A8 BC 6E B6 BC
D [04/May/2020:11:42:51 ] [Job 12] CAPT: D5 B9 BC 88 3E 3C A6 FD FC B1 9C 1C BA 2C EC BF
D [04/May/2020:11:42:51 ] [Job 12] CAPT: F4 94 BD 18 A8 BC 6E B6 BC D5 B9 BC 88 3E 3C A6
D [04/May/2020:11:42:51 ] [Job 12] CAPT: FD FC B1 9C 1C BA 2C EC BF F4 94 BD 18 A8 BC 6E
D [04/May/2020:11:42:51 ] [Job 12] CAPT: B6 BC D5 B9 BC 88 3E 3C A6 FD FC B1 9C 1C BA 2C
D [04/May/2020:11:42:51 ] [Job 12] CAPT: EC BF F4 94 BD 18 A8 BC 6E B6 BC D5 B9 BC 88 3E
D [04/May/2020:11:42:51 ] [Job 12] CAPT: 3C A6 FD FC B1 9C 1C BA 2C EC BF F4 94 BD 18 A8... (80 more)
D [04/May/2020:11:42:51 ] [Job 12] Read 208 bytes of print data...
D [04/May/2020:11:42:51 ] [Job 12] CUPS_SC_CMD_DRAIN_OUTPUT received from driver...
D [04/May/2020:11:42:51 ] [Job 12] Wrote 208 bytes of print data...
D [04/May/2020:11:42:51 ] [Job 12] CAPT: rastertocapt: end page 1
D [04/May/2020:11:42:51 ] [Job 12] CAPT: send  A4 C0 04 00
D [04/May/2020:11:42:51 ] [Job 12] Read 4 bytes of print data...
D [04/May/2020:11:42:51 ] [Job 12] Wrote 4 bytes of print data...
D [04/May/2020:11:42:51 ] [Job 12] CUPS_SC_CMD_DRAIN_OUTPUT received from driver...
D [04/May/2020:11:42:52 ] [Job 12] CAPT: output already empty, not drained
I [04/May/2020:11:42:52 ] Expiring subscriptions...
D [04/May/2020:11:42:52 ] [Job 12] CAPT: send  A7 E0 06 00 01 00
D [04/May/2020:11:42:52 ] [Job 12] Read 6 bytes of print data...
D [04/May/2020:11:42:52 ] [Job 12] CUPS_SC_CMD_DRAIN_OUTPUT received from driver...
D [04/May/2020:11:42:52 ] [Job 12] Wrote 6 bytes of print data...
D [04/May/2020:11:42:52 ] [Job 12] CAPT: waiting for 6 bytes
D [04/May/2020:11:42:52 ] [Job 12] Read 6 bytes of back-channel data...
D [04/May/2020:11:42:52 ] [Job 12] CAPT: recv  A7 E0 06 00 00 00
D [04/May/2020:11:42:52 ] [Job 12] CAPT: send  A0 E0 04 00
D [04/May/2020:11:42:52 ] [Job 12] Read 4 bytes of print data...
D [04/May/2020:11:42:52 ] [Job 12] Wrote 4 bytes of print data...
D [04/May/2020:11:42:52 ] [Job 12] CUPS_SC_CMD_DRAIN_OUTPUT received from driver...
D [04/May/2020:11:42:52 ] [Job 12] Read 6 bytes of back-channel data...
D [04/May/2020:11:42:52 ] [Job 12] Read 6 bytes of back-channel data...
...skipping...
D [04/May/2020:11:42:56 ] [Job 12] CAPT: send  A0 E0 04 00
D [04/May/2020:11:42:56 ] [Job 12] Read 4 bytes of print data...
D [04/May/2020:11:42:56 ] [Job 12] CUPS_SC_CMD_DRAIN_OUTPUT received from driver...
D [04/May/2020:11:42:56 ] [Job 12] Wrote 4 bytes of print data...
D [04/May/2020:11:42:56 ] [Job 12] CAPT: waiting for 6 bytes
D [04/May/2020:11:42:56 ] [Job 12] Read 6 bytes of back-channel data...
D [04/May/2020:11:42:56 ] [Job 12] Read 6 bytes of back-channel data...
D [04/May/2020:11:42:56 ] [Job 12] CAPT: waiting for 6 bytes
D [04/May/2020:11:42:56 ] [Job 12] CAPT: recv  A0 E0 0C 00 00 8A 00 00 0F 00 00 00
I [04/May/2020:11:42:57 ] Expiring subscriptions...

These logs from 216fddba1616546eff73802bab3f12967301dc86 may be useful in debugging the problem in printing from Raspbian. This problem does not seem to be Raspbian specific. I tried printing on LBP2900 from a computer running Ubuntu based Zorin OS (5.3.0-46-generic #38~18.04.1-Ubuntu i686 GNU/Linux) with CUPS 2.2.7 about a week ago and still got similar error log.

# Zorin OS (5.3.0-46-generic #38~18.04.1-Ubuntu i686 GNU/Linux) with CUPS 2.2.7
# libusb-0.1-4/bionic 2:0.1.12-31 i386
# libusb-1.0-0/bionic,now 2:1.0.21-2 i386 [installed,automatic]
D [26/Apr/2020:19:02:51 ] [Job 4] CAPT: send  A0 E0 04 00
D [26/Apr/2020:19:02:51 ] [Job 4] Read 4 bytes of print data...
D [26/Apr/2020:19:02:51 ] [Job 4] CUPS_SC_CMD_DRAIN_OUTPUT received from driver...
D [26/Apr/2020:19:02:51 ] [Job 4] Wrote 4 bytes of print data...
D [26/Apr/2020:19:02:51 ] [Job 4] CAPT: waiting for 6 bytes
D [26/Apr/2020:19:02:51 ] [Job 4] Read 6 bytes of back-channel data...
D [26/Apr/2020:19:02:51 ] [Job 4] CAPT: waiting for 6 bytes
D [26/Apr/2020:19:02:51 ] [Job 4] Read 6 bytes of back-channel data...
D [26/Apr/2020:19:02:51 ] [Job 4] CAPT: recv  A0 E0 0C 00 00 8A 00 00 0F 00 00 00
I [26/Apr/2020:19:02:52 ] Expiring subscriptions...

[mounaiban]

I'm not too familiar with the Arm architecture ecosystem, but is Raspbian 32-bit or 64-bit? What about the Arm version of Ubuntu Server? 🤔

[sbn001]

I don't think it is a problem with the ARM architecture because I encountered the same problem in i686 architecture (Zorin OS 32-bit) as well. The Raspbian we are working with here is a 32-bit system (Raspbian GNU/Linux 10 (buster) armv7l Kernel: 4.19.97-v7l+).

The Ubuntu server is also 32-bit system on running on Raspberry Pi 3B (Ubuntu 19.10 armv7l Kernel: 5.3.0-1023-raspi2) The driver is working well on the 32-bit ARM system.

[mounaiban]

At first I suspected that a bug somewhere was causing the driver to fail on 32-bit operating systems. Now that you have pointed out that Ubuntu 10.19 for Arm is 32-bit, I guess that suspicion can be ruled out.

The last remaining change from 216fddb that I know and haven't accounted for yet is the way the driver gets job numbers. The 216fddb commit was the last time job numbers were decided by the driver. In later versions, the job number uint16_t job is assigned by the printer, and retrieved using the CAPT_JOB_BEGIN command in a job prologue.

We will have to chase down the suspected bug(s) that may be causing the driver to fail to get the required information. Alternatively, the driver could keep track of job numbers, but that's worthy of its own topic (because the filter exits after every job, thus resetting its state).

I might start testing on 32-bit x86 operating systems as well...

[mounaiban]

I have recently pushed the 0.1.4-dev-use-cups-job-id branch with the job number override workaround I have been talking about in agalakhov/captdriver#7. I hope this would get the LBP2900 working again on more platforms 🤞 Based on preliminary tests, the override works with the LBP3000 on Debian 10.6 (x86_64)/CUPS 2.2.10/libusb 1.0.22.

The changes I made affect the LBP2900 and LBP3000 only.

In short, the job ID sent to the printer is no longer queried from the printer, but derived from the job ID generated by CUPS. The changes introduces a unused variable warning in printer.h, but I don't know how to suppress it.

Fun Fact: CAPT job numbers are 16-bit unsigned integers (uint16_t), while CUPS job IDs are 32-bit (int). My workaround simply parses argv[1] in main() to a 32-bit int using atoi(), which is then casted into uint_16t in the job setup and teardown routines. What happens between job 65,535 and 65,536 is not known...

🛈 UPDATE: This hack was found not to solve this issue. Thanks to the testers for trying it out.

[mounaiban]

Finally got to test the LBP3000 on Zorin OS 15.3 Education Lite (x86 32-bit): it did not print. This particular distro uses CUPS 2.2.7 and libusb 1.0.21. Please see #4.

[nerk]

For what it's worth: I just tested the current version from master on Ubuntu 20.04 (64-bit) with Cups 2.3.1, libusb 1.0.23 and my LBP2900. It seems to work without problems so far. Multiple pages are working and the printer never got stuck.

The only thing which did not work is piping something into the lp command, e.g.

echo "This should be printed!" | lp -d LBP2900

which produces a "Filter failed" Job message.

In direct comparison with the original ccpd, the output is just a tiny bit more greyish in general. The question still remains, why the same does not work on Raspberry Pi OS. Maybe it is really related to the version of libusb, as suggested agalakhov#7

[mounaiban]

@nerk I don't think captdriver (or even the LBP3000) supports raw text rendering; everything seems to be done through some software rasteriser like Ghostscript (I am not sure which one CUPS uses). We haven't laid down the raw text pipeline yet...

It has been a long time since I last touched the Canon drivers, but I suspect from memory that the official drivers use a different rasteriser or at least a different setup which is capable of preprocessing the rasters. I think that allows brightness and contrast adjustment and faster compression. With captdriver, we just dump whatever CUPS gives us into the compressor and hope for the best.

My biggest dread at this point is that direct access to libusb may be necessary to get CAPT devices to work properly, due to the need to maintain a two-way conversation with the printer. I'm not really set up for that kind of stuff... 😨

CUPS may not be set up for active bidirectional communications. I was not able to find any meaningful command in CUPS that could flush a read buffer (or otherwise allow more control over the backend) that might resolve the repeated response issue.

[mounaiban]

Long story short: issues with how CUPS interacts with libusb have been causing inaccurate and failed printer status checks. Captdriver has no idea when it is ready to print as a result. This commonly hangs the print job as it is about to begin, thus leading to the "stuck at Rendering Completed (#8, agalakhov/captdriver#7)" problem.

This issue will be closed just to keep the Issues section tidy. This is not to imply that the underlying problem has been solved at time of "closure". It still haunts us all...