TRAMP VC optimization: also breaks process filters -_-

TRAMP VC optimization: also breaks process filters -_-

[Daniel Pittman]

[-- Attachment #1.1: Type: text/plain, Size: 2582 bytes --]

G'day Michael.

I'm sad to report that blocking timers in TRAMP is not sufficient to avoid
it breaking other operations: process filters can also run while TRAMP is
sending, and waiting for the result of, a command.

I have attached a backtrace showing this, which happens during startup: I
trigger an async ELPA package refresh at the start of my init file, which
is what causes the HTTPS connection, and in the process filter invokes the
NSM library to verify the cert – and that tries to access a local path for
the database of ... something related to handling certificates.  (I think
user supplied policy decisions around them or something, but I don't know
the detail.)

That call to NSM from `url-https-proxy-after-change-function` in
`url-http.el`, ultimately called from `url-http-generic-filter` with
`funcall`, which is set as the process filter for the network connection in
`url-http`, the entry point to fetching the content.

I found this when I set down to discover why my package refresh was
breaking during startup; if it is still running when the desktop.el library
triggers restoring state, and that state includes TRAMP files (which it
always does, for me) then it can happen at the same time as the refresh.

A reproducible case should be possible by way of running this code in a
TRAMP backed buffer:
(progn (package-refresh-contents t) (revert-buffer))  ;; the first bit
starts an async package refresh

It is, though, a race condition, so if it doesn't trigger you may want to
loop reverting or something.  The backtrace is fairly clear, however.  In
theory it could also be triggered by any other process filter that triggers
a file operation on a local file.


Notes on the backtrace:

`tramp-user-error@backtrace-on-bad-file-name-handling` is my advice to
capture the backtrace, and consists of calling (debug) at the appropriate
moment.

I censored some names in the source for work related reasons, which are a)
fairly obvious, and b) only in strings, and c) not relevant to the bug
itself.

The `gssh` method is a copy of the `ssh` method with a trivial
modification; while I don't think it is strictly relevant, the performance
of it may be related to how easy the race is for me to hit.

The modification consist of pointing at the "correct" ssh binary for my
environment, by absolute path, rather than the default one.  (I think I
fixed the problem causing it to come into being by adjusting how I handle
the executable-path in init.el too, but I'm too lazy to remove the
configuration now.)

[-- Attachment #1.2: Type: text/html, Size: 2980 bytes --]

[-- Attachment #2: tramp-vc-filename-handling-2.text --]
[-- Type: text/plain, Size: 3663 bytes --]

  tramp-user-error@backtrace-on-bad-file-name-handling(#f(compiled-function (vec-or-proc fmt-string &rest arguments) "Signal a pilot error." #<bytecode 0x1ff56d61adad>) nil "Not a Tramp file name: \"%s\"" "/Users/slippycheeze/.emacs.d/network-security.data")
  apply(tramp-user-error@backtrace-on-bad-file-name-handling #f(compiled-function (vec-or-proc fmt-string &rest arguments) "Signal a pilot error." #<bytecode 0x1ff56d61adad>) (nil "Not a Tramp file name: \"%s\"" "/Users/slippycheeze/.emacs.d/network-security.data"))
  tramp-user-error(nil "Not a Tramp file name: \"%s\"" "/Users/slippycheeze/.emacs.d/network-security.data")
  tramp-dissect-file-name("/Users/slippycheeze/.emacs.d/network-security.data")
  tramp-vc-file-name-handler(expand-file-name "/Users/slippycheeze/.emacs.d/network-security.data" "/gssh:slippycheeze.X.XXXXXXXX.XXX:")
  file-exists-p("/Users/slippycheeze/.emacs.d/network-security.data")
  nsm-host-settings("sha1:6d4eb958390599243ba9f5035cb671fa8dd6a93a")
  nsm-verify-connection(#<process elpa.gnu.org> "elpa.gnu.org" 443)
  process-send-string(#<process *tramp/gssh slippycheeze.X.XXXXXXXX.XXX*> "tramp_vc_registered_read_file_names <<'48a492074c8...")
  tramp-send-string((tramp-file-name "gssh" nil nil "slippycheeze.X.XXXXXXXX.XXX" nil "/XXXXXX/XXXXXX/XXXXXX..." nil) "tramp_vc_registered_read_file_names <<'48a492074c8...")
  tramp-send-command((tramp-file-name "gssh" nil nil "slippycheeze.X.XXXXXXXX.XXX" nil "/XXXXXX/XXXXXX/XXXXXX..." nil) "tramp_vc_registered_read_file_names <<'48a492074c8...")
  tramp-sh-handle-vc-registered("/gssh:slippycheeze.X.XXXXXXXX.XXX:/XXXXXX/XXXXXX/XXXXXX...")
  apply(tramp-sh-handle-vc-registered "/gssh:slippycheeze.X.XXXXXXXX.XXX:/XXXXXX/XXXXXX/XXXXXX...")
  tramp-sh-file-name-handler(vc-registered "/gssh:slippycheeze.X.XXXXXXXX.XXX:/XXXXXX/XXXXXX/XXXXXX...")
  apply(tramp-sh-file-name-handler vc-registered "/gssh:slippycheeze.X.XXXXXXXX.XXX:/XXXXXX/XXXXXX/XXXXXX...")
  tramp-file-name-handler(vc-registered "/gssh:slippycheeze.X.XXXXXXXX.XXX:/XXXXXX/XXXXXX/XXXXXX...")
  vc-registered("/gssh:slippycheeze.X.XXXXXXXX.XXX:/XXXXXX/XXXXXX/XXXXXX...")
  vc-backend("/gssh:slippycheeze.X.XXXXXXXX.XXX:/XXXXXX/XXXXXX/XXXXXX...")
  vc-refresh-state()
  run-hooks(find-file-hook)
  after-find-file(nil nil)
  find-file-noselect-1(#<buffer XXXXXX.XXXXXX> "/gssh:slippycheeze.X.XXXXXXXX.XXX:/XXXXXX/XXXXXX/XXXXXX..." :nowarn nil "/gssh:slippycheeze.X.XXXXXXXX.XXX:/XXXXXX/XXXXXX/XXXXXX..." (489393 (-1 . 1)))
  find-file-noselect("/gssh:slippycheeze.X.XXXXXXXX.XXX:/XXXXXX/XXXXXX/XXXXXX..." :nowarn)
  desktop-restore-file-buffer("/gssh:slippycheeze.X.XXXXXXXX.XXX:/XXXXXX/XXXXXX/XXXXXX..." "XXXXXX.XXXXXX" nil)
  desktop-create-buffer(208 "/gssh:slippycheeze.X.XXXXXXXX.XXX:/XXXXXX/XXXXXX/XXXXXX..." "XXXXXX.XXXXXX" protobuffer-mode (override-global-mode googlemenu-mode super-save-mode beginend-prog-mode beginend-global-mode global-auto-revert-mode ws-butler-mode typo-mode rainbow-delimiters-mode which-key-mode) 2 (nil nil) nil nil ((tab-width . 2) (indent-tabs-mode) (buffer-display-time 23750 65183 759529 0) (buffer-file-coding-system . utf-8-unix)) ((mark-ring nil)))
  eval-buffer(#<buffer  *load*> nil "/Users/slippycheeze/.emacs.d/emacs.slippycheeze.de..." nil t)  ; Reading at buffer position 761841
  load-with-code-conversion("/Users/slippycheeze/.emacs.d/emacs.slippycheeze.de..." "/Users/slippycheeze/.emacs.d/emacs.slippycheeze.de..." t t)
  load("/Users/slippycheeze/.emacs.d/emacs.slippycheeze.de..." t t t)
  desktop-read()
  #f(compiled-function () #<bytecode 0x1ff56caf6cc1>)()
  run-hooks(after-init-hook delayed-warnings-hook)
  command-line()
  normal-top-level()

Re: TRAMP VC optimization: also breaks process filters -_-

[Stefan Monnier]

> I'm sad to report that blocking timers in TRAMP is not sufficient to avoid
> it breaking other operations: process filters can also run while TRAMP is
> sending, and waiting for the result of, a command.

I'm not sure what is the problem with timers and/or process filters
(e.g. I don't see any process filters in your backtrace), so maybe I'm
misunderstanding the problem, but FWIW, here's what I noticed:

>   tramp-user-error(nil "Not a Tramp file name: \"%s\"" "/Users/slippycheeze/.emacs.d/network-security.data")
>   tramp-dissect-file-name("/Users/slippycheeze/.emacs.d/network-security.data")
>   tramp-vc-file-name-handler(expand-file-name "/Users/slippycheeze/.emacs.d/network-security.data" "/gssh:slippycheeze.X.XXXXXXXX.XXX:")

This indicates that Tramp gets confused and thinks that the
tramp-vc-file-name-handler was called in response to expand-file-name on
the file "/Users/slippycheeze/.emacs.d/network-security.data" whereas
it's called because of the directory argument.

So I believe the (untested) patch below should fix the immediate problem.
Can you confirm?

Michael?


        Stefan


diff --git a/lisp/net/tramp.el b/lisp/net/tramp.el
index 1f83756c32..d354086ecf 100644
--- a/lisp/net/tramp.el
+++ b/lisp/net/tramp.el
@@ -2188,7 +2188,9 @@ tramp-file-name-for-operation
    ;; FILE DIRECTORY resp FILE1 FILE2.
    ((eq operation 'expand-file-name)
     (cond
-     ((file-name-absolute-p (nth 0 args)) (nth 0 args))
+     ((and (file-name-absolute-p (nth 0 args))
+           (tramp-tramp-file-p (nth 0 args)))
+      (nth 0 args))
      ((tramp-tramp-file-p (nth 1 args)) (nth 1 args))
      (t default-directory)))
    ;; START END FILE.

Re: TRAMP VC optimization: also breaks process filters -_-

[Michael Albinus]

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

Stefan Monnier <monnier@iro.umontreal.ca> writes:

Hi,

>> I'm sad to report that blocking timers in TRAMP is not sufficient to avoid
>> it breaking other operations: process filters can also run while TRAMP is
>> sending, and waiting for the result of, a command.
>
> I'm not sure what is the problem with timers and/or process filters
> (e.g. I don't see any process filters in your backtrace), so maybe I'm
> misunderstanding the problem, but FWIW, here's what I noticed:
>
>>   tramp-user-error(nil "Not a Tramp file name: \"%s\"" "/Users/slippycheeze/.emacs.d/network-security.data")
>>   tramp-dissect-file-name("/Users/slippycheeze/.emacs.d/network-security.data")
>>   tramp-vc-file-name-handler(expand-file-name "/Users/slippycheeze/.emacs.d/network-security.data" "/gssh:slippycheeze.X.XXXXXXXX.XXX:")
>
> This indicates that Tramp gets confused and thinks that the
> tramp-vc-file-name-handler was called in response to expand-file-name on
> the file "/Users/slippycheeze/.emacs.d/network-security.data" whereas
> it's called because of the directory argument.
>
> So I believe the (untested) patch below should fix the immediate problem.
> Can you confirm?
>
> Michael?

Yes, the analysis is correct. However, we don't need to check this for
every Tramp invocation. Daniel's reports have been covered always
vc-registered. And indeed, the related `tramp-vc-file-name-handler'
seems to expect always a Tramp file name, which is not true for filters
and sentinels which run for non-Tramp processes.

Daniel, does the appended patch fixes the issue for you?

>         Stefan

Best regards, Michael.


[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: Type: text/x-patch, Size: 3008 bytes --]

*** /tmp/ediffKys9Ze	2019-05-07 17:22:48.298108293 +0200
--- /home/albinus/src/tramp/lisp/tramp-sh.el	2019-05-07 17:19:08.563550390 +0200
***************
*** 3550,3573 ****
  	   (tramp-replace-environment-variables
  	    (apply #'tramp-file-name-for-operation operation args)))
  	  (fn (assoc operation tramp-sh-file-name-handler-alist)))
!       (with-parsed-tramp-file-name filename nil
! 	(cond
! 	 ;; That's what we want: file names, for which checks are
! 	 ;; applied.  We assume that VC uses only `file-exists-p' and
! 	 ;; `file-readable-p' checks; otherwise we must extend the
! 	 ;; list.  We do not perform any action, but return nil, in
! 	 ;; order to keep `vc-registered' running.
! 	 ((and fn (memq operation '(file-exists-p file-readable-p)))
! 	  (add-to-list 'tramp-vc-registered-file-names localname 'append)
! 	  nil)
! 	 ;; `process-file' and `start-file-process' shall be ignored.
! 	 ((and fn (eq operation 'process-file) 0))
! 	 ((and fn (eq operation 'start-file-process) nil))
! 	 ;; Tramp file name handlers like `expand-file-name'.  They
! 	 ;; must still work.
! 	 (fn (save-match-data (apply (cdr fn) args)))
! 	 ;; Default file name handlers, we don't care.
! 	 (t (tramp-run-real-handler operation args)))))))

  (defun tramp-sh-handle-file-notify-add-watch (file-name flags _callback)
    "Like `file-notify-add-watch' for Tramp files."
--- 3550,3579 ----
  	   (tramp-replace-environment-variables
  	    (apply #'tramp-file-name-for-operation operation args)))
  	  (fn (assoc operation tramp-sh-file-name-handler-alist)))
!       ;; If connection is not established yet, or if it is not a Tramp
!       ;; file, run the real handler.  This can happen if timers,
!       ;; process filters, or process sentinels not related to us are
!       ;; activated.
!       (if (not (tramp-connectable-p filename))
! 	  (tramp-run-real-handler operation args)
! 	(with-parsed-tramp-file-name filename nil
! 	  (cond
! 	   ;; That's what we want: file names, for which checks are
! 	   ;; applied.  We assume that VC uses only `file-exists-p' and
! 	   ;; `file-readable-p' checks; otherwise we must extend the
! 	   ;; list.  We do not perform any action, but return nil, in
! 	   ;; order to keep `vc-registered' running.
! 	   ((and fn (memq operation '(file-exists-p file-readable-p)))
! 	    (add-to-list 'tramp-vc-registered-file-names localname 'append)
! 	    nil)
! 	   ;; `process-file' and `start-file-process' shall be ignored.
! 	   ((and fn (eq operation 'process-file) 0))
! 	   ((and fn (eq operation 'start-file-process) nil))
! 	   ;; Tramp file name handlers like `expand-file-name'.  They
! 	   ;; must still work.
! 	   (fn (save-match-data (apply (cdr fn) args)))
! 	   ;; Default file name handlers, we don't care.
! 	   (t (tramp-run-real-handler operation args))))))))

  (defun tramp-sh-handle-file-notify-add-watch (file-name flags _callback)
    "Like `file-notify-add-watch' for Tramp files."

Re: TRAMP VC optimization: also breaks process filters -_-

[Stefan Monnier]

> Yes, the analysis is correct. However, we don't need to check this for
> every Tramp invocation.

Indeed, when the first arg of expand-file-name is absolute the second
arg shouldn't matter.

> Daniel's reports have been covered always
> vc-registered. And indeed, the related `tramp-vc-file-name-handler'
> seems to expect always a Tramp file name, which is not true for filters
> and sentinels which run for non-Tramp processes.

I don't understand what filers and sentinels have to do with it.

> Daniel, does the appended patch fixes the issue for you?

The patch looks good to me, at least,


        Stefan

Re: TRAMP VC optimization: also breaks process filters -_-

[Michael Albinus]

Stefan Monnier <monnier@IRO.UMontreal.CA> writes:

>> Daniel's reports have been covered always
>> vc-registered. And indeed, the related `tramp-vc-file-name-handler'
>> seems to expect always a Tramp file name, which is not true for filters
>> and sentinels which run for non-Tramp processes.
>
> I don't understand what filers and sentinels have to do with it.

The last Tramp action as expected was process-send-string (called from
tramp-send-string). According to the Elisp manual, filters or sentinels
from *other* processes can be called during process-send-string:

--8<---------------cut here---------------start------------->8---
   Sometimes the system is unable to accept input for that process,
because the input buffer is full.  When this happens, the send functions
wait a short while, accepting output from subprocesses, and then try
again.  This gives the subprocess a chance to read more of its pending
input and make space in the buffer.  It also allows filters, sentinels
and timers to run—so take account of that in writing your code.
--8<---------------cut here---------------end--------------->8---

This happens here, as Daniel has shown.

The problem is, that expand-file-name has been forwarded to
tramp-vc-file-name-handler due to the remote DIR argument. This isn't
relevant, because FILENAME is absolute, but in the next line FILENAME is
tried to be dissected without any further check. This I have changed.

In the native tramp-file-name-handler, this situation can also happen,
but it is handled already. So we have only to fix tramp-vc-file-name-handler.

>         Stefan

Best regards, Michael.

Re: TRAMP VC optimization: also breaks process filters -_-

[Stefan Monnier]

> The last Tramp action as expected was process-send-string (called from
> tramp-send-string). According to the Elisp manual, filters or sentinels
> from *other* processes can be called during process-send-string:

Right, but a call to expand-file-name like happened to Daniel is
perfectly normal and can occur anywhere, not just in process filters
or timers.


        Stefan

Re: TRAMP VC optimization: also breaks process filters -_-

[Michael Albinus]

Stefan Monnier <monnier@IRO.UMontreal.CA> writes:

>> The last Tramp action as expected was process-send-string (called from
>> tramp-send-string). According to the Elisp manual, filters or sentinels
>> from *other* processes can be called during process-send-string:
>
> Right, but a call to expand-file-name like happened to Daniel is
> perfectly normal and can occur anywhere, not just in process filters
> or timers.

Sure, but it lands in tramp-file-name-handler then, usually. This takes
care about expand-file-name with an absolute file name and a remote directory.

The problem with Daniel's case is tramp-vc-file-name-handler, which
didn't care. This I've tried to fix (let's see, whether Daniel reports
success).

>         Stefan

Best regards, Michael.