Bug 1833308

Hi Stefan,

thank you for reporting the issue and providing debug logs of HP scripts!

Unfortunately, HP libraries is set to send internal logging into journal too, so there can be other useful info there.

Would you mind following https://fedoraproject.org/wiki/How_to_debug_printing_problems#How_to_get_and_attach_logs_for_bug_report and provided incident-bound journal log?

Thank you in advance!

Sorry I didn't know about that.
I'll check the wiki and follow the steps, may take a week or two until I get back to this.

OK, I've added
DebugLogging stderr
LogLevel debug2
to /etc/cups/cupsd.conf and restarted cups.

If you need anything else please let me know.

Created attachment 1692138 [details]
journalctl -u cups -e

Hi Stefan,

(In reply to Stefan Assmann from comment #3)
> OK, I've added
> DebugLogging stderr

DebugLogging directive is not cupsd.conf directive, but cups-browsed.conf directive.

> LogLevel debug2
> to /etc/cups/cupsd.conf and restarted cups.
> 
> If you need anything else please let me know.

Would you mind telling me how you find out the command you used is the right one?

Unfortunately, HPLIP libraries put logs in journal, but not under CUPS unit (as it is explained in the wiki), so whole incident-bound journal is needed (as written in the wiki), so some logs can be missing in the file you attached.

There is the step-by-step manual at https://fedoraproject.org/wiki/How_to_debug_printing_problems#How_to_get_and_attach_logs_for_bug_report which should lead you to getting incident-bound log for HPLIP device.

I would like to enhance the manual to prevent misunderstandings.

So the steps which I wanted are:

$ journalctl -f > log
$ hp-clean -i

Kill the journalctl process and attach the log.

Created attachment 1692190 [details]
log

Hi Zdenek,

sorry the instructions in the wiki weren't obvious to me.
Hope the following log contains what you need. :)
Thanks!

(In reply to Stefan Assmann from comment #6)
> Created attachment 1692190 [details]
> log
> 
> Hi Zdenek,
> 
> sorry the instructions in the wiki weren't obvious to me.

Would you mind telling what I can change in the wiki to make it easier to understand?

I thought the flow:

1) Enable debug
2) Capture debug - job debug
                 - whole incindent-bound debug - not HPLIP
                                               - HPLIP

was useful.

> Hope the following log contains what you need. :)

Yep, now it has all the stuff - thanks!

Hmm... it reads device_id several times:

Mai 26 11:11:34 w541 python3[104654]: io/hpmud/musb.c 427: Found interface conf=0, iface=1, altset=0, index=1
Mai 26 11:11:34 w541 kernel: Did not find alt setting 1 for intf 0, config 1
Mai 26 11:11:34 w541 python3[104654]: io/hpmud/musb.c 389: Active kernel driver on interface=1 ret=0
Mai 26 11:11:34 w541 python3[104654]: io/hpmud/musb.c 535: claimed 7/1/2 interface
Mai 26 11:11:34 w541 python3[104654]: io/hpmud/musb.c 780: read actual device_id successfully fd=1 len=138
Mai 26 11:11:34 w541 python3[104654]: io/hpmud/musb.c 561: released 7/1/2 interface

and in the end it creates PRINT:

Mai 26 11:11:34 w541 python3[104654]: io/hpmud/musb.c 960: new PRINT channel=2 clientCnt=1 channelCnt=1
Mai 26 11:11:34 w541 kernel: Did not find alt setting 1 for intf 0, config 1
Mai 26 11:11:34 w541 python3[104654]: io/hpmud/musb.c 427: Found interface conf=0, iface=1, altset=0, index=1
Mai 26 11:11:34 w541 python3[104654]: io/hpmud/musb.c 389: Active kernel driver on interface=1 ret=0
Mai 26 11:11:34 w541 python3[104654]: io/hpmud/musb.c 535: claimed 7/1/2 interface
Mai 26 11:11:34 w541 /hp-clean[104654]: hp-clean[104654]: error: An error occured: Device I/O error
Mai 26 11:11:34 w541 /hp-clean[104654]: io/hpmud/musb.c 561: released 7/1/2 interface
Mai 26 11:11:34 w541 /hp-clean[104654]: io/hpmud/musb.c 975: removed PRINT channel=2 clientCnt=0 channelCnt=0

Then no more relevant logs - I will need to dig into musb.c to see what can be the issue.

(In reply to Zdenek Dohnal from comment #7)
> (In reply to Stefan Assmann from comment #6)
> > Created attachment 1692190 [details]
> > log
> > 
> > Hi Zdenek,
> > 
> > sorry the instructions in the wiki weren't obvious to me.
> 
> Would you mind telling what I can change in the wiki to make it easier to
> understand?

Sure! As somebody who does not often deal with the lower levels of printing I had trouble finding the right set of instructions for my problem. So do I need to look for A) B1) B2) or "More commands for working with systemd-journald" or cups-browsed or should I install 
system-config-printer?
There's a lot of good information on the wiki and I probably should have read your comment more careful for what to look for too!

Anyway my suggestion would be to work with the concerning HTML anchor. So instead of
https://fedoraproject.org/wiki/How_to_debug_printing_problems#How_to_get_and_attach_logs_for_bug_report
use
https://fedoraproject.org/wiki/How_to_debug_printing_problems#B2._Capture_incident-bound_CUPSD_log_.28broken_print_queues_is_HPLIP_supported.29

[...]
> Then no more relevant logs - I will need to dig into musb.c to see what can
> be the issue.

Let me know if there's something for me to test. Thanks!

Damn, I closed this tab before I send the comment...

(In reply to Stefan Assmann from comment #8)
> Sure! As somebody who does not often deal with the lower levels of printing
> I had trouble finding the right set of instructions for my problem. So do I
> need to look for A) B1) B2) or "More commands for working with
> systemd-journald" or cups-browsed or should I install 
> system-config-printer?

It was intented to end with B1+B2 points, other points after that are just additional info.

The difference between A and B points is in when they are more useful:
- A point is for problems during printing process (e.g. you have your print queue installed, but you are not able to print a document or a document is printed in wrong way). 
- B point is for problems during device discovery, print queue creation atd. everything except for printing itself. To be honest, logs from A point are in logs from B point too, but they are lost among many different messages and it makes it difficult to read, so for 'real printing issues' I enforce using A point.

> Anyway my suggestion would be to work with the concerning HTML anchor. So
> instead of
> https://fedoraproject.org/wiki/
> How_to_debug_printing_problems#How_to_get_and_attach_logs_for_bug_report
> use
> https://fedoraproject.org/wiki/How_to_debug_printing_problems#B2.
> _Capture_incident-bound_CUPSD_log_.28broken_print_queues_is_HPLIP_supported.
> 29
> 

Ok, thank you for the feedback! I think I'll use the same approach as RH docs team. I'll do 3 user stories for 3 different use cases and I'll send the specific anchor which I want to the ticket.

> [...]
> > Then no more relevant logs - I will need to dig into musb.c to see what can
> > be the issue.
> 
> Let me know if there's something for me to test. Thanks!

Anyway, what I have found:

musb library is able to open interfaces and get device_id, but it fails suddenly when it opens new channel for printing... though it is strange that there is no error message about why it fails from musb. And I would say such behavior should influence printing too.

Is hp-clean the only issue you have or are you not able to print anything too?

I don't think I'll be able to understand the code further and investigate more without reproducing and debugging the program :( .

Are you familiar with gdb? Would you mind cooperating with me during debugging?

(In reply to Zdenek Dohnal from comment #9)
[...]
> Anyway, what I have found:
> 
> musb library is able to open interfaces and get device_id, but it fails
> suddenly when it opens new channel for printing... though it is strange that
> there is no error message about why it fails from musb. And I would say such
> behavior should influence printing too.
> 
> Is hp-clean the only issue you have or are you not able to print anything
> too?

Yes, printing and scanning works fine. The only issue I have is cleaning.
 
> I don't think I'll be able to understand the code further and investigate
> more without reproducing and debugging the program :( .
> 
> Are you familiar with gdb? Would you mind cooperating with me during
> debugging?

Your help is appreciated! I can fire up gdb and set breakpoints wherever you want them.

(In reply to Stefan Assmann from comment #10)
> (In reply to Zdenek Dohnal from comment #9)
> [...]
> Yes, printing and scanning works fine. The only issue I have is cleaning.

Hmm... I haven't investigated USB printers much in the past, so I'm not sure, but I would understand not being able to open PRINT channel would affect printing too...

Ok, so let's see if it is general cleaning problem or just problem with hp-clean:

CUPS web interface has a possibility to issue cleaning print heads too.

Would you mind trying if cleaning from CUPS web interface works?

Steps (prereq: running cups service)
1) go to localhost:631 in your browser
2) Printers -> <your_queue_name> -> Maintenance -> Clean print heads

Does it work?

> Your help is appreciated! I can fire up gdb and set breakpoints wherever you
> want them.

(prereq: installed debuginfos, hplip-libs-debuginfo and python-debuginfo especially)

For the start please:
- start gdb for python3 binary, set breakpoint to new_channel() function from libhpmud library and run /usr/bin/hp-clean in it.
- when it stops at the breakpoint, please give me python stack trace by 'py-bt'  
- follow the execution and find out what is assigned into pd->channel[index].vf.
- it contains a functor to an open function specific for assignment in new_channel(). The functor is called after returning from new_channel().
- step into the function which functor points on, tell me its name 
- follow the execution till you get the error and find out where in libhpmud you get the error and tell me.

The error happens somewhere in libhpmud, but unfortunately it has generic error message in syslog...

(In reply to Zdenek Dohnal from comment #11)
> Steps (prereq: running cups service)
> 1) go to localhost:631 in your browser
> 2) Printers -> <your_queue_name> -> Maintenance -> Clean print heads

Hmm, I'm looking at
http://localhost:631/printers/PSC-1400-series
When I click the Maintenance pull-down menu it does not have an entry of "Clean print heads".

> (prereq: installed debuginfos, hplip-libs-debuginfo and python-debuginfo especially)

Done.

> For the start please:

Sorry, I'm having some difficulties setting the breakpoint. Haven't used gdb with python yet.
Please let me know what I'm missing here.
Ran
# gdb python3 -ex 'set args /usr/bin/hp-clean -i' -ex 'thread apply all bt' -ex 'b main' -ex r
(gdb) b new_channel
Function "new_channel" not defined.

When I "c" with gdb at this point it does not stop at the breakpoint.

(In reply to Stefan Assmann from comment #12)
> Hmm, I'm looking at
> http://localhost:631/printers/PSC-1400-series
> When I click the Maintenance pull-down menu it does not have an entry of
> "Clean print heads".

Just checking - the device is an inkjet printer right?

I had hope that CUPS interface could help us, but it uses CUPS commands for maintenance and it seems the device unfortunately doesn't support it. hp-clean does it by sending specific strings to the device, which triggers the cleaning process...

> 
> > For the start please:
> 
> Sorry, I'm having some difficulties setting the breakpoint. Haven't used gdb
> with python yet.
> Please let me know what I'm missing here.
> Ran
> # gdb python3 -ex 'set args /usr/bin/hp-clean -i' -ex 'thread apply all bt'
> -ex 'b main' -ex r
> (gdb) b new_channel
> Function "new_channel" not defined.
> 
> When I "c" with gdb at this point it does not stop at the breakpoint.

Ok, so my assumption were wrong, so we need to track down from which libhpmud function the error comes and use that function as breakpoint.

Please use your favorite python debugger (I use python3-pudb) and follow the code until you get the error. My guess it happens somewhere in __openChannel method in base/device.py.

When you'll have the name of function where the error comes from, please tell me.

(In reply to Zdenek Dohnal from comment #13)
> Just checking - the device is an inkjet printer right?

Yes, correct.

> Ok, so my assumption were wrong, so we need to track down from which
> libhpmud function the error comes and use that function as breakpoint.
> 
> Please use your favorite python debugger (I use python3-pudb) and follow the
> code until you get the error. My guess it happens somewhere in __openChannel
> method in base/device.py.

Never debugged python, so I'll give python3-pudb a try.
I fired up  
# pudb3 /usr/bin/hp-clean -i
and single stepped to get an idea of how pudb3 works, however it failed pretty early
at
/usr/bin/hp-clean:37
from base.g import *
with
ModuleNotFoundError: No module named 'base'

Most likely a beginners error. :}
Any suggestions?

You can put the line:

import pudb; pu.db

somewhere into /usr/bin/hp-clean, run normally 'hp-clean -i' and TUI will start once the execution reaches that line.

Thanks, that works better!

Execution is as follows.
/usr/bin/hp-clean:143 d.open()
/usr/share/hplip/base/device.py:1151 def open(self, open_for_printing=False):
/usr/share/hplip/base/device.py:1170 hpmudext.open_device(self.device_uri, self.io_mode)
However I cannot step into hpmudext.open_device but that looks ok, result_code is 0.
Back in
/usr/bin/hp-clean we end up in
elif clean_type == CLEAN_TYPE_LIDIL:
and jump to
/usr/share/hplip/base/maint.py:1281
at
/usr/share/hplip/base/maint.py:1300 level1(dev)
we jump to
/usr/share/hplip/base/maint.py:1407 def cleanType2(dev): # LIDIL, Level 1
where I get the following exception
Traceback (most recent call last):
  File "/usr/share/hplip/base/maint.py", line 1408, in cleanType2
   dev.printData(ldl.buildResetPacket())
  File "/usr/share/hplip/base/device.py", line 2448, in printData
    self.writePrint(data)
  File "/usr/share/hplip/base/device.py", line 2210, in writePrint
    return self.__writeChannel(self.openPrint, data)
  File "/usr/share/hplip/base/device.py", line 2267, in __writeChannel
    raise Error(ERROR_DEVICE_IO_ERROR)
base.g.Error: ('Device I/O error', 12)

and dmesg shows
Did not find alt setting 1 for intf 0, config 1

Nice, thanks!

It is interesting there is no debug message about writing (from source code):

'Writing %d bytes to channel %d (device-id=%d)...'

can be other bug with logging :( ...

Either way, the exception is raised here:

if total_bytes_to_write != bytes_out:
    raise Error(ERROR_DEVICE_IO_ERROR)

so hpmud_write_channel()(C func which is called in hpmudext python extension method write_channel) returns more or less data than expected...

Would you mind finding out in python debugger values of 'total_bytes_to_write', 'bytes_out' and 'data', probably even bytes_written?

IIUC 'data' should be '$\x00\x10\x00\x06\x00\x00\x00\x00\x00\xff\xff\xff\xff\xff$'.

Then, since you found out the C function, we can return to gdb and debug the script the same way as in https://bugzilla.redhat.com/show_bug.cgi?id=1833308#c11 , but our breakpoint will be hpmud_write_channel().

Especially interesting will be to find out what function is under the functor channel_write:

stat = (msp->device[dd].vf.channel_write)(&msp->device[dd], &msp->device[dd].channel[cd], buf, size, sec_timeout, bytes_wrote);

and under it will be other functor for writing function - we should follow the flow to some libusb function, because 'bytes_written' originates from it.

(In reply to Zdenek Dohnal from comment #17)
> if total_bytes_to_write != bytes_out:
>     raise Error(ERROR_DEVICE_IO_ERROR)
> Would you mind finding out in python debugger values of
> 'total_bytes_to_write', 'bytes_out' and 'data', probably even bytes_written?

bytes_out: 21
bytes_written: 21
total_bytes_to_write: 16
data: '$\x00\x10\x00\x06\x00\x00\x00\x00\x00?????$'

> IIUC 'data' should be
> '$\x00\x10\x00\x06\x00\x00\x00\x00\x00\xff\xff\xff\xff\xff$'.
>
> Especially interesting will be to find out what function is under the
> functor channel_write:
> 
> stat = (msp->device[dd].vf.channel_write)(&msp->device[dd],
> &msp->device[dd].channel[cd], buf, size, sec_timeout, bytes_wrote);

(gdb) p msp->device[dd].vf
$2 = {write = 0x7fffe8c48c50 <musb_write>, read = 0x7fffe8c49db0 <musb_read>, open = 0x7fffe8c4bab0 <musb_open>,
  close = 0x7fffe8c4a430 <musb_close>, get_device_id = 0x7fffe8c4a8d0 <musb_get_device_id>, get_device_status =
    0x7fffe8c4a7e0 <musb_get_device_status>, channel_open = 0x7fffe8c4a050 <musb_channel_open>, channel_close =
    0x7fffe8c4b7b0 <musb_channel_close>, channel_write = 0x7fffe8c48e80 <musb_channel_write>, channel_read =
    0x7fffe8c498b0 <musb_channel_read>}

> and under it will be other functor for writing function - we should follow
> the flow to some libusb function, because 'bytes_written' originates from it.

From inside musb_channel_write()
(gdb) p *pc
$3 = {sn =     "PRINT", '\000' <repeats 250 times>, sockid = 2 '\002', client_cnt = 1, index = 2, fd = 1, pid = 25503, dindex = 1,
  ta = {h2pcredit = 0, p2hcredit = 0, h2psize = 0, p2hsize = 0}, rbuf =     '\000' <repeats 16383 times>, rindex = 0, rcnt = 0,
  socket = 0, vf = {open = 0x7fffe8c4a9e0 <musb_raw_channel_open>, close = 0x7fffe8c4a4e0 <musb_raw_channel_close>, channel_write =
    0x7fffe8c48a20 <musb_raw_channel_write>, channel_read = 0x7fffe8c48b50 <musb_raw_channel_read>}}

Thank you for the debugging data, Steve!

I'm sorry that I'm not much of help in the issue - this is the first time I debug an usb issue and have a willing reporter to debug :) , so most of my advices are guesses based on the code and your info.

Ok, so libusb_bulk_transfer() tells us that it wrote more data than we expected... I'm getting a feeling it can be bytes X string issue in Python after releasing Python3 (most of hplip code is for Python2, but it is claimed to be python3 compatible).

'data' object is defined as a string object (that explains the different print output than how it was defined), but I would say bytes-like object can be needed.

Would you mind finding out 'buf_size' value in 'write_channel()' after parsing the python stuff? In gdb.

(In reply to Zdenek Dohnal from comment #19)
> I'm sorry that I'm not much of help in the issue - this is the first time I
> debug an usb issue and have a willing reporter to debug :) , so most of my
> advices are guesses based on the code and your info.

Don't worry, this is new ground for me too and I'm enjoying the deep dive.

> Would you mind finding out 'buf_size' value in 'write_channel()' after
> parsing the python stuff? In gdb.

(gdb) list
193         if (!PyArg_ParseTuple(args, "iis#|i", &dd, &cd, &buf, &buf_size, &timeout))
194             return NULL;
195
196         Py_BEGIN_ALLOW_THREADS <---- output from here
197         result = hpmud_write_channel(dd, cd, buf, buf_size,  timeout, &bytes_written);
198         Py_END_ALLOW_THREADS
199
200         return Py_BuildValue("(ii)", result, bytes_written);
201     }
202
(gdb) p buf_size
$1 = 21

Thank you for the info!

Now we know that either:

1) PyArg_ParseTuple doesn't compute the buf_size properly (unlikely...)

or

2) it compares apples with peaches when it checks result of hpmudext.write_channel() and expected outcome.

Ok, so let's say we change the python object which we send - string object - to bytes-like object.

Please try to change in /usr/share/hplip/prnt/ldl.py l.148 to:

         p = b'$\x00\x10\x00\x06\x00\x00\x00\x00\x00\xff\xff\xff\xff\xff$'

and then check if buf_size in hpmud_write_channel() will change to our favor (to 16).


If the buf_size will not change, please update /usr/share/hplip/base/device.py l. 2246 to:

        import sys
        buffer, bytes_out, total_bytes_to_write = data, 0, sys.getsizeof(data)

Let's see if we can get further with those changes.

(In reply to Zdenek Dohnal from comment #21)
> Please try to change in /usr/share/hplip/prnt/ldl.py l.148 to:
> 
>          p = b'$\x00\x10\x00\x06\x00\x00\x00\x00\x00\xff\xff\xff\xff\xff$'

(gdb) p buf_size
$1 = 16

That works! The printer started a cleaning cycle.

Ok, please let me know whether the cleaning cycle will end successfully. IMO there will be more needed string->byte-like conversions during the execution, but I would rather know where than changing it everywhere.

I ran a level 1 cleaning and didn't encounter any problems.
Anything else?

If that's the only level of cleaning you will do, then it is okay from my side.

Thank you for the cooperation! I'll do the update by the end of the week I hope.

Yeah usually that's all I need.
Thanks Zdenek!

FEDORA-2020-c77d623d5f has been submitted as an update to Fedora 32. https://bodhi.fedoraproject.org/updates/FEDORA-2020-c77d623d5f

FEDORA-2020-bcc8cef31e has been submitted as an update to Fedora 31. https://bodhi.fedoraproject.org/updates/FEDORA-2020-bcc8cef31e

FEDORA-2020-bcc8cef31e has been pushed to the Fedora 31 testing repository.
In short time you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2020-bcc8cef31e`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2020-bcc8cef31e

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

FEDORA-2020-c77d623d5f has been pushed to the Fedora 32 testing repository.
In short time you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2020-c77d623d5f`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2020-c77d623d5f

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

FEDORA-2020-3ec2da7668 has been submitted as an update to Fedora 32. https://bodhi.fedoraproject.org/updates/FEDORA-2020-3ec2da7668

FEDORA-2020-407a05acd2 has been submitted as an update to Fedora 31. https://bodhi.fedoraproject.org/updates/FEDORA-2020-407a05acd2

FEDORA-2020-407a05acd2 has been pushed to the Fedora 31 testing repository.
In short time you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2020-407a05acd2`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2020-407a05acd2

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

FEDORA-2020-3ec2da7668 has been pushed to the Fedora 32 testing repository.
In short time you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2020-3ec2da7668`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2020-3ec2da7668

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

FEDORA-2020-63fd65420b has been submitted as an update to Fedora 31. https://bodhi.fedoraproject.org/updates/FEDORA-2020-63fd65420b

FEDORA-2020-3013e53d34 has been submitted as an update to Fedora 32. https://bodhi.fedoraproject.org/updates/FEDORA-2020-3013e53d34

FEDORA-2020-3013e53d34 has been pushed to the Fedora 32 stable repository.
If problem still persists, please make note of it in this bug report.

FEDORA-2020-63fd65420b has been pushed to the Fedora 31 stable repository.
If problem still persists, please make note of it in this bug report.