bug#18396: 24.3.1; On windows, process-send-string can freeze Emacs

bug#18396: 24.3.1; On windows, process-send-string can freeze Emacs

[Jorgen Schaefer]

Hi!
A user's bug report[1] on my project Elpy has revealed an apparent bug
in Emacs.

[1] https://github.com/jorgenschaefer/elpy/issues/212#issuecomment-54015294

Elpy starts a Python process using `start-process' with
`process-connection-type' set to nil, `default-directory' set to "/",
and an unchanged coding system. It then proceeds to talk with the
subprocess using a JSON-RPC-based protocol.

After some interactions, this freezes an Emacs under Windows. C-g does
not lead to any reaction. Killing the subprocess unfreezes Emacs. The
freeze happens more reliably the larger the data sent is.

I asked the user to change the function that does the process
communication to the following:

(defun elpy-rpc--call (method-name params success error)
  (let ((promise (elpy-promise success error)))
    (with-current-buffer (elpy-rpc--get-rpc-buffer)
      (setq elpy-rpc--call-id (1+ elpy-rpc--call-id))
      (elpy-rpc--register-callback elpy-rpc--call-id promise)
      (let ((proc (get-buffer-process (current-buffer)))
            (text (json-encode `((id . ,elpy-rpc--call-id)
                                 (method . ,method-name)
                                 (params . ,params)))))
        (message "Sending %s bytes ..." (length text))
        (process-send-string proc text)
        (process-send-string proc "\n")
        (message "Sending %s bytes ... done." (length text))))
    promise))

This lead to the following output in *Messages*:

Sending 978 bytes ... done.
Sending 958 bytes ... done.
Sending 959 bytes ... done.
Sending 960 bytes ... done.
Sending 961 bytes ... done.
Sending 962 bytes ... done.
Sending 958 bytes ...

At this point, Emacs froze. Apparently, it did so in the middle of one
of the two `process-send-string' calls. Killing the subprocess caused
the following output:

eldoc error: (file-error writing to process invalid argument elpy-rpc [project:~/ python:pythonw])

Elpy indeed is called from eldoc, and "elpy-rpc [project:~/
python:pythonw]" is the process name.

I'm a bit at a loss now as to how to continue debugging this. I do not
use Windows myself. I'm sure the user is willing to do some debugging
and reproduction cases there, but I wouldn't even know how to start or
what to ask them to do (Windows doesn't have strace, does it?).

Jorgen

bug#18396: 24.3.1; On windows, process-send-string can freeze Emacs

[Eli Zaretskii]

> From: Jorgen Schaefer <forcer@forcix.cx>
> Date: Wed, 03 Sep 2014 18:58:11 +0200
> 
> A user's bug report[1] on my project Elpy has revealed an apparent bug
> in Emacs.

I'm not sure it is a bug in Emacs.

> Elpy starts a Python process using `start-process' with
> `process-connection-type' set to nil, `default-directory' set to "/",
> and an unchanged coding system.

Using "/" as the default directory on Windows is a bad idea, as that
is not a fully-qualified absolute file name.

> After some interactions, this freezes an Emacs under Windows. C-g does
> not lead to any reaction.

On Windows, C-g cannot interrupt a system call.

> Killing the subprocess unfreezes Emacs.

Probably because it breaks the pipe to the subprocess.  Which probably
means Emacs is not hung, it waits for something that doesn't happen.

> The freeze happens more reliably the larger the data sent is.

This is consistent with the pipe not being read hypothesis, see below.

> (defun elpy-rpc--call (method-name params success error)
>   (let ((promise (elpy-promise success error)))
>     (with-current-buffer (elpy-rpc--get-rpc-buffer)
>       (setq elpy-rpc--call-id (1+ elpy-rpc--call-id))
>       (elpy-rpc--register-callback elpy-rpc--call-id promise)
>       (let ((proc (get-buffer-process (current-buffer)))
>             (text (json-encode `((id . ,elpy-rpc--call-id)
>                                  (method . ,method-name)
>                                  (params . ,params)))))
>         (message "Sending %s bytes ..." (length text))
>         (process-send-string proc text)
>         (process-send-string proc "\n")
>         (message "Sending %s bytes ... done." (length text))))
>     promise))
> 
> This lead to the following output in *Messages*:
> 
> Sending 978 bytes ... done.
> Sending 958 bytes ... done.
> Sending 959 bytes ... done.
> Sending 960 bytes ... done.
> Sending 961 bytes ... done.
> Sending 962 bytes ... done.
> Sending 958 bytes ...
> 
> At this point, Emacs froze. Apparently, it did so in the middle of one
> of the two `process-send-string' calls. Killing the subprocess caused
> the following output:
> 
> eldoc error: (file-error writing to process invalid argument elpy-rpc [project:~/ python:pythonw])

Looks like the write to the pipe never returned.  This could be
because the pipe is full and is not being read from the other end
(Windows pipes have 4K buffers, and you show above more than 6K of
data).

> I'm a bit at a loss now as to how to continue debugging this.

The obvious way: attach a debugger to Emacs and see where it is hung
or waiting.  It is important to ask the user to produce backtraces
from all the threads, because at least 2 threads are involved in
interaction with a subprocess on MS-Windows.

> (Windows doesn't have strace, does it?).

It does, but you don't want to use that, believe me: you would be
drowned in a flood of system calls, most of which are undocumented,
and even if they were, it is entirely non-obvious how to relate them
to what Emacs does.

bug#18396: 24.3.1; On windows, process-send-string can freeze Emacs

[Jorgen Schaefer]

On Wed, 03 Sep 2014 21:03:00 +0300
Eli Zaretskii <eliz@gnu.org> wrote:

> > From: Jorgen Schaefer <forcer@forcix.cx>
> > Date: Wed, 03 Sep 2014 18:58:11 +0200
> > 
> > A user's bug report[1] on my project Elpy has revealed an apparent
> > bug in Emacs.
>
> I'm not sure it is a bug in Emacs.

After your explanation, I'm not so sure, either.
 
> > Elpy starts a Python process using `start-process' with
> > `process-connection-type' set to nil, `default-directory' set to
> > "/", and an unchanged coding system.
> 
> Using "/" as the default directory on Windows is a bad idea, as that
> is not a fully-qualified absolute file name.

What would be the equivalent for "out of the way and not blocking any
mount point" (or equivalent) on Windows?

> Looks like the write to the pipe never returned.  This could be
> because the pipe is full and is not being read from the other end
> (Windows pipes have 4K buffers, and you show above more than 6K of
> data).

That is quite likely the explanation. The Python process does the
equivalent of a REPL, reading one RPC call, evaluating it, and writing
the response. If in the duration of that evaluation Emacs sends more
than 4k of data, it will hang. If the response is larger than 4k,
Python in turn will hang. Resulting in a deadlock.

Am I missing something?

The same would happen on Unix, except the buffer size is much larger,
meaning it's a lot less likely.

I guess the Python process could use threading to avoid this.

Does Emacs have a chance to check for a pipe to be writable before
doing so? The whole process blocking like this feels a bit weird.

> > I'm a bit at a loss now as to how to continue debugging this.
> 
> The obvious way: attach a debugger to Emacs and see where it is hung
> or waiting.  It is important to ask the user to produce backtraces
> from all the threads, because at least 2 threads are involved in
> interaction with a subprocess on MS-Windows.

Thanks. I'll ask, though I'm not sure if the user has a debugger
available.

Jorgen

bug#18396: 24.3.1; On windows, process-send-string can freeze Emacs

[Eli Zaretskii]

> Date: Wed, 3 Sep 2014 20:43:07 +0200
> From: Jorgen Schaefer <forcer@forcix.cx>
> Cc: 18396@debbugs.gnu.org
> 
> > Using "/" as the default directory on Windows is a bad idea, as that
> > is not a fully-qualified absolute file name.
> 
> What would be the equivalent for "out of the way and not blocking any
> mount point" (or equivalent) on Windows?

I might have a suggestion, if you explain what "out of the way" and
"not blocking any mount points" mean.

> > Looks like the write to the pipe never returned.  This could be
> > because the pipe is full and is not being read from the other end
> > (Windows pipes have 4K buffers, and you show above more than 6K of
> > data).
> 
> That is quite likely the explanation. The Python process does the
> equivalent of a REPL, reading one RPC call, evaluating it, and writing
> the response. If in the duration of that evaluation Emacs sends more
> than 4k of data, it will hang. If the response is larger than 4k,
> Python in turn will hang. Resulting in a deadlock.
> 
> Am I missing something?

I'd expect Python to continue reading from the pipe once it evaluated
one call and sent back the response.  It should see that more input is
available and continue reading.

Could this be an end-of-line format issue?  Are you sure the commands
used from Emacs side produce Windows-style CRLF EOLs?  Or maybe they
do, but Python expects Unix-style newline-only EOLs (maybe it's a
Cygwin or MSYS Python, for example)?  A wrong EOL format might cause
Python to fail to realize it was handed a full line of input.

> Does Emacs have a chance to check for a pipe to be writable before
> doing so? The whole process blocking like this feels a bit weird.

I don't know how to do such a check with pipes on Windows.  More
importantly, how would that help?  The pipe will fill up anyway, and
the communications with Python will stop.  Being able to interrupt
with C-g vs killing the subprocess is not such a big win, IMO.

> > The obvious way: attach a debugger to Emacs and see where it is hung
> > or waiting.  It is important to ask the user to produce backtraces
> > from all the threads, because at least 2 threads are involved in
> > interaction with a subprocess on MS-Windows.
> 
> Thanks. I'll ask, though I'm not sure if the user has a debugger
> available.

If the user doesn't have GDB, he/she can download one from the MinGW
site.  I think using a debugger is the only way to understand what
happens here.

bug#18396: 24.3.1; On windows, process-send-string can freeze Emacs

[Jorgen Schaefer]

On Wed, 03 Sep 2014 22:01:18 +0300
Eli Zaretskii <eliz@gnu.org> wrote:

> > Date: Wed, 3 Sep 2014 20:43:07 +0200
> > From: Jorgen Schaefer <forcer@forcix.cx>
> > Cc: 18396@debbugs.gnu.org
> > 
> > > Using "/" as the default directory on Windows is a bad idea, as
> > > that is not a fully-qualified absolute file name.
> > 
> > What would be the equivalent for "out of the way and not blocking
> > any mount point" (or equivalent) on Windows?
> 
> I might have a suggestion, if you explain what "out of the way" and
> "not blocking any mount points" mean.

The primary reason Elpy starts the process in "/" is to avoid
accidental imports of Python modules. As the process is started from a
Python buffer, there often are Python files in the current directory,
which can accidentally be imported. "/" is unlikely to have Python
modules.

Also, a current directory of "/" means the process won't
accidentally block a mount point, much like why daemons chdir to /. I'm
not sure if this concept makes sense in Windows.

> > > Looks like the write to the pipe never returned.  This could be
> > > because the pipe is full and is not being read from the other end
> > > (Windows pipes have 4K buffers, and you show above more than 6K of
> > > data).
> > 
> > That is quite likely the explanation. The Python process does the
> > equivalent of a REPL, reading one RPC call, evaluating it, and
> > writing the response. If in the duration of that evaluation Emacs
> > sends more than 4k of data, it will hang. If the response is larger
> > than 4k, Python in turn will hang. Resulting in a deadlock.
> > 
> > Am I missing something?
> 
> I'd expect Python to continue reading from the pipe once it evaluated
> one call and sent back the response.  It should see that more input is
> available and continue reading.

But if the sending of the response runs into the same problem? The
response can contain docstrings and can easily be larger than 4k, so
it's conceivable that Python sends more than 4k of data as well, which
would block the Python process, too? And thus prevent it from reading,
which keeps Emacs blocked?

> Could this be an end-of-line format issue?  Are you sure the commands
> used from Emacs side produce Windows-style CRLF EOLs?  Or maybe they
> do, but Python expects Unix-style newline-only EOLs (maybe it's a
> Cygwin or MSYS Python, for example)?  A wrong EOL format might cause
> Python to fail to realize it was handed a full line of input.

Unlikely. The RPC calls work perfectly fine most of the time, so the
line ending convention does not cause any confusion. Also, changing
the line ending convention on the Emacs side caused an error, so I
assume it's working fine as is.

> > Does Emacs have a chance to check for a pipe to be writable before
> > doing so? The whole process blocking like this feels a bit weird.
> 
> I don't know how to do such a check with pipes on Windows.  More
> importantly, how would that help?  The pipe will fill up anyway, and
> the communications with Python will stop.  Being able to interrupt
> with C-g vs killing the subprocess is not such a big win, IMO.

Well, if the deadlock hypothesis is correct, Emacs would check if the
pipe is writable, notice that it isn't and keep checking, to notice
that the pipe is readable, read data, and thus break the deadlock. That
of course requires that the deadlock hypothesis is indeed correct. :-)

> > > The obvious way: attach a debugger to Emacs and see where it is
> > > hung or waiting.  It is important to ask the user to produce
> > > backtraces from all the threads, because at least 2 threads are
> > > involved in interaction with a subprocess on MS-Windows.
> > 
> > Thanks. I'll ask, though I'm not sure if the user has a debugger
> > available.
> 
> If the user doesn't have GDB, he/she can download one from the MinGW
> site.  I think using a debugger is the only way to understand what
> happens here.

I'll pass it on, thanks.

Jorgen

bug#18396: 24.3.1; On windows, process-send-string can freeze Emacs

[Eli Zaretskii]

> Date: Wed, 3 Sep 2014 21:28:33 +0200
> From: Jorgen Schaefer <forcer@forcix.cx>
> Cc: 18396@debbugs.gnu.org
> 
> On Wed, 03 Sep 2014 22:01:18 +0300
> Eli Zaretskii <eliz@gnu.org> wrote:
> 
> > > Date: Wed, 3 Sep 2014 20:43:07 +0200
> > > From: Jorgen Schaefer <forcer@forcix.cx>
> > > Cc: 18396@debbugs.gnu.org
> > > 
> > > > Using "/" as the default directory on Windows is a bad idea, as
> > > > that is not a fully-qualified absolute file name.
> > > 
> > > What would be the equivalent for "out of the way and not blocking
> > > any mount point" (or equivalent) on Windows?
> > 
> > I might have a suggestion, if you explain what "out of the way" and
> > "not blocking any mount points" mean.
> 
> The primary reason Elpy starts the process in "/" is to avoid
> accidental imports of Python modules. As the process is started from a
> Python buffer, there often are Python files in the current directory,
> which can accidentally be imported. "/" is unlikely to have Python
> modules.

Why not use ~/, then?

> Also, a current directory of "/" means the process won't
> accidentally block a mount point, much like why daemons chdir to /. I'm
> not sure if this concept makes sense in Windows.

(expand-file-name "/") should do what you want, I think.

> > > > Looks like the write to the pipe never returned.  This could be
> > > > because the pipe is full and is not being read from the other end
> > > > (Windows pipes have 4K buffers, and you show above more than 6K of
> > > > data).
> > > 
> > > That is quite likely the explanation. The Python process does the
> > > equivalent of a REPL, reading one RPC call, evaluating it, and
> > > writing the response. If in the duration of that evaluation Emacs
> > > sends more than 4k of data, it will hang. If the response is larger
> > > than 4k, Python in turn will hang. Resulting in a deadlock.
> > > 
> > > Am I missing something?
> > 
> > I'd expect Python to continue reading from the pipe once it evaluated
> > one call and sent back the response.  It should see that more input is
> > available and continue reading.
> 
> But if the sending of the response runs into the same problem?

Each direction of the pipe has its own separate buffering, so this is
unlikely.

> The response can contain docstrings and can easily be larger than
> 4k, so it's conceivable that Python sends more than 4k of data as
> well, which would block the Python process, too? And thus prevent it
> from reading, which keeps Emacs blocked?

Emacs reads in a separate thread, so again, unlikely.

> > Could this be an end-of-line format issue?  Are you sure the commands
> > used from Emacs side produce Windows-style CRLF EOLs?  Or maybe they
> > do, but Python expects Unix-style newline-only EOLs (maybe it's a
> > Cygwin or MSYS Python, for example)?  A wrong EOL format might cause
> > Python to fail to realize it was handed a full line of input.
> 
> Unlikely. The RPC calls work perfectly fine most of the time

Perhaps this user has a different kind of Python than others.

> > > Does Emacs have a chance to check for a pipe to be writable before
> > > doing so? The whole process blocking like this feels a bit weird.
> > 
> > I don't know how to do such a check with pipes on Windows.  More
> > importantly, how would that help?  The pipe will fill up anyway, and
> > the communications with Python will stop.  Being able to interrupt
> > with C-g vs killing the subprocess is not such a big win, IMO.
> 
> Well, if the deadlock hypothesis is correct, Emacs would check if the
> pipe is writable, notice that it isn't and keep checking, to notice
> that the pipe is readable, read data, and thus break the deadlock.

See above: there's no interconnection between reading and writing, so
that's not the problem.

bug#18396: 24.3.1; On windows, process-send-string can freeze Emacs

[Eli Zaretskii]

> Date: Thu, 04 Sep 2014 05:51:45 +0300
> From: Eli Zaretskii <eliz@gnu.org>
> Cc: 18396@debbugs.gnu.org
> 
> > > > Does Emacs have a chance to check for a pipe to be writable before
> > > > doing so? The whole process blocking like this feels a bit weird.
> > > 
> > > I don't know how to do such a check with pipes on Windows.  More
> > > importantly, how would that help?  The pipe will fill up anyway, and
> > > the communications with Python will stop.  Being able to interrupt
> > > with C-g vs killing the subprocess is not such a big win, IMO.
> > 
> > Well, if the deadlock hypothesis is correct, Emacs would check if the
> > pipe is writable, notice that it isn't and keep checking, to notice
> > that the pipe is readable, read data, and thus break the deadlock.
> 
> See above: there's no interconnection between reading and writing, so
> that's not the problem.

I've just posted a tentative patch for the deadlock problem in
http://debbugs.gnu.org/cgi/bugreport.cgi?bug=18420#20.  If some of
your users can build their own Emacs, please ask them to apply the
patch and see if it resolves the problem.

Thanks.

bug#18396: No further updates

[Jorgen Schaefer]

The user did not provide any further feedback after three weeks.
Closing this bug report, assuming the problem was fixed.

Thank you!