Hello!
Recently I moved some file shares from old server to new one with CentOS
5.2 and samba 3.0.32.
And yesterday we found that antivirus (nod32 ) installed on users
computers do strange thing-
it's often locks and locks files.
Here is part of log with debug level = 10
[2008/11/19 11:32:28, 3]
smbd/process.c:switch_message(927)
switch message SMBreadX (pid 10725) conn
0x2ab8106d5710
[2008/11/19 11:32:28, 4]
smbd/uid.c:change_to_user(183)
change_to_user: Skipping user change - already
user
[2008/11/19 11:32:28, 10]
locking/brlock.c:brl_get_locks_internal(1648)
brl_get_locks_internal: 0 current locks on dev=64783,
inode=612495337
[2008/11/19 11:32:28, 10]
locking/posix.c:is_posix_locked(285)
is_posix_locked: File ????????????? ??? ???/??????????/????????
???????-2005?/Podschet_Sosn_ispr_2005/??? I. ?????1 ?????.
?????.????/??????? ? ??.1,2,3,4
,10/ris.2.1.Tekt.wmf, offset = 330004, count = 24, type READ
[2008/11/19 11:32:28, 10]
locking/posix.c:posix_lock_in_range(173)
posix_lock_in_range: offset_out = 330004, count_out 24
[2008/11/19 11:32:28, 8]
locking/posix.c:posix_fcntl_getlock(235)
posix_fcntl_getlock 28 330004 24
0
[2008/11/19 11:32:28, 8]
lib/util.c:fcntl_getlock(2029)
fcntl_getlock fd=28 offset=330004 count=24
type=0
[2008/11/19 11:32:28, 3]
lib/util.c:fcntl_getlock(2053)
fcntl_getlock: fd 28 is returned info 2 pid
0
[2008/11/19 11:32:28, 8]
locking/posix.c:posix_fcntl_getlock(265)
posix_fcntl_getlock: Lock query call
successful
[2008/11/19 11:32:28, 10]
locking/brlock.c:brl_locktest(1133)
brl_locktest: posix start=330004 len=24 unlocked for fnum 5756 file
????????????? ??? ???/??????????/????????
???????-2005?/Podschet_Sosn_ispr_2005/??? I.
?????1 ?????. ?????.????/??????? ?
??.1,2,3,4,10/ris.2.1.Tekt.wmf
[2008/11/19 11:32:28, 10]
locking/locking.c:is_locked(137)
is_locked: flavour = WINDOWS_LOCK brl start=330004 len=24 unlocked for
fnum 5756 file ????????????? ??? ???/??????????/????????
???????-2005?/Podschet_Sos
n_ispr_2005/??? I. ?????1 ?????. ?????.????/??????? ?
??.1,2,3,4,10/ris.2.1.Tekt.wmf
[2008/11/19 11:32:28, 10]
smbd/fileio.c:read_file(105)
read_file (????????????? ??? ???/??????????/????????
???????-2005?/Podschet_Sosn_ispr_2005/??? I. ?????1 ?????.
?????.????/??????? ? ??.1,2,3,4,10/ris.2.1
.Tekt.wmf): pos = 330004, size = 24, returned
24
[2008/11/19 11:32:28, 3]
smbd/reply.c:send_file_readX(2641)
send_file_readX fnum=5756 max=24
nread=24
[2008/11/19 11:32:28, 5]
lib/util.c:show_msg(484)
[2008/11/19 11:32:28, 5]
lib/util.c:show_msg(494)
size=83
smb_com=0x2e
smb_rcls=0
smb_reh=0
smb_err=0
smb_flg=136
smb_flg2=51201
smb_tid=3
smb_pid=65279
smb_uid=101
smb_mid=46405
smt_wct=12
smb_vwv[ 0]= 255
(0xFF)
smb_vwv[ 1]= 0
(0x0)
smb_vwv[ 2]=65535
(0xFFFF)
smb_vwv[ 3]= 0
(0x0)
smb_vwv[ 4]= 0
(0x0)
smb_vwv[ 5]= 24 (0x18)
smb_vwv[ 6]= 59
(0x3B)
smb_vwv[ 7]= 0
(0x0)
smb_vwv[ 8]= 0
(0x0)
smb_vwv[ 9]= 0
(0x0)
smb_vwv[10]= 0
(0x0)
smb_vwv[11]= 0
(0x0)
smb_bcc=24
[2008/11/19 11:32:28, 10]
lib/util.c:dump_data(2264)
[000] 04 00 00 00 2D 01 0D 00 04 00 00 00 04 01 0D 00 ....-...
........
[010] 04 00 00 00 02 01 01 00
........
[2008/11/19 11:32:28, 10]
lib/util_sock.c:read_smb_length_return_keepalive(623)
got smb length of
59
[2008/11/19 11:32:28, 6]
smbd/process.c:process_smb(1068)
got message type 0x0 of len
0x3b
[2008/11/19 11:32:28, 3]
smbd/process.c:process_smb(1069)
Transaction 66271 of length
63
[2008/11/19 11:32:28, 5]
lib/util.c:show_msg(484)
[2008/11/19 11:32:28, 5]
lib/util.c:show_msg(494)
size=59
smb_com=0x2e
smb_rcls=0
smb_reh=0
smb_err=0
smb_flg=24
smb_flg2=51207
smb_tid=3
smb_pid=65279
smb_uid=101
smb_mid=46466
smt_wct=12
smb_vwv[ 0]= 255
(0xFF)
smb_vwv[ 1]=57054
(0xDEDE)
smb_vwv[ 2]= 5874
(0x16F2)
smb_vwv[ 3]= 4496
(0x1190)
smb_vwv[ 4]= 4
(0x4)
smb_vwv[ 5]= 24
(0x18)
smb_vwv[ 6]= 24
(0x18)
smb_vwv[ 7]= 0
(0x0)
smb_vwv[ 8]= 0
(0x0)
smb_vwv[ 9]= 24
(0x18)
smb_vwv[10]= 0
(0x0)
smb_vwv[11]= 0
(0x0)
smb_bcc=0
[2008/11/19 11:32:28, 3]
smbd/process.c:switch_message(927)
switch message SMBreadX (pid 10725) conn
0x2ab8106d5710
[2008/11/19 11:32:28, 4]
smbd/uid.c:change_to_user(183)
change_to_user: Skipping user change - already
user
[2008/11/19 11:32:28, 10]
locking/brlock.c:brl_get_locks_internal(1648)
brl_get_locks_internal: 0 current locks on dev=64783,
inode=617894338
[2008/11/19 11:32:28, 10]
locking/posix.c:is_posix_locked(285)
is_posix_locked: File ????????????? ??? ???/??????????/????????
???????-2005?/Podschet_Sosn_ispr_2005/??? I. ?????1 ?????.
?????.????/??????? ? ??.1,2,3,4
[2008/11/19 11:32:28, 10]
locking/posix.c:posix_lock_in_range(173)
posix_lock_in_range: offset_out = 266640, count_out 24
[2008/11/19 11:32:28, 8]
locking/posix.c:posix_fcntl_getlock(235)
posix_fcntl_getlock 29 266640 24
0
[2008/11/19 11:32:28, 8]
lib/util.c:fcntl_getlock(2029)
fcntl_getlock fd=29 offset=266640 count=24
type=0
[2008/11/19 11:32:28, 3]
lib/util.c:fcntl_getlock(2053)
fcntl_getlock: fd 29 is returned info 2 pid
0
[2008/11/19 11:32:28, 8]
locking/posix.c:posix_fcntl_getlock(265)
posix_fcntl_getlock: Lock query call
successful
[2008/11/19 11:32:28, 10]
locking/brlock.c:brl_locktest(1133)
brl_locktest: posix start=266640 len=24 unlocked for fnum 5874 file
????????????? ??? ???/??????????/????????
???????-2005?/Podschet_Sosn_ispr_2005/??? I.
?????1 ?????. ?????.????/??????? ?
??.1,2,3,4,10/ris.1.1Obz
[2008/11/19 11:32:28, 10]
locking/locking.c:is_locked(137)
is_locked: flavour = WINDOWS_LOCK brl start=266640 len=24 unlocked for
fnum 5874 file ????????????? ??? ???/??????????/????????
???????-2005?/Podschet_Sos
n_ispr_2005/??? I. ?????1 ?????. ?????.????/??????? ?
??.1,2,3,4,10/ris.1.1Obz
[2008/11/19 11:32:28, 10]
smbd/fileio.c:read_file(105)
read_file (????????????? ??? ???/??????????/????????
???????-2005?/Podschet_Sosn_ispr_2005/??? I. ?????1 ?????.
?????.????/??????? ? ??.1,2,3,4,10/ris.1.1
Obz): pos = 266640, size = 24, returned
24
[2008/11/19 11:32:28, 3]
smbd/reply.c:send_file_readX(2641)
send_file_readX fnum=5874 max=24
nread=24
[2008/11/19 11:32:28, 5]
lib/util.c:show_msg(484)
[2008/11/19 11:32:28, 5]
lib/util.c:show_msg(494)
size=83
smb_com=0x2e
smb_rcls=0
smb_reh=0
smb_err=0
smb_flg=136
smb_flg2=51201
smb_tid=3
smb_pid=65279
smb_uid=101
smb_mid=46466
smt_wct=12
smb_vwv[ 0]= 255
(0xFF)
smb_vwv[ 1]= 0
(0x0)
smb_vwv[ 2]=65535
(0xFFFF)
smb_vwv[ 3]= 0
(0x0)
smb_vwv[ 4]= 0
(0x0)
smb_vwv[ 5]= 24
(0x18)
smb_vwv[ 6]= 59
(0x3B)
smb_vwv[ 7]= 0
(0x0)
smb_vwv[ 8]= 0
(0x0)
smb_vwv[ 9]= 0
(0x0)
smb_vwv[10]= 0
(0x0)
smb_vwv[11]= 0
(0x0)
smb_bcc=24
[2008/11/19 11:32:28, 10]
lib/util.c:dump_data(2264)
[000] 04 00 00 00 04 01 0D 00 04 00 00 00 02 01 01 00 ........
........
[010] 05 00 00 00 13 02 FA 25
.......%
so opening files becomes very slow process.
I turned off kernel oplocks and all becomes OK.
Strange thing is that there was no such problem in on old SLES9 server
with samba 3.0.30 and on our RHEL server with samba 3.0.28 (and with
the same kernel version as CentOS).
Could you tell me- how do you think is it samba or kernel problem?
Thank you!
