Strange character sequences (ANSI escape sequences?) leaking into shell prompt when starting/attaching Tmux #2275
Comments
|
Please also note that there are already a lot of related issues/reports but not in this repository.
Some links to the reports that I found:
Other relevant links:
So my conclusions are the following:
|
|
On |
|
Thanks for the additional data @yoctozepto! :) I think it's the combination of the terminal and OpenSSH for Windows but that the actual bug is in OpenSSH for Windows and the terminal only matters as it will affect the response to tmux's I did run two additional tests yesterday:
To be sure I did another test today via Ubuntu 24.04 LTS in WSL 2: I installed and started
PS: I can also trigger the bug with |
|
OK, so it truly is the Win32-OpenSSH - that is the common denominator here. It needs certain conditions to happen but it does not happen without it. |
|
Sounds like a tmux bug to me. It is normal and expected behaviour that sending to a VT100-style terminal a device-attributes request of the form If an application like tmux sends such a request, it has to wait for and parse the entire response, and not cause it to echo back to the terminal for the user to see. This waiting and parsing by tmux doesn't seem to happen correctly here. The question is why tmux doesn't swallow the response. On my old Linux xterm, I get back On Windows Terminal on current Windows 11, I get instead Different numbers, but still correct syntax that tmux should swallow. I don't think this is anything that OpenSSH gets involved in. Instead, I suspect that the VT100 terminal emulation built into Windows Terminal (or ConPTY?) is returning something that tmux didn't expect, even though it looks syntactically correct to me. Check in the source code of tmux the state machine that is meant to process the reply to that request. |
@primeos-work That is expected behaviour and not a bug. (Or you could say it's a bug in your use of the echo command ... ;-) Your echo command asked the terminal to reply to a device-attributes request and then finished without reading the reply. So the reply now goes to the shell, which didn't expect it and treats it like user keyboard entry. |
|
Since the issue seems random, could it be that the speed at which these characters are produced/transferred is causing it? As in, tmux does not wait long enough for the consumption. |
Yes, that seems likely, and would explain reports that increasing the tmux configuration parameter escape-time alleviates the problem for many users. Looking at tmux/tty-keys.c, the unit for Looking at Nagle's algorithm, I suspect There may be a conflict of interest with vi users who may have to wait for |
|
One thing Windows Terminal and ConPTY folks might want to check is if their device-attributes response is really being sent out via a single |
|
Looking in Windows Terminal at terminal/src/terminal/adaptDispatch.cpp:AdaptDispatch::DeviceAttributes() and _ReturnCsiResponse we can see where the device-attributes response of Windows Terminal comes from. It is one wide string |
|
Maybe try something like this, although last time I was asked about anything like this it turned out the terminal was sending the response twice, so you would want to be sure that is not happening (tmux logs or strace tmux is the easiest way): |
|
@nicm Thanks for the suggestion. I would probably modify it to more something like such that you don't override an even higher user preference for that delay. |
|
I do still wonder, however, why this does not trigger when WSL2 SSH is run in Windows Terminal. Maybe only then do the bytes get sent in different packets or buffered too long? Could it have to do with Windows networking? Especially how it runs (or doesn't run) the Nagle's algorithm? |
|
@yoctozepto If you run ssh in WSL2, you use the Linux-kernel implementation of TCP, which does all kinds of very clever things, like the I can't find anything similar mentioned among the Windows TCP features. (If you are really curious, try disabling TCP autocorking in WSL2 with |
Yup, this is why I am suggesting it might be the Windows vs Linux networking subsystem that causes the discrepancy.
Checked - but it has no effect on the outcome. |
|
@mgkuhn first of all: Huge thanks for your awesome, detailed, and super helpful and interesting analysis!
That thought makes sense given your analysis. However, given the age and spread of Tmux combined with the fact that I only experience this bug when I connect from a Windows client (using the Windows Terminal and OpenSSH for Windows) I find it quite unlikely (certainly not impossible though! – it could of course be a bug that only gets triggered from the behavior of Windows Terminal and/or OpenSSH for Windows).
That response was just from the test with
I wouldn’t expect this either. I only came to that assumption through testing. I did also perform the following experiments just now:
And I could only trigger the bug in case A. However, as I was writing this, I realized that this test was flawed as I ran tmux on host A (I start/attach tmux automatically in my bashrc so it was unintentionally). Without tmux on host A the bug was still there – so I guess it only went away in case B because Tmux on host A became the new/nested terminal that replied to the device-attributes request? It’s probably indeed not related to OpenSSH for Windows then and I apologize for my incorrect experiments / mistakes that lead me to a wrong conclusion. I’m unfortunately out of my depth here… :(
You’re right, the
+1, that seems like the best guess then. I initially ruled this out as I tried increasing the
Agreed, a device-attribute response that is split across 2(+) IP packets seems like a likely cause then. I might have time to test that next week (in the hope that Wireshark makes the analysis relatively straightforward with access to the private SSH key).
Indeed, 500 ms is unfortunately way too much for me. And for some reason (perhaps related to this bug) the shell startup inside Tmux also becomes super slow (from the white screen until the shell prompt appears) if I increase the
That might be an acceptable workaround.
+1, that seems like a very good idea to me!
Indeed… :o And IIRC I also couldn’t trigger this bug via the Git Bash with Git’s SSH binary (but the terminal and perhaps
Interesting, that would indeed explain it then! :)
Would’ve been too nice… :( |
|
My initial plan didn't work out. Wireshark doesn't have support for decrypting encrypted SSH packets/payload yet (https://wiki.wireshark.org/SSH -> https://gitlab.com/wireshark/wireshark/-/issues/16054). I also tried Then I looked at the Tmux source-code and noticed the
Turns out that those logs already contain enough (hopefully) information to debug the issue. In $ grep input_parse_buffer tmux-server-*.log
1731694819.616979 input_parse_buffer: %0 ground, 32 bytes: ^[[?61;6;7;14;21;22;23;24;28;32;
1731694819.637852 input_parse_buffer: %0 ground, 3 bytes: 42c
1731694819.712193 input_parse_buffer: %0 ground, 20 bytes: mweiss@dunwich ~ $ 6
1731694819.712469 input_parse_buffer: %0 ground, 23 bytes: 1;6;7;14;21;22;23;24;28
1731694819.712742 input_parse_buffer: %0 ground, 7 bytes: ;32;42c
1731694821.774889 input_parse_buffer: %0 ground, 23 bytes: ^C\r\nmweiss@dunwich ~ $
1731694822.149083 input_parse_buffer: %0 ground, 8 bytes: logout\r\nI still need to have a closer look at the source code but my current assumptions are the following: The primary device attributes input ( So next, I/we need to figure out where (and why) the DA response gets split up to make a bug report there and it's probably also a good idea to propose the Tmux patch for upstream inclusion to make the parsing more robust against such issues (I'm not sure yet if the patch might also cause unintended/undesired regressions - e.g. for Vim users). |
|
input_parse is data from the pty inside tmux so will not necessarily reflect what tmux itself is receiving from the terminal, although in this case it may be split in the same way. Instead you would be better to look for lines like this (it will grow each time until tmux does something with the input): The pty output is probably like this because first the kernel is echoing it and then when the shell starts it treats it as if you had typed at the prompt. |
|
Yes, you're right, I should've included that output instead (it's just a bit verbose). I did check the first $ grep -e ' read ' -e 'keys are' -e 'next key' -e 'partial key' -e 'complete key' -e 'received ' tmux-server-*.log
1731694819.612110 /dev/pts/4: read 31 bytes (already 0)
1731694819.612117 /dev/pts/4: keys are 31 (\033[?61;6;7;14;21;22;23;24;28;32;)
1731694819.612124 /dev/pts/4: partial key \033[?61;6;7;14;21;22;23;24;28;32;
1731694819.614252 /dev/pts/4: keys are 31 (\033[?61;6;7;14;21;22;23;24;28;32;)
1731694819.614258 /dev/pts/4: partial key \033[?61;6;7;14;21;22;23;24;28;32;
1731694819.614265 /dev/pts/4: next key is 31 (\033[?61;6;7;14;21;22;23;24;28;32;) (expired=1)
1731694819.614272 /dev/pts/4: next key is 30 ([?61;6;7;14;21;22;23;24;28;32;) (expired=1)
1731694819.614278 /dev/pts/4: complete key \033[ 0x10000000005b
1731694819.614292 /dev/pts/4: keys are 29 (?61;6;7;14;21;22;23;24;28;32;)
1731694819.614299 /dev/pts/4: next key is 29 (?61;6;7;14;21;22;23;24;28;32;) (expired=0)
1731694819.614305 /dev/pts/4: complete key ? 0x3f
1731694819.614317 /dev/pts/4: keys are 28 (61;6;7;14;21;22;23;24;28;32;)
1731694819.614323 /dev/pts/4: next key is 28 (61;6;7;14;21;22;23;24;28;32;) (expired=0)
1731694819.614329 /dev/pts/4: complete key 6 0x36
1731694819.614341 /dev/pts/4: keys are 27 (1;6;7;14;21;22;23;24;28;32;)
1731694819.614347 /dev/pts/4: next key is 27 (1;6;7;14;21;22;23;24;28;32;) (expired=0)
1731694819.614353 /dev/pts/4: complete key 1 0x31
1731694819.614365 /dev/pts/4: keys are 26 (;6;7;14;21;22;23;24;28;32;)
1731694819.614371 /dev/pts/4: next key is 26 (;6;7;14;21;22;23;24;28;32;) (expired=0)
1731694819.614377 /dev/pts/4: complete key ; 0x3b
1731694819.614389 /dev/pts/4: keys are 25 (6;7;14;21;22;23;24;28;32;)
1731694819.614395 /dev/pts/4: next key is 25 (6;7;14;21;22;23;24;28;32;) (expired=0)
1731694819.614401 /dev/pts/4: complete key 6 0x36
1731694819.614414 /dev/pts/4: keys are 24 (;7;14;21;22;23;24;28;32;)
1731694819.614420 /dev/pts/4: next key is 24 (;7;14;21;22;23;24;28;32;) (expired=0)
1731694819.614426 /dev/pts/4: complete key ; 0x3b
1731694819.614438 /dev/pts/4: keys are 23 (7;14;21;22;23;24;28;32;)
1731694819.614444 /dev/pts/4: next key is 23 (7;14;21;22;23;24;28;32;) (expired=0)
1731694819.614450 /dev/pts/4: complete key 7 0x37
1731694819.614462 /dev/pts/4: keys are 22 (;14;21;22;23;24;28;32;)
1731694819.614470 /dev/pts/4: next key is 22 (;14;21;22;23;24;28;32;) (expired=0)
1731694819.614476 /dev/pts/4: complete key ; 0x3b
1731694819.614488 /dev/pts/4: keys are 21 (14;21;22;23;24;28;32;)
1731694819.614494 /dev/pts/4: next key is 21 (14;21;22;23;24;28;32;) (expired=0)
1731694819.614500 /dev/pts/4: complete key 1 0x31
1731694819.614513 /dev/pts/4: keys are 20 (4;21;22;23;24;28;32;)
1731694819.614519 /dev/pts/4: next key is 20 (4;21;22;23;24;28;32;) (expired=0)
1731694819.614524 /dev/pts/4: complete key 4 0x34
1731694819.614537 /dev/pts/4: keys are 19 (;21;22;23;24;28;32;)
1731694819.614543 /dev/pts/4: next key is 19 (;21;22;23;24;28;32;) (expired=0)
1731694819.614549 /dev/pts/4: complete key ; 0x3b
1731694819.614561 /dev/pts/4: keys are 18 (21;22;23;24;28;32;)
1731694819.614567 /dev/pts/4: next key is 18 (21;22;23;24;28;32;) (expired=0)
1731694819.614573 /dev/pts/4: complete key 2 0x32
1731694819.614585 /dev/pts/4: keys are 17 (1;22;23;24;28;32;)
1731694819.614591 /dev/pts/4: next key is 17 (1;22;23;24;28;32;) (expired=0)
1731694819.614597 /dev/pts/4: complete key 1 0x31
1731694819.614609 /dev/pts/4: keys are 16 (;22;23;24;28;32;)
1731694819.614615 /dev/pts/4: next key is 16 (;22;23;24;28;32;) (expired=0)
1731694819.614621 /dev/pts/4: complete key ; 0x3b
1731694819.614633 /dev/pts/4: keys are 15 (22;23;24;28;32;)
1731694819.614639 /dev/pts/4: next key is 15 (22;23;24;28;32;) (expired=0)
1731694819.614645 /dev/pts/4: complete key 2 0x32
1731694819.614658 /dev/pts/4: keys are 14 (2;23;24;28;32;)
1731694819.614663 /dev/pts/4: next key is 14 (2;23;24;28;32;) (expired=0)
1731694819.614669 /dev/pts/4: complete key 2 0x32
1731694819.614682 /dev/pts/4: keys are 13 (;23;24;28;32;)
1731694819.614688 /dev/pts/4: next key is 13 (;23;24;28;32;) (expired=0)
1731694819.614694 /dev/pts/4: complete key ; 0x3b
1731694819.614706 /dev/pts/4: keys are 12 (23;24;28;32;)
1731694819.614712 /dev/pts/4: next key is 12 (23;24;28;32;) (expired=0)
1731694819.614718 /dev/pts/4: complete key 2 0x32
1731694819.614730 /dev/pts/4: keys are 11 (3;24;28;32;)
1731694819.614736 /dev/pts/4: next key is 11 (3;24;28;32;) (expired=0)
1731694819.614742 /dev/pts/4: complete key 3 0x33
1731694819.614754 /dev/pts/4: keys are 10 (;24;28;32;)
1731694819.614760 /dev/pts/4: next key is 10 (;24;28;32;) (expired=0)
1731694819.614766 /dev/pts/4: complete key ; 0x3b
1731694819.614778 /dev/pts/4: keys are 9 (24;28;32;)
1731694819.614785 /dev/pts/4: next key is 9 (24;28;32;) (expired=0)
1731694819.614790 /dev/pts/4: complete key 2 0x32
1731694819.614803 /dev/pts/4: keys are 8 (4;28;32;)
1731694819.614809 /dev/pts/4: next key is 8 (4;28;32;) (expired=0)
1731694819.614814 /dev/pts/4: complete key 4 0x34
1731694819.614826 /dev/pts/4: keys are 7 (;28;32;)
1731694819.614832 /dev/pts/4: next key is 7 (;28;32;) (expired=0)
1731694819.614838 /dev/pts/4: complete key ; 0x3b
1731694819.614852 /dev/pts/4: keys are 6 (28;32;)
1731694819.614858 /dev/pts/4: next key is 6 (28;32;) (expired=0)
1731694819.614863 /dev/pts/4: complete key 2 0x32
1731694819.614876 /dev/pts/4: keys are 5 (8;32;)
1731694819.614882 /dev/pts/4: next key is 5 (8;32;) (expired=0)
1731694819.614887 /dev/pts/4: complete key 8 0x38
1731694819.614900 /dev/pts/4: keys are 4 (;32;)
1731694819.614906 /dev/pts/4: next key is 4 (;32;) (expired=0)
1731694819.614911 /dev/pts/4: complete key ; 0x3b
1731694819.614924 /dev/pts/4: keys are 3 (32;)
1731694819.614929 /dev/pts/4: next key is 3 (32;) (expired=0)
1731694819.614935 /dev/pts/4: complete key 3 0x33
1731694819.614947 /dev/pts/4: keys are 2 (2;)
1731694819.614953 /dev/pts/4: next key is 2 (2;) (expired=0)
1731694819.614962 /dev/pts/4: complete key 2 0x32
1731694819.614975 /dev/pts/4: keys are 1 (;)
1731694819.614981 /dev/pts/4: next key is 1 (;) (expired=0)
1731694819.614987 /dev/pts/4: complete key ; 0x3b
1731694819.630263 /dev/pts/4: read 13 bytes (already 0)
1731694819.630278 /dev/pts/4: keys are 13 (42c\033[>0;10;1c)
1731694819.630286 /dev/pts/4: next key is 13 (42c\033[>0;10;1c) (expired=0)
1731694819.630293 /dev/pts/4: complete key 4 0x34
1731694819.630309 /dev/pts/4: keys are 12 (2c\033[>0;10;1c)
1731694819.630315 /dev/pts/4: next key is 12 (2c\033[>0;10;1c) (expired=0)
1731694819.630321 /dev/pts/4: complete key 2 0x32
1731694819.630335 /dev/pts/4: keys are 11 (c\033[>0;10;1c)
1731694819.630341 /dev/pts/4: next key is 11 (c\033[>0;10;1c) (expired=0)
1731694819.630347 /dev/pts/4: complete key c 0x63
1731694819.630361 /dev/pts/4: keys are 10 (\033[>0;10;1c)
1731694819.630368 /dev/pts/4: received secondary DA \033[>0;10;1c
1731694819.630468 /dev/pts/4: complete key \033[>0;10;1c 0xfe000000000
1731694821.742482 /dev/pts/4: read 1 bytes (already 0)
1731694821.742541 /dev/pts/4: keys are 1 (\003)
1731694821.742573 /dev/pts/4: next key is 1 (\003) (expired=0)
1731694821.742600 /dev/pts/4: complete key \003 0x3
1731694822.147021 /dev/pts/4: read 1 bytes (already 0)
1731694822.147075 /dev/pts/4: keys are 1 (\004)
1731694822.147102 /dev/pts/4: next key is 1 (\004) (expired=0)
1731694822.147126 /dev/pts/4: complete key \004 0x4Or in a more minimal but incomplete form: $ grep -e ' read ' -e 'received ' tmux-server-*.log
1731694819.612110 /dev/pts/4: read 31 bytes (already 0)
1731694819.630263 /dev/pts/4: read 13 bytes (already 0)
1731694819.630368 /dev/pts/4: received secondary DA \033[>0;10;1c
1731694821.742482 /dev/pts/4: read 1 bytes (already 0)
1731694822.147021 /dev/pts/4: read 1 bytes (already 0)There are also And here is an unmodified part of the complete |
|
There looks to be 16 milliseconds between the first part of the escape sequence and the end, so I'd say you will need an 16 milliseconds is a fair delay on a modern network but it isn't crazy. |
For what it's worth, this issue showed up for me when I upgraded an OpenBSD machine to v7.6 (from v7.3) and connected from my Windows machine. I suspect the OpenBSD version of tmux has that commit from @nicm in it as well (looks like it). I was able to resolve it by setting the |
|
Some experimentation (trying to uncover some really weird inconsistencies) seems to show that (all else being equal), older ssh client versions like 9.2p1 don't pass the escape sequences, while newer ones (9.9p1) do pass it. Found that out by building both version from source on the same debian instance, so I'm pretty confident that's accurate. In any case it would imply that this is not a TMUX bug, but rather something to do with SSH (or maybe something strange about the way they interact?) Incidentally, it's also only passed when the remote command is I'd rather not mess with escape-time since I use vim, and even if that wasn't a problem I'm very curious to track down the real cause of the issue |
|
When investigating keyboard character-timing effects in recent OpenSSH versions, also be aware of this new keystroke-timing-obfuscation feature in OpenSSH 9.5:
(Another reason for why tmux should perhaps wait by default for longer than 20 ms for the completion of an ESC sequence.) |
Prerequisites
Steps to reproduce
Connect to a Linux/Unix host via
sshand attach to atmuxsession. Strangely the results seem to differ based on the target OS, e.g.:61;6;7;21;22;23;24;28;32;42c(basically every time)0;10;1cbut only on every third/fourth attempt or soExpected behavior
I can attach to my Tmux session and it looks exactly as I left it.
This usually means that the last line of the active Tmux window/pane contains a empty shell prompt like this:
Actual behavior
I get some additional random characters ("garbage") behind the prompt, e.g.:
Error details
No response
Environment data
I am using the Windows Terminal and it doesn't matter if I uses the "Windows PowerShell", "Command Prompt", or "Git Bash". When I use "Git Bash" via "Windows Terminal" everything works as expected with
/usr/bin/ssh(OpenSSH_9.7p1, OpenSSL 3.2.1 30 Jan 2024) but not with/c/Program\ Files/OpenSSH/ssh(OpenSSH_for_Windows_9.5p1, LibreSSL 3.8.2) which is why I came to the conclusion that this seems to be a OpenSSH for Windows bug. The second indication that this seems to be an OpenSSH for Windows bug is that I didn't get those unexpected character sequence withSSH_TERM_CONHOST_PARSER=0(but that also makes the rendering much much slower and I get significant visual glitches like a green background color (probably due to the status line background color from tmux)).Anyway, here is the desired output but I don't expect it to be relevant in this case:
Version
OpenSSH_for_Windows_9.5p1, LibreSSL 3.8.2
Visuals
No response
The text was updated successfully, but these errors were encountered: