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!