Setup is 2 Windows machines connected to a RHEL5 linux server sunning smbd 3.5.4. One Windows machine listen for events on a top directory. The second windows machine create a new file in a subdirectory (top->sub1->sub2->file) and we do get a notification on the first machine. Then we modify the content of the file and do a write -> no notification received on the first machine. If we do the same operations in the top directory, we do get the 2 notifications. But I believe this is because it was generated by the linux kernel via inotify. What we see in the debug log is : [2012/04/26 11:55:15.706407, 10] smbd/notify_internal.c:890(notify_trigger) notify_trigger called action=0x3, filter=0x0, path=/mnt/hires/TestNotifGDF/Directory1/gdf/test55.txt The top directory is "TestNotifGDF". See the filter is 0x0. I have modified the file smbd/trans2.c and in the function NTSTATUS smb_set_file_time(connection_struct *conn, files_struct *fsp, const struct smb_filename *smb_fname, struct smb_file_time *ft, bool setting_write_time) I removed the lines : if (!setting_write_time) { /* ft->mtime comes from change time, not write time. */ action &= ~FILE_NOTIFY_CHANGE_LAST_WRITE; } This fixed my problem. Could somebody review this and let me know if this is expected. Thanks. Gilles.
Can you send network traces and debug level 10 logs? With those it would be easier to extend the existing notify torture test. I'll try to do it from your description, but traces make it much easier. Thanks, Volker
Created attachment 7505 [details] debug log
Created attachment 7506 [details] wireshark capture
Created attachment 7507 [details] debug log
Find in attachment the debug log (level 10) captured on the server. I have added a few more debug messages to the code to show where we clear the filter flags until it gets to 0x0 which prevents the advertisement of the notification (Sorry, the file was added 2 times) The 2nd file is the trace captured on the windows machine where I performed the modification of the file test55.txt [2012/04/27 10:03:03.584523, 10] smbd/trans2.c:5410(smb_set_file_time) Pre Call to notify_fname with filter 112 for file TestNotifGDF/Directory1/gdf/test55.txt [2012/04/27 10:03:03.584534, 10] smbd/trans2.c:5416(smb_set_file_time) step1 to notify_fname with filter 48 for file TestNotifGDF/Directory1/gdf/test55.txt [2012/04/27 10:03:03.584555, 10] smbd/trans2.c:5423(smb_set_file_time) step2 to notify_fname with filter 16 for file TestNotifGDF/Directory1/gdf/test55.txt [2012/04/27 10:03:03.584566, 10] smbd/trans2.c:5439(smb_set_file_time) step4 to notify_fname with filter 0 for file TestNotifGDF/Directory1/gdf/test55.txt [2012/04/27 10:03:03.584577, 5] smbd/trans2.c:5462(smb_set_file_time) smb_set_filetime: actime: Thu Jan 1 01:00:00 1970 smb_set_filetime: modtime: Fri Apr 27 10:03:04 2012 smb_set_filetime: ctime: Thu Jan 1 01:00:00 1970 smb_set_file_time: createtime: Thu Jan 1 01:00:00 1970 smb_set_file_time: setting utimes to modified values. [2012/04/27 10:03:03.584632, 6] smbd/dosmode.c:861(file_ntimes) file_ntime: actime: Thu Jan 1 01:00:00 1970 [2012/04/27 10:03:03.584662, 6] smbd/dosmode.c:863(file_ntimes) file_ntime: modtime: Fri Apr 27 10:03:04 2012 [2012/04/27 10:03:03.584675, 6] smbd/dosmode.c:865(file_ntimes) file_ntime: ctime: Thu Jan 1 01:00:00 1970 [2012/04/27 10:03:03.584688, 6] smbd/dosmode.c:867(file_ntimes) file_ntime: createtime: Thu Jan 1 01:00:00 1970 [2012/04/27 10:03:03.584912, 10] smbd/trans2.c:5512(smb_set_file_time) Calling notify_fname with filter 0 for file TestNotifGDF/Directory1/gdf/test55.txt [2012/04/27 10:03:03.584926, 10] smbd/notify.c:378(notify_fname) notify_fname:378 action: 0x3 filter: 0x0 path: TestNotifGDF/Directory1/gdf/test55.txt [2012/04/27 10:03:03.584960, 10] smbd/notify_internal.c:890(notify_trigger) notify_trigger called action=0x3, filter=0x0, path=/mnt/hires/TestNotifGDF/Directory1/gdf/test55.txt
Unfortunately the debug log seems to contain logs from different processes. Can you set up your server according to https://wiki.samba.org/index.php/Client_specific_Log and re-do the test? Also, I would like to see the network trace piece that sets up the notify record initially. Thanks, Volker
Created attachment 7514 [details] new trace file filtered to show the latest events I have a complete trace from starting the windows machine upto the content of the file being modified. File is too big to be attached. I filtered it to show only the latest events.
Created attachment 7515 [details] log file log file during the problem following the wiki procedure.
Looking at the trace I don't really see how Samba should behave differently. When the write requests come in (frame 154), the notify request has already been canceled (frame 141) and the directory handle has been closed (frame 143). There is no way for Samba to send out notifies in this case. Can you explain your trace and the expected behaviour in a bit more detail please?
Thanks for your patience. Let's try one more time. The design is the following +-------+ +--------+ +--------+ | MS 1 | -------- | Linux | ------- | MS 2 | +-------+ +--------+ +--------+ | DISKS The DISKS are shared by the linux machine. It is called /mnt/hires/ On MS2 I connect through SAMBA to Linux, and start an application that requests notification for directory /TestNotifGDF with recursive flag set to 1. On MS1 I connect through SAMBA to Linux and open the file "TestNotifGDF/Directory1/gdf/gdf1.txt". Once the file is open, I close the explorer window (which result in the notification close messages that you see). I then modify the file and write it - packet #154. MS2 does not get notified of the file modification. From code inspection, I could see as I mentioned before that the trigger filter is NULL because setting_write_time is not set and we do if (!setting_write_time) { /* ft->mtime comes from change time, not write time. */ action &= ~FILE_NOTIFY_CHANGE_LAST_WRITE; } When I remove these lines, I can see the notification going through MS2. If I modify a file which is NOT in a subdirectory, then inotify on the linux machine takes over and send a notification. But inotify is not recursive. So, in the trace you will not see notification. In the log, we just see same sequence where smb_set_file_time() is called with a new modtime but because of the lines of code above, we reset the filter and the trigger fails (filter=0x0) [2012/05/03 15:42:12.908413, 5, pid=12570, effective(500, 500), real(0, 0)] smbd/trans2.c:5438(smb_set_file_time) smb_set_filetime: actime: Thu Jan 1 01:00:00 1970 smb_set_filetime: modtime: Thu May 3 15:42:13 2012 smb_set_filetime: ctime: Thu Jan 1 01:00:00 1970 smb_set_file_time: createtime: Thu Jan 1 01:00:00 1970 smb_set_file_time: setting utimes to modified values. [2012/05/03 15:42:12.908475, 6, pid=12570, effective(500, 500), real(0, 0)] smbd/dosmode.c:861(file_ntimes) file_ntime: actime: Thu Jan 1 01:00:00 1970 [2012/05/03 15:42:12.908505, 6, pid=12570, effective(500, 500), real(0, 0)] smbd/dosmode.c:863(file_ntimes) file_ntime: modtime: Thu May 3 15:42:13 2012 [2012/05/03 15:42:12.908531, 6, pid=12570, effective(500, 500), real(0, 0)] smbd/dosmode.c:865(file_ntimes) file_ntime: ctime: Thu Jan 1 01:00:00 1970 [2012/05/03 15:42:12.908557, 6, pid=12570, effective(500, 500), real(0, 0)] smbd/dosmode.c:867(file_ntimes) file_ntime: createtime: Thu Jan 1 01:00:00 1970 [2012/05/03 15:42:12.908805, 10, pid=12570, effective(500, 500), real(0, 0)] smbd/notify_internal.c:890(notify_trigger) notify_trigger called action=0x3, filter=0x0, path=/mnt/hires/TestNotifGDF/Directory1/gdf/gdf5.txt Could you maybe explain me why we reset the filter when setting_write_time is not set ? Or when should we set it ? I did another test by creating a new file volker1.txt We can see the notification for the file creation. There is 2 successful type 3 notifications for when the file was renamed. But when I change the content of the file you can see the filter ix 0x0 [root@mediasrv04 samba]# cat /tmp/log.172.31.105.122 | grep -E "trigger.*volker" notify_trigger called action=0x5, filter=0x1, path=/mnt/hires/TestNotifGDF/Directory1/gdf/volker1.txt notify_trigger called action=0x3, filter=0x44, path=/mnt/hires/TestNotifGDF/Directory1/gdf/volker1.txt notify_trigger called action=0x3, filter=0xc, path=/mnt/hires/TestNotifGDF/Directory1/gdf/volker1.txt notify_trigger called action=0x3, filter=0x0, path=/mnt/hires/TestNotifGDF/Directory1/gdf/volker1.txt notify_trigger called action=0x3, filter=0x0, path=/mnt/hires/TestNotifGDF/Directory1/gdf/volker1.txt notify_trigger called action=0x3, filter=0x0, path=/mnt/hires/TestNotifGDF/Directory1/gdf/volker1.txt
Don't get me wrong: I can fully believe that we have a problem in Samba. The reason why I am insisting on the full trace showing the complete picture including MS2 opening its notify and MS1 doing its writes is that I want to write a torture test that exactly mimics what you see. I will then run this torture test against Windows to see that Samba actually behaves differently. Then I will modify Samba to behave the same and run that test in our autobuild environment. This will make sure we do not regress on this particular behavior. Writing this torture test is a LOT easier if you have the network traces than without them and with just a textual description of what you are doing.
OK. I'll get a trace from the linux machine capturing both MS machines traffic.
Created attachment 7527 [details] Sniffer trace packet #22 : Notify request for directory /TestNotifGDF (recursive flag set) packet #48 : Write to file "\\TestNotifGDF\\Directory1\\gdf\\volker1.txt" No notification received.
Created attachment 7528 [details] Log file Log file captured during the trace. [2012/05/07 10:13:06.764716, 10, pid=13888, effective(500, 500), real(0, 0)] smbd/notify_internal.c:890(notify_trigger) notify_trigger called action=0x3, filter=0x0, path=/mnt/hires/TestNotifGDF/Directory1/gdf/volker1.txt filter = 0x0 so no notification forwarded.
Is this still an issue with Samba 4.x?