GNOME Bugzilla – Bug 759851
Spurious "file changed" notification after saving file
Last modified: 2016-08-07 00:31:13 UTC
I've discovered a bug in current master commit baa16469bd60fcc278860ef725586a25d998c73c Date: Thu Dec 17 06:07:40 2015 +1000 Merge branch 'Gio' running on Windows 7 x64 with PyGI 3.18.2 AIO for Python 2.7 32 bit. Problem is windows-specific and doesn't arise in linux. In windows it reproduces with ~80% chance. Formal steps: - Open meld in 2 files compare mode - Edit one file - Press save on the file's toolbar Actual behaviour: file is always saved (ok). Also most of the times appears notification "Do you want to reload the file?" with "Reload" button. After reloading all is ok - file has new, just saved content. Expected behaviour: file is saved, no "Reload" notification button appears.
So I've finally got around to testing this, and I can't reproduce the behaviour. Can I ask what filesystem you're testing on? If it's FAT32 I can imagine that this might be a problem because of two second date resolution. Otherwise, I'm really not sure where to go.
Retested with latest Python3 master (c1d703f), bug is still here. In my current windows machine with python 3.4 64bit and pygi-aio-3.18.2 its reproduction is very unstable: sometimes 10 saves works without spurious notification, sometimes all 10 saves are generating this spurious notification. Logging with print shows that it looks like a race between _handle_file_change and file_saved_cb callbacks. Here is a small log for two saves. The first save 1469910733 opens spurious notification, the second one at 1469910738 doesn't. (in both cases there are 3 notifications, 2 of which are late by 1 and 3 seconds, but it doesn't look like a problem). >at 1469910733.249169 before saver.save_async >at 1469910733.250169 after saver.save_async >at 1469910733.430786 _handle_file_change f.get_parse_name() D:\apps\meld-git\meld\meldbuffer.py {'got mtime': (1469910733, 0), 'self._disk_mtime': (1469910729, 0), 'self._mtime': (1469910729, 0)} >at 1469910733.435787 file_saved_cb, gfile.get_parse_name() = D:\apps\meld-git\meld\meldbuffer.py >at 1469910734.287445 _handle_file_change f.get_parse_name() D:\apps\meld-git\meld\meldbuffer.py {'got mtime': (1469910733, 0), 'self._disk_mtime': (1469910733, 0), 'self._mtime': (1469910733, 0)} >at 1469910736.324526 _handle_file_change f.get_parse_name() D:\apps\meld-git\meld\meldbuffer.py {'got mtime': (1469910733, 0), 'self._disk_mtime': (1469910733, 0), 'self._mtime': (1469910733, 0)} >at 1469910738.009006 before saver.save_async >at 1469910738.010006 after saver.save_async >at 1469910738.191024 file_saved_cb, gfile.get_parse_name() = D:\apps\meld-git\meld\meldbuffer.py >at 1469910738.193024 _handle_file_change f.get_parse_name() D:\apps\meld-git\meld\meldbuffer.py {'got mtime': (1469910738, 0), 'self._disk_mtime': (1469910738, 0), 'self._mtime': (1469910738, 0)} >at 1469910739.028268 _handle_file_change f.get_parse_name() D:\apps\meld-git\meld\meldbuffer.py {'got mtime': (1469910738, 0), 'self._disk_mtime': (1469910738, 0), 'self._mtime': (1469910738, 0)} >at 1469910741.043348 _handle_file_change f.get_parse_name() D:\apps\meld-git\meld\meldbuffer.py {'got mtime': (1469910738, 0), 'self._disk_mtime': (1469910738, 0), 'self._mtime': (1469910738, 0)}
(In reply to Kai Willadsen from comment #1) > Can I ask what filesystem you're testing on? If it's FAT32 I can imagine > that this might be a problem because of two second date resolution.
It was NTFS file system, but I don't think that it matters: just now it reproduces on linux with gtksourceview 3.18 in a bit synthetic but not incorrect scenario: -prepare two identical ~12 MB text files on ext4 -compare them with meld -after appearing message about files being identical edit first line of one file, then save it. A message with spurious "file was changed on disk" notification appears. So, it looks like for big files this problem can be reproduced on linux too. Reasoning looks to be simple: the _handle_file_change is called after some time after saving begins, and file_saved_cb is called only after saving is done. So if saving takes some time - the problem appears.
(changed title to indicate that bug is not windows-only)
Created attachment 332632 [details] [review] fix by unsubscribing of change notifications during save Preliminary version of the patch. By now it is tested only on linux: spurious notifications for big files gone.
I've tested this on windows too. The expected notifications when file was externally changed does appear, and there is now spurious ones during file saving from meld itself.
Sorry, are you saying that this patch hasn't fixed the problem on Windows in that case?
Sorry, my wording was a bit confusing. I mean that I verified that patch do fix the problem on Windows. (and verified that it doesn't entirely kill "file modified" notifications - they appear in correct situations). So patch is ready for review/merge.
I'm trying to reproduce this now on linux as you describe and can't. For what it's worth, what you describe also shouldn't actually be a problem that can happen, at least when saving through Meld. When using gio's very reasonable file save mechanics, we *shouldn't* get change notifications until the final file move notification that happens for atomic replacement. I have no idea what this does on Windows, so I don't have expectations there. I don't actually have a problem with your patch. I think it seems sane, but I dislike not understanding what's happening, and to my understanding the patch shouldn't be necessary.
Created attachment 332868 [details] [review] temporal additional logging to clarify the problem I have two hypothesis. First: the presence of the problem is dependent on gtksourceview/gio version. There were changes in gtksourceview 3.20 regarding file changing, at least in public API that introduced modification checks. But I'm not using gtksourceview 3.20. Both windows and linux systems that has this bug appearing has gtksourceview and libgtk 3.18. Second: it looks that my thought that it is strictly file-size dependant is wrong. I'm attaching a small dirty-logging patch witch I used to measure time between start of file saving and receiving both events. Here is the output for saving of 12mb file (/tmp is ext4): >at 1470525084.4571774 before saver.save_async >at 1470525084.4576595 after saver.save_async >at 1470525085.7042973 _handle_file_change f.get_parse_name() /tmp/.goutputstream-FCIKLY {'got mtime': None, 'self._disk_mtime': (1470524823, 8000), 'self._mtime': (1470524823, 8000)} >at 1470525085.7046194 _handle_file_change f.get_parse_name() /tmp/urllib {'got mtime': (1470525085, 468197), 'self._disk_mtime': (1470524823, 8000), 'self._mtime': (1470524823, 8000)} >at 1470525085.718769 _handle_file_change f.get_parse_name() /tmp/urllib {'got mtime': (1470525085, 468197), 'self._disk_mtime': (1470525085, 468197), 'self._mtime': (1470524823, 8000)} >at 1470525085.7942986 file_saved_cb, gfile.get_parse_name() = /tmp/urllib And here for saving of 24mb file in the same place: >at 1470525443.0906818 before saver.save_async >at 1470525443.0910943 after saver.save_async >at 1470525445.380868 _handle_file_change f.get_parse_name() /tmp/.goutputstream-J6JTLY {'self._mtime': (1470525392, 985081), 'self._disk_mtime': (1470525392, 985081), 'got mtime': None} >at 1470525445.381176 _handle_file_change f.get_parse_name() /tmp/urllib24 {'self._mtime': (1470525392, 985081), 'self._disk_mtime': (1470525392, 985081), 'got mtime': (1470525444, 997905)} >at 1470525445.3887885 _handle_file_change f.get_parse_name() /tmp/urllib24 {'self._mtime': (1470525392, 985081), 'self._disk_mtime': (1470525444, 997905), 'got mtime': (1470525444, 997905)} >at 1470525445.3891876 file_saved_cb, gfile.get_parse_name() = /tmp/urllib24 For bigger file the time between saver.save_async and receiving first event is much bigger two. But all events themselves fires in relatively small time frame.
So I'm running GtkSourceview 3.18.2 and glib 2.46.2 (possibly relevant for gio reasons), and my debug trace is: at 1470528954.8674772 before saver.save_async at 1470528954.8677473 after saver.save_async at 1470528956.0116606 file_saved_cb, gfile.get_parse_name() = /tmp/test.txt at 1470528956.0164921 update_mtime self._gfile.get_parse_name() /tmp/test.txt {'got mtime': (1470528955, 978351)} at 1470528956.072862 _handle_file_change f.get_parse_name() /tmp/.goutputstream-2XIZLY {'got mtime': None, 'self._disk_mtime': (1470528955, 978351), 'self._mtime': (1470528955, 978351)} at 1470528956.0733132 _handle_file_change f.get_parse_name() /tmp/test.txt {'got mtime': (1470528955, 978351), 'self._disk_mtime': (1470528955, 978351), 'self._mtime': (1470528955, 978351)} at 1470528956.0736904 _handle_file_change f.get_parse_name() /tmp/test.txt {'got mtime': (1470528955, 978351), 'self._disk_mtime': (1470528955, 978351), 'self._mtime': (1470528955, 978351)} Note that I've added one for update_mtime there, to show how we get into the consistent state. For me, file_saved_cb *always* gets called before I get change notifications. However, I can see how this wouldn't happen, even if I can't reproduce it, so... I'm probably just going to apply your patch.
I've just pushed your patch to master. I'm going to avoid pushing it to the 3.16 branch for now, unless I start to see more reports. Thanks for the patch, and for taking the time to dive into the additional debugging.