[Samba] incoherent oplock request/reply

[Pierre Dinh-van]

Hello,

I'm running a samba 3.0.14a server in production on a fedora core 3 (kernel 
2.6.9-1.667smp) with a least 250 clients (XP Pro SP2) (up to 400 sometimes).


A few days ago, a problem appeared with a soft that we are using for a long 
time. (Petit Robert, a french dictionnary).

When someone launch the dictionnary, many clients are freezed when they try to 
access to the "start menu" (a part of the windows XP menus are stored on the 
samba server)

In the logs, we found :

Broken leases in the /var/log/messages :

Jul 29 09:44:06 Karma kernel: lease broken - owner pid = 14556
Jul 29 09:44:28 Karma kernel: lease broken - owner pid = 14556
Jul 29 09:46:47 Karma kernel: lease broken - owner pid = 14138
Jul 29 09:47:25 Karma kernel: lease broken - owner pid = 14138
Jul 29 09:47:25 Karma kernel: lease broken - owner pid = 14138
Jul 29 09:48:07 Karma kernel: lease broken - owner pid = 14795
Jul 29 09:48:42 Karma kernel: lease broken - owner pid = 15014
[...]

If we look at the first incriminated pid (14556), it's a samba process 
accessing to the dictionnary.

While looking in the samba logs, we can find various clients blocked by this 
pid :

For one workstation it says :
----------------------------------

[2005/07/29 09:43:43, 0] smbd/oplock.c:request_oplock_break(1054)
  request_oplock_break: no response received to oplock break request to pid 
14556 on port 59668 for dev = 6911, inode = 680216880, file_id = 3491
[2005/07/29 09:43:43, 0] smbd/open.c:open_mode_check(743)
  open_mode_check: exlusive oplock left by process 14556 after break ! For 
file PC-BIB/PC_BIB.EXE, dev = 6911, inode = 680216880. Deleting it to 
continue...
[2005/07/29 09:43:43, 0] smbd/open.c:open_mode_check(747)
  open_mode_check: Existent process 14556 left active oplock.
[2005/07/29 09:44:28, 0] smbd/oplock.c:process_local_message(420)
  process_local_message: Received unsolicited break reply - dumping info.
[2005/07/29 09:44:28, 0] smbd/oplock.c:process_local_message(435)
  process_local_message: unsolicited oplock break reply from pid 14748, port 
59668, dev = 6911, inode = 680216880, file_id = 3491

For another one, it says :
------------------------------

[2005/07/29 09:43:21, 0] smbd/oplock.c:request_oplock_break(1054)
  request_oplock_break: no response received to oplock break request to pid 
14556 on port 59668 for dev = 6811, inode = 2801670, file_id = 3503
[2005/07/29 09:43:21, 0] smbd/open.c:open_mode_check(743)
  open_mode_check: exlusive oplock left by process 14556 after break ! For 
file Bureautique/WROBERT/CITATION.EXE, dev = 6811, inode = 2801670. Deleting 
it to continue...
[...]
[2005/07/29 09:44:28, 0] smbd/oplock.c:process_local_message(420)
  process_local_message: Received unsolicited break reply - dumping info.
[2005/07/29 09:44:28, 0] smbd/oplock.c:process_local_message(435)
  process_local_message: unsolicited oplock break reply from pid 14978, port 
59668, dev = 6811, inode = 2801670, file_id = 3503

The process 14556 is owned by a third user :
-----------------------------------------------------

[2005/07/29 09:08:17, 1] smbd/service.c:make_connection_snum(642)
  uc003135 (172.25.11.111) connect to service netlogon initially as user root 
(uid=0, gid=100) (pid 14556)
[2005/07/29 09:08:32, 1] smbd/service.c:make_connection_snum(642)
  uc003135 (172.25.11.111) connect to service m-tchagaspanian initially as 
user m-tchagaspanian (uid=553, gid=100) (pid 14556)
[...]
[2005/07/29 09:42:37, 0] smbd/oplock.c:request_oplock_break(1054)
  request_oplock_break: no response received to oplock break request to pid 
14402 on port 57594 for dev = 6911, inode = 201422791, file_id = 5454
[2005/07/29 09:42:37, 0] smbd/open.c:open_mode_check(743)
  open_mode_check: exlusive oplock left by process 14402 after break ! For 
file CDlepetitRobert/PR1Data/PR1.LCK, dev = 6911, inode = 201422791. Deleting 
it to continue...
[2005/07/29 09:42:37, 0] smbd/open.c:open_mode_check(747)
  open_mode_check: Existent process 14402 left active oplock.
[2005/07/29 09:44:06, 0] smbd/oplock.c:oplock_break(874)
  oplock_break: no break received from client within 30 seconds.
  oplock_break failed for file (null) (dev = 6811, inode = 2801670, file_id = 
3503).
[2005/07/29 09:44:28, 0] smbd/oplock.c:process_local_message(420)
  process_local_message: Received unsolicited break reply - dumping info.
[2005/07/29 09:44:28, 0] smbd/oplock.c:process_local_message(435)
  process_local_message: unsolicited oplock break reply from pid 14556, port 
57594, dev = 6911, inode = 201422791, file_id = 5454



The last 2 messages are strange... Doesn't it looks like a bug ? (such 
messages are appearing in my various tests)


Any ideas to solve this problem ?


Thanks in advance



Pierre Dinh-van


PS : sorry for my bad english