OS/2: Jobs get stuck until .cgi program run from web interface

[Paul Smedley]

Hi All,

As many would have seen, I'm working on building CUPS for OS/2.

One of my last remaining problems, is that after sending a print job, 
nothing comes out of the printer, until I load up http://localhost:631
and click on 'Printers' or 'Jobs' and then the print job is suddenly 
released.

An excerpt of the debug log is:
I [11/Dec/2006:19:10:10 -09-30] [Job 29] Printing page 1, 99% 
complete...
I [11/Dec/2006:19:10:10 -09-30] [Job 29] Processing page 2...
d [11/Dec/2006:19:10:10 -09-30] [Job 29] cups_get_matrix(0x918994, 
0x57eb50)
D [11/Dec/2006:19:10:10 -09-30] [Job 29] cups->header.Duplex = 0
D [11/Dec/2006:19:10:10 -09-30] [Job 29] cups->page = 2
D [11/Dec/2006:19:10:10 -09-30] [Job 29] cupsPPD = 0x9a15e0
D [11/Dec/2006:19:10:10 -09-30] [Job 29] cupsPPD->flip_duplex = 0
D [11/Dec/2006:19:10:10 -09-30] [Job 29] width = 2329, height = 3208
D [11/Dec/2006:19:10:10 -09-30] [Job 29] PageSize = [ 595 842 ], 
HWResolution = [ 300 300 ]
d [11/Dec/2006:19:10:10 -09-30] 
cupsdAddEvent(event=printer-state-changed, dest=0x380220(Kyocera), 
job=0(0), text="Printer "%s" state changed.", ...)
D [11/Dec/2006:19:10:10 -09-30] Discarding unused 
printer-state-changed event...
d [11/Dec/2006:19:10:10 -09-30] cupsdDoSelect: selecting 16 fds for 1 
seconds...
d [11/Dec/2006:19:10:10 -09-30] cupsdDoSelect: select() returned 1...
d [11/Dec/2006:19:10:10 -09-30] cupsdDoSelect: Read on fd 15...
D [11/Dec/2006:19:10:10 -09-30] [Job 29] HWMargins = [ 18.000 36.000 
18.000 36.000 ]
D [11/Dec/2006:19:10:10 -09-30] [Job 29] matrix = [ 4.167 0.000 0.000 
-4.167 -75.000 3358.333 ]
d [11/Dec/2006:19:10:10 -09-30] cupsdDoSelect: selecting 16 fds for 1 
seconds...
d [11/Dec/2006:19:10:11 -09-30] cupsdDoSelect: select() returned 0...
d [11/Dec/2006:19:10:11 -09-30] cupsdCheckJobs: 1 active jobs, 
sleeping=0, reload=0
d [11/Dec/2006:19:10:11 -09-30] cupsdCheckJobs: Job 29: state_value=5,
loaded=yes
d [11/Dec/2006:19:10:11 -09-30] select_timeout: 11 seconds to process 
active jobs
d [11/Dec/2006:19:10:11 -09-30] cupsdDoSelect: selecting 16 fds for 11
seconds...
d [11/Dec/2006:19:10:22 -09-30] cupsdDoSelect: select() returned 0...
d [11/Dec/2006:19:10:22 -09-30] cupsdCheckJobs: 1 active jobs, 
sleeping=0, reload=0
d [11/Dec/2006:19:10:22 -09-30] cupsdCheckJobs: Job 29: state_value=5,
loaded=yes
d [11/Dec/2006:19:10:22 -09-30] select_timeout: 11 seconds to send 
browse update
d [11/Dec/2006:19:10:22 -09-30] cupsdDoSelect: selecting 16 fds for 11
seconds...
d [11/Dec/2006:19:10:33 -09-30] cupsdDoSelect: select() returned 0...
d [11/Dec/2006:19:10:33 -09-30] cupsdCheckJobs: 1 active jobs, 
sleeping=0, reload=0
d [11/Dec/2006:19:10:33 -09-30] cupsdCheckJobs: Job 29: state_value=5,
loaded=yes
d [11/Dec/2006:19:10:33 -09-30] select_timeout: 9 seconds to send 
browse update
d [11/Dec/2006:19:10:33 -09-30] cupsdDoSelect: selecting 16 fds for 9 
seconds...
d [11/Dec/2006:19:10:42 -09-30] cupsdDoSelect: select() returned 0...
d [11/Dec/2006:19:10:42 -09-30] select_timeout: 11 seconds to process 
active jobs
d [11/Dec/2006:19:10:42 -09-30] cupsdDoSelect: selecting 16 fds for 11
seconds...
d [11/Dec/2006:19:10:53 -09-30] cupsdDoSelect: select() returned 0...
d [11/Dec/2006:19:10:53 -09-30] cupsdCheckJobs: 1 active jobs, 
sleeping=0, reload=0
d [11/Dec/2006:19:10:53 -09-30] cupsdCheckJobs: Job 29: state_value=5,
loaded=yes
d [11/Dec/2006:19:10:53 -09-30] select_timeout: 11 seconds to send 
browse update
d [11/Dec/2006:19:10:53 -09-30] cupsdDoSelect: selecting 16 fds for 11
seconds...
d [11/Dec/2006:19:11:00 -09-30] cupsdDoSelect: select() returned 1...
d [11/Dec/2006:19:11:00 -09-30] cupsdDoSelect: Read on fd 3...
d [11/Dec/2006:19:11:00 -09-30] cupsdAcceptClient(lis=0x36e0c0) 3 
Clients = 1
D [11/Dec/2006:19:11:00 -09-30] cupsdAcceptClient: 25 from 
localhost:631 (IPv4)
d [11/Dec/2006:19:11:00 -09-30] cupsdAcceptClient: 25 connected to 
server on localhost:631
d [11/Dec/2006:19:11:00 -09-30] cupsdAddSelect: fd=25, 
read_cb=0x15146, write_cb=0, data=0x382500
d [11/Dec/2006:19:11:00 -09-30] cupsdAddSelect: Adding fd 25 to input 
set...
d [11/Dec/2006:19:11:00 -09-30] cupsdAddSelect: Removing fd 25 from 
output set...
d [11/Dec/2006:19:11:00 -09-30] cupsdDoSelect: selecting 26 fds for 1 
seconds...
d [11/Dec/2006:19:11:00 -09-30] cupsdDoSelect: select() returned 1...
d [11/Dec/2006:19:11:00 -09-30] cupsdDoSelect: Read on fd 25...
d [11/Dec/2006:19:11:00 -09-30] cupsdReadClient: 25, used=0, file=-1 
state=0
D [11/Dec/2006:19:11:00 -09-30] cupsdReadClient: 25 GET /printers/ 
HTTP/1.1
D [11/Dec/2006:19:11:00 -09-30] cupsdReadClient: 25 Browser asked for 
language "en-us.utf-8"...
d [11/Dec/2006:19:11:00 -09-30] cupsdFindBest: uri = "/printers/"...

As can be seen, Job 29 is finished at 19:10:10, then I just get 
regular:
d [11/Dec/2006:19:10:11 -09-30] cupsdCheckJobs: 1 active jobs, 
sleeping=0, reload=0
d [11/Dec/2006:19:10:11 -09-30] cupsdCheckJobs: Job 29: state_value=5,
loaded=yes
until 19:11:00 (which is when I clicked printers), then the job prints
shortly after.  The only other reference to Job 29 is:
d [11/Dec/2006:19:11:00 -09-30] process_children()
D [11/Dec/2006:19:11:00 -09-30] PID 39416 (/cups/lib/cups/backend/lpd)
exited with no errors.
d [11/Dec/2006:19:11:00 -09-30] cupsdDoSelect: selecting 26 fds for 1 
seconds...
d [11/Dec/2006:19:11:00 -09-30] cupsdDoSelect: select() returned 1...
d [11/Dec/2006:19:11:00 -09-30] cupsdDoSelect: Read on fd 15...
D [11/Dec/2006:19:11:00 -09-30] [Job 29] File 0 is complete.
d [11/Dec/2006:19:11:00 -09-30] cupsdFinishJob: job->status is 0

Any ideas?

-- 

Cheers,

Paul.