Printer queue problem (LPRng 3.4.2, Samba 1.9.18p4, Solaris 2.5.1/2.6)

Tue Apr 14 18:48:06 GMT 1998

I've been having a problem with Win95 clients watching a printer queue on
the Samba server (called labserv2).  labserv2 is a Solaris 2.5.1 machine
running samba 1.9.18p4.  The printing system is LPRng 3.4.2.

A user can watch the printer queue from a Win95 client machine.  However,
when the printer queue gets backed up (usually about 12 jobs), the queue
window locks.  The corresponding smbd process on labserv2 starts sucking
up lots of CPU time.  Once you have about 10 clients doing this...well,
things start slowing down pretty badly (although, to samba's credit, it
is still very usable at a load average of 10 :) .

I managed to reproduce this behavior on labserv1, which is currently
unused.  labserv1 runs Solaris 2.6, samba 1.9.18p4, and LPRng 3.4.5.
LPRng is set up so that the printers are served remotely from labserv2.
Using a debug level of 10 and a single client watching a busy printer
queue, I was able to capture debugging information.  At the end of this
post is the debugging info that just loops over and over again, as fast
as it can, on the spazzed smbd process.

As far as I know, I never had this problem with samba 1.9.17p5 (and yes,
we were using LPRng at the time).  This only started happening when I
upgraded to samba 1.9.18.  

Does anybody have any clues?

Owen Magee
mageeol at mail.auburn.edu

-------------------------------------------------------------------------

got message type 0x0 of len 0x83
04/03/1998 10:03:43 Transaction 249 of length 135
size=131
smb_com=0x25
smb_rcls=0
smb_reh=0
smb_err=0
smb_flg=0
smb_flg2=0
smb_tid=68
smb_pid=7487
smb_uid=100
smb_mid=25730
smt_wct=14
smb_vwv[0]=55 (0x37)
smb_vwv[1]=0 (0x0)
smb_vwv[2]=6 (0x6)
smb_vwv[3]=0 (0x0)
smb_vwv[4]=0 (0x0)
smb_vwv[5]=0 (0x0)
smb_vwv[6]=5000 (0x1388)
smb_vwv[7]=0 (0x0)
smb_vwv[8]=0 (0x0)
smb_vwv[9]=55 (0x37)
smb_vwv[10]=76 (0x4C)
smb_vwv[11]=0 (0x0)
smb_vwv[12]=0 (0x0)
smb_vwv[13]=0 (0x0)
smb_bcc=68
[000] 5C 50 49 50 45 5C 4C 41  4E 4D 41 4E 00 46 00 7A  \PIPE\LA NMAN.F.z
[010] 57 72 4C 68 00 42 31 33  42 57 57 57 7A 7A 7A 7A  WrLh.B13 BWWWzzzz
[020] 7A 57 4E 00 50 43 4C 41  42 42 55 53 00 02 00 00  zWN.PCLA BBUS....
[030] 00 57 42 32 31 42 42 31  36 42 31 30 7A 57 57 7A  .WB21BB1 6B10zWWz
[040] 44 44 7A 00                                       DDz. 
switch message SMBtrans (pid 3880)
Skipping become_user - already user
trans <\PIPE\LANMAN> data=0 params=55 setup=0
calling named_pipe
named pipe command on <LANMAN> name
Got API command 70 of form <zWrLh> <B13BWWWzzzzzWN>
(tdscnt=0,tpscnt=55,mdrcnt=0
,mprcnt=6)
Doing DosPrintQGetInfo
PrintQueue uLevel=2 name=PCLABBUS
Using cached lpq output
QUEUE2: Printer: pclabbus at labserv2 

QUEUE2:  Queue: 13 printable jobs

QUEUE2:  Server: pid 14995 active

QUEUE2:  Unspooler: pid 21532 active

QUEUE2:  Status: printed all 160850 bytes at 10:03:41

QUEUE2:  Filter_status: ifhp NOTICE - printer status code 10023 -
processing job
 at Apr  3 10:03:36 

QUEUE2:  Rank   Owner/ID                   Class Job  Files
Size T
ime    

QUEUE2: active  kingrod at labserv2+198           A  198 busine.a004i.
160850 0
9:57:55

Time reported for job 198 is Fri Apr  3 09:57:55 1998
QUEUE2: 2       kingrod at labserv2+218           A  218 busine.a004i.
108888 0
9:58:02

Time reported for job 218 is Fri Apr  3 09:58:02 1998
QUEUE2: 3       hardidl at labserv2+821           A  821 busine.a0050n
98349 1
0:00:25

Time reported for job 821 is Fri Apr  3 10:00:25 1998
QUEUE2: 4       brownc6 at labserv2+967           A  967 busine.a0051U
98460 1
0:01:11

Time reported for job 967 is Fri Apr  3 10:01:11 1998
QUEUE2: 5       adamsj5 at labserv2+993           A  993 busine.a004pz
98819 1
0:01:18

Time reported for job 993 is Fri Apr  3 10:01:18 1998
QUEUE2: 6       brownc6 at labserv2+054           A   54 busine.a0051U
160483 1
0:01:30

Time reported for job 54 is Fri Apr  3 10:01:30 1998
QUEUE2: 7       mageeol at labserv1+903           A  903 .bash_profile
2959 10
:03:02

Time reported for job 903 is Fri Apr  3 10:03:02 1998
QUEUE2: 8       mageeol at labserv1+904           A  904 .bash_profile
2959 10
:03:04

Time reported for job 904 is Fri Apr  3 10:03:04 1998
QUEUE2: 9       mageeol at labserv1+905           A  905 .bash_profile
2959 10
:03:06

Time reported for job 905 is Fri Apr  3 10:03:06 1998
QUEUE2: 10      mageeol at labserv1+908           A  908 .bash_profile
2959 10
:03:21

Time reported for job 908 is Fri Apr  3 10:03:21 1998
QUEUE2: 11      mageeol at labserv1+909           A  909 .bash_profile
2959 10
:03:22

Time reported for job 909 is Fri Apr  3 10:03:22 1998
QUEUE2: 12      mageeol at labserv1+914           A  914 .bash_profile
2959 10
:03:39

Time reported for job 914 is Fri Apr  3 10:03:39 1998
QUEUE2: 13      mageeol at labserv1+915           A  915 .bash_profile
2959 10
:03:40

Time reported for job 915 is Fri Apr  3 10:03:40 1998
printqgetinfo: errorcode 2123
size=63
smb_com=0x25
smb_rcls=0
smb_reh=0
smb_err=0
smb_flg=128
smb_flg2=1
smb_tid=68
smb_pid=7487
smb_uid=100
smb_mid=25730
smt_wct=10
smb_vwv[0]=6 (0x6)
smb_vwv[1]=0 (0x0)
smb_vwv[2]=0 (0x0)
smb_vwv[3]=6 (0x6)
smb_vwv[4]=55 (0x37)
smb_vwv[5]=0 (0x0)
smb_vwv[6]=0 (0x0)
smb_vwv[7]=63 (0x3F)
smb_vwv[8]=0 (0x0)
smb_vwv[9]=0 (0x0)
smb_bcc=8
[000] 4B 08 00 00 00 00 00 00                           K....... 
write_socket(6,67)
write_socket(6,67) wrote 67