[Samba] Re: Re: Change time causes profile corruption

Danny Paul jdpaul at gocolumbiamo.com
Thu Jul 14 19:29:20 GMT 2005


> Could you send me a level 10 debug from smbd of the
> file with a 0 mtime getting created ?  I've got a
> feeling something else is going on here.

Well, not exactly.  The production server serves several users as minute so
a level 10 log would produce so much output it would be unusable.

Here's what I have.  I upped the log level on an internal only server and
booted everyone off - then uploaded the file.  This should be the same,
right?

I've attached the log from that operation.  If this is not sufficient, I can
try to replicate it in my test domain environment, but it's tied up right
now.  I might also try to come in on a weekend when the use would be low
and the output not so high.

Thanks for the help,
Danny
-------------- next part --------------
[2005/07/14 14:16:40, 5] smbd/uid.c:change_to_root_user(296)
  change_to_root_user: now uid=(0,0) gid=(0,0)
[2005/07/14 14:16:40, 3] smbd/error.c:error_packet(129)
  error packet at smbd/notify.c(55) cmd=160 (SMBnttrans) NT_STATUS_CANCELLED
[2005/07/14 14:16:40, 6] lib/util_sock.c:write_socket(449)
  write_socket(22,75)
[2005/07/14 14:16:40, 6] lib/util_sock.c:write_socket(452)
  write_socket(22,75) wrote 75
[2005/07/14 14:16:40, 3] smbd/notify_kernel.c:kernel_remove_notify(144)
  kernel_remove_notify: fd=28
[2005/07/14 14:16:40, 3] smbd/nttrans.c:reply_ntcancel(1523)
  reply_ntcancel: cancel called on mid = 3971.
[2005/07/14 14:16:40, 10] lib/util_sock.c:read_smb_length_return_keepalive(505)
  got smb length of 41
[2005/07/14 14:16:40, 6] smbd/process.c:process_smb(1091)
  got message type 0x0 of len 0x29
[2005/07/14 14:16:40, 3] smbd/process.c:process_smb(1092)
  Transaction 92 of length 45
[2005/07/14 14:16:40, 5] lib/util.c:show_msg(461)
[2005/07/14 14:16:40, 5] lib/util.c:show_msg(471)
  size=41
  smb_com=0x4
  smb_rcls=0
  smb_reh=0
  smb_err=0
  smb_flg=24
  smb_flg2=51207
  smb_tid=2
  smb_pid=65279
  smb_uid=101
  smb_mid=5763
  smt_wct=3
  smb_vwv[ 0]= 7116 (0x1BCC)
  smb_vwv[ 1]=65535 (0xFFFF)
  smb_vwv[ 2]=65535 (0xFFFF)
  smb_bcc=0
[2005/07/14 14:16:40, 3] smbd/process.c:switch_message(887)
  switch message SMBclose (pid 29010) conn 0x82d7bf0
[2005/07/14 14:16:40, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (1091, 513) - sec_ctx_stack_ndx = 0
[2005/07/14 14:16:40, 5] auth/auth_util.c:debug_nt_user_token(491)
  NT user token of user S-1-5-21-175737297-2311997533-1601259624-3182
  contains 9 SIDs
  SID[  0]: S-1-5-21-175737297-2311997533-1601259624-3182
  SID[  1]: S-1-5-21-175737297-2311997533-1601259624-513
  SID[  2]: S-1-1-0
  SID[  3]: S-1-5-2
  SID[  4]: S-1-5-11
  SID[  5]: S-1-5-21-175737297-2311997533-1601259624-1029
  SID[  6]: S-1-5-21-175737297-2311997533-1601259624-1033
  SID[  7]: S-1-5-21-175737297-2311997533-1601259624-1035
  SID[  8]: S-1-5-21-175737297-2311997533-1601259624-1067
[2005/07/14 14:16:40, 5] auth/auth_util.c:debug_unix_user_token(505)
  UNIX token of user 1091
  Primary group is 513 and contains 5 supplementary groups
  Group[  0]: 14
  Group[  1]: 16
  Group[  2]: 17
  Group[  3]: 33
  Group[  4]: 513
[2005/07/14 14:16:40, 5] smbd/uid.c:change_to_user(281)
  change_to_user uid=(1091,1091) gid=(0,513)
[2005/07/14 14:16:40, 3] smbd/reply.c:reply_close(2758)
  close directory fnum=7116
[2005/07/14 14:16:40, 5] smbd/files.c:file_free(385)
  freed files structure 7116 (2 used)
[2005/07/14 14:16:40, 5] lib/util.c:show_msg(461)
[2005/07/14 14:16:40, 5] lib/util.c:show_msg(471)
  size=35
  smb_com=0x4
  smb_rcls=0
  smb_reh=0
  smb_err=0
  smb_flg=136
  smb_flg2=51201
  smb_tid=2
  smb_pid=65279
  smb_uid=101
  smb_mid=5763
  smt_wct=0
  smb_bcc=0
[2005/07/14 14:16:40, 6] lib/util_sock.c:write_socket(449)
  write_socket(22,39)
[2005/07/14 14:16:40, 6] lib/util_sock.c:write_socket(452)
  write_socket(22,39) wrote 39
[2005/07/14 14:16:40, 10] lib/util_sock.c:read_smb_length_return_keepalive(505)
  got smb length of 36
[2005/07/14 14:16:40, 6] smbd/process.c:process_smb(1091)
  got message type 0x0 of len 0x24
[2005/07/14 14:16:40, 3] smbd/process.c:process_smb(1092)
  Transaction 93 of length 40
[2005/07/14 14:16:40, 5] lib/util.c:show_msg(461)
[2005/07/14 14:16:40, 5] lib/util.c:show_msg(471)
  size=36
  smb_com=0xa4
  smb_rcls=0
  smb_reh=0
  smb_err=0
  smb_flg=24
  smb_flg2=51207
  smb_tid=2
  smb_pid=888
  smb_uid=101
  smb_mid=4032
  smt_wct=0
  smb_bcc=0
[2005/07/14 14:16:40, 3] smbd/process.c:switch_message(887)
  switch message SMBntcancel (pid 29010) conn 0x82d7bf0
[2005/07/14 14:16:40, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2005/07/14 14:16:40, 5] auth/auth_util.c:debug_nt_user_token(486)
  NT user token: (NULL)
[2005/07/14 14:16:40, 5] auth/auth_util.c:debug_unix_user_token(505)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2005/07/14 14:16:40, 5] smbd/uid.c:change_to_root_user(296)
  change_to_root_user: now uid=(0,0) gid=(0,0)
[2005/07/14 14:16:40, 3] smbd/error.c:error_packet(129)
  error packet at smbd/notify.c(55) cmd=160 (SMBnttrans) NT_STATUS_CANCELLED
[2005/07/14 14:16:40, 6] lib/util_sock.c:write_socket(449)
  write_socket(22,75)
[2005/07/14 14:16:40, 6] lib/util_sock.c:write_socket(452)
  write_socket(22,75) wrote 75
[2005/07/14 14:16:40, 3] smbd/notify_kernel.c:kernel_remove_notify(144)
  kernel_remove_notify: fd=29
[2005/07/14 14:16:40, 3] smbd/nttrans.c:reply_ntcancel(1523)
  reply_ntcancel: cancel called on mid = 4032.
[2005/07/14 14:16:40, 10] lib/util_sock.c:read_smb_length_return_keepalive(505)
  got smb length of 41
[2005/07/14 14:16:40, 6] smbd/process.c:process_smb(1091)
  got message type 0x0 of len 0x29
[2005/07/14 14:16:40, 3] smbd/process.c:process_smb(1092)
  Transaction 94 of length 45
[2005/07/14 14:16:40, 5] lib/util.c:show_msg(461)
[2005/07/14 14:16:40, 5] lib/util.c:show_msg(471)
  size=41
  smb_com=0x4
  smb_rcls=0
  smb_reh=0
  smb_err=0
  smb_flg=24
  smb_flg2=51207
  smb_tid=2
  smb_pid=65279
  smb_uid=101
  smb_mid=5824
  smt_wct=3
  smb_vwv[ 0]= 7115 (0x1BCB)
  smb_vwv[ 1]=65535 (0xFFFF)
  smb_vwv[ 2]=65535 (0xFFFF)
  smb_bcc=0
[2005/07/14 14:16:40, 3] smbd/process.c:switch_message(887)
  switch message SMBclose (pid 29010) conn 0x82d7bf0
[2005/07/14 14:16:40, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (1091, 513) - sec_ctx_stack_ndx = 0
[2005/07/14 14:16:40, 5] auth/auth_util.c:debug_nt_user_token(491)
  NT user token of user S-1-5-21-175737297-2311997533-1601259624-3182
  contains 9 SIDs
  SID[  0]: S-1-5-21-175737297-2311997533-1601259624-3182
  SID[  1]: S-1-5-21-175737297-2311997533-1601259624-513
  SID[  2]: S-1-1-0
  SID[  3]: S-1-5-2
  SID[  4]: S-1-5-11
  SID[  5]: S-1-5-21-175737297-2311997533-1601259624-1029
  SID[  6]: S-1-5-21-175737297-2311997533-1601259624-1033
  SID[  7]: S-1-5-21-175737297-2311997533-1601259624-1035
  SID[  8]: S-1-5-21-175737297-2311997533-1601259624-1067
[2005/07/14 14:16:40, 5] auth/auth_util.c:debug_unix_user_token(505)
  UNIX token of user 1091
  Primary group is 513 and contains 5 supplementary groups
  Group[  0]: 14
  Group[  1]: 16
  Group[  2]: 17
  Group[  3]: 33
  Group[  4]: 513
[2005/07/14 14:16:40, 5] smbd/uid.c:change_to_user(281)
  change_to_user uid=(1091,1091) gid=(0,513)
[2005/07/14 14:16:40, 3] smbd/reply.c:reply_close(2758)
  close directory fnum=7115
[2005/07/14 14:16:40, 5] smbd/files.c:file_free(385)
  freed files structure 7115 (1 used)
[2005/07/14 14:16:40, 5] lib/util.c:show_msg(461)
[2005/07/14 14:16:40, 5] lib/util.c:show_msg(471)
  size=35
  smb_com=0x4
  smb_rcls=0
  smb_reh=0
  smb_err=0
  smb_flg=136
  smb_flg2=51201
  smb_tid=2
  smb_pid=65279
  smb_uid=101
  smb_mid=5824
  smt_wct=0
  smb_bcc=0
[2005/07/14 14:16:40, 6] lib/util_sock.c:write_socket(449)
  write_socket(22,39)
[2005/07/14 14:16:40, 6] lib/util_sock.c:write_socket(452)
  write_socket(22,39) wrote 39
[2005/07/14 14:16:46, 3] smbd/sec_ctx.c:set_sec_ctx(288)
[2005/07/14 14:16:46, 10] smbd/process.c:async_processing(282)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
  async_processing: Doing async processing.
[2005/07/14 14:16:46, 5] auth/auth_util.c:debug_nt_user_token(486)
[2005/07/14 14:16:46, 5] smbd/oplock.c:receive_local_message(107)
  NT user token: (NULL)
  receive_local_message: doing select with timeout of 1 ms
[2005/07/14 14:16:46, 5] auth/auth_util.c:debug_unix_user_token(505)
[2005/07/14 14:16:46, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  UNIX token of user 0
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
  Primary group is 0 and contains 0 supplementary groups
[2005/07/14 14:16:46, 5] auth/auth_util.c:debug_nt_user_token(486)
  NT user token: (NULL)
[2005/07/14 14:16:46, 5] auth/auth_util.c:debug_unix_user_token(505)
  UNIX token of user 0
[2005/07/14 14:16:46, 5] smbd/uid.c:change_to_root_user(296)
  Primary group is 0 and contains 0 supplementary groups
  change_to_root_user: now uid=(0,0) gid=(0,0)
[2005/07/14 14:16:46, 5] smbd/uid.c:change_to_root_user(296)
[2005/07/14 14:16:46, 2] smbd/server.c:exit_server(571)
  change_to_root_user: now uid=(0,0) gid=(0,0)
  Closing connections
[2005/07/14 14:16:46, 2] smbd/server.c:exit_server(571)
  Closing connections
[2005/07/14 14:16:46, 4] smbd/vfs.c:vfs_ChDir(654)
[2005/07/14 14:16:46, 3] smbd/connection.c:yield_connection(69)
  vfs_ChDir to /tmp
  Yielding connection to 
[2005/07/14 14:16:46, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2005/07/14 14:16:46, 5] auth/auth_util.c:debug_nt_user_token(486)
[2005/07/14 14:16:46, 5] smbd/oplock.c:receive_local_message(107)
  NT user token: (NULL)
  receive_local_message: doing select with timeout of 1 ms
[2005/07/14 14:16:46, 5] auth/auth_util.c:debug_unix_user_token(505)
  UNIX token of user 0
[2005/07/14 14:16:46, 3] smbd/server.c:exit_server(614)
  Primary group is 0 and contains 0 supplementary groups
[2005/07/14 14:16:46, 5] smbd/uid.c:change_to_root_user(296)
  change_to_root_user: now uid=(0,0) gid=(0,0)
[2005/07/14 14:16:46, 3] smbd/service.c:close_cnum(836)
  isdb00684xp (192.168.1.209) closed connection to service IPC$
[2005/07/14 14:16:46, 3] smbd/connection.c:yield_connection(69)
  Yielding connection to IPC$
  Server exit (Caught TERM signal)
[2005/07/14 14:16:46, 4] smbd/vfs.c:vfs_ChDir(654)
  vfs_ChDir to /
[2005/07/14 14:16:46, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2005/07/14 14:16:46, 5] auth/auth_util.c:debug_nt_user_token(486)
  NT user token: (NULL)
[2005/07/14 14:16:46, 5] auth/auth_util.c:debug_unix_user_token(505)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2005/07/14 14:16:46, 5] smbd/uid.c:change_to_root_user(296)
  change_to_root_user: now uid=(0,0) gid=(0,0)
[2005/07/14 14:16:46, 4] smbd/vfs.c:vfs_ChDir(654)
  vfs_ChDir to /data/genvol
[2005/07/14 14:16:46, 10] locking/locking.c:del_share_entry(597)
  del_share_entry: num_share_modes = 1
[2005/07/14 14:16:46, 10] locking/locking.c:del_share_entry(602)
  del_share_entry: deleted share_mode_entry[0]: pid = 29010, share_mode = 0x8020, desired_access = 0x20089, port = 0x8034, type= 0x3, file_id = 11, dev = 0x6804, inode = 2697145
[2005/07/14 14:16:46, 10] locking/locking.c:del_share_entry(612)
  del_share_entry: deleting entry 0
[2005/07/14 14:16:46, 10] locking/locking.c:del_share_entry(634)
  del_share_entry: Remaining table.
[2005/07/14 14:16:46, 10] smbd/close.c:close_normal_file(201)
  close_normal_file: share_entry_count = 0 for file CE6-15-05.pdf
[2005/07/14 14:16:46, 10] smbd/oplock_linux.c:linux_release_kernel_oplock(196)
  linux_release_kernel_oplock: file CE6-15-05.pdf, dev = 6804, inode = 2697145 file_id = 11 has kernel oplock state of 1.
[2005/07/14 14:16:46, 10] locking/posix.c:posix_locking_close_file(1241)
  posix_locking_close_file: file CE6-15-05.pdf has no outstanding locks.
[2005/07/14 14:16:46, 2] smbd/close.c:close_normal_file(270)
  helpdesk closed file CE6-15-05.pdf (numopen=0) 
[2005/07/14 14:16:46, 5] smbd/files.c:file_free(385)
  freed files structure 7125 (0 used)
[2005/07/14 14:16:46, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2005/07/14 14:16:46, 5] auth/auth_util.c:debug_nt_user_token(486)
  NT user token: (NULL)
[2005/07/14 14:16:46, 5] auth/auth_util.c:debug_unix_user_token(505)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2005/07/14 14:16:46, 5] smbd/uid.c:change_to_root_user(296)
  change_to_root_user: now uid=(0,0) gid=(0,0)
[2005/07/14 14:16:46, 1] smbd/service.c:close_cnum(836)
  isdb00684xp (192.168.1.209) closed connection to service genvol
[2005/07/14 14:16:46, 3] smbd/connection.c:yield_connection(69)
  Yielding connection to genvol
[2005/07/14 14:16:46, 4] smbd/vfs.c:vfs_ChDir(654)
  vfs_ChDir to /
[2005/07/14 14:16:46, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2005/07/14 14:16:46, 5] auth/auth_util.c:debug_nt_user_token(486)
  NT user token: (NULL)
[2005/07/14 14:16:46, 5] auth/auth_util.c:debug_unix_user_token(505)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2005/07/14 14:16:46, 5] smbd/uid.c:change_to_root_user(296)
  change_to_root_user: now uid=(0,0) gid=(0,0)
[2005/07/14 14:16:46, 5] auth/auth_util.c:free_server_info(1344)
  attempting to free (and zero) a server_info structure
[2005/07/14 14:16:46, 5] auth/auth_util.c:free_server_info(1344)
  attempting to free (and zero) a server_info structure
[2005/07/14 14:16:46, 3] smbd/connection.c:yield_connection(69)
  Yielding connection to 
[2005/07/14 14:16:46, 5] smbd/oplock.c:receive_local_message(107)
  receive_local_message: doing select with timeout of 1 ms
[2005/07/14 14:16:46, 3] smbd/server.c:exit_server(614)
  Server exit (Caught TERM signal)


More information about the samba mailing list