oplock errors
David Lee
T.D.Lee at durham.ac.uk
Thu Nov 4 10:01:46 GMT 1999
I'm no expert on Samba, but I an aware of a thread on this list about
perplexing oplock problems.
Might the following, extracted from a problem report yesterday, help those
of you tracking it? Firstly, of course, is the problem below related to
the perplexing problem or is it a different one?
The server: Samba 2.0.4b on Solaris 2.6 (Ultra E450). Normal running sees
some 200-250 simultaneous connections (I have seen a peak of over 400)
coming and going throughout the day.
We seem to get these occurences quite about twice a day (it varies) which
is very small compared to the aggregate number of connections during the
course of a day.
(Around this particular instance, the server was accidentally rebooted at
around 15:50, although I think this is irrelevant.)
Anyway, hope the info below can help someone.
Glossary:
NPCS: our name for our "Network PC Service" (NT4/SP3) installed on the
many hundred client machines in the various classrooms.
--
: David Lee I.T. Service :
: Systems Programmer Computer Centre :
: University of Durham :
: http://www.dur.ac.uk/~dcl0tdl South Road :
: Durham :
: Phone: +44 191 374 2882 U.K. :
---------- Forwarded message ----------
[...]
Well this looks very interesting. I've checked the Samba log files and the NPCS
log files to try to identify which PC he was using and at what time. The extract
below is from the NPCS log file which is fed by the logon script. The logout
utility doesn't send anything itself, but as the logon script restarts it writes
a 'close' line and when the user has authenticated and all the drive mappings,
application setups etc. are complete, it then sends an 'open' record. These are
the lines marked #1 and #2 below (this extract is from one of the two server
logs,
but the other is the same within a matter of a couple of seconds)
UCSPC5611 open d7cfj6 1999:11:03:14:51:02
UCSPC5611 close ******** 1999:11:03:16:22:16 <--- #1
UCSPC5611 open dju8cl 1999:11:03:16:24:28 <--- #2
UCSPC5611 close ******** 1999:11:03:17:18:10
UCSPC5611 open dju8vd 1999:11:03:17:19:08
UCSPC5611 close ******** 1999:11:03:18:23:50
On Samba a normal session extract would be just 4 lines like this :-
[1999/11/02 15:58:02, 1] ../smbd/service.c:make_connection(499)
ucspc5611 (193.60.179.119) connect to service d90phn as user d90phn (uid=9794,
gid=3651) (pid 29251)
[1999/11/02 16:13:42, 1] ../smbd/service.c:close_cnum(525)
ucspc5611 (193.60.179.119) closed connection to service d90phn
If we now turn to the Samba log (log.ucspc5611.old), you can see the 'make
connection' occuring at 16:22:39 (#3). Then we have an 'oplock' indication;
but more interestingly at 16:24:24 (#4), we have another 'make connection'
and at 16:25:55 (#5) another, and at 16:27:09 (#6) yet another, all without
any 'close connection' indication. Eventually at 16:27:16 (#7) we do find a
close indication, but the 'oplock' messages continue unabated throughout all
this!
Perhaps even more bizarre is that the rest of the log.ucspc5611.old continues
with 'oplock' messages until its end at 18:11:52, without any user connection
or disconnection information. However, from the NPCS log, user 'dju8vd' looks
to have connected at 17:19. If you now look at the current Samba log
(log.ucspc5611), this starts at 17:18 with just what we expect. However, look
at #8; here's user dju8cl disconnecting at 18:11 from a device without an
IP address!
What all this means I have no idea .... is it a client or server problem? About
all you can say is that there's some multi-tasking(threading) going on at one
end or the other which shouldn't be. I'll see if I can find some more examples
which might help when my head has had time to recover!!
------------------------- log.ucspc5611.old ------------------------------------
[1999/11/03 16:22:39, 1] ../smbd/service.c:make_connection(499) <--- #3
ucspc5611 (193.60.179.119) connect to service dju8cl as user dju8cl (uid=13962
, gid=3651) (pid 2988)
[1999/11/03 16:24:05, 0] ../smbd/oplock.c:request_oplock_break(996)
request_oplock_break: no response received to oplock break request to pid 1661
on port 34146 for dev = 23c7533, inode = 25679
for dev = 23c7533, inode = 25679, tv_sec = 38205ea8, tv_usec = d3fc9
[1999/11/03 16:24:24, 1] ../smbd/service.c:make_connection(499) <--- #4
ucspc5611 (193.60.179.119) connect to service dju8cl as user dju8cl (uid=13962
, gid=3651) (pid 3080)
[1999/11/03 16:24:37, 0] ../smbd/oplock.c:request_oplock_break(996)
request_oplock_break: no response received to oplock break request to pid 1661
on port 34146 for dev = 23c7533, inode = 25679
for dev = 23c7533, inode = 25679, tv_sec = 38205ea8, tv_usec = d3fc9
[1999/11/03 16:25:09, 0] ../smbd/oplock.c:request_oplock_break(996)
request_oplock_break: no response received to oplock break request to pid 1661
on port 34146 for dev = 23c7533, inode = 25679
for dev = 23c7533, inode = 25679, tv_sec = 38205ea8, tv_usec = d3fc9
[1999/11/03 16:25:12, 0] ../smbd/oplock.c:request_oplock_break(996)
request_oplock_break: no response received to oplock break request to pid 1661
on port 34146 for dev = 23c7533, inode = 25064
for dev = 23c7533, inode = 25064, tv_sec = 38205ea8, tv_usec = 428b8
[1999/11/03 16:25:41, 0] ../smbd/oplock.c:request_oplock_break(996)
request_oplock_break: no response received to oplock break request to pid 1661
on port 34146 for dev = 23c7533, inode = 25679
for dev = 23c7533, inode = 25679, tv_sec = 38205ea8, tv_usec = d3fc9
[1999/11/03 16:25:44, 0] ../smbd/oplock.c:request_oplock_break(996)
request_oplock_break: no response received to oplock break request to pid 1661
on port 34146 for dev = 23c7533, inode = 25064
for dev = 23c7533, inode = 25064, tv_sec = 38205ea8, tv_usec = 428b8
[1999/11/03 16:25:55, 1] ../smbd/service.c:make_connection(499) <--- #5
ucspc5611 (193.60.179.119) connect to service dju8cl as user dju8cl (uid=13962
, gid=3651) (pid 3170)
[1999/11/03 16:26:13, 0] ../smbd/oplock.c:request_oplock_break(996)
request_oplock_break: no response received to oplock break request to pid 1661
on port 34146 for dev = 23c7533, inode = 25679
for dev = 23c7533, inode = 25679, tv_sec = 38205ea8, tv_usec = d3fc9
[1999/11/03 16:26:16, 0] ../smbd/oplock.c:request_oplock_break(996)
request_oplock_break: no response received to oplock break request to pid 1661
on port 34146 for dev = 23c7533, inode = 25064
for dev = 23c7533, inode = 25064, tv_sec = 38205ea8, tv_usec = 428b8
[1999/11/03 16:26:27, 0] ../smbd/oplock.c:request_oplock_break(996)
request_oplock_break: no response received to oplock break request to pid 1661
on port 34146 for dev = 23c7533, inode = 25562
for dev = 23c7533, inode = 25562, tv_sec = 38205ea8, tv_usec = 46be5
[1999/11/03 16:26:45, 0] ../smbd/oplock.c:request_oplock_break(996)
request_oplock_break: no response received to oplock break request to pid 1661
on port 34146 for dev = 23c7533, inode = 25679
for dev = 23c7533, inode = 25679, tv_sec = 38205ea8, tv_usec = d3fc9
[1999/11/03 16:26:48, 0] ../smbd/oplock.c:request_oplock_break(996)
request_oplock_break: no response received to oplock break request to pid 1661
on port 34146 for dev = 23c7533, inode = 25064
for dev = 23c7533, inode = 25064, tv_sec = 38205ea8, tv_usec = 428b8
[1999/11/03 16:26:59, 0] ../smbd/oplock.c:request_oplock_break(996)
request_oplock_break: no response received to oplock break request to pid 1661
on port 34146 for dev = 23c7533, inode = 25562
for dev = 23c7533, inode = 25562, tv_sec = 38205ea8, tv_usec = 46be5
[1999/11/03 16:27:09, 1] ../smbd/service.c:make_connection(499) <--- #6
ucspc5611 (193.60.179.119) connect to service dju8cl as user dju8cl (uid=13962
, gid=3651) (pid 3200)
[1999/11/03 16:27:11, 0] ../smbd/nttrans.c:call_nt_transact_ioctl(2311)
call_nt_transact_ioctl: Currently not implemented.
[1999/11/03 16:27:16, 1] ../smbd/service.c:close_cnum(525) <--- #7
ucspc5611 (193.60.179.119) closed connection to service dju8cl
[1999/11/03 16:27:17, 0] ../smbd/oplock.c:request_oplock_break(996)
request_oplock_break: no response received to oplock break request to pid 1661
on port 34146 for dev = 23c7533, inode = 25679
for dev = 23c7533, inode = 25679, tv_sec = 38205ea8, tv_usec = d3fc9
[1999/11/03 16:27:20, 0] ../smbd/oplock.c:request_oplock_break(996)
request_oplock_break: no response received to oplock break request to pid 1661
on port 34146 for dev = 23c7533, inode = 25064
--------------------- log.ucspc5611 --------------------------------------------
[1999/11/03 17:18:20, 1] ../smbd/service.c:make_connection(499)
ucspc5611 (193.60.179.119) connect to service dju8vd as user dju8vd (uid=13946
, gid=3651) (pid 5880)
[1999/11/03 18:07:22, 1] ../smbd/service.c:close_cnum(525)
ucspc5611 (193.60.179.119) closed connection to service dju8vd
[1999/11/03 18:11:59, 1] ../smbd/service.c:close_cnum(525)
ucspc5611 (0.0.0.0) closed connection to service dju8cl <--- #8
[1999/11/03 18:11:59, 1] ../smbd/service.c:close_cnum(525)
[1999/11/03 18:11:59, 0] ../smbd/oplock.c:process_local_message(487)
process_local_message: Received unsolicited break reply - dumping info.
[1999/11/03 18:11:59, 0] ../smbd/oplock.c:process_local_message(512)
More information about the samba-technical
mailing list