bug#22534: File notify broken on Windows

[Fabrice Popineau <fabrice.popineau@gmail.com>]

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

Some information regarding the original problem.

I have turned on some tracing and this is what I get with
file-notify-test02-events
along these lines:

$ git diff -w origin/emacs-25 src/w32notify.c
diff --git a/src/w32notify.c b/src/w32notify.c
index 71787c4..66ad277 100644
--- a/src/w32notify.c
+++ b/src/w32notify.c
@@ -207,6 +207,7 @@ watch_completion (DWORD status, DWORD bytes_ret,
OVERLAPPED *io_info)
      freed by someone already?  In any case, we cannot do anything
      with this request, so just punt and skip it.  FIXME: should we
      raise the 'terminate' flag in this case?  */
+  DebPrint(("status = %lx, io_info = %lx\n", status, io_info));
   if (!io_info)
     return;

@@ -227,6 +228,7 @@ watch_completion (DWORD status, DWORD bytes_ret,
OVERLAPPED *io_info)
          by its buffers; this is done by the main thread in
          remove_watch.  Calling malloc/free from a thread other than
          the main thread is a no-no.  */
+      DebPrint(("Operation aborted."));
       dirwatch->dir = NULL;
       dirwatch->terminate = 1;
     }
@@ -406,11 +408,13 @@ remove_watch (struct notification *dirwatch)
             break;
           Sleep (10);
        }
+      DebPrint(("status = %lx, exit_code = %lx\n", status, exit_code));
       if ((status == FALSE && (err = GetLastError ()) ==
ERROR_INVALID_HANDLE)
           || exit_code == STILL_ACTIVE)
        {
           if (!(status == FALSE && err == ERROR_INVALID_HANDLE))
             {
+              DebPrint(("Terminating thread.\n"));
               TerminateThread (dirwatch->thr, 0);
               if (dirwatch->dir)
                CloseHandle (dirwatch->dir);
@@ -523,7 +527,7 @@ generate notifications correctly, though.  */)
   char *errstr;

   CHECK_LIST (filter);
-
+  DebPrint(("AddWatch\n"));
   /* The underlying features are available only since XP.  */
   if (os_subtype == OS_9X
       || (w32_major_version == 5 && w32_minor_version < 1))

I also forced DebPrint to write on stderr.


When run in batch mode:

$ make SELECTOR='(quote (eql file-notify-test02-events))'   -C
test/automated file-notify-tests
make : on entre dans le répertoire «
/d/Source/emacs/build-emacs-25/test/automated »
make[1] : on entre dans le répertoire «
/d/Source/emacs/build-emacs-25/test/automated »
make[2] : on entre dans le répertoire «
/d/Source/emacs/build-emacs-25/test/automated »
Compiling ../../../emacs/test/automated/file-notify-tests.el
make[2] : on quitte le répertoire «
/d/Source/emacs/build-emacs-25/test/automated »
Testing ../../../emacs/test/automated/file-notify-tests.elc
Running 1 tests (2016-02-11 16:14:39+0100)
AddWatch
status = 0, io_info = 3dd8090
status = 0, io_info = 3dd8090
status = 0, io_info = 3dd8090
status = 3e3, io_info = 3dd8090
Operation aborted.
status = 1, exit_code = 0
AddWatch
status = 0, io_info = 3dd8210
status = 0, io_info = 3dd8210
status = 0, io_info = 3dd8210
status = 3e3, io_info = 3dd8210
Operation aborted.
status = 1, exit_code = 0
AddWatch
status = 0, io_info = 3dd8000
status = 0, io_info = 3dd8000
watch_worker, abnormal exit: 5
QueueUserAPC failed (31)!
status = 1, exit_code = 1
Test file-notify-test02-events backtrace:
  #[0 "\306\307\310C\307C\3111(\312\313\314\315$\317\"\32
  ert--run-test-internal([cl-struct-ert--test-execution-info [cl-struc
  ert-run-test([cl-struct-ert-test file-notify-test02-events "Check fi
  ert-run-or-rerun-test([cl-struct-ert--stats (eql file-notify-test02-
  ert-run-tests((eql file-notify-test02-events) #[385 "\306\307\"\203
  ert-run-tests-batch((eql file-notify-test02-events))
  ert-run-tests-batch-and-exit((eql file-notify-test02-events))
  eval((ert-run-tests-batch-and-exit (quote (eql file-notify-test02-ev
  command-line-1(("-L" ";../../../emacs/test/automated" "-l" "ert" "-l
  command-line()
  normal-top-level()
Test file-notify-test02-events condition:
    (ert-test-failed
     ((should
       (file-notify--test-with-events-check events))
      :form
      (file-notify--test-with-events-check
       ((created changed deleted)))
      :value nil :explanation "Received events `(created changed)' do not
match expected events `(created changed deleted)'"))
   FAILED  1/1  file-notify-test02-events

Ran 1 tests, 0 results as expected, 1 unexpected (2016-02-11 16:15:20+0100)

1 unexpected results:
   FAILED  file-notify-test02-events

When I run in normal mode:

$ src/emacs -Q -l ../emacs/test/automated/file-notify-tests.el
AddWatch
status = 0, io_info = 42dd0a0
status = 0, io_info = 42dd0a0
status = 0, io_info = 42dd0a0
status = 0, io_info = 42dd0a0
status = 3e3, io_info = 42dd0a0
Operation aborted.status = 1, exit_code = 0
AddWatch
status = 0, io_info = 42dcc50
status = 0, io_info = 42dcc50
status = 0, io_info = 42dcc50
status = 0, io_info = 42dcc50
status = 3e3, io_info = 42dcc50
Operation aborted.status = 1, exit_code = 0
AddWatch
status = 0, io_info = 42dd310
status = 0, io_info = 42dd310
status = 0, io_info = 42dd310
watch_worker, abnormal exit: 5
QueueUserAPC failed (31)!
status = 1, exit_code = 1
AddWatch
status = 0, io_info = 42dd2b0
status = 0, io_info = 42dd2b0
status = 0, io_info = 42dd2b0
status = 0, io_info = 42dd2b0
status = 0, io_info = 42dd2b0
status = 0, io_info = 42dd2b0
status = 0, io_info = 42dd2b0
status = 0, io_info = 42dd2b0
watch_worker, abnormal exit: 5
QueueUserAPC failed (31)!
status = 1, exit_code = 1
AddWatch
status = 0, io_info = 42dcec0
status = 0, io_info = 42dcec0
status = 0, io_info = 42dcec0
status = 0, io_info = 42dcec0
status = 5, io_info = 42dcec0
watch_worker, abnormal exit: 5
QueueUserAPC failed (31)!
status = 1, exit_code = 1
AddWatch
status = 0, io_info = 42dcec0
status = 0, io_info = 42dcec0
status = 3e3, io_info = 42dcec0
Operation aborted.status = 1, exit_code = 0

and the test is passed.


The first diagnostic is that QueueUserAPC shouldn't fail with error 31.
This happens because the worker thread is already terminating, but that
does not leave
a chance for watch_end to run.

Fabrice

2016-02-10 20:15 GMT+01:00 Eli Zaretskii <eliz@gnu.org>:

> > From: Fabrice Popineau <fabrice.popineau@gmail.com>
> > Date: Mon, 8 Feb 2016 20:15:59 +0100
> > Cc: Michael Albinus <michael.albinus@gmx.de>, 22534@debbugs.gnu.org
> >
> >  > From: Fabrice Popineau <fabrice.popineau@gmail.com>
> >  > Date: Mon, 8 Feb 2016 11:43:10 +0100
> >  > Cc: Eli Zaretskii <eliz@gnu.org>, 22534@debbugs.gnu.org
> >  >
> >  > > events: ((created changed deleted)) ((17491048 created
> >  > >
> c:/Users/Fabrice/AppData/Local/Temp/file-notify-test-parent20748Ali/file-notify-test20748Nvo)
> >  > > (17491048 changed
> >  > >
> c:/Users/Fabrice/AppData/Local/Temp/file-notify-test-parent20748Ali/file-notify-test20748Nvo))
> >  >
> >  > Fails also for me in batch mode. Surprisingly, it doesn't fail always,
> >  > sometimes (about 1 in 10 runs) it succeeds here, and fails in the next
> >  > step. Strange.
> >  >
> >  > I see the same. The deleted notifications number vary. When you
> expect 2, sometimes I see 1.
> >  > When you expect one, sometimes I see it. But not frequently.
> >
> >  Did you try adding calls to read-event after the functions that are
> >  supposed to produce these events?
> >
> > Yes, but with no results.
>
> Strange.  I see none of that on my machine.  Maybe it's because my
> disk is SSD, maybe because this is XP.  Who knows?
>
> Michael, I think it's time to do what you suggested:
>
> > If we do not care the missing `deleted' event in batch mode, I could
> > make it optional in the test.
>
> Re this:
>
> > But maybe it is an indication for a serious problem in w32notify.
>
> It might, but it's unlikely, and I won't have time to dig into this in
> the following weeks, so I guess this will have to wait for a recipe I
> can reproduce on one of my machines.
>
> Thanks.
>

[-- Attachment #2: Type: text/html, Size: 10895 bytes --]