all messages for Emacs-related lists mirrored at yhetil.org
 help / color / mirror / code / Atom feed
* bug#41333: 27.0.91; Spurious errors using TRAMP and auto-save-visited-mode
@ 2020-05-16 17:48 Philipp Stephani
  2022-06-06 13:36 ` Lars Ingebrigtsen
  0 siblings, 1 reply; 9+ messages in thread
From: Philipp Stephani @ 2020-05-16 17:48 UTC (permalink / raw)
  To: 41333


Unfortunately I don't have good reproduction steps; it seems this issue
is somewhat subtle and requires a certain interaction between
auto-save-visited-mode, and TRAMP, and various private customizations
and before-save-hooks.

When using auto-save-visited-mode for a file visited using TRAMP's SSH
backend, I frequently get prompts that the file has changed outside of
Emacs, even though that's not the case.  The issue isn't easily
reproducible.  It doesn't happen for local files or for manual saving.
Advising 'file-attributes' I noticed that 'file-attributes' for the file
being saved would occasionally return wrong values (newer than
visited-file-modtime) that actually can't come from TRAMP because they
would contain fractional seconds (TRAMP only returns whole seconds for
the modification time).  I've never encountered this issue in Emacs 26,
so it appears to be a regression.

To help debugging, I've added the following advice:

(define-advice file-attributes (:around (oldfun filename &optional id-format))
  (let ((attr (funcall oldfun filename id-format)))
    (message "ATTR (%s %s) = %s (%s)" filename id-format attr
             (find-file-name-handler filename 'file-attributes))
    attr))

I've slightly redacted the output and replaced the hostname with
HOSTNAME (assuming the exact host name doesn't matter):

ATTR (/ssh:HOSTNAME:/tmp/aaa.txt nil) = (nil 1 145471 89939 (24256 6885 0 0) (24256 7214 0 0) (24256 7214 0 0) 29 -rwx------ nil 19141457 (-1 . 2)) (tramp-file-name-handler)
Auto-saving...
Saving file /ssh:HOSTNAME:/tmp/aaa.txt...
ATTR (/ssh:HOSTNAME:/tmp/aaa.txt nil) = nil (tramp-file-name-handler)
ATTR (/ssh:HOSTNAME:/tmp/aaa.txt string) = nil (tramp-file-name-handler)
ATTR (/ssh:HOSTNAME:/tmp/ string) = (nil 1 phst group (24256 6885 0 0) (24256 7214 0 0) (24256 7214 0 0) 29 -rwx------ nil 19141457 (-1 . 2)) (tramp-file-name-handler)
ATTR (/ssh:HOSTNAME:/tmp/ integer) = (t 45 root root (24256 8484 0 0) (24256 8583 0 0) (24256 8583 0 0) 258048 drwxrwxrwt t 19136513 (-1 . 2)) (tramp-file-name-handler)
ATTR (/ssh:HOSTNAME:/tmp/aaa.txt integer) = (nil 1 145471 89939 (24256 6885 0 0) (24256 7214 0 0) (24256 7214 0 0) 29 -rwx------ nil 19141457 (-1 . 2)) (tramp-file-name-handler) [2 times]
ATTR (/ssh:HOSTNAME:/tmp/aaa.txt nil) = (nil 1 145471 89939 (24256 6885 0 0) (24256 7214 0 0) (24256 7214 0 0) 29 -rwx------ nil 19141457 (-1 . 2)) (tramp-file-name-handler)
ATTR (/ssh:HOSTNAME:(("‘/tmp/’") 45 0 0 1589649700 1589649799 1589649799 258048 "drwxrwxrwt" t 19136513 -1) nil) = nil (tramp-file-name-handler)
ATTR (/tmp/tramp.arEAuT.txt nil) = (nil 1 145471 89939 (24256 8985 410615 843000) (24256 8985 410615 843000) (24256 8985 410615 843000) 30 -rw-r----- t 3151576 65025) (nil)
Tramp: Encoding local file ‘/tmp/tramp.arEAuT.txt’ using ‘base64-encode-region’...done
Tramp: Decoding remote file ‘/ssh:HOSTNAME:/tmp/aaa.txt’ using ‘base64 -d -i >%s’...failed
Error running timer ‘save-some-buffers’: (file-error "Couldn’t find exit status of ‘nil’")

In all cases, the file /tmp/aaa.txt on the remote machine already
existed before.

Some observations:

- Several file-attributes invocations incorrectly return nil.  (Or does
  TRAMP temporarily remove files to be written?)

- Requesting attributes for the bogus file /ssh:HOSTNAME:(("‘/tmp/’") 45
  0 0 1589649700 1589649799 1589649799 258048 "drwxrwxrwt" t 19136513
  -1); i.e., TRAMP doesn't correctly parse the results to extract the
  filename.

I've also captured debug output at TRAMP verbosity level 6 (for a
different instance of the same problem, so the times are off):

19:00:18.033151 tramp-do-file-attributes-with-stat (5) # file attributes with stat: /tmp/aaa.txt
19:00:18.034235 tramp-send-command (6) # echo are you awake
19:00:18.072182 tramp-wait-for-regexp (6) # 
are you awake
///3fd45ca7347e13bbff44df1dfec2da79#$
19:00:18.072847 tramp-send-command (6) # ( (test -e /tmp/aaa.txt || test -h /tmp/aaa.txt) && (env QUOTING_STYLE=locale \stat -c '((/////%N/////) %h %u %g %X %Y %Z %s /////%A///// t %i -1)' /tmp/aaa.txt | sed -e 's/"/\\"/g' -e 's/\/\/\/\/\//"/g') || echo nil) 2>/dev/null; echo tramp_exit_status $?
19:00:18.119306 tramp-wait-for-regexp (6) # 
(("‘/tmp/aaa.txt’") 1 145471 89939 1589648101 1589648202 1589648202 28 "-rwx------" t 19141457 -1)
tramp_exit_status 0
///3fd45ca7347e13bbff44df1dfec2da79#$
19:00:23.172867 tramp-sh-handle-file-truename (4) # Finding true name for ‘/ssh:HOSTNAME:/tmp/aaa.txt’
19:00:23.173701 tramp-send-command (6) # \readlink --canonicalize-missing /tmp/aaa.txt 2>/dev/null; echo tramp_exit_status $?
19:00:23.181083 tramp-do-file-attributes-with-stat (5) # file attributes with stat: /tmp/aaa.txt
19:00:23.182313 tramp-send-command (6) # ( (test -e /tmp/aaa.txt || test -h /tmp/aaa.txt) && (env QUOTING_STYLE=locale \stat -c '((/////%N/////) %h %u %g %X %Y %Z %s /////%A///// t %i -1)' /tmp/aaa.txt | sed -e 's/"/\\"/g' -e 's/\/\/\/\/\//"/g') || echo nil) 2>/dev/null; echo tramp_exit_status $?
19:00:23.215904 tramp-wait-for-regexp (6) # 
/tmp/aaa.txt
tramp_exit_status 0
///3fd45ca7347e13bbff44df1dfec2da79#$
19:00:23.216710 tramp-convert-file-attributes (1) # Wrong type argument: "Wrong type argument", "listp /tmp/aaa.txt"
/tmp/aaa.txt
19:00:24.221875 tramp-send-command (6) # test -e /tmp/ 2>/dev/null; echo tramp_exit_status $?
19:00:24.223171 tramp-wait-for-regexp (6) # 
(("‘/tmp/aaa.txt’") 1 145471 89939 1589648101 1589648202 1589648202 28 "-rwx------" t 19141457 -1)
tramp_exit_status 0
///3fd45ca7347e13bbff44df1dfec2da79#$
19:00:24.228612 tramp-do-file-attributes-with-stat (5) # file attributes with stat: /tmp/aaa.txt
19:00:24.229313 tramp-send-command (6) # ( (test -e /tmp/aaa.txt || test -h /tmp/aaa.txt) && (env QUOTING_STYLE=locale \stat -c '((/////%N/////) %h /////%U///// /////%G///// %X %Y %Z %s /////%A///// t %i -1)' /tmp/aaa.txt | sed -e 's/"/\\"/g' -e 's/\/\/\/\/\//"/g') || echo nil) 2>/dev/null; echo tramp_exit_status $?
19:00:24.260094 tramp-wait-for-regexp (6) # 
tramp_exit_status 0
///3fd45ca7347e13bbff44df1dfec2da79#$
19:00:24.260662 tramp-send-command-and-read (1) # End of file during parsing: End of file during parsing, 
19:00:24.260947 tramp-send-command-and-read (1) # File error: ‘( (test -e /tmp/aaa.txt || test -h /tmp/aaa.txt) && (env QUOTING_STYLE=locale \stat -c '((/////%N/////) %h /////%U///// /////%G///// %X %Y %Z %s /////%A///// t %i -1)' /tmp/aaa.txt | sed -e 's/"/\\"/g' -e 's/\/\/\/\/\//"/g') || echo nil)’ does not return a valid Lisp expression: ‘’
19:00:24.264439 tramp-do-file-attributes-with-stat (5) # file attributes with stat: /tmp/
19:00:24.264845 tramp-send-command (6) # ( (test -e /tmp/ || test -h /tmp/) && (env QUOTING_STYLE=locale \stat -c '((/////%N/////) %h /////%U///// /////%G///// %X %Y %Z %s /////%A///// t %i -1)' /tmp/ | sed -e 's/"/\\"/g' -e 's/\/\/\/\/\//"/g') || echo nil) 2>/dev/null; echo tramp_exit_status $?
19:00:24.275420 tramp-wait-for-regexp (6) # 
(("‘/tmp/aaa.txt’") 1 "phst" "group" 1589648101 1589648202 1589648202 28 "-rwx------" t 19141457 -1)
tramp_exit_status 0
///3fd45ca7347e13bbff44df1dfec2da79#$
19:00:24.278446 tramp-do-file-attributes-with-stat (5) # file attributes with stat: /tmp/
19:00:24.278720 tramp-send-command (6) # ( (test -e /tmp/ || test -h /tmp/) && (env QUOTING_STYLE=locale \stat -c '((/////%N/////) %h %u %g %X %Y %Z %s /////%A///// t %i -1)' /tmp/ | sed -e 's/"/\\"/g' -e 's/\/\/\/\/\//"/g') || echo nil) 2>/dev/null; echo tramp_exit_status $?
19:00:24.318651 tramp-wait-for-regexp (6) # 
(("‘/tmp/’") 45 "root" "root" 1589647900 1589648202 1589648202 258048 "drwxrwxrwt" t 19136513 -1)
tramp_exit_status 0
///3fd45ca7347e13bbff44df1dfec2da79#$
19:00:24.332659 tramp-sh-handle-file-truename (4) # Finding true name for ‘/ssh:HOSTNAME:/tmp/aaa.txt’
19:00:24.332978 tramp-send-command (6) # \readlink --canonicalize-missing /tmp/aaa.txt 2>/dev/null; echo tramp_exit_status $?
19:00:24.333462 tramp-wait-for-regexp (6) # 
(("‘/tmp/’") 45 0 0 1589647900 1589648202 1589648202 258048 "drwxrwxrwt" t 19136513 -1)
tramp_exit_status 0
///3fd45ca7347e13bbff44df1dfec2da79#$
19:00:24.335735 tramp-sh-handle-file-truename (4) # True name of ‘/tmp/aaa.txt’ is ‘(("‘/tmp/’") 45 0 0 1589647900 1589648202 1589648202 258048 "drwxrwxrwt" t 19136513 -1)’
19:00:24.336918 tramp-do-file-attributes-with-stat (5) # file attributes with stat: /home/phst/(("‘/tmp/’") 45 0 0 1589647900 1589648202 1589648202 258048 "drwxrwxrwt" t 19136513 -1)
19:00:24.337678 tramp-send-command (6) # ( (test -e /home/phst/\(\(\"\‘/tmp/\’\"\)\ 45\ 0\ 0\ 1589647900\ 1589648202\ 1589648202\ 258048\ \"drwxrwxrwt\"\ t\ 19136513\ -1\) || test -h /home/phst/\(\(\"\‘/tmp/\’\"\)\ 45\ 0\ 0\ 1589647900\ 1589648202\ 1589648202\ 258048\ \"drwxrwxrwt\"\ t\ 19136513\ -1\)) && (env QUOTING_STYLE=locale \stat -c '((/////%N/////) %h %u %g %X %Y %Z %s /////%A///// t %i -1)' /home/phst/\(\(\"\‘/tmp/\’\"\)\ 45\ 0\ 0\ 1589647900\ 1589648202\ 1589648202\ 258048\ \"drwxrwxrwt\"\ t\ 19136513\ -1\) | sed -e 's/"/\\"/g' -e 's/\/\/\/\/\//"/g') || echo nil) 2>/dev/null; echo tramp_exit_status $?
19:00:24.371208 tramp-wait-for-regexp (6) # 
/tmp/aaa.txt
tramp_exit_status 0
///3fd45ca7347e13bbff44df1dfec2da79#$
19:00:24.371743 tramp-convert-file-attributes (1) # Wrong type argument: "Wrong type argument", "listp /tmp/aaa.txt"
/tmp/aaa.txt
19:00:24.374570 tramp-sh-handle-write-region (3) # Encoding local file ‘/tmp/tramp.2D3sJJ.txt’ using ‘base64-encode-region’...
19:00:24.375639 tramp-sh-handle-write-region (3) # Encoding local file ‘/tmp/tramp.2D3sJJ.txt’ using ‘base64-encode-region’...done
19:00:24.376356 tramp-sh-handle-write-region (3) # Decoding remote file ‘/ssh:HOSTNAME:/tmp/aaa.txt’ using ‘base64 -d -i >%s’...
19:00:24.376923 tramp-send-command (6) # base64 -d -i >/tmp/aaa.txt <<'3849061d8d7701c21894129e56a7abdb'
ICAgICBhIGEgYSBhCmEgIGFhCiggKQoKICAgYQo=
3849061d8d7701c21894129e56a7abdb
19:00:24.377966 tramp-wait-for-regexp (6) # 
nil
tramp_exit_status 0
///3fd45ca7347e13bbff44df1dfec2da79#$
19:00:24.378571 tramp-send-command (6) # echo tramp_exit_status $?
19:00:24.417274 tramp-wait-for-regexp (6) # 
///3fd45ca7347e13bbff44df1dfec2da79#$
19:00:24.417459 tramp-send-command-and-check (1) # File error: Couldn’t find exit status of ‘nil’
19:00:24.417918 tramp-sh-handle-write-region (3) # Decoding remote file ‘/ssh:HOSTNAME:/tmp/aaa.txt’ using ‘base64 -d -i >%s’...failed
19:00:24.430936 tramp-wait-for-regexp (6) # 
tramp_exit_status 0
///3fd45ca7347e13bbff44df1dfec2da79#$
19:00:24.433067 tramp-sh-handle-file-truename (4) # True name of ‘/tmp/aaa.txt’ is ‘’
19:00:24.434035 tramp-do-file-attributes-with-stat (5) # file attributes with stat: /home/phst/
19:00:24.434340 tramp-send-command (6) # ( (test -e /home/phst/ || test -h /home/phst/) && (env QUOTING_STYLE=locale \stat -c '((/////%N/////) %h %u %g %X %Y %Z %s /////%A///// t %i -1)' /home/phst/ | sed -e 's/"/\\"/g' -e 's/\/\/\/\/\//"/g') || echo nil) 2>/dev/null; echo tramp_exit_status $?
19:00:24.481437 tramp-wait-for-regexp (6) # 
(("‘/home/phst/’") 120 145471 89939 1589647041 1589647848 1589647848 16384 "drwx------" t 25958919 -1)
tramp_exit_status 0
///3fd45ca7347e13bbff44df1dfec2da79#$

Again some observations:

> Wrong type argument: "Wrong type argument", "listp /tmp/aaa.txt"

Apparently TRAMP doesn't correctly wait for the stat result and seems to
parse the output of readlink here?

> End of file during parsing: End of file during parsing,

Similary, TRAMP doesn't wait for the stat output and tries to parse an
empty string.

> True name of ‘/tmp/aaa.txt’ is ‘(("‘/tmp/’") 45 0 0 1589647900
> 1589648202 1589648202 258048 "drwxrwxrwt" t 19136513 -1)’

More out-of-order parsing: Here TRAMP attempts to parse the stat result
as a filename.  This is probably the source of the spurious filename
starting with (("‘tmp/’") ...

> File error: Couldn’t find exit status of ‘nil’

More out-of-order passing?

It seems likely that there are some bugs lurking in the TRAMP
implementation, especially related to the out-of-order passing:
apparently there are cases where TRAMP doesn't correctly wait for
command output to arrive and then parses the output of the previous
command.


In GNU Emacs 27.0.91 (build 11, x86_64-pc-linux-gnu, GTK+ Version 3.24.13)
 of 2020-05-16
Repository revision: b4937f64cd97ff6bf93538987c014f8ea8ff9d34
Repository branch: emacs-27
Windowing system distributor 'The X.Org Foundation', version 11.0.12007000
System Description: Debian GNU/Linux rodete

Recent messages:
For information about GNU Emacs and the GNU system, type C-h C-a.

Configured using:
 'configure --enable-checking=all --enable-gtk-deprecation-warnings
 --enable-gcc-warnings=warn-only --enable-check-lisp-object-type
 --with-mailutils --without-pop 'CFLAGS=-O0 -g3' LDFLAGS=-g3'

Configured features:
XPM JPEG TIFF GIF PNG SOUND DBUS GSETTINGS GLIB NOTIFY INOTIFY
LIBSELINUX GNUTLS FREETYPE HARFBUZZ XFT ZLIB TOOLKIT_SCROLL_BARS GTK3
X11 XDBE XIM MODULES THREADS PDUMPER GMP

Important settings:
  value of $LANG: en_US.UTF-8
  locale-coding-system: utf-8-unix

Major mode: Lisp Interaction

Minor modes in effect:
  tooltip-mode: t
  global-eldoc-mode: t
  eldoc-mode: t
  electric-indent-mode: t
  mouse-wheel-mode: t
  tool-bar-mode: t
  menu-bar-mode: t
  file-name-shadow-mode: t
  global-font-lock-mode: t
  font-lock-mode: t
  blink-cursor-mode: t
  auto-composition-mode: t
  auto-encryption-mode: t
  auto-compression-mode: t
  line-number-mode: t
  transient-mark-mode: t

Load-path shadows:
None found.

Features:
(shadow sort mail-extr emacsbug message rmc dired dired-loaddefs
format-spec rfc822 mml easymenu mml-sec epa epg epg-config gnus-util
rmail rmail-loaddefs text-property-search time-date mm-decode mm-bodies
mm-encode mail-parse rfc2231 mailabbrev gmm-utils mailheader sendmail
rfc2047 rfc2045 ietf-drums mm-util mail-prsvr mail-utils phst skeleton
derived edmacro kmacro pcase ffap thingatpt url url-proxy url-privacy
url-expand url-methods url-history url-cookie url-domsuf url-util
url-parse auth-source cl-seq eieio eieio-core cl-macs eieio-loaddefs
password-cache json map url-vars mailcap subr-x rx gnutls puny seq
byte-opt gv bytecomp byte-compile cconv dbus xml compile comint
ansi-color ring cl-loaddefs cl-lib tooltip eldoc electric uniquify
ediff-hook vc-hooks lisp-float-type mwheel term/x-win x-win
term/common-win x-dnd tool-bar dnd fontset image regexp-opt fringe
tabulated-list replace newcomment text-mode elisp-mode lisp-mode
prog-mode register page tab-bar menu-bar rfn-eshadow isearch timer
select scroll-bar mouse jit-lock font-lock syntax facemenu font-core
term/tty-colors frame minibuffer cl-generic cham georgian utf-8-lang
misc-lang vietnamese tibetan thai tai-viet lao korean japanese eucjp-ms
cp51932 hebrew greek romanian slovak czech european ethiopic indian
cyrillic chinese composite charscript charprop case-table epa-hook
jka-cmpr-hook help simple abbrev obarray cl-preloaded nadvice loaddefs
button faces cus-face macroexp files text-properties overlay sha1 md5
base64 format env code-pages mule custom widget hashtable-print-readable
backquote threads dbusbind inotify dynamic-setting system-font-setting
font-render-setting move-toolbar gtk x-toolkit x multi-tty
make-network-process emacs)

Memory information:
((conses 16 68847 7436)
 (symbols 48 8957 1)
 (strings 32 23860 1529)
 (string-bytes 1 771764)
 (vectors 16 13233)
 (vector-slots 8 180510 7252)
 (floats 8 25 28)
 (intervals 56 207 0)
 (buffers 1000 12))

-- 
Google Germany GmbH
Erika-Mann-Straße 33
80636 München

Registergericht und -nummer: Hamburg, HRB 86891
Sitz der Gesellschaft: Hamburg
Geschäftsführer: Paul Manicle, Halimah DeLaine Prado

If you received this communication by mistake, please don’t forward it to
anyone else (it may contain confidential or privileged information), please
erase all copies of it, including all attachments, and please let the sender
know it went to the wrong person.  Thanks.





^ permalink raw reply	[flat|nested] 9+ messages in thread

end of thread, other threads:[~2022-07-05 19:25 UTC | newest]

Thread overview: 9+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2020-05-16 17:48 bug#41333: 27.0.91; Spurious errors using TRAMP and auto-save-visited-mode Philipp Stephani
2022-06-06 13:36 ` Lars Ingebrigtsen
2022-06-16 17:57   ` Philipp Stephani
2022-06-17 12:01     ` Lars Ingebrigtsen
2022-06-22 15:27       ` Michael Albinus
2022-07-05 13:11         ` Stefan Kangas
2022-07-05 16:54           ` Michael Albinus
2022-07-05 17:49             ` Stefan Kangas
2022-07-05 19:25               ` Michael Albinus

Code repositories for project(s) associated with this external index

	https://git.savannah.gnu.org/cgit/emacs.git
	https://git.savannah.gnu.org/cgit/emacs/org-mode.git

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.