cups/usb failure

[losepete]

Having failed to get my printer working in wireless mode - see ticket #155 - I decided to test usb connectivity.

With the printer attached via usb and cupsd running I opened the cups browser interface Admin page and clicked on Find printers which failed to find any printers.

I opened a command line window in usr/lib/cups/backend and entered usb which resulted in the prompt returning without any printer information displayed.

Thinking there may be a usb problem with the printer - never tried it with usb before - I rebooted into Windows7, installed the driver and selected USB as the output port during installation. I then successfully printed the Windows Test Page.

So, no problem with the hardware/usb cable involved.

I know the non-rpm cups from Paul does not need the OS/2 usb printer driver installed and loaded as it uses the libusb10.dll library. Is that the same with the rpm packages?

If "Yes" then usb printing does not work because usb.exe cannot find the attached usb printer.

[Silvan Scherrer]

The rpm package also uses libusb, and cups should have installed libusb rpm as well. Please make sure you have only one libusb dll in your path.

But it might well be there are USB issues. As I don't have a USB printer to test atm it's hard to track. There is another USB ticket open already. I hope I have time in the near future to look at them.

[Silvan Scherrer]

what does usb tell you when executed from /@unixroot/usr/lib/cups/backend

[herwigb]

Running latest usb.exe from \usr\lib\backend\cups

STDERR gives me upon connecting

DEBUG: Loading USB quirks from "/@unixroot/usr/share/cups/usb".
DEBUG: Loaded 77 quirks.
DEBUG: list_devices
DEBUG: libusb_get_device_list=2
DEBUG2: Printer found with device ID: MFG:HEWLETT-PACKARD;MDL:DESKJET 940C;CMD:MLC,PCL,PML;CLASS:PRINTER;DESCRIPTION:Hewlett-Packard DeskJet 940C;SERN:CN23D1C1F9CO;VSTATUS:$HB0$NC0,ff,DN,IDLE,CUT,K3,C0,SM,NR,KP000,CP087;VP:0800,FL,B0;VJ:                    ; Device URI: usb://HP/DESKJET%20940C?serial=CN23D1C1F9CO

STDOUT gives me upon connecting

direct usb://HP/DESKJET%20940C?serial=CN23D1C1F9CO "HP DESKJET 940C" "HP DESKJET 940C" "MFG:HEWLETT-PACKARD;MDL:DESKJET 940C;CMD:MLC,PCL,PML;CLASS:PRINTER;DESCRIPTION:Hewlett-Packard DeskJet 940C;SERN:CN23D1C1F9CO;VSTATUS:$HB0$NC0,ff,DN,IDLE,CUT,K3,C0,SM,NR,KP000,CP087;VP:0800,FL,B0;VJ:                    ;" ""

[losepete]

Replying to diver:

what does usb tell you when executed from /@unixroot/usr/lib/cups/backend

As stated above:

I opened a command line window in usr/lib/cups/backend and entered usb which resulted in the prompt returning without any printer information displayed.

[Silvan Scherrer]

as seen in the output of herwigb, there must be some output. it can't be that usb doesn't log anything.
and as you see also by the output of herwigb, it's not that usb isn't working at all. so there is still a chance of some misconfiguring in the usb part. usbcalls or such.

[losepete]

I have spent the past couple of hours rummaging through this system and finally found the fault when running USB (usbcfg.exe configuration tool): I had updated USB to the current Arca Noae 11.14 package but USB showed that the version loaded from config.sys was an older version.

The Arca Noae update placed usbresmg.sys in \os2\boot but as this system started life running eCS2.2beta2 with usbresmg.sys located in \ecs\boot the config.sys line was pointing to the \ecs\boot\usbresmg.sys

Having rectified that and rebooted I can now enter usb at the command line and get a response.

I used the browser interface to setup a printer to use USB - no problems so far, USB attached printer found quickly - and then attempted to print the Test Page. Sadly printing did not happen; the browser interface shows "filter failed" and the log has

[Job 1] PID 129 (/@unixroot/usr/lib/cups/filter/gstoraster.exe) stopped with status 11.

Full log attached as New_error_log

[losepete]

USB error_log: "filter failed" "gstoraster stopped with status 11

[Silvan Scherrer]

ok this is a first good step. Now I need to figure out why gstoraster might fail.

[Silvan Scherrer]

what does yum list gs* say?

[losepete]

Copy'n'Paste from window:-

[I:\USR\BIN]yum list gs*
arcanoae-rel | 1.9 kB 00:00
arcanoae-rel/primary | 7.7 kB 00:00
netlabs-rel | 2.9 kB 00:00
Available Packages
gsoap.i386 2.8.29-1.oc00 netlabs-rel

gsoap.i686 2.8.29-1.oc00 netlabs-rel

gsoap-devel.i386 2.8.29-1.oc00 netlabs-rel

gsoap-devel.i686 2.8.29-1.oc00 netlabs-rel

gsoap-doc.noarch 2.8.29-1.oc00 netlabs-rel

[I:\USR\BIN]

ANPM shows ghostscript 9.18-5 with ghostscript-fonts 6.0-1 installed.

[losepete]

Having discovered cups-filters and cups-filters-libs at 1.13.3-1 in netlabs-experimental I have installed them to see if they provide a resolution.

No, both usb and bjnp connections fail with a gstoraster problem. There is a difference to the filter failure though, the log now shows "stopped with status 1" rather than the "stopped with status 11" shown when using cups-filters 1.8.2-5.

[Silvan Scherrer]

please try to create a new logfile with debug2. If the log is to large when zipped to attach here, send it to info (at) bitwiseworks (dot) com

another question about ghostscript: is it working with gsview? not the printing part, only the view part.

[losepete]

debug2 error log sent by email; Subject: gstoraster failure.

Is there a gsview available as an rpm package? - or a version that works in "*nix style"? I have gsview 5.0 available but it wants to be installed as a subdirectory within the gs directory.

[Silvan Scherrer]

I use older gsview 4.9 and it works nicely with ghostscript rpm. so I assume 5.0 should as well. see also #100 for some references to gsview. The ticket explains which settings are necessary and which are obsolete.

btw I didn't get the debug log until now. I will see if it's some of my spam folders later on.

[losepete]

I edited \os2\gvpm.ini to point to the rpm installed ghostscript file locations based on ticket #100:-

[GSview-5.0]
Configured=1
GSversion=918
Version=5.0
GhostscriptDLL=I:\usr\lib\gsdll2.dll
GhostscriptEXE=I:\usr\bin\gsos2.exe
GhostscriptInclude=I:\usr\lib
GhostscriptOther=-dNOPLATFONTS -sFONTPATH="f:\psfonts"

gsview seems to be working fine, the few files I have opened have displayed fine including text.

[losepete]

error_log from recent gstoraster build sent by email

[Silvan Scherrer]

I got them and I'm looking at them soon

[Silvan Scherrer]

do you have some popuplog entries eventually? As it seems like ghostscript ends with a SIGSEGV

[losepete]

No entries in popuplog.os2 related to gs at all.

[Silvan Scherrer]

please add a SET GS_DEBUG=1 to your config.sys and try with this gsos2.exe. It should write a logfile called gs_debug.log to your %UNIXROOT%\var\log dir.
Eventually this gives already some hints.

[losepete]

Using the new gsos2.exe with the debug line in config.sys and the system rebooted I tried printing the Test Page from the browser interface. After 10 minutes the print job still shows "Color manager: no profiles specified in PPD".

I Cancelled the job, then brought up the Process List which showed 4 instances of cupsd.exe, 1 of usb, 1 of rastertogutenprint and 1 of gstoraster still running several minutes after the job had been Cancelled.

10 minutes later those processes are still running...

I killed all those processes and went looking for log files. The only log in %UNIXROOT%\var\log is yum.log

Do you want the error_logs from %UNIXROOT%\var\log\cups?

[Silvan Scherrer]

are you absolutely sure, that using the old gsos2.exe and no config.sys setting it doesn't hang the same? As according to your analysis gsos2.exe is not even started.

[losepete]

I do not think so but would not like to state that is definitely the case.

Using the new gsos2.exe the current error_log shows the gs command line "/user/bin/gs -d..." and further down the log I see this:-

gs: Invalid executable file format

I would guess that could be the cause of a problem or several. Not sure what has happened to this file so replaced it with the file from the installation package.

That does change the message in the browser interface to "sending data to printer". Sadly nothing gets sent to the printer at all so I Cancelled the job, killed all the cups related processes and had a look through the log. After the message "sending data to printer" all the [Job 1] entries seem to consist of "reading back channel data" until the job gets Cancelled. The error log for this attempt is error_log_new_gsos2

Replaced new gsos2.exe with the original version to test the difference. The result is "filter failed" - gstoraster stopped with status 1. The error log for this attempt is error_log

I have emailed you both the above error_logs.

[losepete]

Is there any way of running the various filters from the command line? - it may help identify where the process goes wrong.

[losepete]

In response to your email question I have tried running gsos2.exe from the command line.

The original gsos2.exe starts, reports version and shows a GS> prompt awaiting input.

The new gsos2.exe fails to start instead delivering a SYS0191: I:\usr/bin\gsos2.exe cannot be run in an OS/2 session.

I also tried running the new gsos2.exe in a bash session which failed with
bash.exe: Execution failed because of "i:\usr\bin\gsos2.exe"
bash.exe: i:\usr\bin\gsos2.exe: No such file or directory

So, it looks like the new gsos2.exe does not work.

[Silvan Scherrer]

this is rather strange, as here the exe works. I even downloaded it from here to be sure. Could you see if some requirements is missing with chkdll32 or pmdll? or if the download was broken?
9.06.17 16.12 181'007 124 a--- gsos2.exe

[losepete]

Broken download.

I used shift-click to download gsos2.exe and ended up with a file the same size as the previous download - 5,773 bytes which seemed small to me on both downloads.

I then tried simply clicking the gsos2.exe link and on the page that opened I clicked the download link and downloaded the file again - this time it was 176.8Kb filesize.

I had not realised that shift-click on the filename link does not work on this site...

I installed the file and started gsos2 in an OS/2 window with no problem.

I then tried printing the cups Test page.
Result: "filter failed" - searching the error_log shows gstoraster stopped with status 1

Having Cancelled the job successfully - only cupsd still running after a few seconds - I had a look for %UNIXROOT%\var\log\gs_debug.log but the file does not exist there. Then I realised that as this is an eCS system it probably has a log setting in config.sys pointing to Boot:\var\log

Yes, there is a gs_debug.log.
Sadly it is of no use at all apart from letting you know that the file gets created but is empty, 0 bytes

[Silvan Scherrer]

this at least gives me a small hint what it might do. As there is not much code involved between log creation and the first log entry it should generate.

[Silvan Scherrer]

new try

[Silvan Scherrer]

please try this gsos2.exe. I hope it writes some lines. As between the creation ofd the file and the first line it should write is really no code. So I wonder what's going on there

[losepete]

Installed the latest gsos2.exe

unixroot is I:

I opened a command window in I: and entered gsos2

I got the GS> prompt and typed quit to close gsos2

I then checked the file \var\logs\gs_debug.log had been created. It had, here is the content:-

main init
Trying to load GSDLL2.DLL
Loaded Ghostscript DLL
gs_load_dll out
-dDisplayFormat=198660
main set_display_callback
main init_with_args rc: 0
main run_string rc: -101
gs_free_dll
main end rc: 0

I then deleted gs_debug.log, started cupsd and tried to print the cups test page - filter failed, error_log shows "gstoraster stopped with status 1".

I tried to open gs_debug.log to see if that gave a clue. It may do as it does not exist.

I take it a possible cause of "gstoraster stopped with status 1" would be that gs had failed in some way, possibly not starting.

[Silvan Scherrer]

please try again with cups-filter 1.13.3 and the gstoraster I send you once. Also try with a renamed gs.exe to gs only. the one in /@unixroot/usr/bin

[losepete]

The results in all instances are "filter failed", error_log shows "gstoraster stopped with status 1".

[Silvan Scherrer]

we already know the filter fails, but is there never a log written from gsos2.exe? If there is no log, it would mean it crashes somewhere in execvp() after fork(). And to debug that you would have to install a debug libc version. But that's less than easy to do unfortunately.

[losepete]

No, no gs_debug.log is produced.

I attach snippet.txt which is the section of the error_log starting with the ghostscript command line and ending just after the gstoraster failure in case that offers any further clues

[losepete]

section of cups error_log

[Silvan Scherrer]

As there is no log from gs it will be very hard to debug. The cups log clearly states that gs is executed, but most probably execvp() dies.

I need to think how to debug that further.

[Silvan Scherrer]

http://trac.netlabs.org/ports/wiki/PortingTips#Debuggingtechniques
describes how to create a libc log. Just be sure to start cupsd by hand after you enabled the log. Eventually we get a better idea whats going on on your system.

[losepete]

Do you want me to upload the 20 odd files totalling around 65Mb somewhere for you to download or do you want to give me a clue as to what to look for within those log files?

[Silvan Scherrer]

please upload them as zip to dropbox or gdrive or any ftp. If you don't have a possibility to do so, please stay tuned. I will then advise you where to put them.

[losepete]

Zipped and uploaded to ​https://www.dropbox.com/s/epbg6ygz6aid6rn/libc_logs.zip

[losepete]

Are we sure that gs gets called?

I must admit to not being overly familiar with deciphering cups logs but looking through the log section SNIPPET.TXT I do not see that gs is clearly started at all.

I do see the ghostscript command line on Line4 followed by "bww before execvp file: gs" on Line46 - maybe these tell an experienced person that gs started? The next "gs" mention is the gstoraster finished/failed on Lines400/401.

A search through the libc_logs does not get any results for gsos2.

[Silvan Scherrer]

yes the execvp() is exactly where gs is called. But later it fails somehow in libc. And for this I need to look at the logs. But unfortunately I'm very busy right now with my daytime job. So I might need some weeks to get to it again.

[Silvan Scherrer]

for the logs you generated, do you have the corresponding error_log as well? It would help for the timestamp comparison. If not could you please redo the whole process again and upload the log as well?

[losepete]

Have emailed you error_log_libc which is the cups log generated while generating all the libc logs.

[Silvan Scherrer]

something is strange, as in this log at the 27th of June I don't see any debug messages I added to gstoraster. And I even don't see the failed messages. For the 17th of June I see them, but this doesn't correspond to the libc log files.
It would be great if you could retest with the debug gstoraster and cups-filters 1.13.3.

[losepete]

There seems to be a problem with the libc debug dll file as the cups interface, using Seamonkey 2.35) is stuck at reporting "Test page sent..." and does not get returned to the printer page as it should.

I have retested this 3 times and see the same behaviour each time. I recall "killing" cupsd, usb, gstoraster, rastertogutenprint, pdftopdf with the previous supplied logs which may be why the cups log does not match the libc logs in some way.

Hunting through the latest cups log I see

... gstoraster.exe) stopped with status 127 (File too large)

Obviously something has glitched somewhere to make the test page too large.

I will have a rummage through the system and double check files in use before attempting to generate the logs again.

[losepete]

All files check out OK so I retried generating libc logs and see the same results: the cups browser interface is extremely slow - I clicked the Printers page and the page mainly loaded but then seems to hang with "Transferring data from localhost..." in the status bar

Clicking the printer, CanonMG7500, results in that page mainly loading and then it gets stuck with the "Transferring ..." message.

Clicking Print Test Page results in the browser displaying the Print Test Page and then it gets stuck with the "Transferring ..." message.

I have not seen this behaviour prior to installing the debug libc066.dll so reverted to the standard libc066.dll and rebooted to see where the problem lies.

The answer seems to be that the problem is with the debug libc066.dll file, aka libc066.logchk, as the browser interface works OK - does not get stuck with the "Transferring ..." message so allows the failed print job to be Cancelled - using the "normal" libc066.dll file.

ANPM reports libc 0.6.6-30 installed

The libc066.logchk file came from this package libc-devel-0.6.6-30.oc00.i686.rpm

From here it looks like there is something wrong with libc066.logchk...

[Silvan Scherrer]

the libc logging slows everything down. So I suspect you get timeouts and so the browser screws things. An idea I have is to set the logging up and not using the browser to send a testpage. As also qpdview or lucide or even a small test from within AE should be printable. With this scenario we might get all logs.

[losepete]

Does the libc logging slow things down to the extent that a print job that should take less than a minute is still going 30 minutes later? I suspect something got stuck in a loop...

I have uploaded new logs to ​https://www.dropbox.com/s/r9c7k4nqndh6jie/new_logs.zip

These were generated by printing a very small text file from (a)e.exe

As the print job was obviously not going to work I started the browser a little later to Cancel the print job - slightly less than 30 minutes after starting it - and hope you have enough log material to be of help.

[erdmann]

Sorry for stepping in but this is the way it worked for me:

1) install the CUPS RPM package. It will complain that you should remove LIBUSB10.DLL and that USBCALLS.DLL will need to be updated.
Therefore unlock \os2\dll\libusb10.dll (or was it \ecs\dll\libusb10.dll ?) and also \os2\dll\usbcalls.dll, delete them and rerun Installation of the CUPS RPM package.
Note: if you have my USB Driver set installed you will either need to reinstall USBRESMG.SYS and USBCALLS.DLL or you need to switch to the AN Driver stack as the CUPS RPM blindly forces USBCALLS.DLL and USBRESMG.SYS to the AN Versions which do version checking against the rest of the USB stack and will not work on a mismatch.
In short: LIBUSB10.DLL needs to be updated and older versions therefore deleted. The older version likely came with the eComStation WarpIn Installation.

2) install the CUPS filter RPM package.

3) if present (from an eCOMstation Installation for example), deinstall all CUPS components that were installed via WarpIN. You will need to kill cupsd.exe manually (via CAD-Commander etc.) before you will be able to deinstall everything successfully.

4) Add "RUN=C:\USR\SBIN\CUPSD.EXE" (if C: is your boot drive) to your config.sys and reboot.

5) attach your USB printer, if not already happened, this should lead to creation of a printer object and a USB associated printer port. Open the USB printer port object and make sure that it shows "ATTACHED".
That'll indicate that not only the USB printer attached properly but also that the USB port driver got properly notified of this device attachment.

6) Now run your browser with the well-known localhost address "localhost:631".[[BR]]
In the admin section select "find Printers". Sometimes you will need to do this repetitively before it will be successful. Your USB connected printer should pop up.
Have it installed, if you have a PS printer (as in my case) you can now Import a PPD file (should be part of your Windows Driver package for the printer), if you have other printer you need to fumble around with the other Driver offerings.

7) Print the test page. For me this worked out ok at this point.

[losepete]

Thanks Lars but it is the printing of the test page that fails - usb connectivity is now fine, the problem seems to be gs/gstoraster related..

[Silvan Scherrer]

it is almost 100% sure a gs issue. But I have not much time right now and I still can't reproduce it. I hope I can look at it again soon. #167 might give us some hint's when fixed.

[Silvan Scherrer]

did you also try to print the same small text file from (a)e.exe w/o the libc debug? As this time the gsos2.exe seems to run normal.

This case is really not easy to track.

[losepete]

I have had a check of the system to make sure eCUPS components are not interfering with the "rpm-cups" installation. I discovered an older gs8.71 lurking in my %temp% directory and have now deleted it.

To avoid excessive log file generation I swapped the libc066.dll debug version for the normal version and rebooted.

Attempting to print the cups test page from the browser interface fails - gstoraster stopped with status 1.

Printing from (a)e.exe now works.

Printing from OpenOffice results in the job showing "Processing page 1... " in the browser interface and nothing happening at the printer. After a couple of minutes I cancelled the job as it was obviously not going to print.

Following a reboot I attempted to print from OpenOffice again to test the above. Printing worked.

I then opened another document in OpenOffice and tried printing. No output at printer after a few minutes and the browser interface shows "Processing page 1... ".

Looks like cups can print once and then needs a reboot to print another document...

I tested the above idea by rebooting without cancelling the print job.

Once cupsd had started the print job was printed.

I have also reinstalled the non-rpm supplied bjnp.exe wireless backend and can report that suffers from the same problem - only 1 print job per boot.

[Silvan Scherrer]

this is good and bad. good as cups and all tools seem to run. but bad as some memory issues exists. and those are very hard to track. as soon as I have more ideas or tests I let you know.

[Silvan Scherrer]

any news on that with latest cups, cups-filters and gs rpm versions?

[Silvan Scherrer]

hmm no more news, so closing it