bug#28192: TRAMP: Sometimes hangs, sometimes not

[Alexander Shukaev]

Hi everyone and Michael,

I observe weird behavior with TRAMP.  Sometimes it hangs, and sometimes 
performing the same action, it does not.  Let me expand with the 
example.  First see the attached backtrace of a hang ('hang.bt') and 
then see the attached debug of a hang ('hang.debug').  Notice how I 
waited for almost 3 minutes until eventually pressing <C-g> to generate 
the backtrace and as soon as I exited the backtrace buffer, the last line

00:36:39.418776 tramp-maybe-open-connection (3) # Opening connection for 
root@g75vw using sudo...failed

got printed in the debug buffer.

What looks peculiar is this bit:

00:32:56.556463 tramp-send-command (6) # test -d /usr/bin 2>/dev/null; 
echo tramp_exit_status $?
00:32:57.493123 tramp-send-command (6) # test -e /\*scratch\* 
2>/dev/null; echo tramp_exit_status $?
00:32:57.567582 tramp-wait-for-regexp (6) #
tramp_exit_status 1
///deee5cb9d3522d2a1faeef9e0327d4f1#$
00:33:57.490307 tramp-send-command (6) # test -e /\*scratch\* 
2>/dev/null; echo tramp_exit_status $?
00:33:57.491565 tramp-wait-for-regexp (6) #
tramp_exit_status 1
///deee5cb9d3522d2a1faeef9e0327d4f1#$

That is where did the status of '/usr/bin' test go?  And why on earth 
would '*scratch*' be tested?  I verified and files like with '*scratch*' 
names of course do not exist.  It looks like TRAMP hangs after these tests.

Now, doing the same action, i.e. opening home directory with the 'sudo' 
method another time later (ensured that there is no open TRAMP 
connection existing before, i.e. it is indeed the same initial state as 
the hang case), results in the attached debug ('through.debug') and of 
course no backtrace as there is no hang to interrupt.

The three obvious differences that I noticed are:
1.  Presence of

    01:02:19.200224 tramp-get-test-command (5) # Finding a suitable 
‘test’ command

    in the beginning and a couple of times subsequently.

2.  The fact that quotes ‘ and ’ are displayed literally instead of some 
cryptic escape sequences \342\200\230 and \342\200\231.
3.  Proper exit status for

    01:02:28.525502 tramp-send-command (6) # test -d /usr/bin 
2>/dev/null; echo tramp_exit_status $?
    01:02:28.525915 tramp-wait-for-regexp (6) #
    tramp_exit_status 0

    and no further '*scratch*' testing but rather proceeds with next 
directories mentioned in '$PATH'.

Why does the same action result in different behavior out which the 
first one is totally broken?

To supplement (or maybe confuse even more) on the first case, I have 
another variant of it.  The initial action and the resulting backtrace 
of the hang were of course still the same ('hang.bt'), but what I did 
when backtrace appeared was a bit different.  In particular, I executed 
'M-x copy-region-as-kill' (I also hit <TAB> at some point to auto 
complete it) in the backtrace buffer and only then closed it.  As a 
result, the attached debug ('hang.copy-region-as-kill.debug') appeared.

As you can see the first part of it is almost identical to 'hang.debug', 
except that tests for '*scratch*' came a bit earlier.  However, after 
those '*scratch*' tests, when I interrupted it, you will find something 
even more weird involving 'tramp_perl_file_name_all_completions' and 
subsequent tests for 'copy-region-as-kill' which are for sure a 
questionable side effect of my manipulations in the backtrace buffer.

Phew...  Any ideas where to start looking?

Regards,
Alexander

hang.bt
Description: Binary data

hang.copy-region-as-kill.debug
Description: Binary data

hang.debug
Description: Binary data