search

OpenPrinting / ipp-usb

ipp-usb -- HTTP reverse proxy, backed by IPP-over-USB connection to device
BSD 2-Clause "Simplified" License
135 stars 14 forks source link

Canon 3120L fails to print job by using driverless #9

Closed tangyanli closed 2 years ago

tangyanli commented 4 years ago

Hi, Alexander

My Canon 3120L fails to print job by using driverless + ipp-usb. The job status is always "Connected to printer".

But when I uninstall ipp-usb and install ippusbxd, the job can be printed successfully. I am not sure this is ipp-usb issue, can you help to confirm it?

The log file is retrieved by below command # LIBUSB_DEBUG=1000 ipp-usb debug 2>libusb.log libusb.log

And I will send you ipp-usb console log by email.

alexpevzner commented 4 years ago

Hi Tess,

you probably don't use the latest version of ipp-usb. Please, upgrade. Even if it will not fix the issue, at least I will work with the actual code, plus it contains some useful logging tweaks.

For now, I don't need libusb logs, ipp-usb logs would be enough.

tangyanli commented 4 years ago

I am sorry I used the version 0.9.5. I will upgrade to the latest version and resend the log tomorrow morning :-)

tangyanli commented 4 years ago

Hi, Alexander

The issue can be reproduced based on ipp-usb v0.9.8. The phenomenon is as below:

  1. Print the 1st job, the job is printed out at printer side; but at PC side, the job status is "Waiting for job to complete"
  2. After waiting 2 minutes the job status is still "Waiting for job to complete", so I cancel the 1st job at PC side manually.
  3. Print the 2st job, the job status at PC side is always "Connected to printer". And at this time, the http://localhost:60000 cannot be connected successfully.

I retry the ippusbxd (newest code), the issue cannot be reproduced.

PS: I am afraid I cannot supply more log file on the weekend. So I also supply the ippusbxd & libusb log file.

04a9-2831-74bfc0dafecc-iR-C3120L.log ipp-usb_console.log libusb-2th.log main.log ippusbxd.log

alexpevzner commented 4 years ago

Hi Tess,

the log rotated, so the interesting information went out. May I ask you to resend all files from /var/log/ipp-usb/04a9-2831-74bfc0dafecc-iR-C3120L.log*?

tangyanli commented 4 years ago

Hi, Alexander

04a9-2831-74bfc0dafecc-iR-C3120L.log.0.gz

alexpevzner commented 4 years ago

Thank a lot and have a nice weekend!

alexpevzner commented 4 years ago

Hi Tess,

please, fetch the latest Git version and retest.

Note, this version will change name for log and state files for your device from 04a9-2831-74bfc0dafecc-iR-C3120L-XXX to 04a9-2831-74bfc0dafecc-Canon-iR-C3120L-XXX

tangyanli commented 4 years ago

Hi, Alexander

Got it. I will reply you after I test.

tangyanli commented 4 years ago

Hi, Alexander

Fixed! Thanks so so much for you and your work :-)

BTW: Towards the Canon iR3120L, the airscan also works well for both eSCL and WSD protocol.

alexpevzner commented 4 years ago

Thank a lot for your feedback and testing effort.

A little bit of technical background, if you are interested.

Some devices sometimes return truncated response to the HTTP request. It happens not always, but with some probability. Once response is truncated, ipp-usb will wait forever for the missed bytes, which effectively block USB connection. Once all USB connections are blocked, device doesn't work anymore.

Your device is the 3rd that have this problem. Previous 2 were HPs. The solution is the same in all cases: HTTP request sent to device should have "properly" set Connection header (either Connection: close or Connection: keep-alive, or no Connection header at all). Unfortunately, the "proper" setting is different for different devices.

Actually, this is firmware bug. Connection header should not affect IPP over USB at all, because unlike TCP, USB doesn't have such thing as "connection close". But in reality it does, and I have to live with it.

So I close this issue as resolved. The just created 0.9.9 release contains this fix.

alexpevzner commented 4 years ago

Other Canon devices of the same model, or another models?

I usually try to document non-obvious technical details in commit comments and in code comments. First of all for myself. Otherwise when few months later I'll see these lines of code, it will be very hard to remember, for what reasons they were written.

tangyanli commented 4 years ago

Other model devices have no this issue, for example iR-ADV 4545/4551. Another device of the same model also has this issue.

tangyanli commented 4 years ago

PS: I tested the fixed version on both iR3120L and iR-ADV 4545/4551. All of them work fine.

tangyanli commented 4 years ago

Hi, Alexander

May I ask your help again.

On my ARM PC, Canon iR2625/2630 works well based on ipp-usb v0.9.5. But after upgrading to ipp-usb v0.9.9, the device fails to print job, and the web-console stuck.

But on my MIPS PC, Canon iR2625/2630 works well based on both ipp-usb v0.9.5 & v0.9.9.

ipp-usb v0.9.5 log on ARM PC: 04a9-2828-74bfc0146ffa-iR2625-2630-UFR.log

ipp-usb v0.9.9 log on ARM PC 04a9-2828-74bfc0146ffa-Canon-iR2625-2630-UFR.log

ipp-usb v0.9.9 log on MIPS PC mips-04a9-2828-74bfc0146ffa-Canon-iR2625-2630-UFR.log

I am confused that the code + device are the same, the issue can reproduced on my ARM PC, but can't reproduced on my MIPS PC.

PS: Is it ok to delete the previous log files?

alexpevzner commented 4 years ago

Hi Tess,

please git pull, rebuild and retest with Canon iR2625/2630 UFR on both ARM and MIPS

Please don't delete old logs from here

tangyanli commented 4 years ago

Hi, Alexander

I tested the newest code on ARM PC, the workaround doesn't work.

04a9-2828-74bfc0146ffa-Canon-iR2625-2630-UFR.log

alexpevzner commented 4 years ago

Please retry, it was a stupid mistake

tangyanli commented 4 years ago

Hi, Alexander：

Thanks your quickly reply. I just saw the message. Sorry for that I will test it on tomorrow.

alexpevzner commented 4 years ago

Hi Tess,

what is interesting, there are a lot of "malformed HTTP ..." errors in iR2625/2630 logs both on ARM and MIPS (more on ARM). This error message means that ipp-usb has sent HTTP request, started fetching a response and was unable to parse it, because of instead of valid response it got a tail from the previous response.

I'm trying to read your latest ARM log in attempt to understand, was it junk left from a previous invocation of the IPP over USB program, or synchronization was lost in the middle of session.

alexpevzner commented 4 years ago

I've added USB device reset just after device open, in a hope to purge data left in USB buffers from the previous use.

However, it is not guaranteed that it will help, and it is not guaranteed that it will not cause regression on other devices. I've tested for regression on my Kyocera, but I don't have any other devices to test witch. Please, test on your hardware.

tangyanli commented 4 years ago

Hi, Alexander

I have trouble. The "reset" action has no effect. I also tested Connection: close and Connection: keep-alive, the issue still exists. From the log, it is still "malformed HTTP ..."

I rollback to previous versions, the v0.9.6 has no this issue, the v0.9.7 has this issue. I can't understand the code clearly, I need your help.

Some additional information: I tested the ipp-usb v0.9.9 version on Deepin (compatible with Debian10) X64/ARM/MIPS, this issue can't be reproduced.

alexpevzner commented 4 years ago

Try to clear the following line in usbtransport.go, line 571:

err = conn.iface.ClearHalt(true)
tangyanli commented 4 years ago

I change the file based on v0.9.9 source. It works for iR2625! Great!

alexpevzner commented 4 years ago

Am I correct, that Connection tweaks and reset are not needed, ClearHalt removal is enough?

tangyanli commented 4 years ago

Yes, the Connection tweaks and reset are not needed. Just remove ClearHalt.

tangyanli commented 4 years ago

Hi, Alexander:

I haven't do enough test now. Just test for iR3120L, iR2625/2630, iR-ADV 4545/4551 on the ARM PC. They all work well. Do you need me to do more test before you commit the code?

alexpevzner commented 4 years ago

Yhank a lot, I think it's enough. I will harmonize these changes and commit. I will explain technical details later

tangyanli commented 4 years ago

I like the technical detail :-) Then I will perform enough tests after you commit the code.

alexpevzner commented 4 years ago

Hi Tess,

please retest the latest committed changes, and if everything is OK, I'll issue a new release. Technical details coming soon :-)

tangyanli commented 4 years ago

Hi, Alexander:

Good news!

BTW: Everything means web server, printing and airscan.

tangyanli commented 4 years ago

Hi, Alexander:

I made a mistake when I tested the web server. I only visited the main page of localhost:60000.

Just now I retested the web server. For iR3120L, the Canon http server port is 80, each page can be visited. For iR2625/2630, the Canon http server port is 8000. I checked the user manual and there is no record to change the http port. It's OK to visit the main page; but it's NG to visit other pages. Is there some method to visit other page?

09-07-2020 15:20:58: < HTTP[004]: GET http://localhost:60000/sysmonitor - 302 Moved Temporarily
09-07-2020 15:20:58: < HTTP[004]: HTTP response header:
09-07-2020 15:20:58: <   HTTP/1.1 302 Moved Temporarily
09-07-2020 15:20:58: <   Cache-Control: no-cache,no-store,max-age=0
09-07-2020 15:20:58: <   Connection: Keep-Alive
09-07-2020 15:20:58: <   Content-Length: 0
09-07-2020 15:20:58: <   Content-Type: text/html; charset=UTF-8
09-07-2020 15:20:58: <   Date: Fri, 9 Jul 2021 7:23:30 GMT
09-07-2020 15:20:58: <   Expires: Thu, 1 Jan 1970 0:0:0 GMT
09-07-2020 15:20:58: <   Keep-Alive: timeout=30
09-07-2020 15:20:58: <   Location: http://localhost:8000/rps/nativetop.cgi?RUIPNxBundle=&CorePGTAG=PGTAG_JOB_PRT_STAT&Dummy=1625815410369
09-07-2020 15:20:58: <   Pragma: No-cache
09-07-2020 15:20:58: <   Server: Catwalk
09-07-2020 15:20:58: <   X-Frame-Options: SAMEORIGIN
09-07-2020 15:20:58: <
09-07-2020 15:20:58: < HTTP[004]: response body: got 0 bytes; EOF

If I changed the port in the URI from 8000 to 60000. The http://localhost:60000/rps/nativetop.cgi?RUIPNxBundle=&CorePGTAG=PGTAG_JOB_PRT_STAT&Dummy=1625815410369 can be visited successfully.

alexpevzner commented 4 years ago

Hi Tess,

the promised technical details first. Sometimes USB read request finishes quickly and returns 0 bytes, It is not necessarily an error and in most cases after several attempts finally device returns some data bytes. But often when device is about to stuck in response, there are many "zero-sized read" events, so there truncated response and zero-sized read are somehow associated. Some of devices never return zero bytes, other do it often.

I don't quite understand, what zero-size read should mean. If device has currently no data to return and want to ask reader to wait, USB protocol provides special mechanisms for doing so, and read request should simply block until some data is available. But it happens, and without ability to look to the USB conversation from device's point of view, I can only guess what actually goes on.

One hypothesis was that device and host lose synchronization at the signalling level, so I tried to send "unhalt" command to device. As we know, it didn't help, and sometimes breaks things. I don't know why it breaks things on ARM but doesn't break on MIPS. May be it is because ARM and MIPS machines use different USB host controller.

So I decided to remove unhalt sent "just in case" and to send it only when device cleanly indicates that it is halted by returning appropriate error code (which was never actutally observed with printers so far).

If you have more questions, don't hesitate to ask

alexpevzner commented 4 years ago

Now about iR2625/2630 web console. Technically it is not difficult to override Location: header in the response. But if device's web page really want to redirect to the external location, it will be broken in result.

So I need to think a little bit.

This is firmware bug. Firmware knows port (60000 in this case) from the Host: header in request and must mirror this value in every URL it returns in response (not only in HTTP headers, but in data as well, and most devices really do so).

tangyanli commented 4 years ago

Hi, Alexander:

Thanks for your explanation. It will spend some times for me to read and understand (I am not an expert).

The ARM is weird, although the web console, printing and airscan are all OK, I found there are still several (2~3 times) “malformed HTTP...” in the log file. On other PC’s log files, there are no “malformed HTTP...”.

I got it, this is firmware bug. Even there is no workaround, the present situation is acceptable. But I am curious how can the firmware know the port 60000... This is firmware bug. Firmware knows port (60000 in this case) from the Host: header in request and must mirror this value in every URL it returns in response (not only in HTTP headers, but in data as well, and most devices really do so).

alexpevzner commented 4 years ago

Hi Tess,

may you play a little bit with Connection: close/Connection: keep-alive on ARM? May be we will find a working combination.

Every request that goes to device has a following header field: Host: localhost:60000. In theory, clients must set this fields by themselves (per HTTP/1.1 specification; client knows the port number it is connected to); ipp-usb enforces that this field is not missed, by adding it when appropriate (it also knows the port number). Firmware, when request comes from USB, cannot know port number, so it MUST reflect port number from the Host: header of the request.

Most likely, in the iR2625/2630 firmware HTTP requests, falling from USB, are internally routed to the same HTTP server, that serves requests coming from network, and instead of taking port number from the request header, it takes port number from its own network configuration. It would work correctly when HTTP server accessed from the network, both numbers would be the same at this case, but not when it is accessed from USB.

I can rewrite response header, fixing the port number. But if it appears within web bages (in HTPL, in JavaScript and so on) I can't reliable detect and override it there

tangyanli commented 4 years ago

Hi, Alexander:

About the “malformed HTTP...” in the iR2525 log file: If change to Connection: close, the web-console stuck.

10-07-2020 09:08:28: > HTTP[000]: HTTP request header:
10-07-2020 09:08:28: >   POST /ipp/print HTTP/1.1
10-07-2020 09:08:28: >   Host: localhost:60000
10-07-2020 09:08:28: >   User-Agent: ipp-usb
10-07-2020 09:08:28: >   Content-Length: 151
10-07-2020 09:08:28: >   Connection: close
10-07-2020 09:08:28: >   Content-Type: application/ipp
10-07-2020 09:08:28: >
10-07-2020 09:08:28:   USB[0]: connection allocated, 1 in use: a-- ---
10-07-2020 09:08:28:   HTTP[000]: connection 0 allocated
10-07-2020 09:08:29: > USB[0]: write: wanted 294 sent 294 total 294
10-07-2020 09:08:29: < USB[0]: read: wanted 4096 got 0 total 0
10-07-2020 09:08:29: ! USB[0]: zero-size read
10-07-2020 09:08:29: < USB[0]: read: wanted 4096 got 0 total 0
10-07-2020 09:08:29: ! USB[0]: zero-size read

If change to Connection: keep-alive, everything is OK, but the "malformed HTTP" still appears.

10-07-2020 09:13:14: > HTTP[000]: HTTP request header:
10-07-2020 09:13:14: >   POST /ipp/print HTTP/1.1
10-07-2020 09:13:14: >   Host: localhost:60000
10-07-2020 09:13:14: >   User-Agent: ipp-usb
10-07-2020 09:13:14: >   Content-Length: 151
10-07-2020 09:13:14: >   Connection: keep-alive
10-07-2020 09:13:14: >   Content-Type: application/ipp
10-07-2020 09:13:14: >
10-07-2020 09:13:14:   USB[0]: connection allocated, 1 in use: a-- ---
10-07-2020 09:13:14:   HTTP[000]: connection 0 allocated
10-07-2020 09:13:14: > USB[0]: write: wanted 299 sent 299 total 299
10-07-2020 09:13:14: < USB[0]: read: wanted 4096 got 0 total 0
10-07-2020 09:13:14: ! USB[0]: zero-size read
10-07-2020 09:13:14: < USB[0]: read: wanted 4096 got 0 total 0
10-07-2020 09:13:14: ! USB[0]: zero-size read
10-07-2020 09:13:14: < USB[0]: read: wanted 4096 got 155 total 155
10-07-2020 09:13:14: ! HTTP[000]: malformed HTTP response "lose"
10-07-2020 09:13:14:   USB[0]: connection released, 0 in use: --- ---
10-07-2020 09:13:14: ! IPP: HTTP: Post http://localhost:60000/ipp/print: malformed HTTP response "lose"

Because all features (printing and airscan) are OK, so I think we can keep the present situation without Connection header.

About the web-console URI, the iR-ADV 4545/4551 has the same phenomenon. Form the log, there are two http servers, one named "Catwalk", the other named "CANON HTTP Server" And It seems this is common phenomenon on Canon old devices. So I think just let it be. 

10-07-2020 09:21:45: > HTTP[014]: GET http://localhost:60000/sysmonitor
10-07-2020 09:21:45: > HTTP[014]: HTTP request header:
10-07-2020 09:21:45: >   GET /sysmonitor HTTP/1.1
10-07-2020 09:21:45: >   Host: localhost:60000
10-07-2020 09:21:45: >   User-Agent: Mozilla/5.0 (X11; Linux aarch64; rv:52.0) Gecko/20100101 Firefox/52.0
10-07-2020 09:21:45: >   Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
10-07-2020 09:21:45: >   Accept-Encoding: gzip, deflate
10-07-2020 09:21:45: >   Accept-Language: en-US,en;q=0.5
10-07-2020 09:21:45: >   Connection: keep-alive
10-07-2020 09:21:45: >   Cookie: sessionid=eee98e5dc8a5b5a37ae6b257ce9f152e; com.canon.meap.service.login.session=10245c04c24c11ea8000f80d609c8532; portalLang=en; iR=134311358; org.cups.sid=67ae952ff05ada4300229f987101a36a
10-07-2020 09:21:45: >   Referer: http://localhost:60000/
10-07-2020 09:21:45: >   Upgrade-Insecure-Requests: 1
10-07-2020 09:21:45: >
10-07-2020 09:21:45:   USB[1]: connection allocated, 1 in use: --- a--
10-07-2020 09:21:45:   HTTP[014]: connection 1 allocated
10-07-2020 09:21:45: > HTTP[014]: request body: got 0 bytes; EOF
10-07-2020 09:21:46: > USB[1]: write: wanted 559 sent 559 total 559
10-07-2020 09:21:46: < USB[1]: read: wanted 4096 got 32 total 32
10-07-2020 09:21:46: < USB[1]: read: wanted 4096 got 17 total 49
10-07-2020 09:21:46: < USB[1]: read: wanted 4096 got 138 total 187
10-07-2020 09:21:46: < USB[1]: read: wanted 4096 got 281 total 468
10-07-2020 09:21:46: < HTTP[014]: GET http://localhost:60000/sysmonitor - 302 Moved Temporarily
10-07-2020 09:21:46: < HTTP[014]: HTTP response header:
10-07-2020 09:21:46: <   HTTP/1.1 302 Moved Temporarily
10-07-2020 09:21:46: <   Cache-Control: no-cache,no-store,max-age=0
10-07-2020 09:21:46: <   Connection: Keep-Alive
10-07-2020 09:21:46: <   Content-Length: 0
10-07-2020 09:21:46: <   Content-Type: text/html; charset=UTF-8
10-07-2020 09:21:46: <   Date: Fri, 10 Jul 2020 1:24:18 GMT
10-07-2020 09:21:46: <   Expires: Thu, 1 Jan 1970 0:0:0 GMT
10-07-2020 09:21:46: <   Keep-Alive: timeout=30
10-07-2020 09:21:46: <   Location: http://localhost:8000/rps/nativetop.cgi?RUIPNxBundle=&CorePGTAG=PGTAG_JOB_PRT_STAT&Dummy=1594344258958
10-07-2020 09:21:46: <   Pragma: No-cache
10-07-2020 09:21:46: <   Server: Catwalk
10-07-2020 09:21:46: <   X-Frame-Options: SAMEORIGIN
10-07-2020 09:21:46: <   X-Xss-Protection: 1; mode=block
10-07-2020 09:21:46: <
10-07-2020 09:21:46: < HTTP[014]: response body: got 0 bytes; EOF
10-07-2020 09:21:46:   USB[1]: connection released, 0 in use: --- ---
10-07-2020 09:21:51: > HTTP[015]: GET http://localhost:60000/rps/nativetop.cgi?RUIPNxBundle=&CorePGTAG=PGTAG_JOB_PRT_STAT&Dummy=1594344258958
10-07-2020 09:21:51: > HTTP[015]: HTTP request header:
10-07-2020 09:21:51: >   GET /rps/nativetop.cgi?RUIPNxBundle=&CorePGTAG=PGTAG_JOB_PRT_STAT&Dummy=1594344258958 HTTP/1.1
10-07-2020 09:21:51: >   Host: localhost:60000
10-07-2020 09:21:51: >   User-Agent: Mozilla/5.0 (X11; Linux aarch64; rv:52.0) Gecko/20100101 Firefox/52.0
10-07-2020 09:21:51: >   Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
10-07-2020 09:21:51: >   Accept-Encoding: gzip, deflate
10-07-2020 09:21:51: >   Accept-Language: en-US,en;q=0.5
10-07-2020 09:21:51: >   Connection: keep-alive
10-07-2020 09:21:51: >   Cookie: sessionid=eee98e5dc8a5b5a37ae6b257ce9f152e; com.canon.meap.service.login.session=10245c04c24c11ea8000f80d609c8532; portalLang=en; iR=134311358; org.cups.sid=67ae952ff05ada4300229f987101a36a
10-07-2020 09:21:51: >   Upgrade-Insecure-Requests: 1
10-07-2020 09:21:51: >
10-07-2020 09:21:51:   USB[0]: connection allocated, 1 in use: a-- ---
10-07-2020 09:21:51:   HTTP[015]: connection 0 allocated
10-07-2020 09:21:51: > HTTP[015]: request body: got 0 bytes; EOF
10-07-2020 09:21:52: > USB[0]: write: wanted 595 sent 595 total 595
10-07-2020 09:21:52: < USB[0]: read: wanted 4096 got 17 total 17
10-07-2020 09:21:52: < USB[0]: read: wanted 4096 got 87 total 104
10-07-2020 09:21:52: < USB[0]: read: wanted 4096 got 193 total 297
10-07-2020 09:21:52: < USB[0]: read: wanted 4096 got 112 total 409
10-07-2020 09:21:52: < USB[0]: read: wanted 4096 got 50 total 459
10-07-2020 09:21:52: < HTTP[015]: GET http://localhost:60000/rps/nativetop.cgi?RUIPNxBundle=&CorePGTAG=PGTAG_JOB_PRT_STAT&Dummy=1594344258958 - 200 OK
10-07-2020 09:21:52: < HTTP[015]: HTTP response header:
10-07-2020 09:21:52: <   HTTP/1.1 200 OK
10-07-2020 09:21:52: <   Cache-Control: no-cache,no-store,max-age=0
10-07-2020 09:21:52: <   Connection: Keep-Alive
10-07-2020 09:21:52: <   Content-Type: text/html;charset=UTF-8
10-07-2020 09:21:52: <   Date: Fri, 10 Jul 2020 01:24:24 GMT
10-07-2020 09:21:52: <   Expires: Thu, 01 Jan 1970 00:00:00 GMT
10-07-2020 09:21:52: <   Keep-Alive: timeout=30
10-07-2020 09:21:52: <   Pragma: no-cache
10-07-2020 09:21:52: <   Server: CANON HTTP Server
10-07-2020 09:21:52: <   Set-Cookie: portalLang=en; path=/
10-07-2020 09:21:52: <   Transfer-Encoding: chunked
10-07-2020 09:21:52: <   X-Content-Type-Options: nosniff
10-07-2020 09:21:52: <   X-Frame-Options: DENY
10-07-2020 09:21:52: <   X-Xss-Protection: 1; mode=block
10-07-2020 09:21:52: <
10-07-2020 09:21:52: < USB[0]: read: wanted 4096 got 3 total 462
10-07-2020 09:21:52: < USB[0]: read: wanted 3584 got 1028 total 1490
tangyanli commented 4 years ago

I think we can close this issue. And thanks for the various technical details. It is my good luck to talk with you :-)

BTW: Towards the Canon iR2625/2630, the airscan (I used the version 0.99.5) also works well for both eSCL and WSD protocol.

tangyanli commented 2 years ago

Dear Alexander:

Are you all right recently? I was hurry to close this issue before, but this issue was not solved completely, so I ask your help again.

I will summarize the problem I encountered: As I demanded before, I want to use ipp-usb + airscan to scan and use canon-driver to print; so I did a script to start-up ipp-usb before scanning, and exit the ipp-usb after scanning. So the ipp-usb is only used as proxy for eSCL protocol.

But for the Canon iR2625/2630, the device sometimes returns malformed HTTP package, this causes scanning failed continually.

[Architecture]: amd64, arm64, mips64el [Ratio]: About 2~3 times in 10 times scanning

I used the quirks you told me in this issue, but they are no effect. The quirks I tried as (1) Set http-connection = close (2) Set http-connection = keep-alive (3) Invoke (*UsbDevHandle)(devhandle).Reset() in func UsbOpenDevice (4) Invoke err = conn.iface.SoftReset() in func openUsbConn

14-03-2022 15:10:31: < USB[0]: read: wanted 4096 got 148 total 148
14-03-2022 15:10:31: ! HTTP[022]: malformed HTTP status code "localHTTP/1.1"
14-03-2022 15:10:31:   USB[0]: connection released, 0 in use: --- ---
14-03-2022 15:10:31: > HTTP[022]: GET http://localhost:60000/eSCL/ScannerStatus
14-03-2022 15:10:31: > HTTP[022]: HTTP request header:
14-03-2022 15:10:31: >   GET /eSCL/ScannerStatus HTTP/1.1
14-03-2022 15:10:31: >   Host: localhost:60000
14-03-2022 15:10:31: >   User-Agent: ipp-usb
14-03-2022 15:10:31: >   Connection: close
14-03-2022 15:11:31: < USB[0]: read: wanted 4096 got 178 total 178
14-03-2022 15:11:31: ! HTTP[034]: malformed HTTP version "\x14P\x01E\x00\x14P\x01HTTP/1.1"
14-03-2022 15:11:31:   USB[0]: connection released, 0 in use: --- ---
14-03-2022 15:11:31: > HTTP[034]: POST http://localhost:60000/eSCL/ScanJobs
14-03-2022 15:11:31: > HTTP[034]: HTTP request header:
14-03-2022 15:11:31: >   POST /eSCL/ScanJobs HTTP/1.1
14-03-2022 15:11:31: >   Host: localhost:60000
14-03-2022 15:11:31: >   User-Agent: ipp-usb
14-03-2022 15:11:31: >   Connection: close
14-03-2022 15:11:31: >   Content-Length: 793
14-03-2022 15:11:31: >   Content-Type: text/xml

Would you have some other ideas or quirks?

alexpevzner commented 2 years ago

Hi Tess,

glad to hear from you, as usually!

I want to better investigate this problem. So I added a hex dump of all the USB traffic. Please, rebuild ipp-usb from the fresh sources, and edit its configuration file as follows:

[logging]
 device-log    = all, trace-usb

Please note, if you run ipp-usb directly out of the build directory, the example configuration file placed there overrides system configuration file at /etc/ipp-usb/ipp-usb.conf.

Please, show me resulting logs. Note, with hex dumps enabled, logs can be really huge.

tangyanli commented 2 years ago

Hi, Alexander:

Glad to receive from you again :-) I captured the USB logs on Deepin (compatible with Debian10) aarch64.

Blow logs contains the last 3 scan jobs. The 1st Job: Scan OK, Device return correct HTTP header. The 2st Job: Scan failed, Device return wrong HTTP header. The 3st Job: Scan failed, Device return HTTP header with error code 409 Conflict. I'm guessing the 409 error code is caused by the second job wasn't fetched. (My test experience is: When device returns 409 conflict, wait several minutes and scan again, device will return 201 Created)

scan_ok_04a9-2828-74bfc0146ffa-Canon-iR2625-2630-UFR.log scan_fail_04a9-2828-74bfc0146ffa-Canon-iR2625-2630-UFR.log 04a9-2828-74bfc0146ffa-Canon-iR2625-2630-UFR.log

I tried to analyse the wrong HTTP header by comparing the correct one vs the wrong one; The wrong HTTP header has several invalid characters on the begin and misses server characters in the middle. compare

It's so strange, so I captured the USB data by wireshark. It's same as the ipp-usb log. This is definitely a firmware bug (I think so). I have reported it to Canon, hope they can fix the firmware.

tangyanli commented 2 years ago

PS: I got more logs for analysis. The conclusion is same: the malformed HTTP header has 8 invalid characters on the begin and misses 8 characters in the middle.

malformed_rlocal_04a9-2828-74bfc0146ffa-Canon-iR2625-2630-UFR.log

malformed_invalid_04a9-2828-74bfc0146ffa-Canon-iR2625-2630-UFR.log

tangyanli commented 2 years ago

Once more, the invalid 8 characters in the malformed HTTP header is random.

malformed_tatus_04a9-2828-74bfc0146ffa-Canon-iR2625-2630-UFR.log

alexpevzner commented 2 years ago

Hi Tess,

a lot of samples, very informative, thank you very much!

I see many cases when junk is inserted before the valid data, but I don't see any case when junk is inserted in the middle of valid data. Correct me, if I'm wrong here.

I'll try to implement a patch, that drains data from the connection, until beginning of the valid HTTP header is found (i.e., until HTTP/1.1 characters are found). It should fix compatibility with this device. Well, at least I hope so :-)

tangyanli commented 2 years ago

Hi, Alexander:

I see many cases when junk is inserted before the valid data, but I don't see any case when junk is inserted in the middle of valid data. Correct me, if I'm wrong here.

You are right. As far as I can see the junk is only inserted before the valid data. But there are 8 characters missing / disappearing in the middle of the valid data.

It's grateful if you can fix compatibility with this device. :-)

tangyanli commented 2 years ago

Hi, Alexander:

I have a query. For example the below case: 

21-03-2022 15:48:19: < 0000: 74 61 74 75:73 3e 74 61:48 54 54 50:2f 31 2e 31: tatus>taHTTP/1.1
21-03-2022 15:48:19: < 0010: 20 32 30 30:20 4f 4b 0d:0a 44 61 74:65 3a 20 4d:  200 OK..Date: M
21-03-2022 15:48:19: < 0020: 6f 6e 2c 20:32 31 20 4d:61 72 20 32:30 32 32 20: on, 21 Mar 2022
21-03-2022 15:48:19: < 0030: 30 37 3a 35:35 3a 31 39:20 47 4d 54:0d 0a 53 65: 07:55:19 GMT..Se
21-03-2022 15:48:19: < 0040: 4e 4f 4e 20:48 54 54 50:20 53 65 72:76 65 72 0d: NON HTTP Server.
21-03-2022 15:48:19: < 0050: 0a 43 6f 6e:74 65 6e 74:2d 54 79 70:65 3a 20 74: .Content-Type: t
21-03-2022 15:48:19: < 0060: 65 78 74 2f:78 6d 6c 0d:0a 43 6f 6e:74 65 6e 74: ext/xml..Content
21-03-2022 15:48:19: < 0070: 2d 4c 65 6e:67 74 68 3a:20 31 30 37:34 0d 0a 53: -Length: 1074..S
21-03-2022 15:48:19: < 0080: 65 72 76 65:72 3a 20 6c:6f 63 61 6c:68 6f 73 74: erver: localhost
21-03-2022 15:48:19: < 0090: 0d 0a 0d 0a:                                     ....

After draining the junk. The http header becomes

HTTP/1.1 200 OK..
Date: Mon, 21 Mar 2022 07:55:19 GMT..
SeNON HTTP Server..
Content-Type: text/xml..
Content-Length: 1074..
Server: localhost

Because the 8 characters "rver: CA" miss, the third line becomes SeNON HTTP Server, there is no ":" in this line. So this http header also be treated as malformed http, does it?

alexpevzner commented 2 years ago

Hi Tess,

taking in account that 8 bytes disappearing in the middle of the HTTP header, simple hack to drain random bytes at the beginning will not help: the resulting reader will be unparseable anyway.

I've also noticed that lost bytes are always at the 64-bytes boundary (more precisely, are always at the beginning of the second 64-bytes block). Looks like hardware problem.

What is really interesting, does it happen at printer side or at the host side?

What is your host computer? Does it happen at common PC-compatible computer? May be, you have a hardware-level USB debugger, which can sniff the USB traffic at physical wire, unlike wireshark, which actually sniffs traffic as it seen by Linux driver?

One thing I want to verify too. What if we will limit ipp-usb to use single USB interface only, instead of two available on device?

To test it, please add the following lines somewhere to /usr/share/ipp-usb/quirks/:

[Canon iR2625/2630]
 usb-max-interfaces = 1

P.S. Not sure about model name in squire braces. Please, clarify with ipp-usb check

tangyanli commented 2 years ago

Hi, Alexander:

What is your host computer? Does it happen at common PC-compatible computer? May be, you have a hardware-level USB debugger, which can sniff the USB traffic at physical wire, unlike wireshark, which actually sniffs traffic as it seen by Linux driver?

The issue also happens on Debian11 AMD64bit, (in order to report it to Canon, I tested it on Debain11 several days ago). Canon
also hope me to take the USB log by USB analyzer (a hardware-level USB debugger, I guess), but unfortunately we don't have. So at the last, we only send wireshark package to Canon, they will continue investigate it.

For the usb-max-interfaces = 1, I tested several devices (iR2625/3120L...) , but I can't remember the test result now. I will test the usb-max-interfaces again when I return to my office, it may be several days later.

tangyanli commented 2 years ago

After setting usb-max-interfaces = 1, the device wouldn't accept/response any data. From the log-viewer, the libusb_bulk_transfer is always timed out.

06-04-2022 10:26:30:   USB[0]: connection allocated, 1 in use: a-- ---
06-04-2022 10:26:30:   HTTP[001]: connection 0 allocated
06-04-2022 10:26:35: > USB[0]: write: wanted 275 sent 0 total 0
06-04-2022 10:26:35: ! USB[0]: send: libusb_bulk_transfer: Operation timed out
06-04-2022 10:26:35: ! HTTP[001]: libusb_bulk_transfer: Operation timed out
06-04-2022 10:26:35:   USB[0]: connection released, 0 in use: --- ---
06-04-2022 10:26:35: ! IPP: HTTP: Post http://localhost:60000/ipp/print: libusb_bulk_transfer: Operation timed out
tangyanli commented 2 years ago

Hi, Alexander:

I close this issue because it is firmware bug. If I get some feedback from canon, I will post here.

alexpevzner commented 2 years ago

Hi Tess,

I've added init-delay and request-delay quirks (delay before the first IPP-USB request sent to the USB interface and subsequent requests, in milliseconds).

The fact that reducing number of available USB interfaces makes situation worse makes me think that there is a race within a hardware which causes conversation to fail when requests sent to the same interface goes with very small delay between them (though it can be a false idea).

Please, play a little bit with these quirks using a reasonable interval values (say, 1000...2000 milliseconds). If it helps, please, let me know.