bug#49954: 28.0.50; TRAMP: cannot kill child processes: "Forbidden reentrant call of Tramp"

bug#49954: 28.0.50; TRAMP: cannot kill child processes: "Forbidden reentrant call of Tramp"

[Dima Kogan]

Hi. I see this problem often in everyday use of emacs, but every time I
try to construct a reliable reproducing recipe, it always works ok, so
some of this report is a request for debugging help.

I've seen this sort of bug for years, so probably it exists in the
latest emacs. Today I'm seeing it in a build from a few weeks ago:
553ad9c9e85 built on 20210716. I don't know how to reproduce in the
latest emacs. In the session I have running (from the 20210716 build) I
have a shell buffer that shows the problem 100% of the time. New shell
buffers do not show this problem.

A recipe that should work:

1. emacs
   Run emacs. Possibly my config is triggering it. I don't know

2. C-x C-f /ssh:server:
   Open a remote TRAMP connection

3. M-x shell
   Open a remote shell

4. cat
   Run a "cat" command in the remote shell

5. C-c C-c
   kill the "cat"

In fresh emacs sessions and fresh shell buffers this works fine: the
"cat" process is killed and we get back to the prompt. Something happens
with older shell buffers where the child process is NOT killed, and
emacs complains with "Forbidden reentrant call of Tramp"

I just tried to (setq tramp-verbose 10) to get a debug log of the
failure. It says this:

  ;; Emacs: 28.0.50 Tramp: 2.5.1 -*- mode: outline; coding: utf-8; -*-
  ;; Location: /usr/share/emacs/28.0.50/lisp/net/tramp.el.gz Git: /
  01:49:39.391745 tramp-interrupt-process (5) # Interrupt process shell<6> with pid 3705628
  01:49:39.391864 tramp-get-connection-property (7) # null-device /dev/null; cache used: t
  01:49:39.391946 tramp-get-connection-property (7) # process-name nil; cache used: nil
  01:49:39.392019 tramp-get-connection-property (7) # process-name nil; cache used: nil
  01:49:39.392089 tramp-get-connection-property (7) # process-buffer nil; cache used: nil
  01:49:39.392180 tramp-get-connection-property (7) # last-cmd-time (24848 60388 520023 896000); cache used: t
  01:49:39.392262 tramp-get-connection-property (7) # process-name nil; cache used: nil
  01:49:39.392325 tramp-get-connection-property (7) # remote-echo nil; cache used: nil
  01:49:39.392385 tramp-send-command (6) # echo are you awake
  01:49:39.392447 tramp-get-connection-property (7) # process-name nil; cache used: nil
  01:49:39.392509 tramp-get-connection-property (7) # chunksize 0; cache used: t
  01:49:39.392573 tramp-set-connection-property (7) # last-cmd-time (24848 60451 392543 712000)
  01:49:39.392637 tramp-send-string (10) # echo are you awake
  01:49:39.392698 tramp-get-connection-property (7) # process-buffer nil; cache used: nil
  01:49:39.392775 tramp-get-connection-property (7) # locked nil; cache used: nil
  01:49:39.392828 tramp-set-connection-property (7) # locked t
  01:49:39.392912 tramp-flush-connection-property (7) # locked
  01:49:39.392981 tramp-get-connection-property (7) # check-remote-echo nil; cache used: nil
  01:49:39.393036 tramp-get-connection-property (7) # check-remote-echo nil; cache used: nil
  01:49:39.393120 tramp-get-connection-property (7) # locked nil; cache used: nil
  01:49:39.393173 tramp-set-connection-property (7) # locked t
  01:49:39.441305 tramp-accept-process-output (10) # *tramp/ssh fatty* nil run t
  are you awake
  ///66c246702753a7fa497f74164e69b140#$
  01:49:39.441619 tramp-flush-connection-property (7) # locked
  01:49:39.441783 tramp-get-connection-property (7) # check-remote-echo nil; cache used: nil
  01:49:39.441931 tramp-get-connection-property (7) # check-remote-echo nil; cache used: nil
  01:49:39.442103 tramp-wait-for-regexp (6) # 
  are you awake
  ///66c246702753a7fa497f74164e69b140#$
  01:49:39.442387 tramp-get-connection-property (7) # process-name nil; cache used: nil
  01:49:39.442556 tramp-get-connection-property (7) # remote-echo nil; cache used: nil
  01:49:39.442710 tramp-send-command (6) # (\kill -2 -3705628 || \kill -2 3705628) 2>/dev/null
  01:49:39.442872 tramp-get-connection-property (7) # process-name nil; cache used: nil
  01:49:39.443034 tramp-get-connection-property (7) # chunksize 0; cache used: t
  01:49:39.443204 tramp-set-connection-property (7) # last-cmd-time (24848 60451 443130 172000)
  01:49:39.443376 tramp-send-string (10) # (\kill -2 -3705628 || \kill -2 3705628) 2>/dev/null
  01:49:39.443589 tramp-get-connection-property (7) # process-buffer nil; cache used: nil
  01:49:39.443792 tramp-get-connection-property (7) # locked nil; cache used: nil
  01:49:39.443936 tramp-set-connection-property (7) # locked t
  01:49:39.444124 tramp-flush-connection-property (7) # locked
  01:49:39.444293 tramp-get-connection-property (7) # check-remote-echo nil; cache used: nil
  01:49:39.444433 tramp-get-connection-property (7) # check-remote-echo nil; cache used: nil
  01:49:39.444579 tramp-get-connection-property (7) # locked nil; cache used: nil
  01:49:39.444719 tramp-set-connection-property (7) # locked t
  01:49:39.493255 tramp-accept-process-output (10) # *tramp/ssh fatty* nil run t
  ///66c246702753a7fa497f74164e69b140#$
  01:49:39.493535 tramp-flush-connection-property (7) # locked
  01:49:39.493687 tramp-get-connection-property (7) # check-remote-echo nil; cache used: nil
  01:49:39.493835 tramp-get-connection-property (7) # check-remote-echo nil; cache used: nil
  01:49:39.494001 tramp-wait-for-regexp (6) # 
  ///66c246702753a7fa497f74164e69b140#$
  01:49:39.494263 tramp-get-connection-property (7) # locked t; cache used: t
  01:49:39.512596 tramp-accept-process-output (10) # 
    backtrace()
    tramp-error(#<process shell<6>> remote-file-error "Forbidden reentrant call of Tramp")
    tramp-accept-process-output(#<process shell<6>> 0)
    tramp-interrupt-process(nil t)
    comint-interrupt-subjob()
    funcall-interactively(comint-interrupt-subjob)
    command-execute(comint-interrupt-subjob)
  01:49:41.733242 tramp-accept-process-output


If I open a fresh shell in the same emacs session, it works OK. That
debug log is similar, except the last tramp-get-connection-property line says:

  01:48:36.571873 tramp-get-connection-property (7) # locked nil; cache used: nil

I don't know how it's unlocked. Debugging suggestions? Should I just add
more diagnostics in every lock/unlock path? Do we think this may be
fixed in the latest emacs?

Thanks!

bug#49954: 28.0.50; TRAMP: cannot kill child processes: "Forbidden reentrant call of Tramp"

[Michael Albinus]

Dima Kogan <dima@secretsauce.net> writes:

> Hi.

Hi Dima,

> I don't know how it's unlocked. Debugging suggestions? Should I just add
> more diagnostics in every lock/unlock path? Do we think this may be
> fixed in the latest emacs?

This error message has been added to Tramp 2.5 in order to get more
diagnostics when the problem happens. It is an indication that a remote
opeation has been started asynchronously, from a timer, a process filter
or sentinel, or other asynchronous invocation (like interrupt process).

I don't believe it has been fixed yet in Emacs master, I haven't done
anything in this area for weeks. I'll try to fix your use case, but it
might take time - these days I'm occupied otherwise. Holiday season.

See the respective entry in Tramp's FAQ (info "(tramp) Frequently Asked Questions")

See also the discussion on the Tramp ML
<https://lists.gnu.org/archive/cgi-bin/namazu.cgi?query=forbidden&submit=Search%21&idxname=tramp-devel&max=20&result=normal&sort=score>

> Thanks!

Best regards, Michael.

bug#49954: 28.0.50; TRAMP: cannot kill child processes: "Forbidden reentrant call of Tramp"

[Dima Kogan]

Hi Michael. There's no rush to work on this. I'll reply here for
whenever you get around to looking at it.

I did some debugging, and it appears that the tramp property-caching
mechanism is failing. We exit the (with-tramp-locked-connection ...)
form, but when we try to enter the next (with-tramp-locked-connection
...) form, it looks locked because

(tramp-get-connection-property proc "locked" nil)

is evaluating to t. I instrumented (tramp-get-connection-property), and
I can see that this t comes from the property cache. I can "fix" the bug
by removing the

    (when (and (not (eq cached tramp-cache-undefined))
	       ;; If the key is an auxiliary process object, check
	       ;; whether the process is still alive.
	       (not (and (processp key) (not (process-live-p key)))))
      (setq value cached
	    cache-used t))

form from (tramp-get-connection-property)

Can I get the intent of this form? Are you trying to use this form if
the process is alive, or if the process is dead? My process is very much
alive, so this form is being used. Is this what we want?

If it is what we want, then the cached value of t is the problem. I
haven't looked into why that's happening yet.

Thanks!

bug#49954: 28.0.50; TRAMP: cannot kill child processes: "Forbidden reentrant call of Tramp"

[Michael Albinus]

Dima Kogan <dima@secretsauce.net> writes:

> Hi Michael.

Hi Dima,

> I did some debugging, and it appears that the tramp property-caching
> mechanism is failing. We exit the (with-tramp-locked-connection ...)
> form, but when we try to enter the next (with-tramp-locked-connection
> ...) form, it looks locked because
>
> (tramp-get-connection-property proc "locked" nil)
>
> is evaluating to t. I instrumented (tramp-get-connection-property), and
> I can see that this t comes from the property cache. I can "fix" the bug
> by removing the
>
>     (when (and (not (eq cached tramp-cache-undefined))
> 	       ;; If the key is an auxiliary process object, check
> 	       ;; whether the process is still alive.
> 	       (not (and (processp key) (not (process-live-p key)))))
>       (setq value cached
> 	    cache-used t))
>
> form from (tramp-get-connection-property)
>
> Can I get the intent of this form? Are you trying to use this form if
> the process is alive, or if the process is dead? My process is very much
> alive, so this form is being used. Is this what we want?

No, I believe the mechanism is working correctly. A lock is placed on
the connection process of Tramp, and it is kept until the related
operation has finished. The process is expected to be alive, the
additional check of process-live-p is just a reassurance.

> If it is what we want, then the cached value of t is the problem. I
> haven't looked into why that's happening yet.

The problem is the following: Tramp sends a (shell) command to the
remote host, and waits for the reply. This must be atomic, no other
command shall be sent in parallel, in order to get the proper reply.

If there is asynchronous code running, from a timer, a process filter or
sentinel, or process interrupt, this can happen: a second command is
sent, while the other command didn't get its reply yet. The macro
with-tramp-locked-connection shall protect us in this case, and it
raises the respective error. That's not a perfect solution. A better way
would do use threads with mutexes, so that the second command can wait
until the first command got its reply. Something like this needs to be
implemented.

> Thanks!

Best regards, Michael.

bug#49954: 28.0.50; TRAMP: cannot kill child processes: "Forbidden reentrant call of Tramp"

[Dima Kogan]

Hi Michael.

So I've seen this a number of times now, and it really looks like the
caching mechanism is the problem. Every time I see "Forbidden reentrant
call of Tramp" when trying to C-c C-c a remote process, I re-evaluate
tramp-get-connection-property with

  (when (and (not (eq cached tramp-cache-undefined))
             ;; If the key is an auxiliary process object, check
             ;; whether the process is still alive.
             (not (and (processp key) (not (process-live-p key)))))
    (setq value cached
          cache-used t))

removed. This effectively disables the caching mechanism. Then I can C-c
C-c my process, and it dies like it's supposed to. TRAMP feels slower
after than, as expected, so I put tramp-get-connection-property back to
what it was. Eventually the problem comes back, and I do the same dance
to "fix" it.

bug#49954: 28.0.50; TRAMP: cannot kill child processes: "Forbidden reentrant call of Tramp"

[Michael Albinus]

Dima Kogan <dima@secretsauce.net> writes:

> Hi Michael.

Hi Dima,

> So I've seen this a number of times now, and it really looks like the
> caching mechanism is the problem.

No, it isn't. Tramp uses its cache just as memory. The problem is
somewhere else, see below.

> Every time I see "Forbidden reentrant call of Tramp" when trying to
> C-c C-c a remote process, I re-evaluate tramp-get-connection-property
> with
>
>   (when (and (not (eq cached tramp-cache-undefined))
>              ;; If the key is an auxiliary process object, check
>              ;; whether the process is still alive.
>              (not (and (processp key) (not (process-live-p key)))))
>     (setq value cached
>           cache-used t))
>
> removed. This effectively disables the caching mechanism. Then I can C-c
> C-c my process, and it dies like it's supposed to. TRAMP feels slower
> after than, as expected, so I put tramp-get-connection-property back to
> what it was. Eventually the problem comes back, and I do the same dance
> to "fix" it.

The Tramp manual tells you how to bypass the problem, see Frequently
Asked Questions:

--8<---------------cut here---------------start------------->8---
   • I get an error ‘Remote file error: Forbidden reentrant call of
     Tramp’

     Timers, process filters and sentinels, and other event based
     functions can run at any time, when a remote file operation is
     still running.  This can cause TRAMP to block.  When such a
     situation is detected, this error is triggered.  It should be fixed
     in the respective function (sending an error report will help), but
     for the time being you can suppress this error by the following
     code in your ‘~/.emacs’:

          (setq debug-ignored-errors
                (cons 'remote-file-error debug-ignored-errors))
--8<---------------cut here---------------end--------------->8---

In order to understand the problem, let's assume the following scenario:

- You have connected to a remote host, say "/ssh:host:". Tramp uses
  internally the process *tramp/ssh host* for communicating with that
  process.

- You have also started another asynchronous process to that remote
  host.

- Now, while normal use of Emacs, the function (file-attributes
  "/ssh:host:/path/to/file") is called. Tramp sends a command to the
  process *tramp/ssh host*, like "stat /path/to/file".

- While Tramp waits for the answer of the "stat ..." command, your other
  process has finished. It might have a process sentinel, which is
  called exactly at this time, because Tramp is in a loop
  (accept-process-output ...).

- This process filter might trigger another file operation, like
  (delete-file "/ssh:host:/tmp/tmpfile"). This would require to send
  another command to the *tramp/ssh host* process like "rm -f /tmp/tmpfile".

- Since the first command, "stat ...", hasn't been finished, this would
  result in inconsistencies. Tramp detects this situation, and raises
  the "Forbidden reentrant call of Tramp" error.

Not so easy to solve. Ideally, remote file name functions initiated in
process filters, process sentinels, timers and alike shall wait, until
the currently executed remote command has finished. Don't know how to
achieve this.

Best regards, Michael.

bug#49954: 28.0.50; TRAMP: cannot kill child processes: "Forbidden reentrant call of Tramp"

[Dima Kogan]

Thanks for the explanation. What would be an example of an asynchronous
process? I have several remote 'M-x shell' buffers and probably some
dired buffers looking at remote directories. Is each 'M-x shell' child
an "asynchronous process" for the purposes of this issue?

Does it make sense to you that disabling caching fixes it?

Usually, I can C-c in "M-x shell" just fine. When this bug is triggered,
though, I cannot C-c in remote M-x shell processes at all: it fails each
time. Disabling the caching, getting one successful C-c, and re-enabling
it makes it work that time and in the future. Is this consistent with
the failure mechanism you're thinking of?

Thanks

bug#49954: 28.0.50; TRAMP: cannot kill child processes: "Forbidden reentrant call of Tramp"

[Dima Kogan]

I paid more attention to my usage patterns recently. I often have
multiple remote M-x shell buffers going at the same time, using the same
TRAMP connection. One shell might be running a long job, writing stuff
to the console, while I use another shell to do stuff. Could this usage
trigger the race condition you're talking about? If so, setting up an
experiment to try to reproduce the breakage wouldn't be too hard.

bug#49954: 28.0.50; TRAMP: cannot kill child processes: "Forbidden reentrant call of Tramp"

[Michael Albinus]

Dima Kogan <dima@secretsauce.net> writes:

Hi Dima,

> Thanks for the explanation. What would be an example of an asynchronous
> process? I have several remote 'M-x shell' buffers and probably some
> dired buffers looking at remote directories. Is each 'M-x shell' child
> an "asynchronous process" for the purposes of this issue?

It is an synchronous process, indeed.

> Does it make sense to you that disabling caching fixes it?
>
> Usually, I can C-c in "M-x shell" just fine. When this bug is triggered,
> though, I cannot C-c in remote M-x shell processes at all: it fails each
> time. Disabling the caching, getting one successful C-c, and re-enabling
> it makes it work that time and in the future. Is this consistent with
> the failure mechanism you're thinking of?

Why do you mess with Tramp's cache? Adding remote-file-error to
debug-ignored-errors, as  I have recommended, shall mask the error
sufficiently.

> Thanks

Best regards, Michael.

bug#49954: 28.0.50; TRAMP: cannot kill child processes: "Forbidden reentrant call of Tramp"

[Michael Albinus]

Dima Kogan <dima@secretsauce.net> writes:

Hi Dima,

> I paid more attention to my usage patterns recently. I often have
> multiple remote M-x shell buffers going at the same time, using the same
> TRAMP connection. One shell might be running a long job, writing stuff
> to the console, while I use another shell to do stuff. Could this usage
> trigger the race condition you're talking about? If so, setting up an
> experiment to try to reproduce the breakage wouldn't be too hard.

I have not the problem to reproduce the bug,
tramp-test44-asynchronous-requests of tramp-tests.el is good enough.

My problem is to find a solution. I'm thinking about using threads, but
there are some hairy details I need to solve first.

Best regards, Michael.

bug#49954: 28.0.50; TRAMP: cannot kill child processes: "Forbidden reentrant call of Tramp"

[Dima Kogan]

Michael Albinus <michael.albinus@gmx.de> writes:

> Why do you mess with Tramp's cache? Adding remote-file-error to
> debug-ignored-errors, as I have recommended, shall mask the error
> sufficiently.

Tweaking the cache is the method I've found to work, before I knew about
debug-ignored-errors. I'll do what you suggest next time.

Thanks

bug#49954: 28.0.50; TRAMP: cannot kill child processes: "Forbidden reentrant call of Tramp"

[Michael Albinus]

Dima Kogan <dima@secretsauce.net> writes:

Hi Dima,

>> Why do you mess with Tramp's cache? Adding remote-file-error to
>> debug-ignored-errors, as I have recommended, shall mask the error
>> sufficiently.
>
> Tweaking the cache is the method I've found to work, before I knew about
> debug-ignored-errors. I'll do what you suggest next time.

Thanks! I didn't want to bash you, sorry.

> Thanks

Best regards, Michael.

bug#49954: 28.0.50; TRAMP: cannot kill child processes: "Forbidden reentrant call of Tramp"

[Dima Kogan]

Hi. I just hit this error again, and tried to work around it with

  (setq debug-ignored-errors
    (cons 'remote-file-error debug-ignored-errors))

as you suggested. It doesn't work to kill the process, though. I C-c C-c
in my M-x shell, and it fails with a different error:

  tramp-accept-process-output: No catch for tag: non-essential, non-essential

Doing my caching dance actually makes C-c C-c do the right thing. Does
this make sense?

bug#49954: 28.0.50; TRAMP: cannot kill child processes: "Forbidden reentrant call of Tramp"

[Michael Albinus]

Dima Kogan <dima@secretsauce.net> writes:

> Hi.

Hi Dima,

> I just hit this error again, and tried to work around it with
>
>   (setq debug-ignored-errors
>     (cons 'remote-file-error debug-ignored-errors))
>
> as you suggested. It doesn't work to kill the process, though. I C-c C-c
> in my M-x shell, and it fails with a different error:
>
>   tramp-accept-process-output: No catch for tag: non-essential, non-essential
>
> Doing my caching dance actually makes C-c C-c do the right thing. Does
> this make sense?

If the "caching dance" helps you you might continue with this. But I
won't recommend it to the public, I fear too many undesired side-effects.

The best solution would be to fix the problem itself. As always.

Best regards, Michael.