bug#21337: 25.0.50; inotify error message

bug#21337: 25.0.50; inotify error message

[Robert Pluim]

commit 200c2b10faf298bf65e8b6dbd0cb9ef00b2f95d6 made inotify be
preferred to gnotify.

That has shown that there's something amiss in our inotify
support: my emacs now spams me with

"Error while trying to read file system events"

whenever I run Gnus, making it unusable.

Regards

Robert

In GNU Emacs 25.0.50.39 (x86_64-unknown-linux-gnu, GTK+ Version 3.14.13)
 of 2015-08-24 on rpluim-ubuntu
Repository revision: 0abf56df5de778d02e8acccb2044fcd6e7e4953c
Windowing system distributor `The X.Org Foundation', version 11.0.11701000
System Description:	Ubuntu 15.04

Configured features:
XPM JPEG TIFF GIF PNG RSVG IMAGEMAGICK SOUND GPM DBUS GCONF GSETTINGS
NOTIFY ACL LIBSELINUX GNUTLS LIBXML2 FREETYPE M17N_FLT LIBOTF XFT ZLIB
TOOLKIT_SCROLL_BARS GTK3 X11

Important settings:
  value of $LC_COLLATE: C
  value of $LC_MONETARY: en_GB.UTF-8
  value of $LC_NUMERIC: en_GB.UTF-8
  value of $LC_TIME: en_GB.UTF-8
  value of $LANG: en_US.UTF-8
  value of $XMODIFIERS: @im=ibus
  locale-coding-system: utf-8-unix

bug#21337: 25.0.50; inotify error message

[Eli Zaretskii]

> From: Robert Pluim <rpluim@gmail.com>
> Date: Mon, 24 Aug 2015 14:12:33 +0200
> 
> commit 200c2b10faf298bf65e8b6dbd0cb9ef00b2f95d6 made inotify be
> preferred to gnotify.
> 
> That has shown that there's something amiss in our inotify
> support: my emacs now spams me with
> 
> "Error while trying to read file system events"
> 
> whenever I run Gnus, making it unusable.

Please provide more details.  Do you have global-auto-revert-mode
enabled, per chance?

bug#21337: 25.0.50; inotify error message

[Robert Pluim]

Eli Zaretskii <eliz@gnu.org> writes:

>> From: Robert Pluim <rpluim@gmail.com>
>> Date: Mon, 24 Aug 2015 14:12:33 +0200
>> 
>> commit 200c2b10faf298bf65e8b6dbd0cb9ef00b2f95d6 made inotify be
>> preferred to gnotify.
>> 
>> That has shown that there's something amiss in our inotify
>> support: my emacs now spams me with
>> 
>> "Error while trying to read file system events"
>> 
>> whenever I run Gnus, making it unusable.
>
> Please provide more details.  Do you have global-auto-revert-mode
> enabled, per chance?

I do, but I've had that enabled for at least the last 6 months.  I
went away on vacation, re-pulled & re-built, and got the inotify
errors. Relevant .emacs:

 '(dired-auto-revert-buffer (quote dired-directory-changed-p))
 '(global-auto-revert-mode t)
 '(global-auto-revert-non-file-buffers t)

although disabling those 3 makes no difference to the behaviour.

I've double checked my emacs build was using gnotify before.

It's always possible that inotify is trying to access some
non-existent file, but without a filename that's hard to determine.

Regards

Robert

bug#21337: 25.0.50; inotify error message

[Eli Zaretskii]

> From: Robert Pluim <rpluim@gmail.com>
> Cc: 21337@debbugs.gnu.org
> Date: Mon, 24 Aug 2015 18:22:16 +0200
> 
> >> That has shown that there's something amiss in our inotify
> >> support: my emacs now spams me with
> >> 
> >> "Error while trying to read file system events"
> >> 
> >> whenever I run Gnus, making it unusable.
> >
> > Please provide more details.  Do you have global-auto-revert-mode
> > enabled, per chance?
> 
> I do, but I've had that enabled for at least the last 6 months.  I
> went away on vacation, re-pulled & re-built, and got the inotify
> errors. Relevant .emacs:
> 
>  '(dired-auto-revert-buffer (quote dired-directory-changed-p))
>  '(global-auto-revert-mode t)
>  '(global-auto-revert-non-file-buffers t)
> 
> although disabling those 3 makes no difference to the behaviour.

Then I guess the next step is to set debug-on-error non-nil and show
the backtrace, so that we see what Lisp code errors out.

> I've double checked my emacs build was using gnotify before.
> 
> It's always possible that inotify is trying to access some
> non-existent file, but without a filename that's hard to determine.

Emacs doesn't watch files, it watches directories.

bug#21337: 25.0.50; inotify error message

[Robert Pluim]

Eli Zaretskii <eliz@gnu.org> writes:

>>  '(dired-auto-revert-buffer (quote dired-directory-changed-p))
>>  '(global-auto-revert-mode t)
>>  '(global-auto-revert-non-file-buffers t)
>> 
>> although disabling those 3 makes no difference to the behaviour.
>
> Then I guess the next step is to set debug-on-error non-nil and show
> the backtrace, so that we see what Lisp code errors out.
>

I hadn't considered that, however it's not very enlightening:

Debugger entered--Lisp error: (file-notify-error "Error while trying to read file system events")

That error is coming from the inotify_callback function. From gdb the
c-backtrace is:

#0  inotify_callback (fd=16, _=<optimized out>) at inotify.c:139
#1  0x000000000059e3a0 in wait_reading_process_output (time_limit=<optimized out>, nsecs=<optimized out>, read_kbd=-1, 
    do_display=true, wait_for_cell=0, wait_proc=0x0, just_wait_proc=0) at process.c:5085
#2  0x0000000000422672 in sit_for (timeout=30, reading=112, display_option=0) at dispnew.c:5756
#3  0x00000000004fa6dd in read_char (commandflag=0, commandflag@entry=1, map=13674864, map@entry=99582755, prev_event=-11, 
    used_mouse_menu=0xfffffffffffffea8, used_mouse_menu@entry=0x7fffffffd7db, end_time=0xd0a990, end_time@entry=0x0)
    at keyboard.c:2786
#4  0x00000000004fb469 in read_key_sequence (keybuf=keybuf@entry=0x7fffffffd8b0, prompt=prompt@entry=0, 
    dont_downcase_last=dont_downcase_last@entry=false, can_return_switch_frame=can_return_switch_frame@entry=true, 
    fix_current_buffer=fix_current_buffer@entry=true, prevent_redisplay=prevent_redisplay@entry=false, bufsize=30) at keyboard.c:9188
#5  0x00000000004fd171 in command_loop_1 () at keyboard.c:1406
#6  0x000000000055fbd7 in internal_condition_case (bfun=bfun@entry=0x4fcf30 <command_loop_1>, handlers=handlers@entry=18912, 
    hfun=hfun@entry=0x4f3a30 <cmd_error>) at eval.c:1356
#7  0x00000000004ef00c in command_loop_2 (ignore=ignore@entry=0) at keyboard.c:1138
#8  0x000000000055fab3 in internal_catch (tag=tag@entry=45168, func=func@entry=0x4eeff0 <command_loop_2>, arg=arg@entry=0)
    at eval.c:1116
#9  0x00000000004eefc9 in command_loop () at keyboard.c:1117
#10 0x00000000004f363b in recursive_edit_1 () at keyboard.c:723
#11 0x00000000004f3960 in Frecursive_edit () at keyboard.c:794
#12 0x00000000004187d6 in main (argc=1, argv=0x7fffffffdc38) at emacs.c:1629

xbacktrace gives no output at all.

printf time?

Regards

Robert

bug#21337: 25.0.50; inotify error message

[Eli Zaretskii]

> From: Robert Pluim <rpluim@gmail.com>
> Cc: 21337@debbugs.gnu.org
> Date: Mon, 24 Aug 2015 18:51:38 +0200
> 
> Eli Zaretskii <eliz@gnu.org> writes:
> 
> >>  '(dired-auto-revert-buffer (quote dired-directory-changed-p))
> >>  '(global-auto-revert-mode t)
> >>  '(global-auto-revert-non-file-buffers t)
> >> 
> >> although disabling those 3 makes no difference to the behaviour.
> >
> > Then I guess the next step is to set debug-on-error non-nil and show
> > the backtrace, so that we see what Lisp code errors out.
> >
> 
> I hadn't considered that, however it's not very enlightening:
> 
> Debugger entered--Lisp error: (file-notify-error "Error while trying to read file system events")
> 
> That error is coming from the inotify_callback function. From gdb the
> c-backtrace is:
> 
> #0  inotify_callback (fd=16, _=<optimized out>) at inotify.c:139
> #1  0x000000000059e3a0 in wait_reading_process_output (time_limit=<optimized out>, nsecs=<optimized out>, read_kbd=-1, 
>     do_display=true, wait_for_cell=0, wait_proc=0x0, just_wait_proc=0) at process.c:5085
> #2  0x0000000000422672 in sit_for (timeout=30, reading=112, display_option=0) at dispnew.c:5756
> #3  0x00000000004fa6dd in read_char (commandflag=0, commandflag@entry=1, map=13674864, map@entry=99582755, prev_event=-11, 
>     used_mouse_menu=0xfffffffffffffea8, used_mouse_menu@entry=0x7fffffffd7db, end_time=0xd0a990, end_time@entry=0x0)
>     at keyboard.c:2786
> #4  0x00000000004fb469 in read_key_sequence (keybuf=keybuf@entry=0x7fffffffd8b0, prompt=prompt@entry=0, 
>     dont_downcase_last=dont_downcase_last@entry=false, can_return_switch_frame=can_return_switch_frame@entry=true, 
>     fix_current_buffer=fix_current_buffer@entry=true, prevent_redisplay=prevent_redisplay@entry=false, bufsize=30) at keyboard.c:9188
> #5  0x00000000004fd171 in command_loop_1 () at keyboard.c:1406
> #6  0x000000000055fbd7 in internal_condition_case (bfun=bfun@entry=0x4fcf30 <command_loop_1>, handlers=handlers@entry=18912, 
>     hfun=hfun@entry=0x4f3a30 <cmd_error>) at eval.c:1356
> #7  0x00000000004ef00c in command_loop_2 (ignore=ignore@entry=0) at keyboard.c:1138
> #8  0x000000000055fab3 in internal_catch (tag=tag@entry=45168, func=func@entry=0x4eeff0 <command_loop_2>, arg=arg@entry=0)
>     at eval.c:1116
> #9  0x00000000004eefc9 in command_loop () at keyboard.c:1117
> #10 0x00000000004f363b in recursive_edit_1 () at keyboard.c:723
> #11 0x00000000004f3960 in Frecursive_edit () at keyboard.c:794
> #12 0x00000000004187d6 in main (argc=1, argv=0x7fffffffdc38) at emacs.c:1629

Strange.  Does auto-revert-mode work in "emacs -Q"?  Do the related
tests in the test suite pass?

Can you use strace to see what error is that and what directory is
being watched?

bug#21337: 25.0.50; inotify error message

[Robert Pluim]

Eli Zaretskii <eliz@gnu.org> writes:

>
> Strange.  Does auto-revert-mode work in "emacs -Q"?  Do the related
> tests in the test suite pass?
>

Yes and yes.

> Can you use strace to see what error is that and what directory is
> being watched?

strace indicates that the directory where emacs is being run from is
being watched, along with my home directory plus any directories
containing files that are being visited. What's strange is that
inotify_add_watch is being called 22 times for the current directory.

I've debugged inotify_callback a little. The expectation of this code

  to_read = 0;
  if (ioctl (fd, FIONREAD, &to_read) == -1)
    xsignal1
      (Qfile_notify_error,
       build_string ("Error while trying to retrieve file system events"));
  buffer = xmalloc (to_read);
  n = read (fd, buffer, to_read);
  if (n < 0)
    {

is that the read will succeed, however to_read is very often 0, so
it's not surprising the read fails. (what does xmalloc do when its
argument is 0?)

My understanding was that the callback should only be called when
there are actual inotify events to process, so this behaviour is
somewhat surprising to me.

I can add in skipping the read if to_read == 0, but I suspect that's
just papering over the cracks.

Regards

Robert

bug#21337: 25.0.50; inotify error message

[Eli Zaretskii]

> From: Robert Pluim <rpluim@gmail.com>
> Cc: 21337@debbugs.gnu.org
> Date: Mon, 24 Aug 2015 20:32:59 +0200
> 
> strace indicates that the directory where emacs is being run from is
> being watched, along with my home directory plus any directories
> containing files that are being visited. What's strange is that
> inotify_add_watch is being called 22 times for the current directory.

Can you see which code causes these 22 calls for the same directory?

> I've debugged inotify_callback a little. The expectation of this code
> 
>   to_read = 0;
>   if (ioctl (fd, FIONREAD, &to_read) == -1)
>     xsignal1
>       (Qfile_notify_error,
>        build_string ("Error while trying to retrieve file system events"));
>   buffer = xmalloc (to_read);
>   n = read (fd, buffer, to_read);
>   if (n < 0)
>     {
> 
> is that the read will succeed, however to_read is very often 0, so
> it's not surprising the read fails.

That's strange, isn't it?  If to_read is zero, how come pselect
indicated that FD has stuff to be read?

> (what does xmalloc do when its argument is 0?)

Nothing, usually.

> My understanding was that the callback should only be called when
> there are actual inotify events to process, so this behaviour is
> somewhat surprising to me.

Exactly.

Could it be that we are somehow trying to read the same event 22
times, and then only the 1st time succeeds?

> I can add in skipping the read if to_read == 0, but I suspect that's
> just papering over the cracks.

The important question is, IMO, how come pselect says this FD is ready
to be read, when there's nothing to be read.

Btw, it would be nice to have errno description added to the error
message.

Thanks.

bug#21337: 25.0.50; inotify error message

[Robert Pluim]

Eli Zaretskii <eliz@gnu.org> writes:

>> is that the read will succeed, however to_read is very often 0, so
>> it's not surprising the read fails.
>
> That's strange, isn't it?  If to_read is zero, how come pselect
> indicated that FD has stuff to be read?

pselect didn't, but we fooled ourselves into thinking it did.

I suspected this was down to Gnus tickling some file descriptor
handling bug, and since the only code I could see in
wait_reading_process_output() that looked like it might be messing
things up was under a HAVE_GNUTLS define, I rebuilt without GnuTLS,
and the problem went away. After debugging some more, here's my
current theory (look around line 4904 of process.c:

1. the file descriptor for inotify events is checked by xg_select
   (since HAVE_GLIB == 1) using the Available fd_set
2. there is nothing to be read, so xg_select returns nfds =
   0. However, the inotify FD is still set in Available, which is
   unexpected but not wrong.
3. We then run:

		  for (channel = 0; channel < FD_SETSIZE; ++channel)
		    if (! NILP (chan_process[channel]))
		      {
			struct Lisp_Process *p =
			  XPROCESS (chan_process[channel]);
			if (p && p->gnutls_p && p->gnutls_state
			    && ((emacs_gnutls_record_check_pending
				 (p->gnutls_state))
				> 0))
			  {
			    nfds++;
			    eassert (p->infd == channel);
			    FD_SET (p->infd, &Available);
			  }
		      }

   which checks if any of the TLS file descriptors have waiting data
   that hasn't been indicated by xg_select, and sets the corresponding
   bit in the Available fd_set. In my case one of them does, so we
   increment nfds
   
4. We then reach

      if (no_avail || nfds == 0)
	continue;

      for (channel = 0; channel <= max_input_desc; ++channel)
        {
          struct fd_callback_data *d = &fd_callback_info[channel];
          if (d->func
	      && ((d->condition & FOR_READ
		   && FD_ISSET (channel, &Available))
		  || (d->condition & FOR_WRITE
		      && FD_ISSET (channel, &write_mask))))
            d->func (channel, d->data);
	}

   around line 5085 and loop over all the FDs we know about,
   checking to see if any of them are set in the Available fd_set

5. the inotify FD is still set in Available, so we call its callback
   function, which tries to read data when it shouldn't

Step 5 should never happen, but because step 2 did not clear the
Available fd_set, and the HAVE_GNUTLS code incremented nfds, we think
there's data to be read.

The following patch, which zeros out Available when the GNUTLS code
does its thing has fixed things for me. I've convinced myself it has
no bad side-effects, but would appreciate a second opinion, especially
since the option also exists to just zero out Available
unconditionally when nfds==0.

diff --git a/src/process.c b/src/process.c
index 9d8fa22..dcc004e 100644
--- a/src/process.c
+++ b/src/process.c
@@ -4913,6 +4913,10 @@ wait_reading_process_output (intmax_t time_limit, int nsecs, int read_kbd,
              data is available in the buffers manually.  */
           if (nfds == 0)
 	    {
+	      fd_set tls_available;
+	      int set = 0;
+
+	      FD_ZERO (&tls_available);
 	      if (! wait_proc)
 		{
 		  /* We're not waiting on a specific process, so loop
@@ -4933,7 +4937,8 @@ wait_reading_process_output (intmax_t time_limit, int nsecs, int read_kbd,
 			  {
 			    nfds++;
 			    eassert (p->infd == channel);
-			    FD_SET (p->infd, &Available);
+			    FD_SET (p->infd, &tls_available);
+			    set++;
 			  }
 		      }
 		}
@@ -4950,9 +4955,12 @@ wait_reading_process_output (intmax_t time_limit, int nsecs, int read_kbd,
 		      nfds = 1;
 		      eassert (0 <= wait_proc->infd);
 		      /* Set to Available.  */
-		      FD_SET (wait_proc->infd, &Available);
+		      FD_SET (wait_proc->infd, &tls_available);
+		      set++;
 		    }
 		}
+	      if (set)
+		Available = tls_available;
 	    }
 #endif
 	}

bug#21337: 25.0.50; inotify error message

[Eli Zaretskii]

> From: Robert Pluim <rpluim@gmail.com>
> Cc: 21337@debbugs.gnu.org
> Date: Wed, 26 Aug 2015 19:02:23 +0200
> 
> Step 5 should never happen, but because step 2 did not clear the
> Available fd_set, and the HAVE_GNUTLS code incremented nfds, we think
> there's data to be read.
> 
> The following patch, which zeros out Available when the GNUTLS code
> does its thing has fixed things for me. I've convinced myself it has
> no bad side-effects, but would appreciate a second opinion, especially
> since the option also exists to just zero out Available
> unconditionally when nfds==0.

Thanks for the investigation and the patch.  If no one objects in a
few days, I will commit your changes.

bug#21337: 25.0.50; inotify error message

[Eli Zaretskii]

> Date: Fri, 28 Aug 2015 16:30:16 +0300
> From: Eli Zaretskii <eliz@gnu.org>
> Cc: 21337@debbugs.gnu.org
> 
> > From: Robert Pluim <rpluim@gmail.com>
> > Cc: 21337@debbugs.gnu.org
> > Date: Wed, 26 Aug 2015 19:02:23 +0200
> > 
> > Step 5 should never happen, but because step 2 did not clear the
> > Available fd_set, and the HAVE_GNUTLS code incremented nfds, we think
> > there's data to be read.
> > 
> > The following patch, which zeros out Available when the GNUTLS code
> > does its thing has fixed things for me. I've convinced myself it has
> > no bad side-effects, but would appreciate a second opinion, especially
> > since the option also exists to just zero out Available
> > unconditionally when nfds==0.
> 
> Thanks for the investigation and the patch.  If no one objects in a
> few days, I will commit your changes.

Done.

bug#21337: 25.0.50; inotify error message

[Tassilo Horn]

Hi Robert and Eli,

could this issue also be the cause of bug#21313 which I've reported some
days ago?  I've tried very hard to reproduce it with the current master
branch which contains Robert's patch already and didn't succeed, so it
is possible that his patch also fixed that issue.

Bye,
Tassilo

bug#21337: 25.0.50; inotify error message

[Robert Pluim]

Tassilo Horn <tsdh@gnu.org> writes:

> Hi Robert and Eli,
>
> could this issue also be the cause of bug#21313 which I've reported some
> days ago?  I've tried very hard to reproduce it with the current master
> branch which contains Robert's patch already and didn't succeed, so it
> is possible that his patch also fixed that issue.

It's possible, but I haven't looked in detail at 21313. Any code in
emacs which reads from file descriptors could have been triggered
incorrectly before the fix went in.

Regards

Robert

bug#21337: 25.0.50; inotify error message

[Eli Zaretskii]

> From: Robert Pluim <rpluim@gmail.com>
> Cc: Robert Pluim <rpluim@gmail.com>,  Eli Zaretskii <eliz@gnu.org>,  21337@debbugs.gnu.org
> Date: Mon, 07 Sep 2015 09:43:07 +0200
> 
> Tassilo Horn <tsdh@gnu.org> writes:
> 
> > Hi Robert and Eli,
> >
> > could this issue also be the cause of bug#21313 which I've reported some
> > days ago?  I've tried very hard to reproduce it with the current master
> > branch which contains Robert's patch already and didn't succeed, so it
> > is possible that his patch also fixed that issue.
> 
> It's possible, but I haven't looked in detail at 21313. Any code in
> emacs which reads from file descriptors could have been triggered
> incorrectly before the fix went in.

Provided GnuTLS is compiled in -- which it is in this case.

So feel free to merge these two bugs and close the other one.

bug#21337: 25.0.50; inotify error message

[Robert Pluim]

forcemerge 21337 21313
stop

Eli Zaretskii <eliz@gnu.org> writes:
> Provided GnuTLS is compiled in -- which it is in this case.
>
> So feel free to merge these two bugs and close the other one.

I *think* this should close 21313 as well. admin/notes/bugtracker does
not suffer from being too short.

Thanks

Robert

bug#21337: 25.0.50; inotify error message

[Tassilo Horn]

Robert Pluim <rpluim@gmail.com> writes:

> forcemerge 21337 21313
> stop
>
> Eli Zaretskii <eliz@gnu.org> writes:
>> Provided GnuTLS is compiled in -- which it is in this case.
>>
>> So feel free to merge these two bugs and close the other one.
>
> I *think* this should close 21313 as well.

It did, but today I hit bug#21313 once again so apparently it is not
fixed by your commit.  Can the two bugs be separated again and bug#21313
be re-opened?

Bye,
Tassilo

bug#21337: 25.0.50; inotify error message

[Eli Zaretskii]

> From: Tassilo Horn <tsdh@gnu.org>
> Cc: Eli Zaretskii <eliz@gnu.org>,  21337@debbugs.gnu.org
> Date: Wed, 09 Sep 2015 18:49:35 +0200
> 
> > I *think* this should close 21313 as well.
> 
> It did, but today I hit bug#21313 once again so apparently it is not
> fixed by your commit.  Can the two bugs be separated again and bug#21313
> be re-opened?

Done.