bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not

unofficial mirror of bug-gnu-emacs@gnu.org 
 help / color / mirror / code / Atom feed

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
@ 2012-12-11 21:51 Drew Adams
  2012-12-11 22:48 ` Dmitry Gutov
  0 siblings, 1 reply; 68+ messages in thread
From: Drew Adams @ 2012-12-11 21:51 UTC (permalink / raw)
  To: 13149

Dunno whether this will ring a bell.  This happened once the other day,
and I just ignored it.  It has now happened again.

I am editing a file, doing nothing special.  Suddenly when I try to type
a char Emacs asks me (taken from *Messages*):

bar.el changed on disk; really edit the buffer? (y, n, r or C-h) n
ask-user-about-supersession-threat: File changed on disk: c:/foo/bar.el

I just reverted the buffer and continued.  But I am positive that
nothing outside Emacs modified the file.  I'm not even aware of
something running that could do that.  I was editing and saving
occasionally - nothing more.

Anyway, hoping this helps in some way...

In GNU Emacs 24.3.50.1 (i386-mingw-nt5.1.2600)
 of 2012-12-07 on MS-W7-DANI
Bzr revision: 111150 eggert@cs.ucla.edu-20121207175317-wxhrqxpp0173whq0
Windowing system distributor `Microsoft Corp.', version 5.1.2600
Configured using:
 `configure --with-gcc (4.7) --no-opt --enable-checking --cflags
 -Ic:/emacs/libs/libXpm-3.5.10/include -Ic:/emacs/libs/libXpm-3.5.10/src
 -Ic:/emacs/libs/libpng-1.2.37-lib/include -Ic:/emacs/libs/zlib-1.2.5
 -Ic:/emacs/libs/giflib-4.1.4-1-lib/include
 -Ic:/emacs/libs/jpeg-6b-4-lib/include
 -Ic:/emacs/libs/tiff-3.8.2-1-lib/include
 -Ic:/emacs/libs/libxml2-2.7.8-w32-bin/include/libxml2
 -Ic:/emacs/libs/gnutls-3.0.9-w32-bin/include
 -Ic:/emacs/libs/libiconv-1.9.2-1-lib/include'

^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2012-12-11 21:51 bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not Drew Adams
@ 2012-12-11 22:48 ` Dmitry Gutov
  2012-12-11 22:54   ` Drew Adams
  0 siblings, 1 reply; 68+ messages in thread
From: Dmitry Gutov @ 2012-12-11 22:48 UTC (permalink / raw)
  To: Drew Adams; +Cc: 13149

"Drew Adams" <drew.adams@oracle.com> writes:

> Dunno whether this will ring a bell.  This happened once the other day,
> and I just ignored it.  It has now happened again.
>  
> I am editing a file, doing nothing special.  Suddenly when I try to type
> a char Emacs asks me (taken from *Messages*):
>  
> bar.el changed on disk; really edit the buffer? (y, n, r or C-h) n
> ask-user-about-supersession-threat: File changed on disk: c:/foo/bar.el
>  
> I just reverted the buffer and continued.  But I am positive that
> nothing outside Emacs modified the file.  I'm not even aware of
> something running that could do that.  I was editing and saving
> occasionally - nothing more.
>  
> Anyway, hoping this helps in some way...

I've been seeing the same kind of prompts lately when editing files in
Emacs in Ubuntu inside a virtual machine.

IIRC all those files were were mounted from the host machine (MS Windows
7) using the vboxsf file system type.





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2012-12-11 22:48 ` Dmitry Gutov
@ 2012-12-11 22:54   ` Drew Adams
  2013-01-14  5:10     ` Dmitry Gutov
  0 siblings, 1 reply; 68+ messages in thread
From: Drew Adams @ 2012-12-11 22:54 UTC (permalink / raw)
  To: 'Dmitry Gutov'; +Cc: 13149

> > Anyway, hoping this helps in some way...
> 
> I've been seeing the same kind of prompts lately when editing files in
> Emacs in Ubuntu inside a virtual machine.
> 
> IIRC all those files were were mounted from the host machine 
> (MS Windows 7) using the vboxsf file system type.

Good to know that someone else is seeing something similar.

In my case, I'm using Windows XP and am not using vboxsf or anything else
special - just an ordinary laptop.






^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2012-12-11 22:54   ` Drew Adams
@ 2013-01-14  5:10     ` Dmitry Gutov
  2013-01-14 14:57       ` Dmitry Gutov
  0 siblings, 1 reply; 68+ messages in thread
From: Dmitry Gutov @ 2013-01-14  5:10 UTC (permalink / raw)
  To: 13149

On 12.12.2012 2:54, Drew Adams wrote:
>>> Anyway, hoping this helps in some way...
>>
>> I've been seeing the same kind of prompts lately when editing files in
>> Emacs in Ubuntu inside a virtual machine.
>>
>> IIRC all those files were were mounted from the host machine
>> (MS Windows 7) using the vboxsf file system type.
>
> Good to know that someone else is seeing something similar.
>
> In my case, I'm using Windows XP and am not using vboxsf or anything else
> special - just an ordinary laptop.

So, I can now reproduce it 100% in the conditions I mentioned above. And 
it's mighty annoying.

0. Open a file.
1. Make some changes. Emacs complies.
2. Press C-x C-s, saved successfully.
3. Try to make a single modification. Emacs instantly prompts "... 
changed on disk; really edit the buffer?".

Answer yes -> goto 4, answer no -> goto 3.
Answer "revert", buffer reverts, goto -> 1.

4. Make modifications, try to save: "... has changed since visited or 
save.  Save anyway?" Answer yes -> goto 2.

If auto-revert-mode is enabled, and you wait the required interval of 
time after 2. without making modifications, the buffer is "reverted", 
also goto -> 1.

All this on the latest trunk. A build from the latest emacs-24 doesn't 
exhibit the problem. Same with not-exactly-latest builds from these 
branches I had a few hours ago, with the possible exception of 
auto-revert-mode, IIRC it was less reliably helpful. Not sure.

Any tips for debugging this?

I'm doing bzr bisect, but it will take a while.

--Dmitry

^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-14  5:10     ` Dmitry Gutov
@ 2013-01-14 14:57       ` Dmitry Gutov
  2013-01-14 17:02         ` Eli Zaretskii
  2013-01-14 18:28         ` Paul Eggert
  0 siblings, 2 replies; 68+ messages in thread
From: Dmitry Gutov @ 2013-01-14 14:57 UTC (permalink / raw)
  To: Paul Eggert; +Cc: 13149

On 14.01.2013 9:10, Dmitry Gutov wrote:
> On 12.12.2012 2:54, Drew Adams wrote:
>>>> Anyway, hoping this helps in some way...
>>>
>>> I've been seeing the same kind of prompts lately when editing files in
>>> Emacs in Ubuntu inside a virtual machine.
>>>
>>> IIRC all those files were were mounted from the host machine
>>> (MS Windows 7) using the vboxsf file system type.
>>
>> Good to know that someone else is seeing something similar.
>>
>> In my case, I'm using Windows XP and am not using vboxsf or anything else
>> special - just an ordinary laptop.
>
> So, I can now reproduce it 100% in the conditions I mentioned above. And
> it's mighty annoying.
>
> 0. Open a file.
> 1. Make some changes. Emacs complies.
> 2. Press C-x C-s, saved successfully.
> 3. Try to make a single modification. Emacs instantly prompts "...
> changed on disk; really edit the buffer?".
>
> Answer yes -> goto 4, answer no -> goto 3.
> Answer "revert", buffer reverts, goto -> 1.
>
> 4. Make modifications, try to save: "... has changed since visited or
> save.  Save anyway?" Answer yes -> goto 2.
>
> If auto-revert-mode is enabled, and you wait the required interval of
> time after 2. without making modifications, the buffer is "reverted",
> also goto -> 1.
>
> All this on the latest trunk. A build from the latest emacs-24 doesn't
> exhibit the problem. Same with not-exactly-latest builds from these
> branches I had a few hours ago, with the possible exception of
> auto-revert-mode, IIRC it was less reliably helpful. Not sure.

Bisect points to revision 110875 
(eggert@cs.ucla.edu-20121113013514-5dej3lndyeb2dwq3):
Fix a race with verify-visited-file-modtime.

Since at least 1991 Emacs has ignored an mtime difference of no
more than one second, but my guess is that this was to work around
file system bugs that were fixed long ago.  Since the race is
causing problems now, let's remove that code.
* fileio.c (Fverify_visited_file_modtime): Do not accept a file
whose time stamp is off by no more than a second.  Insist that the
file time stamps match exactly.

Paul, any suggestions?





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-14 14:57       ` Dmitry Gutov
@ 2013-01-14 17:02         ` Eli Zaretskii
  2013-01-14 22:22           ` Dmitry Gutov
  2013-01-14 18:28         ` Paul Eggert
  1 sibling, 1 reply; 68+ messages in thread
From: Eli Zaretskii @ 2013-01-14 17:02 UTC (permalink / raw)
  To: Dmitry Gutov; +Cc: 13149, eggert

> Date: Mon, 14 Jan 2013 18:57:43 +0400
> From: Dmitry Gutov <raaahh@gmail.com>
> Cc: 13149@debbugs.gnu.org
> 
> Bisect points to revision 110875 
> (eggert@cs.ucla.edu-20121113013514-5dej3lndyeb2dwq3):
> Fix a race with verify-visited-file-modtime.
> 
> Since at least 1991 Emacs has ignored an mtime difference of no
> more than one second, but my guess is that this was to work around
> file system bugs that were fixed long ago.  Since the race is
> causing problems now, let's remove that code.
> * fileio.c (Fverify_visited_file_modtime): Do not accept a file
> whose time stamp is off by no more than a second.  Insist that the
> file time stamps match exactly.

Therefore, I doubt that the same problem was the root cause of the
problem on Drew's laptop.

> Paul, any suggestions?

I'm not Paul, but can't you synchronize the clocks of the two
machines?





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-14 14:57       ` Dmitry Gutov
  2013-01-14 17:02         ` Eli Zaretskii
@ 2013-01-14 18:28         ` Paul Eggert
  2013-01-14 22:20           ` Dmitry Gutov
  1 sibling, 1 reply; 68+ messages in thread
From: Paul Eggert @ 2013-01-14 18:28 UTC (permalink / raw)
  To: Dmitry Gutov; +Cc: 13149

[-- Attachment #1: Type: text/plain, Size: 485 bytes --]

On 01/14/2013 06:57 AM, Dmitry Gutov wrote:
> any suggestions?

I'd guess it's a filesystem problem, where a file's
timestamp spontaneously changes even though the file
itself has not changed.  I had thought those bugs
fixed long ago, but maybe not.

Could you please start by trying the attached patch,
and then see what gets sent to stderr around the time
of the problem?  That might help us work around the
problem better than the old code did (it introduced
some race conditions).

[-- Attachment #2: instrument-mtime.txt --]
[-- Type: text/plain, Size: 770 bytes --]

=== modified file 'lib/stat-time.h'
--- lib/stat-time.h	2013-01-01 09:11:05 +0000
+++ lib/stat-time.h	2013-01-14 18:18:16 +0000
@@ -22,6 +22,7 @@
 
 #include <sys/stat.h>
 #include <time.h>
+#include <stdio.h>
 
 _GL_INLINE_HEADER_BEGIN
 #ifndef _GL_STAT_TIME_INLINE
@@ -136,14 +137,15 @@
 _GL_STAT_TIME_INLINE struct timespec
 get_stat_mtime (struct stat const *st)
 {
+  struct timespec t;
 #ifdef STAT_TIMESPEC
-  return STAT_TIMESPEC (st, st_mtim);
+  t = STAT_TIMESPEC (st, st_mtim);
 #else
-  struct timespec t;
   t.tv_sec = st->st_mtime;
   t.tv_nsec = get_stat_mtime_ns (st);
+#endif
+  fprintf (stderr, "stat_mtime=%ld.%09ld\n", (long) t.tv_sec, (long) t.tv_nsec);
   return t;
-#endif
 }
 
 /* Return *ST's birth time, if available; otherwise return a value


^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-14 18:28         ` Paul Eggert
@ 2013-01-14 22:20           ` Dmitry Gutov
  2013-01-15  6:45             ` Paul Eggert
  0 siblings, 1 reply; 68+ messages in thread
From: Dmitry Gutov @ 2013-01-14 22:20 UTC (permalink / raw)
  To: Paul Eggert; +Cc: 13149

On 14.01.2013 22:28, Paul Eggert wrote:
> I'd guess it's a filesystem problem, where a file's
> timestamp spontaneously changes even though the file
> itself has not changed.  I had thought those bugs
> fixed long ago, but maybe not.

My uninformed guess was there's a delay when writing to the file, and so 
the mtime is slightly later than the time Emacs saved.

> Could you please start by trying the attached patch,
> and then see what gets sent to stderr around the time
> of the problem?  That might help us work around the
> problem better than the old code did (it introduced
> some race conditions).

Here you go, the stderr output during (open, modify, save, try to 
modify, y, modify, try to save, yes):

stat_mtime=1358175175.428731700
stat_mtime=1358175175.428731700
stat_mtime=1358175175.428731700
stat_mtime=1358175175.428731700
stat_mtime=1358175175.428731700
stat_mtime=1358175175.428731700
stat_mtime=1358175175.428731700
stat_mtime=1358175175.428731700
stat_mtime=1358175175.428731700
stat_mtime=1358175175.428731700
stat_mtime=1358201692.000000000
stat_mtime=1358201692.912737000
stat_mtime=1358201692.912737000
stat_mtime=1358194311.328310000
stat_mtime=1358194758.218531401
stat_mtime=1358201692.912737000
stat_mtime=1358201692.912737000
stat_mtime=1358201692.912737000
stat_mtime=1358201692.912737000
stat_mtime=1358201692.912737000
stat_mtime=1358201692.912737000
stat_mtime=1358201706.000000000
stat_mtime=1358201706.392448700

Suspicious zeros?





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-14 17:02         ` Eli Zaretskii
@ 2013-01-14 22:22           ` Dmitry Gutov
  0 siblings, 0 replies; 68+ messages in thread
From: Dmitry Gutov @ 2013-01-14 22:22 UTC (permalink / raw)
  To: Eli Zaretskii; +Cc: 13149, eggert

On 14.01.2013 21:02, Eli Zaretskii wrote:
>> Date: Mon, 14 Jan 2013 18:57:43 +0400
>> From: Dmitry Gutov <raaahh@gmail.com>
>> Cc: 13149@debbugs.gnu.org
>>
>> Bisect points to revision 110875
>> (eggert@cs.ucla.edu-20121113013514-5dej3lndyeb2dwq3):
>> Fix a race with verify-visited-file-modtime.
>>
>> Since at least 1991 Emacs has ignored an mtime difference of no
>> more than one second, but my guess is that this was to work around
>> file system bugs that were fixed long ago.  Since the race is
>> causing problems now, let's remove that code.
>> * fileio.c (Fverify_visited_file_modtime): Do not accept a file
>> whose time stamp is off by no more than a second.  Insist that the
>> file time stamps match exactly.
>
> Therefore, I doubt that the same problem was the root cause of the
> problem on Drew's laptop.

It hard for me to say, but the symptoms are similar, and the timing 
matches. I think this commit is the likely culprit, although the fix may 
have to be slightly different in Drew's case. Or would be, if we could 
reproduce it.

>> Paul, any suggestions?
>
> I'm not Paul, but can't you synchronize the clocks of the two
> machines?

To the nanosecond? I'm not sure if I can.

But if what you're implying is right, I think rewinding the clock on the 
host machine would also help. It doesn't.





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-14 22:20           ` Dmitry Gutov
@ 2013-01-15  6:45             ` Paul Eggert
  2013-01-15  8:54               ` Dmitry Gutov
  0 siblings, 1 reply; 68+ messages in thread
From: Paul Eggert @ 2013-01-15  6:45 UTC (permalink / raw)
  To: Dmitry Gutov; +Cc: 13149

On 01/14/2013 02:20 PM, Dmitry Gutov wrote:

> stat_mtime=1358201692.000000000
> stat_mtime=1358201692.912737000

That looks like a file system bug, I'm afraid.
Does the following work around the bug, if you
set the variable sloppy-file-time-stamps?

=== modified file 'src/ChangeLog'
--- src/ChangeLog	2013-01-14 17:46:14 +0000
+++ src/ChangeLog	2013-01-15 05:38:42 +0000
@@ -1,3 +1,10 @@
+2013-01-15  Paul Eggert  <eggert@penguin.cs.ucla.edu>
+
+	Add workaround for file system time stamp bug (Bug#13149).
+	Reported by Dmitry Gutov for Ubuntu vboxsf mounting MS Windows 7.
+	* fileio.c (syms_of_fileio) <sloppy-file-time-stamps>: New variable.
+	(Fverify_visited_file_modtime): Use it.
+
 2013-01-14  Paul Eggert  <eggert@cs.ucla.edu>
 
 	Avoid needless casts with XSAVE_POINTER.

=== modified file 'src/fileio.c'
--- src/fileio.c	2013-01-14 17:46:14 +0000
+++ src/fileio.c	2013-01-15 05:38:42 +0000
@@ -5358,7 +5358,17 @@
   mtime = (stat (SSDATA (filename), &st) == 0
 	   ? get_stat_mtime (&st)
 	   : time_error_value (errno));
-  if (EMACS_TIME_EQ (mtime, b->modtime)
+
+  /* On a few buggy file systems, the fractional part of the time stamp,
+     or perhaps even the low order bit of the seconds part, can
+     spontaneously change even though the file has not changed.  If
+     SLOPPY_FILE_TIME_STAMPS, work around these bugs at the cost of
+     possibly missing some changes.  */
+  if ((EMACS_TIME_EQ (mtime, b->modtime)
+       || (sloppy_file_time_stamps
+	   && EMACS_TIME_VALID_P (mtime)
+	   && EMACS_TIME_VALID_P (b->modtime)
+	   && EMACS_SECS (mtime) >> 1 == EMACS_SECS (b->modtime) >> 1))
       && (b->modtime_size < 0
 	  || st.st_size == b->modtime_size))
     return Qt;
@@ -6036,6 +6046,13 @@
   write_region_inhibit_fsync = 0;
 #endif
 
+  DEFVAR_BOOL ("sloppy-file-time-stamps", sloppy_file_time_stamps,
+	       doc: /* Non-nil means file time stamps are sloppy.
+When non-nil, ignore low-order part of time stamp when inferring whether
+a file may have changed.  Although this suppresses bogus diagnostics
+on buggy file systems, it can also lose changes to files.  */);
+  sloppy_file_time_stamps = 0;
+
   DEFVAR_BOOL ("delete-by-moving-to-trash", delete_by_moving_to_trash,
                doc: /* Specifies whether to use the system's trash can.
 When non-nil, certain file deletion commands use the function







^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-15  6:45             ` Paul Eggert
@ 2013-01-15  8:54               ` Dmitry Gutov
  2013-01-15 17:31                 ` Paul Eggert
  0 siblings, 1 reply; 68+ messages in thread
From: Dmitry Gutov @ 2013-01-15  8:54 UTC (permalink / raw)
  To: Paul Eggert; +Cc: 13149

On 15.01.2013 10:45, Paul Eggert wrote:
> On 01/14/2013 02:20 PM, Dmitry Gutov wrote:
>
>> stat_mtime=1358201692.000000000
>> stat_mtime=1358201692.912737000
>
> That looks like a file system bug, I'm afraid.
> Does the following work around the bug, if you
> set the variable sloppy-file-time-stamps?

Not entirely.

When the value is t, it works ok right after I open the file, and also 
if I wait a second or more between save buffer commands.

If I repeat modify -> save cycle quickly enough, the problem is still 
visible.

> === modified file 'src/ChangeLog'
> --- src/ChangeLog	2013-01-14 17:46:14 +0000
> +++ src/ChangeLog	2013-01-15 05:38:42 +0000
> @@ -1,3 +1,10 @@
> +2013-01-15  Paul Eggert  <eggert@penguin.cs.ucla.edu>
> +
> +	Add workaround for file system time stamp bug (Bug#13149).
> +	Reported by Dmitry Gutov for Ubuntu vboxsf mounting MS Windows 7.
> +	* fileio.c (syms_of_fileio) <sloppy-file-time-stamps>: New variable.
> +	(Fverify_visited_file_modtime): Use it.
> +
>   2013-01-14  Paul Eggert  <eggert@cs.ucla.edu>
>
>   	Avoid needless casts with XSAVE_POINTER.
>
> === modified file 'src/fileio.c'
> --- src/fileio.c	2013-01-14 17:46:14 +0000
> +++ src/fileio.c	2013-01-15 05:38:42 +0000
> @@ -5358,7 +5358,17 @@
>     mtime = (stat (SSDATA (filename), &st) == 0
>   	   ? get_stat_mtime (&st)
>   	   : time_error_value (errno));
> -  if (EMACS_TIME_EQ (mtime, b->modtime)
> +
> +  /* On a few buggy file systems, the fractional part of the time stamp,
> +     or perhaps even the low order bit of the seconds part, can
> +     spontaneously change even though the file has not changed.  If
> +     SLOPPY_FILE_TIME_STAMPS, work around these bugs at the cost of
> +     possibly missing some changes.  */
> +  if ((EMACS_TIME_EQ (mtime, b->modtime)
> +       || (sloppy_file_time_stamps
> +	   && EMACS_TIME_VALID_P (mtime)
> +	   && EMACS_TIME_VALID_P (b->modtime)
> +	   && EMACS_SECS (mtime) >> 1 == EMACS_SECS (b->modtime) >> 1))
>         && (b->modtime_size < 0
>   	  || st.st_size == b->modtime_size))
>       return Qt;
> @@ -6036,6 +6046,13 @@
>     write_region_inhibit_fsync = 0;
>   #endif
>
> +  DEFVAR_BOOL ("sloppy-file-time-stamps", sloppy_file_time_stamps,
> +	       doc: /* Non-nil means file time stamps are sloppy.
> +When non-nil, ignore low-order part of time stamp when inferring whether
> +a file may have changed.  Although this suppresses bogus diagnostics
> +on buggy file systems, it can also lose changes to files.  */);
> +  sloppy_file_time_stamps = 0;
> +
>     DEFVAR_BOOL ("delete-by-moving-to-trash", delete_by_moving_to_trash,
>                  doc: /* Specifies whether to use the system's trash can.
>   When non-nil, certain file deletion commands use the function
>
>






^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-15  8:54               ` Dmitry Gutov
@ 2013-01-15 17:31                 ` Paul Eggert
  2013-01-15 21:38                   ` Dmitry Gutov
  0 siblings, 1 reply; 68+ messages in thread
From: Paul Eggert @ 2013-01-15 17:31 UTC (permalink / raw)
  To: Dmitry Gutov; +Cc: 13149

On 01/15/13 00:54, Dmitry Gutov wrote:
> If I repeat modify -> save cycle quickly enough, the problem is still visible.

Can you send the stderr output for that,
where get_stat_mtime is modified as before?





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-15 17:31                 ` Paul Eggert
@ 2013-01-15 21:38                   ` Dmitry Gutov
  2013-01-15 21:47                     ` Paul Eggert
  0 siblings, 1 reply; 68+ messages in thread
From: Dmitry Gutov @ 2013-01-15 21:38 UTC (permalink / raw)
  To: Paul Eggert; +Cc: 13149

On 15.01.2013 21:31, Paul Eggert wrote:
> On 01/15/13 00:54, Dmitry Gutov wrote:
>> If I repeat modify -> save cycle quickly enough, the problem is still visible.

The "cycle quickly enough" principle doesn't work now. It was "almost 
always works fine with very few occasional failures" an hour ago, then I 
rebooted, and now the fix seems to not do anything at all, even after a 
few later reboots and "make bootstrap"s.

And yes, the patch is applied and sloppy-file-time-stamps is t.

> Can you send the stderr output for that,
> where get_stat_mtime is modified as before?

Here you go (this is the "fix not working" state):

stat_mtime=1358283708.846084200
stat_mtime=1358283708.846084200
stat_mtime=1358283708.846084200
stat_mtime=1358194311.328310000
stat_mtime=1358281767.960074887
stat_mtime=1358283708.846084200
stat_mtime=1358283708.846084200
stat_mtime=1358283708.846084200
stat_mtime=1358283708.846084200
stat_mtime=1358283708.846084200
stat_mtime=1358283708.846084200
stat_mtime=1358283708.846084200
stat_mtime=1358283748.000000000
stat_mtime=1358283753.018693400
stat_mtime=1358283753.018693400
stat_mtime=1358194311.328310000
stat_mtime=1358281481.888067978
stat_mtime=1358283753.018693400
stat_mtime=1358283753.018693400
stat_mtime=1358283753.018693400
stat_mtime=1358283753.018693400
stat_mtime=1358283753.018693400
stat_mtime=1358283753.018693400
stat_mtime=1358283755.000000000
stat_mtime=1358283759.717044000
stat_mtime=1358283759.717044000
stat_mtime=1358283759.717044000
stat_mtime=1358283759.717044000
stat_mtime=1358283759.717044000
stat_mtime=1358283759.717044000
stat_mtime=1358283759.717044000
stat_mtime=1358283759.717044000

If this is too bizarre, please wait until I re-confirm this on a new 
virtual machine with a different distro.





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-15 21:38                   ` Dmitry Gutov
@ 2013-01-15 21:47                     ` Paul Eggert
  2013-01-15 22:11                       ` Dmitry Gutov
  0 siblings, 1 reply; 68+ messages in thread
From: Paul Eggert @ 2013-01-15 21:47 UTC (permalink / raw)
  To: Dmitry Gutov; +Cc: 13149

On 01/15/13 13:38, Dmitry Gutov wrote:
> If this is too bizarre, please wait until I re-confirm this on a new virtual machine with a different distro.

It's strange all right: it indicates that time stamps
are spontaneously jumping by 2 or more seconds, which I
can't explain by any file system bugs that I can think of.
Maybe it's a new class of bugs, but we'd need to know more
about them.

Could you please try instrumenting via this patch instead?
It should help diagnosis.  Thanks.

=== modified file 'lib/stat-time.h'
--- lib/stat-time.h	2013-01-01 09:11:05 +0000
+++ lib/stat-time.h	2013-01-15 21:44:42 +0000
@@ -22,6 +22,7 @@
 
 #include <sys/stat.h>
 #include <time.h>
+#include <stdio.h>
 
 _GL_INLINE_HEADER_BEGIN
 #ifndef _GL_STAT_TIME_INLINE
@@ -134,18 +135,22 @@
 
 /* Return *ST's data modification time.  */
 _GL_STAT_TIME_INLINE struct timespec
-get_stat_mtime (struct stat const *st)
+get_stat_mtime (struct stat const *st, char const *file, int line)
 {
+  struct timespec t;
 #ifdef STAT_TIMESPEC
-  return STAT_TIMESPEC (st, st_mtim);
+  t = STAT_TIMESPEC (st, st_mtim);
 #else
-  struct timespec t;
   t.tv_sec = st->st_mtime;
   t.tv_nsec = get_stat_mtime_ns (st);
+#endif
+  fprintf (stderr, "%s:%d: stat_mtime=%ld.%09ld\n", file, line,
+	   (long) t.tv_sec, (long) t.tv_nsec);
   return t;
-#endif
 }
 
+#define get_stat_mtime(st) get_stat_mtime (st, __FILE__, __LINE__)
+
 /* Return *ST's birth time, if available; otherwise return a value
    with tv_sec and tv_nsec both equal to -1.  */
 _GL_STAT_TIME_INLINE struct timespec







^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-15 21:47                     ` Paul Eggert
@ 2013-01-15 22:11                       ` Dmitry Gutov
  2013-01-15 22:38                         ` Paul Eggert
  0 siblings, 1 reply; 68+ messages in thread
From: Dmitry Gutov @ 2013-01-15 22:11 UTC (permalink / raw)
  To: Paul Eggert; +Cc: 13149

On 16.01.2013 1:47, Paul Eggert wrote:
> On 01/15/13 13:38, Dmitry Gutov wrote:
>> If this is too bizarre, please wait until I re-confirm this on a new virtual machine with a different distro.
>
> It's strange all right: it indicates that time stamps
> are spontaneously jumping by 2 or more seconds, which I
> can't explain by any file system bugs that I can think of.
> Maybe it's a new class of bugs, but we'd need to know more
> about them.
>
> Could you please try instrumenting via this patch instead?
> It should help diagnosis.  Thanks.

Here you go:

fileio.c:5020: stat_mtime=1358287600.000000000
dired.c:958: stat_mtime=1358287604.023708900
fileio.c:5359: stat_mtime=1358287604.023708900
fileio.c:5359: stat_mtime=1358287604.023708900
dired.c:958: stat_mtime=1358287604.023708900
dired.c:958: stat_mtime=1358287604.023708900
dired.c:958: stat_mtime=1358287604.023708900
fileio.c:2200: stat_mtime=1358287604.023708900
fileio.c:5359: stat_mtime=1358287604.023708900
fileio.c:5020: stat_mtime=1358287610.000000000
dired.c:958: stat_mtime=1358287613.927966600
fileio.c:5359: stat_mtime=1358287613.927966600
fileio.c:5359: stat_mtime=1358287613.927966600
dired.c:958: stat_mtime=1358287613.927966600
dired.c:958: stat_mtime=1358287613.927966600
dired.c:958: stat_mtime=1358287613.927966600
fileio.c:2200: stat_mtime=1358287613.927966600
fileio.c:5359: stat_mtime=1358287613.927966600
fileio.c:5020: stat_mtime=1358287623.000000000
dired.c:958: stat_mtime=1358287626.880611400





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-15 22:11                       ` Dmitry Gutov
@ 2013-01-15 22:38                         ` Paul Eggert
  2013-01-15 23:09                           ` Dmitry Gutov
  0 siblings, 1 reply; 68+ messages in thread
From: Paul Eggert @ 2013-01-15 22:38 UTC (permalink / raw)
  To: Dmitry Gutov; +Cc: 13149

On 01/15/13 14:11, Dmitry Gutov wrote:

> Here you go:

Sorry, what scenario are you using for that?

Here's what I get when I run "src/emacs -Q /tmp/r" and type "a C-x C-s b".
In this transcript I indicate exactly when I typed each character.

fileio.c:3573: stat_mtime=1358285891.979499498
fileio.c:3573: stat_mtime=1358185278.123368557
dired.c:958: stat_mtime=1358285832.923323363
dired.c:958: stat_mtime=1358285832.923323363
fileio.c:3573: stat_mtime=1339474634.000000000
fileio.c:3573: stat_mtime=1357144798.955079131
lread.c:1228: stat_mtime=1357144798.939079049
lread.c:1228: stat_mtime=1358185424.004185658
dired.c:958: stat_mtime=1358288328.739209633
dired.c:958: stat_mtime=1358288328.739209633
fileio.c:3573: stat_mtime=1358288328.739209633
fileio.c:3363: stat_mtime=1358288328.739209633
fileio.c:3363: stat_mtime=1358288344.827280766
a
fileio.c:5350: stat_mtime=1358288328.739209633
C-x C-s
fileio.c:5350: stat_mtime=1358288328.739209633
fileio.c:5350: stat_mtime=1358288328.739209633
fileio.c:5011: stat_mtime=1358288369.760392065
dired.c:958: stat_mtime=1358288369.760392065
b
fileio.c:5350: stat_mtime=1358288369.760392065


You're evidently getting different behavior, since you don't see
lread.c at all, for example.  If I'm guessing right, I think the key
sequence in your transcript is here:

fileio.c:5359: stat_mtime=1358287604.023708900
fileio.c:5020: stat_mtime=1358287610.000000000
dired.c:958: stat_mtime=1358287613.927966600
fileio.c:5359: stat_mtime=1358287613.927966600

and that this corresponds to the last 5 lines of my transcript.

What happens if you apply the following patch as well?
Does it cause Emacs to output "fstat and lstat disagree!"?

=== modified file 'src/fileio.c'
--- src/fileio.c	2013-01-15 10:14:31 +0000
+++ src/fileio.c	2013-01-15 22:35:57 +0000
@@ -5017,6 +5017,20 @@ This calls `write-region-annotate-functi
   if (emacs_close (desc) < 0)
     ok = 0, save_errno = errno;
 
+  if (ok && visiting)
+    {
+      struct stat st1;
+      EMACS_TIME modtime1;
+      if (lstat (fn, &st1) != 0)
+	perror (fn);
+      else
+	{
+	  modtime1 = get_stat_mtime (&st1);
+	  if (! EMACS_TIME_EQ (modtime, modtime1))
+	    fprintf (stderr, "fstat and lstat disagree!\n");
+	}
+    }
+
   /* Discard the unwind protect for close_file_unwind.  */
   specpdl_ptr = specpdl + count1;
 







^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-15 22:38                         ` Paul Eggert
@ 2013-01-15 23:09                           ` Dmitry Gutov
  2013-01-15 23:44                             ` Dmitry Gutov
  0 siblings, 1 reply; 68+ messages in thread
From: Dmitry Gutov @ 2013-01-15 23:09 UTC (permalink / raw)
  To: Paul Eggert; +Cc: 13149

On 16.01.2013 2:38, Paul Eggert wrote:
> On 01/15/13 14:11, Dmitry Gutov wrote:
>
>> Here you go:
>
> Sorry, what scenario are you using for that?

Sorry, in that and previous messages, I only posted the part I supposed 
relevant, which is after the file is opened.

> Here's what I get when I run "src/emacs -Q /tmp/r" and type "a C-x C-s b".
> In this transcript I indicate exactly when I typed each character.
>
> ...
>
> You're evidently getting different behavior, since you don't see
> lread.c at all, for example.  If I'm guessing right, I think the key
> sequence in your transcript is here:
>
> fileio.c:5359: stat_mtime=1358287604.023708900
> fileio.c:5020: stat_mtime=1358287610.000000000
> dired.c:958: stat_mtime=1358287613.927966600
> fileio.c:5359: stat_mtime=1358287613.927966600
>
> and that this corresponds to the last 5 lines of my transcript.
>
> What happens if you apply the following patch as well?
> Does it cause Emacs to output "fstat and lstat disagree!"?

It does!

Here's the more detailed log:

$ src/emacs -Q
fileio.c:3581: stat_mtime=1358290106.959122882
fileio.c:3581: stat_mtime=1358290027.851586258
dired.c:958: stat_mtime=1358289897.278327924
dired.c:958: stat_mtime=1358289897.278327924
fileio.c:3581: stat_mtime=1341302771.000000000
fileio.c:3581: stat_mtime=1358138630.713864000
lread.c:1228: stat_mtime=1358194311.328310000
lread.c:1228: stat_mtime=1358290456.533834487
find-file
dired.c:958: stat_mtime=1358291126.115457800
dired.c:958: stat_mtime=1358291126.115457800
fileio.c:3581: stat_mtime=1358291126.115457800
fileio.c:3363: stat_mtime=1358291126.115457800
fileio.c:3363: stat_mtime=1358285614.014009800
lread.c:1228: stat_mtime=1358194311.328310000
lread.c:1228: stat_mtime=1358290442.274708012
modify
fileio.c:5373: stat_mtime=1358291126.115457800
save-buffer
fileio.c:5373: stat_mtime=1358291126.115457800
dired.c:958: stat_mtime=1358291126.115457800
dired.c:958: stat_mtime=1358291126.115457800
dired.c:958: stat_mtime=1358291126.115457800
fileio.c:2200: stat_mtime=1358291126.115457800
fileio.c:5373: stat_mtime=1358291126.115457800
fileio.c:5020: stat_mtime=1358291194.000000000
fileio.c:5037: stat_mtime=1358291196.726424200
fstat and lstat disagree!
dired.c:958: stat_mtime=1358291196.726424200
modify again
fileio.c:5373: stat_mtime=1358291196.726424200
lread.c:1228: stat_mtime=1358194311.328310000
lread.c:1228: stat_mtime=1358290142.953112077
y
save-buffer again
fileio.c:5373: stat_mtime=1358291196.726424200
yes
dired.c:958: stat_mtime=1358291196.726424200
dired.c:958: stat_mtime=1358291196.726424200
dired.c:958: stat_mtime=1358291196.726424200
fileio.c:2200: stat_mtime=1358291196.726424200
fileio.c:5373: stat_mtime=1358291196.726424200
y
fileio.c:5020: stat_mtime=1358291233.000000000
fileio.c:5037: stat_mtime=1358291234.976781400
fstat and lstat disagree!
dired.c:958: stat_mtime=1358291234.976781400





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-15 23:09                           ` Dmitry Gutov
@ 2013-01-15 23:44                             ` Dmitry Gutov
  2013-01-16  5:57                               ` Paul Eggert
  0 siblings, 1 reply; 68+ messages in thread
From: Dmitry Gutov @ 2013-01-15 23:44 UTC (permalink / raw)
  To: Paul Eggert; +Cc: 13149

On 16.01.2013 3:09, Dmitry Gutov wrote:
> On 16.01.2013 2:38, Paul Eggert wrote:
>> ...
>> What happens if you apply the following patch as well?
>> Does it cause Emacs to output "fstat and lstat disagree!"?
>
> It does!
>
> Here's the more detailed log:
>...

So, this is definitely new behavior, I checked the emacs-24 build, and 
it now also exhibits the problem (it didn't previously), so this stuff 
is not caused by the 2-months-old commit of yours.

Maybe it's a sign of my system slowly falling apart. I'm going to test 
this on a different virtual machine.





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-15 23:44                             ` Dmitry Gutov
@ 2013-01-16  5:57                               ` Paul Eggert
  2013-01-17 10:32                                 ` Dmitry Gutov
  2013-01-17 17:16                                 ` David Engster
  0 siblings, 2 replies; 68+ messages in thread
From: Paul Eggert @ 2013-01-16  5:57 UTC (permalink / raw)
  To: Dmitry Gutov; +Cc: 13149

[-- Attachment #1: Type: text/plain, Size: 323 bytes --]

On 01/15/2013 03:44 PM, Dmitry Gutov wrote:
> Maybe it's a sign of my system slowly falling apart.

It does sound like a fairly serious issue of some sort.
I did think of a patch (attached) but I'd rather not
apply it if the system in question is merely experimental,
since it introduces a race even on non-buggy systems.


[-- Attachment #2: mtime.txt --]
[-- Type: text/plain, Size: 4140 bytes --]

=== modified file 'src/ChangeLog'
--- src/ChangeLog	2013-01-15 21:38:58 +0000
+++ src/ChangeLog	2013-01-16 05:01:01 +0000
@@ -1,3 +1,18 @@
+2013-01-16  Paul Eggert  <eggert@cs.ucla.edu>
+
+	Work around bug in vboxsf file system (Bug#13149).
+	The bug was observed on Ubuntu operating inside a virtual machine,
+	editing files mounted via vboxsf from the MS Windows 7 host.
+	The workaround introduces a race condition on non-buggy hosts,
+	but it's an unlikely race and anyway there's a nearly identical
+	nearby race that can't be fixed.
+	* fileio.c (valid_timestamp_file_system, timestamp_file_system):
+	New static vars.
+	(Fwrite_region): Test for file system time stamp bug.
+	(init_fileio): New function.
+	* lisp.h (init_fileio): Declare it.
+	* emacs.c (main): Call it.
+
 2013-01-15  Paul Eggert  <eggert@cs.ucla.edu>
 
 	* alloc.c (free_save_value): Now static.

=== modified file 'src/emacs.c'
--- src/emacs.c	2013-01-13 20:03:01 +0000
+++ src/emacs.c	2013-01-16 05:01:01 +0000
@@ -1317,6 +1317,7 @@
     }
 
   init_callproc ();	/* Must follow init_cmdargs but not init_sys_modes.  */
+  init_fileio ();
   init_lread ();
 #ifdef WINDOWSNT
   /* Check to see if Emacs has been installed correctly.  */

=== modified file 'src/fileio.c'
--- src/fileio.c	2013-01-15 10:14:31 +0000
+++ src/fileio.c	2013-01-16 05:04:51 +0000
@@ -103,6 +103,11 @@
 /* Set by auto_save_1 if an error occurred during the last auto-save.  */
 static bool auto_save_error_occurred;
 
+/* If VALID_TIMESTAMP_FILE_SYSTEM, then TIMESTAMP_FILE_SYSTEM is the device
+   number of a file system where time stamps were observed to to work.  */
+static bool valid_timestamp_file_system;
+static dev_t timestamp_file_system;
+
 /* The symbol bound to coding-system-for-read when
    insert-file-contents is called for recovering a file.  This is not
    an actual coding system name, but just an indicator to tell
@@ -5020,6 +5025,42 @@
   /* Discard the unwind protect for close_file_unwind.  */
   specpdl_ptr = specpdl + count1;
 
+  /* Some file systems have a bug where st_mtime is updated merely
+     because a file was closed.  Update MODTIME to the newer st_mtime
+     if this file system appears to have the bug.  Working around this
+     bug introduces a race condition: to avoid most instances of the
+     race condition on non-buggy file systems, skip this check if the
+     most recently encountered non-buggy file system was the current
+     file system.
+
+     A race condition can occur if some other process modifies the
+     file between the fstat above and the stat below, but the race is
+     unlikely and a similar race between the last write and the fstat
+     above cannot possibly be closed anyway.  */
+
+  if (visiting && EMACS_TIME_VALID_P (modtime)
+      && ! (valid_timestamp_file_system && st.st_dev == timestamp_file_system))
+    {
+      struct stat stat_st;
+      if (stat (fn, &stat_st) != 0)
+	ok = 0, save_errno = errno;
+      else if (stat_st.st_dev == st.st_dev && stat_st.st_ino == st.st_ino)
+	{
+	  EMACS_TIME stat_modtime = get_stat_mtime (&stat_st);
+	  if (EMACS_TIME_EQ (modtime, stat_modtime)
+	      && st.st_size == stat_st.st_size)
+	    {
+	      timestamp_file_system = st.st_dev;
+	      valid_timestamp_file_system = 1;
+	    }
+	  else
+	    {
+	      st.st_size = stat_st.st_size;
+	      modtime = stat_modtime;
+	    }
+	}
+    }
+
   /* Call write-region-post-annotation-function. */
   while (CONSP (Vwrite_region_annotation_buffers))
     {
@@ -5814,8 +5855,13 @@
   args[6] = predicate;
   RETURN_UNGCPRO (Ffuncall (7, args));
 }
+\f
+void
+init_fileio (void)
+{
+  valid_timestamp_file_system = 0;
+}
 
-\f
 void
 syms_of_fileio (void)
 {

=== modified file 'src/lisp.h'
--- src/lisp.h	2013-01-15 21:38:58 +0000
+++ src/lisp.h	2013-01-16 05:01:01 +0000
@@ -3256,6 +3256,7 @@
 extern bool internal_delete_file (Lisp_Object);
 extern bool file_directory_p (const char *);
 extern bool file_accessible_directory_p (const char *);
+extern void init_fileio (void);
 extern void syms_of_fileio (void);
 extern Lisp_Object make_temp_name (Lisp_Object, bool);
 extern Lisp_Object Qdelete_file;


^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-16  5:57                               ` Paul Eggert
@ 2013-01-17 10:32                                 ` Dmitry Gutov
  2013-01-17 17:05                                   ` Eli Zaretskii
                                                     ` (2 more replies)
  2013-01-17 17:16                                 ` David Engster
  1 sibling, 3 replies; 68+ messages in thread
From: Dmitry Gutov @ 2013-01-17 10:32 UTC (permalink / raw)
  To: Paul Eggert; +Cc: 13149

[-- Attachment #1: Type: text/plain, Size: 4090 bytes --]

On 16.01.2013 9:57, Paul Eggert wrote:
> On 01/15/2013 03:44 PM, Dmitry Gutov wrote:
>> Maybe it's a sign of my system slowly falling apart.
>
> It does sound like a fairly serious issue of some sort.
> I did think of a patch (attached) but I'd rather not
> apply it if the system in question is merely experimental,
> since it introduces a race even on non-buggy systems.

I've been using the virtual machine to code Ruby for some time now, and 
I intend to continue doing it. It is replaceable, though, since all the 
important stuff is backed up.

Thank you for the patch, it works perfectly on the file mounted over 
vboxsf (but regarding applying it, see (*)).

I just now recompiled emacs-24 (revno 111176) again (bzr revert; make 
clean; make bootstrap) on the Ubuntu machine, and it seems to work fine 
now. Also recompiled the trunk a few times. The "sloppy" patch now works 
fine as well, aside from the need to explicitly set the variable. "fstat 
and lstat mismatch" is still there, though, so it's probably unrelated.
No idea what the problem was with my tests last time, I'm blaming space 
rays.

Looked at the VirtualBox bug reports, found just this one: 
https://www.virtualbox.org/ticket/10986, not much information there.

Some more about space rays:
1) I now have a version of Emacs compiled on a brand-new Fedora virtual 
machine from emacs-24 branch (revno 111185) that exhibits the problem. 
Just tested it simultaneously with Ubuntu, emacs-24 on Fedora is buggy, 
Ubuntu's is not. The following items (2 and 3) are from a few hours ago, 
when I tested Fedora machine exclusively.
2) Editing the file on a different disk on the host system (HDD vs SSD) 
makes no difference, the bug is present.
3) Process Monitor doesn't show any other processes accessing the file 
on the host machine other than VirtualBox.exe, SYSTEM and 
SearchProtocolHost.exe. The last one goes away if I stop the Windows 
Search service, but the problem stays. I'm attaching the exported event 
log for the open-modify-save scenario (file-access-log.csv) in case 
someone knowledgeable can see anything weird there (Eli?).

(*) I tried to work around the whole thing by instead sharing the 
directory in Windows the usual way and mounting it over CIFS (the 
package cifs-utils in Ubuntu). Yet again, emacs-24 works fine as-is (on 
both virtual machines, in this use case), but the trunk (revno 111517) 
exhibits the same buggy behavior I've been writing about.

And the "sloppy" patch helps (when the var is set), but the last one 
doesn't. See the instrumented output for the usual scenario with the 
last patch applied, below.

Can anyone confirm this? Mounting stuff over CIFS/Samba should be a 
relatively common situation.

If this is indeed reproducible, I think we need this to work without 
requiring the user to customize a variable.

find-file
dired.c:958: stat_mtime=1358411932.626214300
dired.c:958: stat_mtime=1358411932.626214300
fileio.c:3586: stat_mtime=1358411932.626214300
lread.c:1228: stat_mtime=1358194311.328310000
lread.c:1228: stat_mtime=1358411625.122214750
lread.c:1228: stat_mtime=1358194311.328310000
lread.c:1228: stat_mtime=1358411580.742214813
modify
fileio.c:5414: stat_mtime=1358411932.626214300
save
fileio.c:5414: stat_mtime=1358411932.626214300
fileio.c:5414: stat_mtime=1358411932.626214300
fileio.c:5025: stat_mtime=1358412092.606214085
fileio.c:5042: stat_mtime=1358412092.606214085
fileio.c:5072: stat_mtime=1358412092.606214085
dired.c:958: stat_mtime=1358412092.606214085
dired.c:958: stat_mtime=1358412092.606214085
modify again
fileio.c:5414: stat_mtime=1358412092.606214000
lread.c:1228: stat_mtime=1358194311.328310000
lread.c:1228: stat_mtime=1358411328.034215171
y
save
fileio.c:5414: stat_mtime=1358412092.606214000
yes
fileio.c:5414: stat_mtime=1358412092.606214000
y
fileio.c:5025: stat_mtime=1358412142.122214017
fileio.c:5042: stat_mtime=1358412142.122214017
dired.c:958: stat_mtime=1358412142.122214017
dired.c:958: stat_mtime=1358412142.122214017

No zeros or "fstat and lstat disagree" messages here, although I applied 
that patch, too.

[-- Attachment #2: file-access-log.csv --]
[-- Type: text/plain, Size: 125232 bytes --]

"Time of Day","Process Name","PID","Operation","Path","Result","Detail"
"9:50:25.9944537","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:25.9944932","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:25.9945225","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:25.9945369","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:25.9945566","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:25.9947480","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:25.9947862","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:25.9948095","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:25.9948253","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:25.9948437","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0004524","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0004903","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0005152","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0005291","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0005471","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0009802","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0010174","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0010404","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0010539","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0010716","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0034335","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0034753","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0035072","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0035227","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0035414","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0044578","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0044950","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0045183","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0045321","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0045496","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0049583","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0049948","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0050175","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0050313","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0050487","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0064304","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0065094","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0065353","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0065495","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0065679","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0074222","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0074587","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0074814","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0074952","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0075126","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0080282","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0080650","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0080877","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0081015","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0081189","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0089624","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0089985","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0090212","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0090350","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0090525","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0094415","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0094783","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0095010","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0095145","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0095319","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0104598","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0104993","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0105269","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0105414","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0105595","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0109419","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0109790","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0110021","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0110159","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0110330","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0110869","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Generic Read, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, Write, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0112066","VirtualBox.exe","4132","FileSystemControl","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Control: FSCTL_READ_FILE_USN_DATA"
"9:50:26.0112628","VirtualBox.exe","4132","QueryInformationVolume","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","VolumeCreationTime: 09.01.2012 1:32:47, VolumeSerialNumber: DE12-C429, SupportsObjects: True, VolumeLabel: "
"9:50:26.0112799","VirtualBox.exe","4132","QueryAllInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","BUFFER OVERFLOW","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, FileAttributes: A, AllocationSize: 184, EndOfFile: 180, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0x1300000000b1c9, EaSize: 0, Access: Generic Read, Position: 0, Mode: Synchronous IO Non-Alert, AlignmentRequirement: Word"
"9:50:26.0114213","VirtualBox.exe","4132","ReadFile","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED","Offset: 0, Length: 180"
"9:50:26.0114348","VirtualBox.exe","4132","ReadFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Offset: 0, Length: 180, Priority: Normal"
"9:50:26.0119149","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0129556","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\.#test.rb","FAST IO DISALLOWED",""
"9:50:26.0129951","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\.#test.rb","NAME NOT FOUND","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a"
"9:50:26.0139710","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\.#test.rb","FAST IO DISALLOWED",""
"9:50:26.0140085","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\.#test.rb","NAME NOT FOUND","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a"
"9:50:26.0149673","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0150061","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0150334","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0150472","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0150660","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0154997","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0155405","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0155855","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0156000","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0156184","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0163211","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0163668","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0164007","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0164161","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0164352","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0173579","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0173986","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0174305","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0174453","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0174647","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0181424","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0181793","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0182033","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0182171","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0182348","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0209506","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0209881","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0210131","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0210272","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0210450","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0214192","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0214557","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0214787","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0214925","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0215106","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0224296","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0224665","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0224898","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0225036","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0225214","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0229364","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0229729","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0229955","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0230090","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0230265","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0245016","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0245440","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0245759","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0245910","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0246101","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0314220","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0314585","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0314841","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0314979","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0315160","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0344481","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\s.test.rb","FAST IO DISALLOWED",""
"9:50:26.0344849","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\s.test.rb","NAME NOT FOUND","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a"
"9:50:26.0354421","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0354786","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0355033","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0355171","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0355349","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0389632","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0389997","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0390250","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0390388","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0390569","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0414678","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0415043","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0415273","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0415411","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0415589","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0439452","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0439827","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0440057","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0440195","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0440372","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0465508","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:26.0465905","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:26.0466205","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:26.0466353","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:26.0466540","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:27.6895525","System","4","CreateFileMapping","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","SyncType: SyncTypeOther"
"9:50:27.6895617","System","4","FASTIO_RELEASE_FOR_SECTION_SYNCHRONIZATION","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:27.6895686","System","4","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:29.5328267","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\.#test.rb","FAST IO DISALLOWED",""
"9:50:29.5328675","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\.#test.rb","NAME NOT FOUND","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a"
"9:50:29.5338145","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:29.5338523","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:29.5338809","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:29.5338950","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:29.5339144","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:29.5340999","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:29.5341377","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:29.5341614","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:29.5341752","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:29.5341956","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:29.5346615","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\.#test.rb","FAST IO DISALLOWED",""
"9:50:29.5347016","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\.#test.rb","NAME NOT FOUND","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a"
"9:50:30.3465348","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.3465746","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.3466035","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.3466183","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3466384","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3467896","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.3468271","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.3468508","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.3468652","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3468833","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3476607","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.3477054","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.3477416","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.3477570","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3477781","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3481694","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.3482101","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.3482407","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.3482552","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3482739","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3488793","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.3489191","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.3489464","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.3489608","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3489796","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3491861","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.3492249","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.3492518","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.3492663","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3492857","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3497296","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.3497668","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.3497918","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.3498056","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3498230","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3499388","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.3499753","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.3499986","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.3500121","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3500298","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3504593","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.3504961","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.3505188","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.3505326","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3505500","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3509551","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.3509920","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.3510156","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.3510291","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3510469","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3511764","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.3512129","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.3512356","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.3512494","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3512669","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3516825","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.3517197","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.3517427","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.3517562","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3517746","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3518893","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.3519262","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.3519492","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.3519627","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3519804","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3534256","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.3534664","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.3534946","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.3535091","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3535275","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3589258","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.3589643","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.3589893","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.3590031","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3590212","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3593763","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.3594135","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.3594361","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.3594500","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3594674","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3628986","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.3629358","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.3629608","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.3629743","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3629924","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3633981","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.3634350","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.3634580","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.3634718","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3634889","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3674058","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.3674426","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.3674663","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.3674798","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3674976","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3679109","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.3679477","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.3679701","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.3679836","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3680010","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3680523","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Generic Read, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, Write, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.3681779","VirtualBox.exe","4132","FileSystemControl","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Control: FSCTL_READ_FILE_USN_DATA"
"9:50:30.3682345","VirtualBox.exe","4132","QueryInformationVolume","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","VolumeCreationTime: 09.01.2012 1:32:47, VolumeSerialNumber: DE12-C429, SupportsObjects: True, VolumeLabel: "
"9:50:30.3682516","VirtualBox.exe","4132","QueryAllInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","BUFFER OVERFLOW","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, FileAttributes: A, AllocationSize: 184, EndOfFile: 180, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0x1300000000b1c9, EaSize: 0, Access: Generic Read, Position: 0, Mode: Synchronous IO Non-Alert, AlignmentRequirement: Word"
"9:50:30.3697441","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.3697872","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.3698187","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.3698338","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3698526","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.3750102","VirtualBox.exe","4132","ReadFile","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED","Offset: 0, Length: 16 384"
"9:50:30.3750233","VirtualBox.exe","4132","ReadFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Offset: 0, Length: 180, Priority: Normal"
"9:50:30.3757132","VirtualBox.exe","4132","ReadFile","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED","Offset: 180, Length: 16 384"
"9:50:30.3757260","VirtualBox.exe","4132","ReadFile","C:\Users\gutov\Documents\Ruby\test.rb","END OF FILE","Offset: 180, Length: 16 384, Priority: Normal"
"9:50:30.3794667","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.4094159","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\.#test.rb","FAST IO DISALLOWED",""
"9:50:30.4094524","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\.#test.rb","NAME NOT FOUND","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a"
"9:50:30.4104250","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.4104684","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.4104964","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.4105102","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.4105290","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.4108808","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.4109173","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.4109406","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.4109544","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.4109722","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.4118860","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\.#test.rb","FAST IO DISALLOWED",""
"9:50:30.4119228","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\.#test.rb","NAME NOT FOUND","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a"
"9:50:30.4129465","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.4129830","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.4130063","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.4130201","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.4130379","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.4134048","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.4134407","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.4134634","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:49:16, ChangeTime: 17.01.2013 9:49:16, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.4134768","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.4134943","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.4135544","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Generic Write, Read Attributes, Disposition: OverwriteIf, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, Write, AllocationSize: 0, OpenResult: Overwritten"
"9:50:30.4136541","VirtualBox.exe","4132","SetEndOfFileInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","EndOfFile: 0"
"9:50:30.4136866","VirtualBox.exe","4132","SetAllInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","AllocationSize: 0"
"9:50:30.4137113","VirtualBox.exe","4132","QueryInformationVolume","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","VolumeCreationTime: 09.01.2012 1:32:47, VolumeSerialNumber: DE12-C429, SupportsObjects: True, VolumeLabel: "
"9:50:30.4137271","VirtualBox.exe","4132","QueryAllInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","BUFFER OVERFLOW","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, FileAttributes: A, AllocationSize: 0, EndOfFile: 0, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0x1300000000b1c9, EaSize: 0, Access: Generic Write, Read Attributes, Position: 0, Mode: Synchronous IO Non-Alert, AlignmentRequirement: Word"
"9:50:30.4139116","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.4139507","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.4139763","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.4139905","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.4140086","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.4140635","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Generic Write, Read Attributes, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, Write, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.4140901","VirtualBox.exe","4132","QueryInformationVolume","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","VolumeCreationTime: 09.01.2012 1:32:47, VolumeSerialNumber: DE12-C429, SupportsObjects: True, VolumeLabel: "
"9:50:30.4141036","VirtualBox.exe","4132","QueryAllInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","BUFFER OVERFLOW","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, FileAttributes: A, AllocationSize: 0, EndOfFile: 0, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0x1300000000b1c9, EaSize: 0, Access: Generic Write, Read Attributes, Position: 0, Mode: Synchronous IO Non-Alert, AlignmentRequirement: Word"
"9:50:30.4143522","VirtualBox.exe","4132","SetBasicInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 01.01.1601 4:00:00, LastAccessTime: 01.01.1601 4:00:00, LastWriteTime: 17.01.2013 9:50:28, ChangeTime: 01.01.1601 4:00:00, FileAttributes: n/a"
"9:50:30.4143877","VirtualBox.exe","4132","QueryInformationVolume","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","VolumeCreationTime: 09.01.2012 1:32:47, VolumeSerialNumber: DE12-C429, SupportsObjects: True, VolumeLabel: "
"9:50:30.4144012","VirtualBox.exe","4132","QueryAllInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","BUFFER OVERFLOW","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:28, ChangeTime: 17.01.2013 9:50:30, FileAttributes: A, AllocationSize: 0, EndOfFile: 0, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0x1300000000b1c9, EaSize: 0, Access: Generic Write, Read Attributes, Position: 0, Mode: Synchronous IO Non-Alert, AlignmentRequirement: Word"
"9:50:30.4149654","VirtualBox.exe","4132","SetEndOfFileInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","EndOfFile: 0"
"9:50:30.4149917","VirtualBox.exe","4132","SetAllInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","AllocationSize: 0"
"9:50:30.4150138","VirtualBox.exe","4132","QueryInformationVolume","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","VolumeCreationTime: 09.01.2012 1:32:47, VolumeSerialNumber: DE12-C429, SupportsObjects: True, VolumeLabel: "
"9:50:30.4150269","VirtualBox.exe","4132","QueryAllInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","BUFFER OVERFLOW","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:28, ChangeTime: 17.01.2013 9:50:30, FileAttributes: A, AllocationSize: 0, EndOfFile: 0, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0x1300000000b1c9, EaSize: 0, Access: Generic Write, Read Attributes, Position: 0, Mode: Synchronous IO Non-Alert, AlignmentRequirement: Word"
"9:50:30.4153528","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.4153712","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.4158848","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.4159226","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.4159486","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:28, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.4159627","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.4159805","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.4164596","VirtualBox.exe","4132","WriteFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Offset: 0, Length: 55, Priority: Normal"
"9:50:30.4168581","VirtualBox.exe","4132","WriteFile","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED","Offset: 55, Length: 124"
"9:50:30.4168729","VirtualBox.exe","4132","WriteFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Offset: 55, Length: 124, Priority: Normal"
"9:50:30.4174697","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.4175099","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.4175395","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:28, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.4175542","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.4175825","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.4179061","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.4180495","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.4180689","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.4189337","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\.#test.rb","FAST IO DISALLOWED",""
"9:50:30.4189711","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\.#test.rb","NAME NOT FOUND","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a"
"9:50:30.4199287","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\.#test.rb","FAST IO DISALLOWED",""
"9:50:30.4199655","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\.#test.rb","NAME NOT FOUND","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a"
"9:50:30.4208934","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.4209303","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.4209539","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.4209681","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.4209858","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.4213959","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:30.4214344","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:30.4214587","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:30.4214728","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:30.4214906","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:32.3771603","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\.#test.rb","FAST IO DISALLOWED",""
"9:50:32.3772018","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\.#test.rb","NAME NOT FOUND","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a"
"9:50:32.3781146","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:32.3781527","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:32.3781813","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:32.3781955","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:32.3782149","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:32.3788449","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:32.3788830","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:32.3789071","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:32.3789218","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:32.3789399","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:32.3796101","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:32.3796472","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:32.3796706","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:32.3796847","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:32.3797028","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:32.3801336","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:32.3801710","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:32.3801944","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:32.3802085","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:32.3802266","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:34.2783320","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\.#test.rb","FAST IO DISALLOWED",""
"9:50:34.2783738","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\.#test.rb","NAME NOT FOUND","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a"
"9:50:37.6897672","System","4","WriteFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Offset: 0, Length: 4 096, I/O Flags: Non-cached, Paging I/O, Synchronous Paging I/O, Priority: Normal"
"9:50:37.6897800","System","4","SetEndOfFileInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","EndOfFile: 179"
"9:50:37.6897896","System","4","CreateFileMapping","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","SyncType: SyncTypeOther"
"9:50:37.6898027","System","4","FASTIO_RELEASE_FOR_SECTION_SYNCHRONIZATION","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:37.6898109","System","4","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:38.4082357","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:38.4082749","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:38.4083035","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:38.4083179","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:38.4083377","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:38.4087878","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:38.4088256","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:38.4088500","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:38.4088644","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:38.4088829","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:38.4094419","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:38.4094800","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:38.4095037","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:38.4095181","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:38.4095362","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:38.4097602","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:38.4103573","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:38.4103918","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:38.4104070","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:38.4104270","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3796518","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:40.3796913","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:40.3797202","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:40.3797350","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3797544","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3799455","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:40.3799839","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:40.3800080","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:40.3800221","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3800402","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3809125","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:40.3809589","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:40.3810020","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:40.3810194","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3810398","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3811644","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:40.3812049","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:40.3812312","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:40.3812460","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3812644","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3830124","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:40.3830545","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:40.3830847","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:40.3830995","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3831183","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3859958","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:40.3860369","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:40.3860688","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:40.3860836","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3861027","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3869228","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:40.3869596","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:40.3869826","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:40.3869967","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3870148","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3882864","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:40.3883328","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:40.3883673","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:40.3883827","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3884018","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3885202","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:40.3885580","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:40.3885817","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:40.3885955","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3886136","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3894251","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:40.3894619","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:40.3894850","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:40.3894991","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3895168","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3899519","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:40.3899884","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:40.3900111","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:40.3900245","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3900430","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3910127","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:40.3910508","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:40.3910771","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:40.3910916","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3911097","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3944959","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:40.3945340","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:40.3945590","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:40.3945732","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3945912","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3947418","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:40.3947787","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:40.3948020","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:40.3948158","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3948339","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3979587","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:40.3979952","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:40.3980182","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:40.3980320","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3980498","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3984921","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:40.3985332","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:40.3985644","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:40.3985795","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.3985986","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.4016971","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:40.4017395","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:40.4017717","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:40.4017869","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.4018059","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.4020203","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:40.4020604","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:40.4020917","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:40.4021065","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.4021249","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.4021805","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Generic Read, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, Write, AllocationSize: n/a, OpenResult: Opened"
"9:50:40.4023015","VirtualBox.exe","4132","FileSystemControl","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Control: FSCTL_READ_FILE_USN_DATA"
"9:50:40.4023570","VirtualBox.exe","4132","QueryInformationVolume","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","VolumeCreationTime: 09.01.2012 1:32:47, VolumeSerialNumber: DE12-C429, SupportsObjects: True, VolumeLabel: "
"9:50:40.4023741","VirtualBox.exe","4132","QueryAllInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","BUFFER OVERFLOW","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, FileAttributes: A, AllocationSize: 184, EndOfFile: 179, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0x1300000000b1c9, EaSize: 0, Access: Generic Read, Position: 0, Mode: Synchronous IO Non-Alert, AlignmentRequirement: Word"
"9:50:40.4030364","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:40.4030772","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:40.4031081","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:40.4031235","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.4031423","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.4069382","VirtualBox.exe","4132","ReadFile","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED","Offset: 0, Length: 16 384"
"9:50:40.4069520","VirtualBox.exe","4132","ReadFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Offset: 0, Length: 179, Priority: Normal"
"9:50:40.4079313","VirtualBox.exe","4132","ReadFile","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED","Offset: 179, Length: 16 384"
"9:50:40.4079441","VirtualBox.exe","4132","ReadFile","C:\Users\gutov\Documents\Ruby\test.rb","END OF FILE","Offset: 179, Length: 16 384, Priority: Normal"
"9:50:40.4143344","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.4221061","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\.#test.rb","FAST IO DISALLOWED",""
"9:50:40.4221459","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\.#test.rb","NAME NOT FOUND","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a"
"9:50:40.4230019","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:40.4230393","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:40.4230656","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:40.4230795","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.4230979","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.4234484","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:40.4234849","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:40.4235079","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:40.4235214","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.4235392","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.4244868","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:40.4245236","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:40.4245470","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:40.4245608","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.4245782","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.4249547","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:40.4249909","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:40.4250136","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:40.4250271","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:40.4250445","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:41.6887416","System","4","CreateFileMapping","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","SyncType: SyncTypeOther"
"9:50:41.6887663","System","4","FASTIO_RELEASE_FOR_SECTION_SYNCHRONIZATION","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:41.6887745","System","4","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:41.8152121","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\.#test.rb","FAST IO DISALLOWED",""
"9:50:41.8152562","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\.#test.rb","NAME NOT FOUND","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a"
"9:50:41.8169552","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:41.8169976","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:41.8170305","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:41.8170453","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:41.8170647","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:41.8176579","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:41.8176954","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:41.8177191","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:30, ChangeTime: 17.01.2013 9:50:30, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:41.8177329","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:41.8177500","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:41.8178147","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Generic Write, Read Attributes, Disposition: OverwriteIf, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, Write, AllocationSize: 0, OpenResult: Overwritten"
"9:50:41.8179216","VirtualBox.exe","4132","SetEndOfFileInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","EndOfFile: 0"
"9:50:41.8179555","VirtualBox.exe","4132","SetAllInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","AllocationSize: 0"
"9:50:41.8179969","VirtualBox.exe","4132","QueryInformationVolume","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","VolumeCreationTime: 09.01.2012 1:32:47, VolumeSerialNumber: DE12-C429, SupportsObjects: True, VolumeLabel: "
"9:50:41.8180147","VirtualBox.exe","4132","QueryAllInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","BUFFER OVERFLOW","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:41, ChangeTime: 17.01.2013 9:50:41, FileAttributes: A, AllocationSize: 0, EndOfFile: 0, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0x1300000000b1c9, EaSize: 0, Access: Generic Write, Read Attributes, Position: 0, Mode: Synchronous IO Non-Alert, AlignmentRequirement: Word"
"9:50:41.8181403","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:41.8181797","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:41.8182060","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:41, ChangeTime: 17.01.2013 9:50:41, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:41.8182199","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:41.8182379","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:41.8182948","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Generic Write, Read Attributes, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, Write, AllocationSize: n/a, OpenResult: Opened"
"9:50:41.8183208","VirtualBox.exe","4132","QueryInformationVolume","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","VolumeCreationTime: 09.01.2012 1:32:47, VolumeSerialNumber: DE12-C429, SupportsObjects: True, VolumeLabel: "
"9:50:41.8183343","VirtualBox.exe","4132","QueryAllInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","BUFFER OVERFLOW","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:41, ChangeTime: 17.01.2013 9:50:41, FileAttributes: A, AllocationSize: 0, EndOfFile: 0, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0x1300000000b1c9, EaSize: 0, Access: Generic Write, Read Attributes, Position: 0, Mode: Synchronous IO Non-Alert, AlignmentRequirement: Word"
"9:50:41.8185921","VirtualBox.exe","4132","SetBasicInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 01.01.1601 4:00:00, LastAccessTime: 01.01.1601 4:00:00, LastWriteTime: 17.01.2013 9:50:40, ChangeTime: 01.01.1601 4:00:00, FileAttributes: n/a"
"9:50:41.8186309","VirtualBox.exe","4132","QueryInformationVolume","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","VolumeCreationTime: 09.01.2012 1:32:47, VolumeSerialNumber: DE12-C429, SupportsObjects: True, VolumeLabel: "
"9:50:41.8186450","VirtualBox.exe","4132","QueryAllInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","BUFFER OVERFLOW","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:40, ChangeTime: 17.01.2013 9:50:41, FileAttributes: A, AllocationSize: 0, EndOfFile: 0, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0x1300000000b1c9, EaSize: 0, Access: Generic Write, Read Attributes, Position: 0, Mode: Synchronous IO Non-Alert, AlignmentRequirement: Word"
"9:50:41.8189314","VirtualBox.exe","4132","SetEndOfFileInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","EndOfFile: 0"
"9:50:41.8189581","VirtualBox.exe","4132","SetAllInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","AllocationSize: 0"
"9:50:41.8189824","VirtualBox.exe","4132","QueryInformationVolume","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","VolumeCreationTime: 09.01.2012 1:32:47, VolumeSerialNumber: DE12-C429, SupportsObjects: True, VolumeLabel: "
"9:50:41.8189959","VirtualBox.exe","4132","QueryAllInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","BUFFER OVERFLOW","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:40, ChangeTime: 17.01.2013 9:50:41, FileAttributes: A, AllocationSize: 0, EndOfFile: 0, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0x1300000000b1c9, EaSize: 0, Access: Generic Write, Read Attributes, Position: 0, Mode: Synchronous IO Non-Alert, AlignmentRequirement: Word"
"9:50:41.8191350","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:41.8191567","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:41.8196437","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:41.8196834","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:41.8197117","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:40, ChangeTime: 17.01.2013 9:50:41, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:41.8197262","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:41.8197439","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:41.8203582","VirtualBox.exe","4132","WriteFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Offset: 0, Length: 66, Priority: Normal"
"9:50:41.8205884","VirtualBox.exe","4132","WriteFile","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED","Offset: 66, Length: 113"
"9:50:41.8206025","VirtualBox.exe","4132","WriteFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Offset: 66, Length: 113, Priority: Normal"
"9:50:41.8207363","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:41.8207755","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:41.8208028","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:40, ChangeTime: 17.01.2013 9:50:41, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:41.8208172","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:41.8208455","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:41.8210770","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:41.8212144","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:41.8221082","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\.#test.rb","FAST IO DISALLOWED",""
"9:50:41.8221460","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\.#test.rb","NAME NOT FOUND","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a"
"9:50:41.8231058","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\.#test.rb","FAST IO DISALLOWED",""
"9:50:41.8231427","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\.#test.rb","NAME NOT FOUND","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a"
"9:50:41.8246220","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:41.8247151","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:41.8247430","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:41, ChangeTime: 17.01.2013 9:50:41, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:41.8247572","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:41.8247759","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:41.8252445","VirtualBox.exe","4132","QueryOpen","C:\Users\gutov\Documents\Ruby\test.rb","FAST IO DISALLOWED",""
"9:50:41.8252849","VirtualBox.exe","4132","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:50:41.8253145","VirtualBox.exe","4132","QueryNetworkOpenInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:41, ChangeTime: 17.01.2013 9:50:41, AllocationSize: 01.01.1601 4:00:00, EndOfFile: 01.01.1601 4:00:00, FileAttributes: A"
"9:50:41.8253293","VirtualBox.exe","4132","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:41.8253481","VirtualBox.exe","4132","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:43.6880596","System","4","WriteFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Offset: 0, Length: 4 096, I/O Flags: Non-cached, Paging I/O, Synchronous Paging I/O, Priority: Normal"
"9:50:43.6880863","System","4","SetEndOfFileInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","EndOfFile: 179"
"9:50:43.6880988","System","4","CreateFileMapping","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","SyncType: SyncTypeOther"
"9:50:43.6881076","System","4","FASTIO_RELEASE_FOR_SECTION_SYNCHRONIZATION","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:50:43.6881155","System","4","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:51:40.7433709","SearchProtocolHost.exe","4248","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Generic Read, Disposition: Open, Options: Open Reparse Point, Open Requiring Oplock, Attributes: N, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:51:40.7435156","SearchProtocolHost.exe","4248","FileSystemControl","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Control: FSCTL_READ_FILE_USN_DATA"
"9:51:40.7435771","SearchProtocolHost.exe","4248","FileSystemControl","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Control: FSCTL_REQUEST_FILTER_OPLOCK"
"9:51:40.7435939","SearchProtocolHost.exe","4248","QueryStandardInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","AllocationSize: 184, EndOfFile: 179, NumberOfLinks: 1, DeletePending: False, Directory: False"
"9:51:40.7436073","SearchProtocolHost.exe","4248","QueryBasicInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:41, ChangeTime: 17.01.2013 9:50:41, FileAttributes: A"
"9:51:40.7436195","SearchProtocolHost.exe","4248","QueryFileInternalInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","IndexNumber: 0x1300000000b1c9"
"9:51:40.7436346","SearchProtocolHost.exe","4248","FileSystemControl","C:\Users\gutov\Documents\Ruby\test.rb","NOT REPARSE POINT","Control: FSCTL_GET_REPARSE_POINT"
"9:51:40.7436606","SearchProtocolHost.exe","4248","QuerySecurityFile","C:\Users\gutov\Documents\Ruby\test.rb","BUFFER OVERFLOW","Information: Owner, Group, DACL"
"9:51:40.7436774","SearchProtocolHost.exe","4248","QuerySecurityFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Information: Owner, Group, DACL"
"9:51:40.7436991","SearchProtocolHost.exe","4248","QueryNameInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Name: \Users\gutov\Documents\Ruby\test.rb"
"9:51:40.7438701","SearchProtocolHost.exe","4248","QueryBasicInformationFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","CreationTime: 14.11.2012 17:22:46, LastAccessTime: 17.01.2013 7:28:04, LastWriteTime: 17.01.2013 9:50:41, ChangeTime: 17.01.2013 9:50:41, FileAttributes: A"
"9:51:40.7440023","SearchProtocolHost.exe","4248","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Generic Read, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:51:40.7441213","SearchProtocolHost.exe","4248","FileSystemControl","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Control: FSCTL_READ_FILE_USN_DATA"
"9:51:40.7494739","SearchProtocolHost.exe","4248","CreateFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Desired Access: Read Attributes, Read Control, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"9:51:40.7495094","SearchProtocolHost.exe","4248","QuerySecurityFile","C:\Users\gutov\Documents\Ruby\test.rb","BUFFER OVERFLOW","Information: Owner"
"9:51:40.7495265","SearchProtocolHost.exe","4248","QuerySecurityFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","Information: Owner"
"9:51:40.7495419","SearchProtocolHost.exe","4248","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:51:40.7495600","SearchProtocolHost.exe","4248","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:51:40.7502190","SearchProtocolHost.exe","4248","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:51:40.7502420","SearchProtocolHost.exe","4248","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:51:40.7502640","SearchProtocolHost.exe","4248","CloseFile","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:51:41.6880633","System","4","CreateFileMapping","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS","SyncType: SyncTypeOther"
"9:51:41.6880718","System","4","FASTIO_RELEASE_FOR_SECTION_SYNCHRONIZATION","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""
"9:51:41.6880784","System","4","IRP_MJ_CLOSE","C:\Users\gutov\Documents\Ruby\test.rb","SUCCESS",""

^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-17 10:32                                 ` Dmitry Gutov
@ 2013-01-17 17:05                                   ` Eli Zaretskii
  2013-01-18  4:15                                     ` Dmitry Gutov
  2013-01-17 21:14                                   ` Paul Eggert
  2013-01-17 21:33                                   ` Paul Eggert
  2 siblings, 1 reply; 68+ messages in thread
From: Eli Zaretskii @ 2013-01-17 17:05 UTC (permalink / raw)
  To: Dmitry Gutov; +Cc: 13149, eggert

> Date: Thu, 17 Jan 2013 14:32:56 +0400
> From: Dmitry Gutov <raaahh@gmail.com>
> CC: 13149@debbugs.gnu.org, Eli Zaretskii <eliz@gnu.org>
> 
> Looked at the VirtualBox bug reports, found just this one: 
> https://www.virtualbox.org/ticket/10986, not much information there.
> 
> Some more about space rays:
> 1) I now have a version of Emacs compiled on a brand-new Fedora virtual 
> machine from emacs-24 branch (revno 111185) that exhibits the problem. 
> Just tested it simultaneously with Ubuntu, emacs-24 on Fedora is buggy, 
> Ubuntu's is not. The following items (2 and 3) are from a few hours ago, 
> when I tested Fedora machine exclusively.
> 2) Editing the file on a different disk on the host system (HDD vs SSD) 
> makes no difference, the bug is present.
> 3) Process Monitor doesn't show any other processes accessing the file 
> on the host machine other than VirtualBox.exe, SYSTEM and 
> SearchProtocolHost.exe. The last one goes away if I stop the Windows 
> Search service, but the problem stays.

I suspect that what you see is some bad interaction between VirtualBox
and the nasty way Windows disk cache optimizes its disk I/O.  It is
known to update the file attributes lazily, so data could be written
to a file without the file's directory entry updated at the same time,
until some time later.

> I'm attaching the exported event log for the open-modify-save
> scenario (file-access-log.csv) in case someone knowledgeable can see
> anything weird there (Eli?).

I don't see anything interesting there, although I cannot pretend that
I've studied every single entry.





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-16  5:57                               ` Paul Eggert
  2013-01-17 10:32                                 ` Dmitry Gutov
@ 2013-01-17 17:16                                 ` David Engster
  1 sibling, 0 replies; 68+ messages in thread
From: David Engster @ 2013-01-17 17:16 UTC (permalink / raw)
  To: Paul Eggert; +Cc: 13149, Dmitry Gutov

Paul Eggert writes:
> On 01/15/2013 03:44 PM, Dmitry Gutov wrote:
>> Maybe it's a sign of my system slowly falling apart.
>
> but I'd rather not apply it if the system in question is merely
> experimental, since it introduces a race even on non-buggy systems.

Just wanted to say that I see the same issue in a VirtualBox VM running
Ubuntu 12.04 in a Windows 7 host after I upgraded to the latest Emacs
pretest (from a version somewhere around shortly before the first
one). It's difficult to reproduce, so I'm afraid bisecting the offending
commit is not feasible. It happens maybe once an hour, but then several
times in a row.

-David

^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-17 10:32                                 ` Dmitry Gutov
  2013-01-17 17:05                                   ` Eli Zaretskii
@ 2013-01-17 21:14                                   ` Paul Eggert
  2013-01-18  4:55                                     ` Dmitry Gutov
  2013-01-17 21:33                                   ` Paul Eggert
  2 siblings, 1 reply; 68+ messages in thread
From: Paul Eggert @ 2013-01-17 21:14 UTC (permalink / raw)
  To: Dmitry Gutov; +Cc: 13149

On 01/17/13 02:32, Dmitry Gutov wrote:
> I think we need this to work without requiring the user to customize a variable.

I agree.  But I would rather avoid having Emacs assume
that file system time stamps can be off by several seconds,
since that'll cause Emacs to miss changes that it should report.

Does the following patch help?  It should be applied anyway,
since it closes a minor race even on non-buggy file systems.
I'm hoping that it helps to work around your bug by using
fstat both times, instead of fstat in one place and stat
in another, since the file system bug seems to be that
fstat and stat disagree.

=== modified file 'src/ChangeLog'
--- src/ChangeLog	2013-01-17 06:29:40 +0000
+++ src/ChangeLog	2013-01-17 21:09:26 +0000
@@ -1,3 +1,11 @@
+2013-01-17  Paul Eggert  <eggert@cs.ucla.edu>
+
+	Close a race when statting and reading files (Bug#13149).
+	* fileio.c (Finsert_file_contents): Use open+fstat, not stat+open.
+	This avoids a race if the file is renamed between stat and open.
+	Also, perhaps it works around a file system bug that happen in
+	virtualized environments based on MS-Windows hosts.
+
 2013-01-17  Dmitry Antipov  <dmantipov@yandex.ru>
 
 	* lisp.h (toplevel): Add comment about using Lisp_Save_Value

=== modified file 'src/fileio.c'
--- src/fileio.c	2013-01-17 06:29:40 +0000
+++ src/fileio.c	2013-01-17 21:09:26 +0000
@@ -3492,7 +3492,6 @@
   (Lisp_Object filename, Lisp_Object visit, Lisp_Object beg, Lisp_Object end, Lisp_Object replace)
 {
   struct stat st;
-  int file_status;
   EMACS_TIME mtime;
   int fd;
   ptrdiff_t inserted = 0;
@@ -3554,26 +3553,9 @@
   orig_filename = filename;
   filename = ENCODE_FILE (filename);
 
-  fd = -1;
-
-#ifdef WINDOWSNT
-  {
-    Lisp_Object tem = Vw32_get_true_file_attributes;
-
-    /* Tell stat to use expensive method to get accurate info.  */
-    Vw32_get_true_file_attributes = Qt;
-    file_status = stat (SSDATA (filename), &st);
-    Vw32_get_true_file_attributes = tem;
-  }
-#else
-  file_status = stat (SSDATA (filename), &st);
-#endif /* WINDOWSNT */
-
-  if (file_status == 0)
-    mtime = get_stat_mtime (&st);
-  else
+  fd = emacs_open (SSDATA (filename), O_RDONLY, 0);
+  if (fd < 0)
     {
-    badopen:
       save_errno = errno;
       if (NILP (visit))
 	report_file_error ("Opening input file", Fcons (orig_filename, Qnil));
@@ -3585,6 +3567,17 @@
       goto notfound;
     }
 
+  /* Replacement should preserve point as it preserves markers.  */
+  if (!NILP (replace))
+    record_unwind_protect (restore_point_unwind, Fpoint_marker ());
+
+  record_unwind_protect (close_file_unwind, make_number (fd));
+
+  if (fstat (fd, &st) != 0)
+    report_file_error ("Getting input file status",
+		       Fcons (orig_filename, Qnil));
+  mtime = get_stat_mtime (&st);
+
   /* This code will need to be changed in order to work on named
      pipes, and it's probably just not worth it.  So we should at
      least signal an error.  */
@@ -3600,17 +3593,6 @@
 		  build_string ("not a regular file"), orig_filename);
     }
 
-  if (fd < 0)
-    if ((fd = emacs_open (SSDATA (filename), O_RDONLY, 0)) < 0)
-      goto badopen;
-
-  /* Replacement should preserve point as it preserves markers.  */
-  if (!NILP (replace))
-    record_unwind_protect (restore_point_unwind, Fpoint_marker ());
-
-  record_unwind_protect (close_file_unwind, make_number (fd));
-
-
   if (!NILP (visit))
     {
       if (!NILP (beg) || !NILP (end))







^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-17 10:32                                 ` Dmitry Gutov
  2013-01-17 17:05                                   ` Eli Zaretskii
  2013-01-17 21:14                                   ` Paul Eggert
@ 2013-01-17 21:33                                   ` Paul Eggert
  2013-01-18  4:36                                     ` Dmitry Gutov
  2 siblings, 1 reply; 68+ messages in thread
From: Paul Eggert @ 2013-01-17 21:33 UTC (permalink / raw)
  To: Dmitry Gutov; +Cc: 13149

On 01/17/13 02:32, Dmitry Gutov wrote:
> dired.c:958: stat_mtime=1358412092.606214085
> modify again
> fileio.c:5414: stat_mtime=1358412092.606214000

The first time stamp comes from lstat, the second
from stat.  If the file is actually on an NTFS file
system from the underlying host, the first time stamp
cannot possibly be right, since these file systems
have a time stamp resolution of 100 nanoseconds.
The second time stamp would be the correct one.

So it does seem to be a file system bug.  Is this something
that you can reproduce with a little C program, that
creates a file, and invoke lstat and stat on it?
What happens when you run the following program
in your file system?  It should output time stamps
that are identical.  You may need to substitute
something else (like sleep (10)) for "sync ()"
to trigger the bug.

#include <fcntl.h>
#include <sys/stat.h>
#include <stdio.h>
#include <unistd.h>

int
main (void)
{
  char const *file = "foo";
  struct stat lst, st;
  int fd;
  unlink (file);
  fd = open (file, O_CREAT | O_WRONLY, -1);
  if (fd < 0)
    return perror ("open"), 1;
  if (lstat (file, &lst) != 0)
    return perror ("lstat"), 1;
  sync ();
  if (stat (file, &st) != 0)
    return perror ("stat"), 1;
  printf ("%ld.%09ld\n", (long) lst.st_mtim.tv_sec, lst.st_mtim.tv_nsec);
  printf ("%ld.%09ld\n", (long) st.st_mtim.tv_sec, st.st_mtim.tv_nsec);
  return 0;
}

^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-17 17:05                                   ` Eli Zaretskii
@ 2013-01-18  4:15                                     ` Dmitry Gutov
  2013-01-18  7:49                                       ` Eli Zaretskii
  0 siblings, 1 reply; 68+ messages in thread
From: Dmitry Gutov @ 2013-01-18  4:15 UTC (permalink / raw)
  To: Eli Zaretskii; +Cc: 13149, eggert

On 17.01.2013 21:05, Eli Zaretskii wrote:
>> Date: Thu, 17 Jan 2013 14:32:56 +0400
>> From: Dmitry Gutov <raaahh@gmail.com>
>> CC: 13149@debbugs.gnu.org, Eli Zaretskii <eliz@gnu.org>
>>
>> Looked at the VirtualBox bug reports, found just this one:
>> https://www.virtualbox.org/ticket/10986, not much information there.
>>
>> Some more about space rays:
>> 1) I now have a version of Emacs compiled on a brand-new Fedora virtual
>> machine from emacs-24 branch (revno 111185) that exhibits the problem.
>> Just tested it simultaneously with Ubuntu, emacs-24 on Fedora is buggy,
>> Ubuntu's is not. The following items (2 and 3) are from a few hours ago,
>> when I tested Fedora machine exclusively.
>> 2) Editing the file on a different disk on the host system (HDD vs SSD)
>> makes no difference, the bug is present.
>> 3) Process Monitor doesn't show any other processes accessing the file
>> on the host machine other than VirtualBox.exe, SYSTEM and
>> SearchProtocolHost.exe. The last one goes away if I stop the Windows
>> Search service, but the problem stays.
>
> I suspect that what you see is some bad interaction between VirtualBox
> and the nasty way Windows disk cache optimizes its disk I/O.  It is
> known to update the file attributes lazily, so data could be written
> to a file without the file's directory entry updated at the same time,
> until some time later.

I wonder why I don't see that with the straight Windows build editing 
files on the local filesystem. Does it forcibly disable some optimizations?

>> I'm attaching the exported event log for the open-modify-save
>> scenario (file-access-log.csv) in case someone knowledgeable can see
>> anything weird there (Eli?).
>
> I don't see anything interesting there, although I cannot pretend that
> I've studied every single entry.

Oh well. It was worth a try.





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-17 21:33                                   ` Paul Eggert
@ 2013-01-18  4:36                                     ` Dmitry Gutov
  2013-01-18  5:01                                       ` Paul Eggert
  2013-01-18  7:57                                       ` Eli Zaretskii
  0 siblings, 2 replies; 68+ messages in thread
From: Dmitry Gutov @ 2013-01-18  4:36 UTC (permalink / raw)
  To: Paul Eggert; +Cc: 13149

On 18.01.2013 1:33, Paul Eggert wrote:
> On 01/17/13 02:32, Dmitry Gutov wrote:
>> dired.c:958: stat_mtime=1358412092.606214085
>> modify again
>> fileio.c:5414: stat_mtime=1358412092.606214000
>
> The first time stamp comes from lstat, the second
> from stat.  If the file is actually on an NTFS file
> system from the underlying host, the first time stamp
> cannot possibly be right, since these file systems
> have a time stamp resolution of 100 nanoseconds.
> The second time stamp would be the correct one.

It is on NTFS, but we're separated from it by at least CIFS server and 
client implementations.

> So it does seem to be a file system bug.  Is this something
> that you can reproduce with a little C program, that
> creates a file, and invoke lstat and stat on it?
> What happens when you run the following program
> in your file system?  It should output time stamps
> that are identical.  You may need to substitute
> something else (like sleep (10)) for "sync ()"
> to trigger the bug.

The time stamps were identical in all combinations:

1) Local VM filesystem (ext4).
2) vboxsf.
3) cifs.

a) sync ();
b) sleep (10);
c) sleep (0.1);

Maybe the bug is only triggered when we're editing an existing file?





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-17 21:14                                   ` Paul Eggert
@ 2013-01-18  4:55                                     ` Dmitry Gutov
  2013-01-18  5:26                                       ` Paul Eggert
  0 siblings, 1 reply; 68+ messages in thread
From: Dmitry Gutov @ 2013-01-18  4:55 UTC (permalink / raw)
  To: Paul Eggert; +Cc: 13149

On 18.01.2013 1:14, Paul Eggert wrote:
> On 01/17/13 02:32, Dmitry Gutov wrote:
>> I think we need this to work without requiring the user to customize a variable.
>
> I agree.  But I would rather avoid having Emacs assume
> that file system time stamps can be off by several seconds,
> since that'll cause Emacs to miss changes that it should report.

I'd like to report that after shutdown, reboot and whatever, my 
yesterday's build of emacs-24 on Ubuntu is again buggy on vboxsf. But it 
still works fine in the cifs-mounted folder, so if all else fails, I 
guess we can still revert the commit I mentioned previously and 
recommend people to avoid vboxsf. Maybe then change that code 
piece-by-piece to see what causes the breakage.

> Does the following patch help?  It should be applied anyway,
> since it closes a minor race even on non-buggy file systems.
> I'm hoping that it helps to work around your bug by using
> fstat both times, instead of fstat in one place and stat
> in another, since the file system bug seems to be that
> fstat and stat disagree.

Alas, no dice. It didn't help neither with vboxsf, nor with cifs.





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-18  4:36                                     ` Dmitry Gutov
@ 2013-01-18  5:01                                       ` Paul Eggert
  2013-01-18  5:10                                         ` Dmitry Gutov
  2013-01-18  7:57                                       ` Eli Zaretskii
  1 sibling, 1 reply; 68+ messages in thread
From: Paul Eggert @ 2013-01-18  5:01 UTC (permalink / raw)
  To: Dmitry Gutov; +Cc: 13149

On 01/17/2013 08:36 PM, Dmitry Gutov wrote:
> The time stamps were identical in all combinations:

Did vboxsf and/or cifs report time stamps that
were not on 100-ns boundaries?  That would be a bug.

How about the following program?  What does it output?

#include <fcntl.h>
#include <sys/stat.h>
#include <stdio.h>
#include <unistd.h>
#include <time.h>

static int
report_times (int fd, char const *file)
{
  struct stat fst, lst, st;
  if (fstat (fd, &fst) != 0)
    return perror ("fstat"), -1;
  if (lstat (file, &lst) != 0)
    return perror ("lstat"), -1;
  if (stat (file, &st) != 0)
    return perror ("stat"), -1;
  printf ("%ld.%09ld fstat\n", (long) fst.st_mtim.tv_sec, fst.st_mtim.tv_nsec);
  printf ("%ld.%09ld lstat\n", (long) lst.st_mtim.tv_sec, lst.st_mtim.tv_nsec);
  printf ("%ld.%09ld stat\n", (long) st.st_mtim.tv_sec, st.st_mtim.tv_nsec);
  printf ("\n");
  return 0;
}

int
main (void)
{
  static char const file[] = "foo";
  struct timespec interval;
  int fd;
  unlink (file);
  fd = open (file, O_CREAT | O_WRONLY, -1);
  if (fd < 0)
    return perror ("open"), 1;
  if (report_times (fd, file) != 0)
    return 1;
  interval.tv_sec = 0;
  interval.tv_nsec = 10000000;
  if (nanosleep (&interval, 0) != 0)
    return perror ("nanosleep"), 1;
  if (write (fd, file, sizeof file - 1) != sizeof file - 1)
    return perror ("write"), 1;
  if (report_times (fd, file) != 0)
    return 1;
  return 0;
}






^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-18  5:01                                       ` Paul Eggert
@ 2013-01-18  5:10                                         ` Dmitry Gutov
  2013-01-18  5:25                                           ` Paul Eggert
  0 siblings, 1 reply; 68+ messages in thread
From: Dmitry Gutov @ 2013-01-18  5:10 UTC (permalink / raw)
  To: Paul Eggert; +Cc: 13149

On 18.01.2013 9:01, Paul Eggert wrote:
> On 01/17/2013 08:36 PM, Dmitry Gutov wrote:
>> The time stamps were identical in all combinations:
>
> Did vboxsf and/or cifs report time stamps that
> were not on 100-ns boundaries?  That would be a bug.

Nope, only on ext4.

> How about the following program?  What does it output?

vboxsf:

1358485717.265985900 fstat
1358485717.265985900 lstat
1358485717.265985900 stat

1358485717.265985900 fstat
1358485717.265985900 lstat
1358485717.265985900 stat

cifs:

1358485764.638001400 fstat
1358485764.638001400 lstat
1358485764.638001400 stat

1358485764.638001400 fstat
1358485764.638001400 lstat
1358485764.638001400 stat

ext4 (just for completeness):

1358485649.211315918 fstat
1358485649.211315918 lstat
1358485649.211315918 stat

1358485649.223315921 fstat
1358485649.223315921 lstat
1358485649.223315921 stat

Ran it quite a few times, the results were always identical.





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-18  5:10                                         ` Dmitry Gutov
@ 2013-01-18  5:25                                           ` Paul Eggert
  2013-01-18  5:54                                             ` Dmitry Gutov
  2013-01-18  7:56                                             ` Eli Zaretskii
  0 siblings, 2 replies; 68+ messages in thread
From: Paul Eggert @ 2013-01-18  5:25 UTC (permalink / raw)
  To: Dmitry Gutov; +Cc: 13149

On 01/17/2013 09:10 PM, Dmitry Gutov wrote:
> cifs:
> 
> 1358485764.638001400 fstat
> 1358485764.638001400 lstat
> 1358485764.638001400 stat
> *
> 1358485764.638001400 fstat
> 1358485764.638001400 lstat
> 1358485764.638001400 stat

That looks busted, since there's
a 10 ms sleep followed by a write at the two
points I marked "*" above, which means that
fstat, lstat, and stat are all wrong after the "*".
There's a similar problem with your vboxsf output.
ext4 looks OK.

I see that there is a known bug about Samba and 'write'
and st_mtime; see <https://bugzilla.samba.org/show_bug.cgi?id=6925>.
Could this be the bug you're running into, with cifs?

If you change the sleep to 100 ms, does that fix
the above behavior?  How about 1 second?  2 seconds?

^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-18  4:55                                     ` Dmitry Gutov
@ 2013-01-18  5:26                                       ` Paul Eggert
  0 siblings, 0 replies; 68+ messages in thread
From: Paul Eggert @ 2013-01-18  5:26 UTC (permalink / raw)
  To: Dmitry Gutov; +Cc: 13149

On 01/17/2013 08:55 PM, Dmitry Gutov wrote:
> Alas, no dice. It didn't help neither with vboxsf, nor with cifs.

Too bad.  Oh well, it's a change that should be made anyway,
so I installed it as trunk bzr 111546.  I'll look into the
main problem a bit more.





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-18  5:25                                           ` Paul Eggert
@ 2013-01-18  5:54                                             ` Dmitry Gutov
  2013-01-18  6:22                                               ` Dmitry Gutov
  2013-01-18  7:56                                             ` Eli Zaretskii
  1 sibling, 1 reply; 68+ messages in thread
From: Dmitry Gutov @ 2013-01-18  5:54 UTC (permalink / raw)
  To: Paul Eggert; +Cc: 13149

On 18.01.2013 9:25, Paul Eggert wrote:
> On 01/17/2013 09:10 PM, Dmitry Gutov wrote:
>> cifs:
>>
>> 1358485764.638001400 fstat
>> 1358485764.638001400 lstat
>> 1358485764.638001400 stat
>> *
>> 1358485764.638001400 fstat
>> 1358485764.638001400 lstat
>> 1358485764.638001400 stat
>
> That looks busted, since there's
> a 10 ms sleep followed by a write at the two
> points I marked "*" above, which means that
> fstat, lstat, and stat are all wrong after the "*".
> There's a similar problem with your vboxsf output.
> ext4 looks OK.

Two points? I see one asterisk. Otherwise, yes, looks like a problem.

> I see that there is a known bug about Samba and 'write'
> and st_mtime; see <https://bugzilla.samba.org/show_bug.cgi?id=6925>.
> Could this be the bug you're running into, with cifs?

Maybe it is, I don't know. The bug describes a Linux server and says 
that the Windows client is also having the problem. I just mounted the 
shared folder on the same machine as a different disk, and the native 
Emacs trunk build doesn't seem to trigger the bug.

> If you change the sleep to 100 ms, does that fix
> the above behavior?  How about 1 second?  2 seconds?

Nope, not even 10 or 60 seconds. The pause is visible, but the numbers 
are the same.





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-18  5:54                                             ` Dmitry Gutov
@ 2013-01-18  6:22                                               ` Dmitry Gutov
  0 siblings, 0 replies; 68+ messages in thread
From: Dmitry Gutov @ 2013-01-18  6:22 UTC (permalink / raw)
  To: Paul Eggert; +Cc: 13149

On 18.01.2013 9:54, Dmitry Gutov wrote:
> On 18.01.2013 9:25, Paul Eggert wrote:
>> If you change the sleep to 100 ms, does that fix
>> the above behavior?  How about 1 second?  2 seconds?
>
> Nope, not even 10 or 60 seconds. The pause is visible, but the numbers
> are the same.

I'd like to add that when I open a file on cifs in a emacs-24 Emacs 
build, and then do "touch <filename>" in the console on the server (host 
machine), Emacs still reliably detects the change.

If I do nothing, and auto-revert-mode is on, it will revert it in a few 
seconds. If I "touch" and then quickly switch to the Emacs in the VM and 
try to make a change, it also says "file changed, really edit?"

^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-18  4:15                                     ` Dmitry Gutov
@ 2013-01-18  7:49                                       ` Eli Zaretskii
  0 siblings, 0 replies; 68+ messages in thread
From: Eli Zaretskii @ 2013-01-18  7:49 UTC (permalink / raw)
  To: Dmitry Gutov; +Cc: 13149, eggert

> Date: Fri, 18 Jan 2013 08:15:43 +0400
> From: Dmitry Gutov <raaahh@gmail.com>
> CC: eggert@cs.ucla.edu, 13149@debbugs.gnu.org
> 
> > I suspect that what you see is some bad interaction between VirtualBox
> > and the nasty way Windows disk cache optimizes its disk I/O.  It is
> > known to update the file attributes lazily, so data could be written
> > to a file without the file's directory entry updated at the same time,
> > until some time later.
> 
> I wonder why I don't see that with the straight Windows build editing 
> files on the local filesystem.

This is speculation, but I presume that locally the file-I/O API calls
interact with the cached files better than what VirtualBox's Posix
emulation does.

Or maybe I'm wrong, and we will start seeing similar problems on
Windows, now that Emacs uses 'fstat' much more than it did a year or
so ago (when 'fstat' was not used in the native Windows build at all).





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-18  5:25                                           ` Paul Eggert
  2013-01-18  5:54                                             ` Dmitry Gutov
@ 2013-01-18  7:56                                             ` Eli Zaretskii
  2013-01-18 14:45                                               ` Dmitry Gutov
  2013-01-18 21:35                                               ` Paul Eggert
  1 sibling, 2 replies; 68+ messages in thread
From: Eli Zaretskii @ 2013-01-18  7:56 UTC (permalink / raw)
  To: Paul Eggert; +Cc: 13149, dgutov

> Date: Thu, 17 Jan 2013 21:25:31 -0800
> From: Paul Eggert <eggert@cs.ucla.edu>
> CC: 13149@debbugs.gnu.org, Eli Zaretskii <eliz@gnu.org>
> 
> On 01/17/2013 09:10 PM, Dmitry Gutov wrote:
> > cifs:
> > 
> > 1358485764.638001400 fstat
> > 1358485764.638001400 lstat
> > 1358485764.638001400 stat
> > *
> > 1358485764.638001400 fstat
> > 1358485764.638001400 lstat
> > 1358485764.638001400 stat
> 
> That looks busted, since there's
> a 10 ms sleep followed by a write at the two
> points I marked "*" above, which means that
> fstat, lstat, and stat are all wrong after the "*".

Who said anything was actually written to the file?  You'd need
'fsync' to be sure, don't you?





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-18  4:36                                     ` Dmitry Gutov
  2013-01-18  5:01                                       ` Paul Eggert
@ 2013-01-18  7:57                                       ` Eli Zaretskii
  1 sibling, 0 replies; 68+ messages in thread
From: Eli Zaretskii @ 2013-01-18  7:57 UTC (permalink / raw)
  To: Dmitry Gutov; +Cc: 13149, eggert

> Date: Fri, 18 Jan 2013 08:36:32 +0400
> From: Dmitry Gutov <raaahh@gmail.com>
> CC: 13149@debbugs.gnu.org, Eli Zaretskii <eliz@gnu.org>
> 
> > So it does seem to be a file system bug.  Is this something
> > that you can reproduce with a little C program, that
> > creates a file, and invoke lstat and stat on it?
> > What happens when you run the following program
> > in your file system?  It should output time stamps
> > that are identical.  You may need to substitute
> > something else (like sleep (10)) for "sync ()"
> > to trigger the bug.
> 
> The time stamps were identical in all combinations:

A small wonder, since nothing is written to the file in this test
proggy, unlike in the original scenario.





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-18  7:56                                             ` Eli Zaretskii
@ 2013-01-18 14:45                                               ` Dmitry Gutov
  2013-01-18 21:35                                               ` Paul Eggert
  1 sibling, 0 replies; 68+ messages in thread
From: Dmitry Gutov @ 2013-01-18 14:45 UTC (permalink / raw)
  To: Eli Zaretskii; +Cc: 13149, Paul Eggert

On 18.01.2013 11:56, Eli Zaretskii wrote:
>> Date: Thu, 17 Jan 2013 21:25:31 -0800
>> From: Paul Eggert <eggert@cs.ucla.edu>
>> CC: 13149@debbugs.gnu.org, Eli Zaretskii <eliz@gnu.org>
>>
>> On 01/17/2013 09:10 PM, Dmitry Gutov wrote:
>>> cifs:
>>>
>>> 1358485764.638001400 fstat
>>> 1358485764.638001400 lstat
>>> 1358485764.638001400 stat
>>> *
>>> 1358485764.638001400 fstat
>>> 1358485764.638001400 lstat
>>> 1358485764.638001400 stat
>>
>> That looks busted, since there's
>> a 10 ms sleep followed by a write at the two
>> points I marked "*" above, which means that
>> fstat, lstat, and stat are all wrong after the "*".
>
> Who said anything was actually written to the file?  You'd need
> 'fsync' to be sure, don't you?

Sticking fsync(fd) after the call to 'write' doesn't change anything.

If, however, I move the 'nanosleep' after the 'write' and set the 
interval to 1 or 2 seconds, on vboxsf the numbers often become 
different, but without guarantee. With 1 second, they usually the same, 
with 2 second, they're mostly different, but still the same sometimes.

gutov@vbx:~/docs/Ruby$ ~/emacs-bzr/fs-test2
1358520180.757726300 fstat
1358520180.757726300 lstat
1358520180.757726300 stat

1358520181.689844700 fstat
1358520181.689844700 lstat
1358520181.689844700 stat

gutov@vbx:~/docs/Ruby$ ~/emacs-bzr/fs-test2
1358520183.414063600 fstat
1358520183.414063600 lstat
1358520183.414063600 stat

1358520183.414063600 fstat
1358520183.414063600 lstat
1358520183.414063600 stat

Adding another 'nanosleep' before the 'write' doesn't change that.

On cifs, the numbers are never different.

#include <fcntl.h>
#include <sys/stat.h>
#include <stdio.h>
#include <unistd.h>
#include <time.h>

static int
report_times (int fd, char const *file)
{
   struct stat fst, lst, st;
   if (fstat (fd, &fst) != 0)
     return perror ("fstat"), -1;
   if (lstat (file, &lst) != 0)
     return perror ("lstat"), -1;
   if (stat (file, &st) != 0)
     return perror ("stat"), -1;
   printf ("%ld.%09ld fstat\n", (long) fst.st_mtim.tv_sec, 
fst.st_mtim.tv_nsec);
   printf ("%ld.%09ld lstat\n", (long) lst.st_mtim.tv_sec, 
lst.st_mtim.tv_nsec);
   printf ("%ld.%09ld stat\n", (long) st.st_mtim.tv_sec, 
st.st_mtim.tv_nsec);
   printf ("\n");
   return 0;
}

int
main (void)
{
   static char const file[] = "foo";
   struct timespec interval, bef_interval;
   int fd;
   unlink (file);
   fd = open (file, O_CREAT | O_WRONLY, -1);
   if (fd < 0)
     return perror ("open"), 1;
   if (report_times (fd, file) != 0)
     return 1;
   bef_interval.tv_sec = 0;
   bef_interval.tv_nsec = 100000000;
   interval.tv_sec = 2;
   interval.tv_nsec = 0;
   //  if (nanosleep (&bef_interval, 0) != 0)
   //  return perror ("nanosleep"), 1;
   if (write (fd, file, sizeof file - 1) != sizeof file - 1)
     return perror ("write"), 1;
   // fsync(fd);
   if (nanosleep (&interval, 0) != 0)
     return perror ("nanosleep"), 1;
   if (report_times (fd, file) != 0)
     return 1;
   return 0;
}






^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-18  7:56                                             ` Eli Zaretskii
  2013-01-18 14:45                                               ` Dmitry Gutov
@ 2013-01-18 21:35                                               ` Paul Eggert
  2013-01-18 22:52                                                 ` Dmitry Gutov
  1 sibling, 1 reply; 68+ messages in thread
From: Paul Eggert @ 2013-01-18 21:35 UTC (permalink / raw)
  To: Eli Zaretskii; +Cc: 13149, dgutov

On 01/17/13 23:56, Eli Zaretskii wrote:
> Who said anything was actually written to the file?  You'd need
> 'fsync' to be sure, don't you?

That depends on what one means by "actually written".  :-)

POSIX says a 'write' must result in st_mtime being updated
some time before the file's time stamp is used (and 'fstat'
and 'stat' both count as uses).  It is not required that the
written data or the updated st_mtime physically be stored on
nonvolatile storage; if the system crashes, the updates might
get lost.]

Also, it's not required that st_mtime must be updated to the
exact time stamp of the write -- it can be updated to a later
time stamp, so long as the later time stamp comes before st_mtime's
first use.  But the point is that st_mtime must be updated
"in memory", so to speak, just as the file's data must get
updated "in memory", so that any uses of the file see the
new st_mtime and the new data that got written.

Here, we seem to have some cases where a write can occur
but st_mtime is not updated before the next stat or fstat.
I don't yet know how to characterize these cases, or how to
work around them.  Even Emacs's old approach (allow up to
1 second of slop) seems like it won't work in some cases
that have been reported here: over 2 seconds of slop in
<http://bugs.gnu.org/13149#115>, and over one minute of
slop in <http://bugs.gnu.org/13149##100>!

One approach that I've been toying with is that
Emacs could inspect the file system type, and if the file
system is known to be reliable (ext2, ufs, zfs, ...) we stick
with the new behavior in the trunk which uses fstat with no slop,
but otherwise we fall back on the Emacs-24 behavior, using stat
with 1 second of slop.  This won't allow the instances of
longer-than-1-second slops that we've seen reported here,
but maybe that's good enough.

I'm not particularly happy with this idea, but there is
a limit to what Emacs can do to work around filesystem bugs.

^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-18 21:35                                               ` Paul Eggert
@ 2013-01-18 22:52                                                 ` Dmitry Gutov
  2013-01-19  0:55                                                   ` Paul Eggert
  0 siblings, 1 reply; 68+ messages in thread
From: Dmitry Gutov @ 2013-01-18 22:52 UTC (permalink / raw)
  To: Paul Eggert; +Cc: 13149

On 19.01.2013 1:35, Paul Eggert wrote:
> Here, we seem to have some cases where a write can occur
> but st_mtime is not updated before the next stat or fstat.
> I don't yet know how to characterize these cases, or how to
> work around them.  Even Emacs's old approach (allow up to
> 1 second of slop) seems like it won't work in some cases
> that have been reported here: over 2 seconds of slop in
> <http://bugs.gnu.org/13149#115>, and over one minute of
> slop in <http://bugs.gnu.org/13149##100>!

Is is possible that the test is measuring something not directly 
relevant? Like I mentioned, emacs-24 build seems to work fine on cifs in 
all observable respects, but with this test, cifs has the slop of 
infinity. Or close enough.





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-18 22:52                                                 ` Dmitry Gutov
@ 2013-01-19  0:55                                                   ` Paul Eggert
  2013-01-19  1:09                                                     ` Dmitry Gutov
  0 siblings, 1 reply; 68+ messages in thread
From: Paul Eggert @ 2013-01-19  0:55 UTC (permalink / raw)
  To: Dmitry Gutov; +Cc: 13149

On 01/18/2013 02:52 PM, Dmitry Gutov wrote:
> Is is possible that the test is measuring something not directly relevant?
> Like I mentioned, emacs-24 build seems to work fine on cifs in all observable respects

I suspect the problem is that cifs mishandles fstat
but works with stat/lstat.  What does the following
program do for you?

#include <fcntl.h>
#include <sys/stat.h>
#include <stdio.h>
#include <unistd.h>
#include <time.h>

static int
report_times (int fd, char const *file)
{
  struct stat fst, lst, st;
  if (0 <= fd && fstat (fd, &fst) != 0)
    return perror ("fstat"), -1;
  if (lstat (file, &lst) != 0)
    return perror ("lstat"), -1;
  if (stat (file, &st) != 0)
    return perror ("stat"), -1;
  if (0 <= fd)
    printf ("%ld.%09ld fstat\n", (long) fst.st_mtim.tv_sec, fst.st_mtim.tv_nsec);
  printf ("%ld.%09ld lstat\n", (long) lst.st_mtim.tv_sec, lst.st_mtim.tv_nsec);
  printf ("%ld.%09ld stat\n", (long) st.st_mtim.tv_sec, st.st_mtim.tv_nsec);
  printf ("\n");
  return 0;
}

int
main (void)
{
  static char const file[] = "foo";
  struct timespec interval;
  int fd;
  unlink (file);
  fd = open (file, O_CREAT | O_WRONLY, -1);
  if (fd < 0)
    return perror ("open O_CREAT"), 1;
  if (report_times (fd, file) != 0)
    return 1;
  interval.tv_sec = 0;
  interval.tv_nsec = 10000000;
  if (nanosleep (&interval, 0) != 0)
    return perror ("nanosleep"), 1;
  if (write (fd, file, sizeof file - 1) != sizeof file - 1)
    return perror ("write"), 1;
  if (report_times (fd, file) != 0)
    return 1;
  if (close (fd) != 0)
    return perror ("close"), 1;
  if (report_times (-1, file) != 0)
    return 1;
  fd = open (file, O_RDONLY, 0);
  if (fd < 0)
    return perror ("open O_RDONLY"), 1;
  if (report_times (fd, file) != 0)
    return 1;
  return 0;
}


It should output something like this:

1358556859.329948949 fstat
1358556859.329948949 lstat
1358556859.329948949 stat

1358556859.341948950 fstat
1358556859.341948950 lstat
1358556859.341948950 stat

1358556859.341948950 lstat
1358556859.341948950 stat

1358556859.341948950 fstat
1358556859.341948950 lstat
1358556859.341948950 stat

That is, the first batch of times should differ from the other
batches, all of which should be the same.






^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-19  0:55                                                   ` Paul Eggert
@ 2013-01-19  1:09                                                     ` Dmitry Gutov
  2013-01-19  2:37                                                       ` Paul Eggert
  0 siblings, 1 reply; 68+ messages in thread
From: Dmitry Gutov @ 2013-01-19  1:09 UTC (permalink / raw)
  To: Paul Eggert; +Cc: 13149

On 19.01.2013 4:55, Paul Eggert wrote:
> On 01/18/2013 02:52 PM, Dmitry Gutov wrote:
>> Is is possible that the test is measuring something not directly relevant?
>> Like I mentioned, emacs-24 build seems to work fine on cifs in all observable respects
>
> I suspect the problem is that cifs mishandles fstat
> but works with stat/lstat.  What does the following
> program do for you?

cifs:

1358557459.946082000 fstat
1358557459.946082000 lstat
1358557459.946082000 stat

1358557459.946082000 fstat
1358557459.946082000 lstat
1358557459.946082000 stat

1358557459.946082000 lstat
1358557459.946082000 stat

1358557459.958583600 fstat
1358557459.958583600 lstat
1358557459.958583600 stat

vboxsf:

1358557454.975950900 fstat
1358557454.975950900 lstat
1358557454.975950900 stat

1358557454.975950900 fstat
1358557454.975950900 lstat
1358557454.975950900 stat

1358557454.988952600 lstat
1358557454.988952600 stat

1358557454.988952600 fstat
1358557454.988952600 lstat
1358557454.988952600 stat

So, vboxsf sees the change after the file has been closed, cifs - when 
it's reopened.





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-19  1:09                                                     ` Dmitry Gutov
@ 2013-01-19  2:37                                                       ` Paul Eggert
  2013-01-19  4:02                                                         ` Dmitry Gutov
  0 siblings, 1 reply; 68+ messages in thread
From: Paul Eggert @ 2013-01-19  2:37 UTC (permalink / raw)
  To: Dmitry Gutov; +Cc: 13149

[-- Attachment #1: Type: text/plain, Size: 407 bytes --]

On 01/18/2013 05:09 PM, Dmitry Gutov wrote:
> So, vboxsf sees the change after the file has been closed, cifs - when it's reopened.

My goodness, I didn't realize CIFS was *that* buggy.

But this suggests a reason why the patch in
<http://bugs.gnu.org/13149#61> worked for vboxsf
and not CIFS, and even better it suggests a
variation that might work with CIFS too.
Could you please try the attached patch?


[-- Attachment #2: reopen.txt --]
[-- Type: text/plain, Size: 4286 bytes --]

=== modified file 'src/ChangeLog'
--- src/ChangeLog	2013-01-19 00:40:07 +0000
+++ src/ChangeLog	2013-01-19 02:32:33 +0000
@@ -1,5 +1,18 @@
 2013-01-19  Paul Eggert  <eggert@cs.ucla.edu>
 
+	Work around bug in CIFS and vboxsf file systems (Bug#13149).
+	The bug was observed on Ubuntu operating inside a virtual machine,
+	editing files mounted via CIFS or vboxsf from the MS Windows 7 host.
+	The workaround introduces a race condition on non-buggy hosts,
+	but it's an unlikely race and anyway there's a nearly identical
+	nearby race that can't be fixed.
+	* fileio.c (valid_timestamp_file_system, timestamp_file_system):
+	New static vars.
+	(Fwrite_region): Test for file system time stamp bug.
+	(init_fileio): New function.
+	* lisp.h (init_fileio): Declare it.
+	* emacs.c (main): Call it.
+
 	* fileio.c (Finsert_file_contents): Simplify new diagnostic
 	and make it more consistent with other stat-failure diagnostics.
 

=== modified file 'src/emacs.c'
--- src/emacs.c	2013-01-13 20:03:01 +0000
+++ src/emacs.c	2013-01-19 02:32:33 +0000
@@ -1317,6 +1317,7 @@
     }
 
   init_callproc ();	/* Must follow init_cmdargs but not init_sys_modes.  */
+  init_fileio ();
   init_lread ();
 #ifdef WINDOWSNT
   /* Check to see if Emacs has been installed correctly.  */

=== modified file 'src/fileio.c'
--- src/fileio.c	2013-01-19 00:40:07 +0000
+++ src/fileio.c	2013-01-19 02:32:33 +0000
@@ -103,6 +103,11 @@
 /* Set by auto_save_1 if an error occurred during the last auto-save.  */
 static bool auto_save_error_occurred;
 
+/* If VALID_TIMESTAMP_FILE_SYSTEM, then TIMESTAMP_FILE_SYSTEM is the device
+   number of a file system where time stamps were observed to to work.  */
+static bool valid_timestamp_file_system;
+static dev_t timestamp_file_system;
+
 /* The symbol bound to coding-system-for-read when
    insert-file-contents is called for recovering a file.  This is not
    an actual coding system name, but just an indicator to tell
@@ -4971,6 +4976,48 @@
   /* Discard the unwind protect for close_file_unwind.  */
   specpdl_ptr = specpdl + count1;
 
+  /* Some file systems have a bug where st_mtime is not updated
+     properly after a write.  For example, CIFS might not see the
+     st_mtime change until after the file is opened again.
+
+     Attempt to detect this file system bug, and update MODTIME to the
+     newer st_mtime if the bug appears to be present.  This introduces
+     a race condition, so to avoid most instances of the race condition
+     on non-buggy file systems, skip this check if the most recently
+     encountered non-buggy file system was the current file system.
+
+     A race condition can occur if some other process modifies the
+     file between the fstat above and the fstat below, but the race is
+     unlikely and a similar race between the last write and the fstat
+     above cannot possibly be closed anyway.  */
+
+  if (EMACS_TIME_VALID_P (modtime)
+      && ! (valid_timestamp_file_system && st.st_dev == timestamp_file_system))
+    {
+      int desc1 = emacs_open (fn, O_WRONLY, 0);
+      if (0 <= desc1)
+	{
+	  struct stat st1;
+	  if (fstat (desc1, &st1) == 0
+	      && st.st_dev == st1.st_dev && st.st_ino == st1.st_ino)
+	    {
+	      EMACS_TIME modtime1 = get_stat_mtime (&st1);
+	      if (EMACS_TIME_EQ (modtime, modtime1)
+		  && st.st_size == st1.st_size)
+		{
+		  timestamp_file_system = st.st_dev;
+		  valid_timestamp_file_system = 1;
+		}
+	      else
+		{
+		  st.st_size = st1.st_size;
+		  modtime = modtime1;
+		}
+	    }
+	  emacs_close (desc1);
+	}
+    }
+
   /* Call write-region-post-annotation-function. */
   while (CONSP (Vwrite_region_annotation_buffers))
     {
@@ -5768,6 +5815,12 @@
 
 \f
 void
+init_fileio (void)
+{
+  valid_timestamp_file_system = 0;
+}
+
+void
 syms_of_fileio (void)
 {
   DEFSYM (Qoperations, "operations");

=== modified file 'src/lisp.h'
--- src/lisp.h	2013-01-17 06:29:40 +0000
+++ src/lisp.h	2013-01-19 02:32:33 +0000
@@ -3299,6 +3299,7 @@
 extern bool internal_delete_file (Lisp_Object);
 extern bool file_directory_p (const char *);
 extern bool file_accessible_directory_p (const char *);
+extern void init_fileio (void);
 extern void syms_of_fileio (void);
 extern Lisp_Object make_temp_name (Lisp_Object, bool);
 extern Lisp_Object Qdelete_file;


^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-19  2:37                                                       ` Paul Eggert
@ 2013-01-19  4:02                                                         ` Dmitry Gutov
  2013-01-19  4:51                                                           ` Paul Eggert
  0 siblings, 1 reply; 68+ messages in thread
From: Dmitry Gutov @ 2013-01-19  4:02 UTC (permalink / raw)
  To: Paul Eggert; +Cc: 13149

On 19.01.2013 6:37, Paul Eggert wrote:
> On 01/18/2013 05:09 PM, Dmitry Gutov wrote:
>> So, vboxsf sees the change after the file has been closed, cifs - when it's reopened.
>
> My goodness, I didn't realize CIFS was *that* buggy.
>
> But this suggests a reason why the patch in
> <http://bugs.gnu.org/13149#61> worked for vboxsf
> and not CIFS, and even better it suggests a
> variation that might work with CIFS too.
> Could you please try the attached patch?

Ooooh yeah. It works. Thanks a lot! :)

I think I saw it fail once, right after I recompiled the patched 
version, but after that it's been working fine, on both filesystems.

That means, better than the emacs-24 build, which started to go haywire 
again on vboxsf. I even opened the same file in both at the same time, 
and the patched trunk was the non-buggy one.

So I think it's good to install, but I can play with it for a few days 
first, if you prefer.

^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-19  4:02                                                         ` Dmitry Gutov
@ 2013-01-19  4:51                                                           ` Paul Eggert
       [not found]                                                             ` <DEB91990BBBB4255BFB466956EB54214@us.oracl!>
                                                                               ` (4 more replies)
  0 siblings, 5 replies; 68+ messages in thread
From: Paul Eggert @ 2013-01-19  4:51 UTC (permalink / raw)
  To: Dmitry Gutov; +Cc: 13149

On 01/18/2013 08:02 PM, Dmitry Gutov wrote:
> I think it's good to install

Likewise.  It may not fix all the problems in this area, but
given the test results posted so far it should fix a good many
of them.  I pushed it as trunk bzr 111550.

Drew, I don't know whether this fixes the problems you observed
on Windows XP -- could you please let us know if you
still observe those problems post-111550?  Thanks.

^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-19  4:51                                                           ` Paul Eggert
                                                                               ` (3 preceding siblings ...)
       [not found]                                                             ` <DEB91990BBBB4255BFB466956EB54214@us.oracl! e.com>
@ 2013-01-19  5:02                                                             ` Drew Adams
  2013-02-01 16:32                                                               ` Drew Adams
  4 siblings, 1 reply; 68+ messages in thread
From: Drew Adams @ 2013-01-19  5:02 UTC (permalink / raw)
  To: 'Paul Eggert', 'Dmitry Gutov'; +Cc: 13149

> > I think it's good to install
> 
> Likewise.  It may not fix all the problems in this area, but
> given the test results posted so far it should fix a good many
> of them.  I pushed it as trunk bzr 111550.
> 
> Drew, I don't know whether this fixes the problems you observed
> on Windows XP -- could you please let us know if you
> still observe those problems post-111550?  Thanks.

Thanks for remembering me. ;-)  Just kidding.

I'll be glad to keep an eye out.  But I probably won't be able to help any more
with this.  As you've seen, you have had to dig into it without me.

I only saw the problem once.  And I have no idea what I was doing at the time or
whether it even mattered.  Anyway, I'm glad you were able to learn something
about either the problem I saw or something similar.  Let's hope it's taken care
of now.  Thx.






^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-01-19  5:02                                                             ` Drew Adams
@ 2013-02-01 16:32                                                               ` Drew Adams
  2013-02-01 16:43                                                                 ` Drew Adams
                                                                                   ` (2 more replies)
  0 siblings, 3 replies; 68+ messages in thread
From: Drew Adams @ 2013-02-01 16:32 UTC (permalink / raw)
  To: 'Paul Eggert', 'Dmitry Gutov'; +Cc: 13149

> > > I think it's good to install
> > 
> > Likewise.  It may not fix all the problems in this area, but
> > given the test results posted so far it should fix a good many
> > of them.  I pushed it as trunk bzr 111550.
> > 
> > Drew, I don't know whether this fixes the problems you observed
> > on Windows XP -- could you please let us know if you
> > still observe those problems post-111550?  Thanks.
> 
> I'll be glad to keep an eye out.  But I probably won't be 
> able to help any more with this.  As you've seen, you have had
> to dig into it without me.
> 
> I only saw the problem once.  And I have no idea what I was 
> doing at the time or whether it even mattered.  Anyway, I'm glad
> you were able to learn something about either the problem I saw
> or something similar.  Let's hope it's taken care of now.  Thx.

Nope, this is still a problem - it just happened again, with a 2-day-old build.

I was editing a file, then had just saved it (C-x C-s) and tried to continue
editing, and I got the message saying that the file on disk had been changed and
asking me if I really wanted to edit the buffer.

IOW: I typed some chars, did C-x C-s, then tried to type some more chars.  Boom.

Oh, and BTW, shouldn't the prompt/message saying that the file was changed and
asking me whether I wanted to edit be recorded in *Messages*?  It is not.  That
too seems like a bug, but I'll let you decide that.

This is with this build:

In GNU Emacs 24.3.50.1 (i386-mingw-nt5.1.2600)
 of 2013-01-30 on ODIEONE
Bzr revision: 111631 michael.albinus@gmx.de-20130130192046-nx4rskw7jemmtrw8
Windowing system distributor `Microsoft Corp.', version 5.1.2600
Configured using:
 `configure --with-gcc (4.7) --no-opt --enable-checking --cflags
 -IC:/Devel/emacs/build/include --ldflags -LC:/Devel/emacs/build/lib'







^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-02-01 16:32                                                               ` Drew Adams
@ 2013-02-01 16:43                                                                 ` Drew Adams
  2013-02-01 16:49                                                                   ` Drew Adams
  2013-02-01 18:43                                                                 ` Eli Zaretskii
  2013-02-01 21:05                                                                 ` Paul Eggert
  2 siblings, 1 reply; 68+ messages in thread
From: Drew Adams @ 2013-02-01 16:43 UTC (permalink / raw)
  To: 'Paul Eggert', 'Dmitry Gutov'; +Cc: 13149

> Nope, this is still a problem - it just happened again, with 
> a 2-day-old build.
> 
> I was editing a file, then had just saved it (C-x C-s) and 
> tried to continue
> editing, and I got the message saying that the file on disk 
> had been changed and
> asking me if I really wanted to edit the buffer.
> 
> IOW: I typed some chars, did C-x C-s, then tried to type some 
> more chars.  Boom.
> 
> Oh, and BTW, shouldn't the prompt/message saying that the 
> file was changed and
> asking me whether I wanted to edit be recorded in *Messages*? 
>  It is not.  That
> too seems like a bug, but I'll let you decide that.
> 
> This is with this build... 2013-01-30 on ODIEONE Bzr revision: 111631 

Wow, it just happened _again_, and I wasn't even doing anything in Emacs (and
certainly wasn't doing anything to the file outside Emacs).

I was reading mail (outside Emacs), then went back to Emacs and tried to type
some more in the buffer (which I know had been saved), and I got the same
message/prompt again.

HTH.






^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-02-01 16:43                                                                 ` Drew Adams
@ 2013-02-01 16:49                                                                   ` Drew Adams
  0 siblings, 0 replies; 68+ messages in thread
From: Drew Adams @ 2013-02-01 16:49 UTC (permalink / raw)
  To: 'Paul Eggert', 'Dmitry Gutov'; +Cc: 13149

> Wow, it just happened _again_, and I wasn't even doing 
> anything in Emacs (and
> certainly wasn't doing anything to the file outside Emacs).
> 
> I was reading mail (outside Emacs), then went back to Emacs 
> and tried to type some more in the buffer (which I know had
> been saved), and I got the same message/prompt again.

If that last message of mine confuses things, don't put too much stock in it.

There's a tiny possibility that after the first message/prompt I did not bother
to revert the buffer (I don't remember), so perhaps the second message/prompt
was just a repeat from the same Emacs state.  Sorry, IOW, I can't be sure about
this second occurrence.  HTH/thx.






^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-02-01 16:32                                                               ` Drew Adams
  2013-02-01 16:43                                                                 ` Drew Adams
@ 2013-02-01 18:43                                                                 ` Eli Zaretskii
  2013-02-01 19:19                                                                   ` Drew Adams
  2013-02-01 21:05                                                                 ` Paul Eggert
  2 siblings, 1 reply; 68+ messages in thread
From: Eli Zaretskii @ 2013-02-01 18:43 UTC (permalink / raw)
  To: Drew Adams; +Cc: 13149, dgutov, eggert

> From: "Drew Adams" <drew.adams@oracle.com>
> Date: Fri, 1 Feb 2013 08:32:22 -0800
> Cc: 13149@debbugs.gnu.org
> 
> Nope, this is still a problem - it just happened again, with a 2-day-old build.

Then it's a different problem.  That one was solved on Jan 19.

What is the filesystem of that file? NTFS or FAT32?





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-02-01 18:43                                                                 ` Eli Zaretskii
@ 2013-02-01 19:19                                                                   ` Drew Adams
  2013-02-01 19:36                                                                     ` Eli Zaretskii
  2013-02-01 19:38                                                                     ` Eli Zaretskii
  0 siblings, 2 replies; 68+ messages in thread
From: Drew Adams @ 2013-02-01 19:19 UTC (permalink / raw)
  To: 'Eli Zaretskii'; +Cc: 13149, dgutov, eggert

> > Nope, this is still a problem - it just happened again, 
> > with a 2-day-old build.
> 
> Then it's a different problem.  That one was solved on Jan 19.

Nope, this is the bug I filed.  You fixed a different bug, perhaps.  This one is
still live.

> What is the filesystem of that file? NTFS or FAT32?

FAT32.






^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-02-01 19:19                                                                   ` Drew Adams
@ 2013-02-01 19:36                                                                     ` Eli Zaretskii
  2013-02-01 22:15                                                                       ` Drew Adams
  2013-02-01 19:38                                                                     ` Eli Zaretskii
  1 sibling, 1 reply; 68+ messages in thread
From: Eli Zaretskii @ 2013-02-01 19:36 UTC (permalink / raw)
  To: Drew Adams; +Cc: 13149, dgutov, eggert

> From: "Drew Adams" <drew.adams@oracle.com>
> Cc: <eggert@cs.ucla.edu>, <dgutov@yandex.ru>, <13149@debbugs.gnu.org>
> Date: Fri, 1 Feb 2013 11:19:01 -0800
> 
> > What is the filesystem of that file? NTFS or FAT32?
> 
> FAT32.

Debugging this needs running Emacs under a debugger or instrumenting
the functions involved with special code.  So I guess we are waiting
for someone else to hit this and offer help.





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-02-01 19:19                                                                   ` Drew Adams
  2013-02-01 19:36                                                                     ` Eli Zaretskii
@ 2013-02-01 19:38                                                                     ` Eli Zaretskii
  2013-02-01 22:13                                                                       ` Drew Adams
  1 sibling, 1 reply; 68+ messages in thread
From: Eli Zaretskii @ 2013-02-01 19:38 UTC (permalink / raw)
  To: Drew Adams; +Cc: 13149, dgutov, eggert

> From: "Drew Adams" <drew.adams@oracle.com>
> Cc: <eggert@cs.ucla.edu>, <dgutov@yandex.ru>, <13149@debbugs.gnu.org>
> Date: Fri, 1 Feb 2013 11:19:01 -0800
> 
> > What is the filesystem of that file? NTFS or FAT32?
> 
> FAT32.

Did you customize w32-get-true-file-attributes, and if so, to what
value?





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-02-01 16:32                                                               ` Drew Adams
  2013-02-01 16:43                                                                 ` Drew Adams
  2013-02-01 18:43                                                                 ` Eli Zaretskii
@ 2013-02-01 21:05                                                                 ` Paul Eggert
  2013-02-01 22:14                                                                   ` Drew Adams
  2013-02-02  9:38                                                                   ` Eli Zaretskii
  2 siblings, 2 replies; 68+ messages in thread
From: Paul Eggert @ 2013-02-01 21:05 UTC (permalink / raw)
  To: Drew Adams; +Cc: 13149, 'Dmitry Gutov'

I stared at the code a bit and found an unlikely bug
that would cause the reported symptoms.  The bug occurs if the
first write-region to a buggy file system happens to be
an append that appends nothing.  If this occurs, Emacs
incorrectly concludes that the file system is not buggy,
and later uses of write-region to that file system (assuming
no other non-buggy file systems are used in the meantime)
will behave in the bad way that Drew reported.

I installed a fix for this bug as trunk bzr 111656.
I'd be surprised if this fixes Drew's bug though.

Eli, does MS-Windows conform to POSIX by updating st_mtime when
Emacs creates a file (open with O_CREAT on a file that didn't
previous exist) or truncates a file (open with O_TRUNC
on a file that previously existed)?
For example, if Emacs uses O_TRUNC on a file that is already
empty, does MS-Windows update the file's time
stamp even though the file has not changed?  If not,
that might explain the bug as well.

Drew, can you please try using the following hacky patch
for a while, and report what's in your *Messages* buffer
if you see the problem again?

=== modified file 'src/fileio.c'
--- src/fileio.c	2013-02-01 20:51:12 +0000
+++ src/fileio.c	2013-02-01 21:03:11 +0000
@@ -5051,6 +5051,23 @@ This calls `write-region-annotate-functi
 		  st.st_size = st1.st_size;
 		  modtime = modtime1;
 		}
+
+	      {
+		char format[sizeof "write-region ? .000000000 .000000000: %s"
+			    + 2 * INT_STRLEN_BOUND (long)];
+		if (valid_timestamp_file_system
+		    && st.st_dev == timestamp_file_system)
+		  sprintf (format, "write-region = %ld.%09d: %%s",
+			   (long) EMACS_SECS (modtime),
+			   (int) EMACS_NSECS (modtime));
+		else
+		  sprintf (format, "write-region ? %ld.%09d %ld.%09d: %%s",
+			   (long) EMACS_SECS (modtime),
+			   (int) EMACS_NSECS (modtime),
+			   (long) EMACS_SECS (modtime1),
+			   (int) EMACS_NSECS (modtime1));
+		add_to_log (format, filename, Qnil);
+	      }
 	    }
 	  emacs_close (desc1);
 	}

^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-02-01 19:38                                                                     ` Eli Zaretskii
@ 2013-02-01 22:13                                                                       ` Drew Adams
  0 siblings, 0 replies; 68+ messages in thread
From: Drew Adams @ 2013-02-01 22:13 UTC (permalink / raw)
  To: 'Eli Zaretskii'; +Cc: 13149, dgutov, eggert

> Did you customize w32-get-true-file-attributes, and if so, to what
> value?

No, I don't believe so.  The value is `local'.






^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-02-01 21:05                                                                 ` Paul Eggert
@ 2013-02-01 22:14                                                                   ` Drew Adams
  2013-02-01 22:22                                                                     ` Paul Eggert
  2013-02-02  9:38                                                                   ` Eli Zaretskii
  1 sibling, 1 reply; 68+ messages in thread
From: Drew Adams @ 2013-02-01 22:14 UTC (permalink / raw)
  To: 'Paul Eggert'; +Cc: 13149, 'Dmitry Gutov'

> Drew, can you please try using the following hacky patch
> for a while, and report what's in your *Messages* buffer
> if you see the problem again?

No, sorry.  I don't build Emacs.  If there is a Lisp change I can test that, but
not a C change.






^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-02-01 19:36                                                                     ` Eli Zaretskii
@ 2013-02-01 22:15                                                                       ` Drew Adams
  2013-02-02  9:41                                                                         ` Eli Zaretskii
  0 siblings, 1 reply; 68+ messages in thread
From: Drew Adams @ 2013-02-01 22:15 UTC (permalink / raw)
  To: 'Eli Zaretskii'; +Cc: 13149, dgutov, eggert

> Debugging this needs running Emacs under a debugger or instrumenting
> the functions involved with special code.  So I guess we are waiting
> for someone else to hit this and offer help.

My crystal ball tells me that others will run into the same problem sooner or
later.  AFAIK, I really don't do anything special that should affect this.  But
my crystal ball has been wrong before.






^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-02-01 22:14                                                                   ` Drew Adams
@ 2013-02-01 22:22                                                                     ` Paul Eggert
  2013-02-02  9:43                                                                       ` Eli Zaretskii
  0 siblings, 1 reply; 68+ messages in thread
From: Paul Eggert @ 2013-02-01 22:22 UTC (permalink / raw)
  To: Drew Adams; +Cc: 13149

On 02/01/13 14:14, Drew Adams wrote:

> No, sorry.  I don't build Emacs.  If there is a Lisp change I can test that, but
> not a C change.

I suppose I could install this patch into the trunk instead,
temporarily.  Eli, do you think it'd be a good idea?

=== modified file 'src/fileio.c'
--- src/fileio.c	2013-02-01 20:51:12 +0000
+++ src/fileio.c	2013-02-01 22:19:12 +0000
@@ -5051,6 +5051,26 @@ This calls `write-region-annotate-functi
 		  st.st_size = st1.st_size;
 		  modtime = modtime1;
 		}
+
+#ifdef DOS_NT
+	      /* Temporary hack to diagnose file time stamp bug.  */
+	      {
+		char format[sizeof "write-region ? .000000000 .000000000: %s"
+			    + 2 * INT_STRLEN_BOUND (long)];
+		if (valid_timestamp_file_system
+		    && st.st_dev == timestamp_file_system)
+		  sprintf (format, "write-region = %ld.%09d: %%s",
+			   (long) EMACS_SECS (modtime),
+			   (int) EMACS_NSECS (modtime));
+		else
+		  sprintf (format, "write-region ? %ld.%09d %ld.%09d: %%s",
+			   (long) EMACS_SECS (modtime),
+			   (int) EMACS_NSECS (modtime),
+			   (long) EMACS_SECS (modtime1),
+			   (int) EMACS_NSECS (modtime1));
+		add_to_log (format, filename, Qnil);
+	      }
+#endif
 	    }
 	  emacs_close (desc1);
 	}







^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-02-01 21:05                                                                 ` Paul Eggert
  2013-02-01 22:14                                                                   ` Drew Adams
@ 2013-02-02  9:38                                                                   ` Eli Zaretskii
  2013-02-02 19:31                                                                     ` Paul Eggert
  1 sibling, 1 reply; 68+ messages in thread
From: Eli Zaretskii @ 2013-02-02  9:38 UTC (permalink / raw)
  To: Paul Eggert; +Cc: 13149, dgutov

> Date: Fri, 01 Feb 2013 13:05:38 -0800
> From: Paul Eggert <eggert@cs.ucla.edu>
> Cc: 13149@debbugs.gnu.org, 'Dmitry Gutov' <dgutov@yandex.ru>
> 
> I stared at the code a bit and found an unlikely bug
> that would cause the reported symptoms.  The bug occurs if the
> first write-region to a buggy file system happens to be
> an append that appends nothing.  If this occurs, Emacs
> incorrectly concludes that the file system is not buggy,
> and later uses of write-region to that file system (assuming
> no other non-buggy file systems are used in the meantime)
> will behave in the bad way that Drew reported.
> 
> I installed a fix for this bug as trunk bzr 111656.
> I'd be surprised if this fixes Drew's bug though.

Me too, but who knows?

> Eli, does MS-Windows conform to POSIX by updating st_mtime when
> Emacs creates a file (open with O_CREAT on a file that didn't
> previous exist) or truncates a file (open with O_TRUNC
> on a file that previously existed)?

MS-Windows doesn't conform to Posix, period ;-)

It's hard to say something definitive here, especially since some of
this depends on the filesystem being used (Drew uses FAT32, most
others use NTFS).  I cannot find any documentation on this issue.  The
only thing that Windows promises in its docs is that st_mtime is
updated when the last file descriptor for the file is closed.  So the
time stamp might not be up to date by the time we look at it in
write-region, because we use 'fstat' there before closing the
descriptor we used for writing.  However, the code that determines
valid_timestamp_file_system right after that should catch any problems
caused by this, and update the buffer's modtime to the value actually
recorded in the filesystem.  Perhaps FAT32 (see below) should always
do this, i.e. we should disable the optimization of probing its time
stamp validity only once?

> For example, if Emacs uses O_TRUNC on a file that is already empty,
> does MS-Windows update the file's time stamp even though the file
> has not changed?

My testing indicates that a file on NTFS has its time stamp changed in
this scenario, while a file on FAT32 will not.  (I used a USB flash
device for this testing, as I have no other volume accessible to me
that is formatted as FAT32.)

However, when the file is closed, the time stamp does get updated on
FAT32 as well.  So the code which determines
valid_timestamp_file_system should have caught this as well.  And
anyway, Drew's use case involves a non-empty file, so this precise
scenario is not a problem there.  For a non-empty file, when it is
truncated by opening it with O_TRUNC, the file's size reflects
truncation on both NTFS and FAT32, at least on my XP system.

^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-02-01 22:15                                                                       ` Drew Adams
@ 2013-02-02  9:41                                                                         ` Eli Zaretskii
  2013-02-02 16:06                                                                           ` Drew Adams
  0 siblings, 1 reply; 68+ messages in thread
From: Eli Zaretskii @ 2013-02-02  9:41 UTC (permalink / raw)
  To: Drew Adams; +Cc: 13149, dgutov, eggert

> From: "Drew Adams" <drew.adams@oracle.com>
> Cc: <eggert@cs.ucla.edu>, <dgutov@yandex.ru>, <13149@debbugs.gnu.org>
> Date: Fri, 1 Feb 2013 14:15:35 -0800
> 
> > Debugging this needs running Emacs under a debugger or instrumenting
> > the functions involved with special code.  So I guess we are waiting
> > for someone else to hit this and offer help.
> 
> My crystal ball tells me that others will run into the same problem sooner or
> later.

I certainly hope so.  I tried to reproduce this using a USB flash
device, but couldn't.

> AFAIK, I really don't do anything special that should affect this.

Can you describe the file where this happened and any customizations
that could have made it stand out?  What major mode was active there?
any hooks related to saving that could matter?

Also, does it happen always with this file, or very rarely?





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-02-01 22:22                                                                     ` Paul Eggert
@ 2013-02-02  9:43                                                                       ` Eli Zaretskii
  2013-03-19  8:39                                                                         ` Uwe Siart
  0 siblings, 1 reply; 68+ messages in thread
From: Eli Zaretskii @ 2013-02-02  9:43 UTC (permalink / raw)
  To: Paul Eggert; +Cc: 13149

> Date: Fri, 01 Feb 2013 14:22:00 -0800
> From: Paul Eggert <eggert@cs.ucla.edu>
> CC: Eli Zaretskii <eliz@gnu.org>, 13149@debbugs.gnu.org
> 
> On 02/01/13 14:14, Drew Adams wrote:
> 
> > No, sorry.  I don't build Emacs.  If there is a Lisp change I can test that, but
> > not a C change.
> 
> I suppose I could install this patch into the trunk instead,
> temporarily.  Eli, do you think it'd be a good idea?

Yes, definitely.

I would also install something similar in verify-visited-file-modtime,
so that next time it happens we could see how different are the time
stamps.

Thanks.





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-02-02  9:41                                                                         ` Eli Zaretskii
@ 2013-02-02 16:06                                                                           ` Drew Adams
  0 siblings, 0 replies; 68+ messages in thread
From: Drew Adams @ 2013-02-02 16:06 UTC (permalink / raw)
  To: 'Eli Zaretskii'; +Cc: 13149, dgutov, eggert

> Can you describe the file where this happened and any customizations
> that could have made it stand out?  What major mode was active there?
> any hooks related to saving that could matter?
> 
> Also, does it happen always with this file, or very rarely?

I have noticed the bug only a few times, as I said.
The file was an ordinary Emacs Lisp file, in Emacs Lisp mode.  I don't recall
which file.  I'm not aware of using any saving hooks.






^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-02-02  9:38                                                                   ` Eli Zaretskii
@ 2013-02-02 19:31                                                                     ` Paul Eggert
  0 siblings, 0 replies; 68+ messages in thread
From: Paul Eggert @ 2013-02-02 19:31 UTC (permalink / raw)
  To: Eli Zaretskii; +Cc: 13149, dgutov

On 02/02/2013 01:38 AM, Eli Zaretskii wrote:
> My testing indicates that a file on NTFS has its time stamp changed in
> this scenario, while a file on FAT32 will not.

OK, thanks, then we need to check for that problem too.

Rather than go through a lengthy remote debugging session
with Drew, I'm inclined to disable the heuristic
on MS-Windows, as that should fix the problem once
and for all.  That is, we just live with the race conditions
on MS-Windows (which is what Emacs users have done for many years)
and fix the race conditions only on GNU and other systems
that support POSIX.1-2008 well.

I installed the following patch to try to do that, as trunk
bzr 111664.  If Drew continues to have the problem even with
this patch, we can investigate further by inserting some
logging code along the lines that we discussed.

=== modified file 'src/ChangeLog'
--- src/ChangeLog	2013-02-02 17:14:24 +0000
+++ src/ChangeLog	2013-02-02 19:18:00 +0000
@@ -1,3 +1,14 @@
+2013-02-02  Paul Eggert  <eggert@cs.ucla.edu>
+
+	Avoid file time stamp bug on MS-Windows (Bug#13149).
+	* fileio.c (Fwrite_region): Don't use the heuristic on empty files,
+	as FAT32 doesn't update time stamps when truncating them.
+	Also, check that a file time stamp is not a multiple of 100 ns;
+	this should catch all instances of the problem on MS-Windows,
+	as its native file system resolution is 100 ns or worse, and
+	checking for a non-multiple of 100 ns should impose only a small
+	overhead on systems with ns resolution.
+
 2013-02-02  Eli Zaretskii  <eliz@gnu.org>
 
 	Avoid encoding file names on MS-Windows when they need to be run

=== modified file 'src/fileio.c'
--- src/fileio.c	2013-02-02 17:14:24 +0000
+++ src/fileio.c	2013-02-02 19:18:00 +0000
@@ -5020,11 +5020,22 @@
 	  if (fstat (desc1, &st1) == 0
 	      && st.st_dev == st1.st_dev && st.st_ino == st1.st_ino)
 	    {
+	      /* Use the heuristic if it appears to be valid.  With neither
+		 O_EXCL nor O_TRUNC, if Emacs happened to write nothing to the
+		 file, the time stamp won't change.  Also, some non-POSIX
+		 systems don't update an empty file's time stamp when
+		 truncating it.  Finally, file systems with 100 ns or worse
+		 resolution sometimes seem to have bugs: on a system with ns
+		 resolution, checking ns % 100 incorrectly avoids the heuristic
+		 1% of the time, but the problem should be temporary as we will
+		 try again on the next time stamp.  */
+	      bool use_heuristic
+		= ((open_flags & (O_EXCL | O_TRUNC)) != 0
+		   && st.st_size != 0
+		   && EMACS_NSECS (modtime) % 100 != 0);
+
 	      EMACS_TIME modtime1 = get_stat_mtime (&st1);
-	      /* If neither O_EXCL nor O_TRUNC is used, and Emacs happened to
-		 write nothing to the file, the file's time stamp won't change
-		 so it should not be used in this heuristic.  */
-	      if ((open_flags & (O_EXCL | O_TRUNC)) != 0
+	      if (use_heuristic
 		  && EMACS_TIME_EQ (modtime, modtime1)
 		  && st.st_size == st1.st_size)
 		{







^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-02-02  9:43                                                                       ` Eli Zaretskii
@ 2013-03-19  8:39                                                                         ` Uwe Siart
  2013-03-19 16:55                                                                           ` Eli Zaretskii
  0 siblings, 1 reply; 68+ messages in thread
From: Uwe Siart @ 2013-03-19  8:39 UTC (permalink / raw)
  To: 13149

Eli Zaretskii <eliz@gnu.org> writes:

>> Date: Fri, 01 Feb 2013 14:22:00 -0800
>> From: Paul Eggert <eggert@cs.ucla.edu>
>> CC: Eli Zaretskii <eliz@gnu.org>, 13149@debbugs.gnu.org
>> 
>> On 02/01/13 14:14, Drew Adams wrote:
>> 
>> > No, sorry.  I don't build Emacs.  If there is a Lisp change I can test that, but
>> > not a C change.
>> 
>> I suppose I could install this patch into the trunk instead,
>> temporarily.  Eli, do you think it'd be a good idea?
>
> Yes, definitely.
>
> I would also install something similar in verify-visited-file-modtime,
> so that next time it happens we could see how different are the time
> stamps.

Now that 24.3 windows binaries have been released I observe exactly the
same problem on my XP box. I don't know how to reproduce it 100%. It
happens sporadically, but it happens. And yes, my user files are on a
FAT32 partition.

Is there a fix for it, e.g. some customization? Should I avoid FAT32? Or
do we have to live with it?

-- 
Uwe






^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-03-19  8:39                                                                         ` Uwe Siart
@ 2013-03-19 16:55                                                                           ` Eli Zaretskii
  2013-03-19 17:50                                                                             ` Uwe Siart
  2014-02-06  1:40                                                                             ` Lars Ingebrigtsen
  0 siblings, 2 replies; 68+ messages in thread
From: Eli Zaretskii @ 2013-03-19 16:55 UTC (permalink / raw)
  To: Uwe Siart; +Cc: 13149

> From: Uwe Siart <usenet@siart.de>
> Date: Tue, 19 Mar 2013 09:39:40 +0100
> 
> Now that 24.3 windows binaries have been released I observe exactly the
> same problem on my XP box. I don't know how to reproduce it 100%. It
> happens sporadically, but it happens. And yes, my user files are on a
> FAT32 partition.
> 
> Is there a fix for it, e.g. some customization?

The fix for this bug is in the trunk, it didn't make it into Emacs
24.3.  So I don't think you can do anything to avoid these annoyances,
especially since you don't build your Emacs (if you did, I could
perhaps show you how to work around that by a simple source change).

> Should I avoid FAT32? Or do we have to live with it?

I can only say that I never saw this on NTFS filesystems that I use
every day with Emacs 24.3.  (Why do you use FAT32, btw? it's so much
worse than NTFS.)





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-03-19 16:55                                                                           ` Eli Zaretskii
@ 2013-03-19 17:50                                                                             ` Uwe Siart
  2014-02-06  1:40                                                                             ` Lars Ingebrigtsen
  1 sibling, 0 replies; 68+ messages in thread
From: Uwe Siart @ 2013-03-19 17:50 UTC (permalink / raw)
  To: 13149

Eli Zaretskii <eliz@gnu.org> writes:

> (Why do you use FAT32, btw? it's so much worse than NTFS.)

You're right. I'll consider to migrate everything to NTFS.

The reason why I still prefered FAT32 was that I used to backup some
directory trees by sync-ing them against FTP servers. NTFS volumes were
out of sync whenever we changed to daylight-saving time and back because
windows returns a modified timestamp on NTFS volumes, while FTP doesn't.
I avoided these annoyances stolidly keeping at FAT32.

-- 
Uwe

^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2013-03-19 16:55                                                                           ` Eli Zaretskii
  2013-03-19 17:50                                                                             ` Uwe Siart
@ 2014-02-06  1:40                                                                             ` Lars Ingebrigtsen
  2014-02-06  6:12                                                                               ` Drew Adams
  2014-02-06  6:19                                                                               ` Eli Zaretskii
  1 sibling, 2 replies; 68+ messages in thread
From: Lars Ingebrigtsen @ 2014-02-06  1:40 UTC (permalink / raw)
  To: Eli Zaretskii; +Cc: Uwe Siart, 13149

Eli Zaretskii <eliz@gnu.org> writes:

>> Now that 24.3 windows binaries have been released I observe exactly the
>> same problem on my XP box. I don't know how to reproduce it 100%. It
>> happens sporadically, but it happens. And yes, my user files are on a
>> FAT32 partition.
>> 
>> Is there a fix for it, e.g. some customization?
>
> The fix for this bug is in the trunk, it didn't make it into Emacs
> 24.3.  So I don't think you can do anything to avoid these annoyances,
> especially since you don't build your Emacs (if you did, I could
> perhaps show you how to work around that by a simple source change).

There's a long thread in this bug report, but I think the conclusion is
that this was fixed on the trunk?

-- 
(domestic pets only, the antidote for overdose, milk.)
  bloggy blog http://lars.ingebrigtsen.no/





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2014-02-06  1:40                                                                             ` Lars Ingebrigtsen
@ 2014-02-06  6:12                                                                               ` Drew Adams
  2014-02-06  6:19                                                                               ` Eli Zaretskii
  1 sibling, 0 replies; 68+ messages in thread
From: Drew Adams @ 2014-02-06  6:12 UTC (permalink / raw)
  To: Lars Ingebrigtsen, Eli Zaretskii; +Cc: Uwe Siart, 13149

> There's a long thread in this bug report, but I think the conclusion
> is that this was fixed on the trunk?

I can't speak to that.  But I reported the bug when I was using
FAT32, and I no longer have that, FWIW.  (I also have not noticed
the bug in a while, probably not since I switched from FAT32.)





^ permalink raw reply	[flat|nested] 68+ messages in thread

* bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not
  2014-02-06  1:40                                                                             ` Lars Ingebrigtsen
  2014-02-06  6:12                                                                               ` Drew Adams
@ 2014-02-06  6:19                                                                               ` Eli Zaretskii
  1 sibling, 0 replies; 68+ messages in thread
From: Eli Zaretskii @ 2014-02-06  6:19 UTC (permalink / raw)
  To: Lars Ingebrigtsen; +Cc: usenet, 13149

> From: Lars Ingebrigtsen <larsi@gnus.org>
> Cc: Uwe Siart <usenet@siart.de>,  13149@debbugs.gnu.org
> Date: Wed, 05 Feb 2014 17:40:21 -0800
> 
> Eli Zaretskii <eliz@gnu.org> writes:
> 
> >> Now that 24.3 windows binaries have been released I observe exactly the
> >> same problem on my XP box. I don't know how to reproduce it 100%. It
> >> happens sporadically, but it happens. And yes, my user files are on a
> >> FAT32 partition.
> >> 
> >> Is there a fix for it, e.g. some customization?
> >
> > The fix for this bug is in the trunk, it didn't make it into Emacs
> > 24.3.  So I don't think you can do anything to avoid these annoyances,
> > especially since you don't build your Emacs (if you did, I could
> > perhaps show you how to work around that by a simple source change).
> 
> There's a long thread in this bug report, but I think the conclusion is
> that this was fixed on the trunk?

IMO, yes.





^ permalink raw reply	[flat|nested] 68+ messages in thread

end of thread, other threads:[~2014-02-06  6:19 UTC | newest]

Thread overview: 68+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2012-12-11 21:51 bug#13149: 24.3.50; Emacs thinks file was changed outside Emacs, but it was not Drew Adams
2012-12-11 22:48 ` Dmitry Gutov
2012-12-11 22:54   ` Drew Adams
2013-01-14  5:10     ` Dmitry Gutov
2013-01-14 14:57       ` Dmitry Gutov
2013-01-14 17:02         ` Eli Zaretskii
2013-01-14 22:22           ` Dmitry Gutov
2013-01-14 18:28         ` Paul Eggert
2013-01-14 22:20           ` Dmitry Gutov
2013-01-15  6:45             ` Paul Eggert
2013-01-15  8:54               ` Dmitry Gutov
2013-01-15 17:31                 ` Paul Eggert
2013-01-15 21:38                   ` Dmitry Gutov
2013-01-15 21:47                     ` Paul Eggert
2013-01-15 22:11                       ` Dmitry Gutov
2013-01-15 22:38                         ` Paul Eggert
2013-01-15 23:09                           ` Dmitry Gutov
2013-01-15 23:44                             ` Dmitry Gutov
2013-01-16  5:57                               ` Paul Eggert
2013-01-17 10:32                                 ` Dmitry Gutov
2013-01-17 17:05                                   ` Eli Zaretskii
2013-01-18  4:15                                     ` Dmitry Gutov
2013-01-18  7:49                                       ` Eli Zaretskii
2013-01-17 21:14                                   ` Paul Eggert
2013-01-18  4:55                                     ` Dmitry Gutov
2013-01-18  5:26                                       ` Paul Eggert
2013-01-17 21:33                                   ` Paul Eggert
2013-01-18  4:36                                     ` Dmitry Gutov
2013-01-18  5:01                                       ` Paul Eggert
2013-01-18  5:10                                         ` Dmitry Gutov
2013-01-18  5:25                                           ` Paul Eggert
2013-01-18  5:54                                             ` Dmitry Gutov
2013-01-18  6:22                                               ` Dmitry Gutov
2013-01-18  7:56                                             ` Eli Zaretskii
2013-01-18 14:45                                               ` Dmitry Gutov
2013-01-18 21:35                                               ` Paul Eggert
2013-01-18 22:52                                                 ` Dmitry Gutov
2013-01-19  0:55                                                   ` Paul Eggert
2013-01-19  1:09                                                     ` Dmitry Gutov
2013-01-19  2:37                                                       ` Paul Eggert
2013-01-19  4:02                                                         ` Dmitry Gutov
2013-01-19  4:51                                                           ` Paul Eggert
     [not found]                                                             ` <DEB91990BBBB4255BFB466956EB54214@us.oracl!>
     [not found]                                                               ` <e.com@[87.69.4.28]>
     [not found]                                                                 ` <83wq! urc1u3.fsf@gnu.org>
     [not found]                                                             ` <DEB91990BBBB4255BFB466956EB54214@us.oracl!e.com>
     [not found]                                                             ` <DEB91990BBBB4255BFB466956! EB54214@us.oracl!>
     [not found]                                                             ` <DEB91990BBBB4255BFB466956EB54214@us.oracl! e.com>
2013-01-19  5:02                                                             ` Drew Adams
2013-02-01 16:32                                                               ` Drew Adams
2013-02-01 16:43                                                                 ` Drew Adams
2013-02-01 16:49                                                                   ` Drew Adams
2013-02-01 18:43                                                                 ` Eli Zaretskii
2013-02-01 19:19                                                                   ` Drew Adams
2013-02-01 19:36                                                                     ` Eli Zaretskii
2013-02-01 22:15                                                                       ` Drew Adams
2013-02-02  9:41                                                                         ` Eli Zaretskii
2013-02-02 16:06                                                                           ` Drew Adams
2013-02-01 19:38                                                                     ` Eli Zaretskii
2013-02-01 22:13                                                                       ` Drew Adams
2013-02-01 21:05                                                                 ` Paul Eggert
2013-02-01 22:14                                                                   ` Drew Adams
2013-02-01 22:22                                                                     ` Paul Eggert
2013-02-02  9:43                                                                       ` Eli Zaretskii
2013-03-19  8:39                                                                         ` Uwe Siart
2013-03-19 16:55                                                                           ` Eli Zaretskii
2013-03-19 17:50                                                                             ` Uwe Siart
2014-02-06  1:40                                                                             ` Lars Ingebrigtsen
2014-02-06  6:12                                                                               ` Drew Adams
2014-02-06  6:19                                                                               ` Eli Zaretskii
2013-02-02  9:38                                                                   ` Eli Zaretskii
2013-02-02 19:31                                                                     ` Paul Eggert
2013-01-18  7:57                                       ` Eli Zaretskii
2013-01-17 17:16                                 ` David Engster

Code repositories for project(s) associated with this public inbox

	https://git.savannah.gnu.org/cgit/emacs.git

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).