GNU bug report logs - #28192
TRAMP: Sometimes hangs, sometimes not

Previous Next

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 28192 in the body.
You can then email your comments to 28192 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):

From: Alexander Shukaev <emacs <at> Alexander.Shukaev.name>
To: bug-gnu-emacs <at> gnu.org
Subject: TRAMP: Sometimes hangs, sometimes not
Date: Wed, 23 Aug 2017 01:39:49 +0200

[Message part 1 (text/plain, inline)]

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 <at> 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 (application/octet-stream, attachment)]

[hang.copy-region-as-kill.debug (application/octet-stream, attachment)]

[hang.debug (application/octet-stream, attachment)]

Message #8 received at 28192 <at> debbugs.gnu.org (full text, mbox):

From: Michael Albinus <michael.albinus <at> gmx.de>
To: Alexander Shukaev <emacs <at> Alexander.Shukaev.name>
Cc: 28192 <at> debbugs.gnu.org
Subject: Re: bug#28192: TRAMP: Sometimes hangs, sometimes not
Date: Mon, 28 Aug 2017 10:20:22 +0200

Alexander Shukaev <emacs <at> Alexander.Shukaev.name> writes:

> Hi everyone and Michael,

Hi Alexander,

> 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 <at> 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.

There are even more dubious tests. See for example

> 00:21:44.114726 tramp-send-command (6) # test -e /\>copy-region-as-kill 2>/dev/null; echo tramp_exit_status $?

I doubt, that you have a file "/>copy-region-as-kill".

> Phew...  Any ideas where to start looking?

Does the same problem happen if you start

# emacs -Q --eval '(setq tramp-verbose 6)'

> Regards,
> Alexander

Best regards, Michael.

Message #11 received at 28192 <at> debbugs.gnu.org (full text, mbox):

From: Michael Albinus <michael.albinus <at> gmx.de>
To: Alexander Shukaev <emacs <at> Alexander.Shukaev.name>
Cc: 28192 <at> debbugs.gnu.org
Subject: Re: bug#28192: TRAMP: Sometimes hangs, sometimes not
Date: Mon, 11 Dec 2017 13:14:44 +0100

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

Hi Alexander,

>> 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 <at> 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.
>
> There are even more dubious tests. See for example
>
>> 00:21:44.114726 tramp-send-command (6) # test -e /\>copy-region-as-kill 2>/dev/null; echo tramp_exit_status $?
>
> I doubt, that you have a file "/>copy-region-as-kill".
>
>> Phew...  Any ideas where to start looking?
>
> Does the same problem happen if you start
>
> # emacs -Q --eval '(setq tramp-verbose 6)'

Several months without an answer, so I'm closing this. Feel free to
reopen if you could contribute.

>> Regards,
>> Alexander

Best regards, Michael.

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.