Occasionally print "[[O" or "[[I" abnormally on the screen

[fengyichui]

Recently I have been using the master version and occasionally print "[[O" or "[[I" abnormally on the screen.

I used version 3.1 before and didn't find this issue

The logs: tmux_log.zip
There may be an error reading of the key on line 720311 of tmux-server-19578.log

Linux x86_64
tmux next-3.4
tmux-256color
mintty
WSL1

[nicm]

This does not seem to be a problem with tmux, it is being sent literally "[[O" by the terminal:

1687768861.176526 /dev/pts/0: read 3 bytes (already 0)
1687768861.176561 /dev/pts/0: keys are 3 ([[O)

I'd say this is a bug in WSL.

You could turn focus-events off and you probably won't get these.

[fengyichui]

Thanks!

[mintty]

I'd suggest to reopen here.
Please see my comment from mintty/wsltty#335 (comment):
There may be a race condition if a program disables the reporting (and does not expect it anymore) while a report was already triggered. Please report to tmux.
I tried to check tmux code about this but a quick overview did not lead to an analysis.
@fengyichui, do you have multiple tmux panes open when this happens? Describe the incident precisely and if possible, provide a reproducible test case.

[nicm]

I won't rule anything out, but how could a race in tmux cause the terminal to send [[O instead of \033[O? That is what tmux is receiving from the pty.

I have included the nearest 1004 sequences as well from the log, you can tmux enabled it a few minutes earlier (this was at startup). I have also included the most recent previous input which was an SGR mouse sequence:

1687767743.131247 /dev/pts/0: \033[?1004h
...
1687768861.151560 /dev/pts/0: read 11 bytes (already 0)
1687768861.151576 /dev/pts/0: keys are 11 (\033[<0;78;36m)
1687768861.151589 /dev/pts/0: mouse input (SGR): \033[<0;78;36m
1687768861.151603 /dev/pts/0: complete key \033[<0;78;36m 0x10e005
...
1687768861.176526 /dev/pts/0: read 3 bytes (already 0)
1687768861.176561 /dev/pts/0: keys are 3 ([[O)

If you look at the sequence of focus in/out, it is clear this should have been \033[O:

1687768860.639268 /dev/pts/0: keys are 3 (\033[O)
1687768860.937514 /dev/pts/0: keys are 3 (\033[I)
1687768861.176561 /dev/pts/0: keys are 3 ([[O)
1687768861.438622 /dev/pts/0: keys are 3 (\033[I)
1687768861.759279 /dev/pts/0: keys are 3 (\033[O)

The application inside tmux has enabled and disabled focus, but minutes earlier - note it leaves it disabled:

1687768152.936425 input_parse_buffer: %0 ground, 36 bytes: \033[?1000h\033[?1049h\033[1 q\033[?1h\033=\033[?1004h
1687768215.708037 input_parse_buffer: %0 ground, 59 bytes: \033[?1000l\033[46;1H\033[K\033[46;1H\033[?1004l\033[?1l\033>\033[?1049l\033[34h\033[?25h
1687768353.222477 input_parse_buffer: %0 ground, 36 bytes: \033[?1000h\033[?1049h\033[1 q\033[?1h\033=\033[?1004h
1687768398.094636 input_parse_buffer: %0 ground, 59 bytes: \033[?1000l\033[46;1H\033[K\033[46;1H\033[?1004l\033[?1l\033>\033[?1049l\033[34h\033[?25h

@fengyichui could you please run tmux kill-server and then strace -vvtttostrace.out tmux new and then reproduce and show us the strace.out file so we can see if strace shows the same input?

[fengyichui]

@mintty, I have no multiple tmux panes opened when this happens, only 1 session, 1 window, 1 pane.
I use TinyTask tool to repeat terminal focus in and than focus out..., the problem can be reproduced after a while.

@nicm, the strace and tmux log: tmux_strace_log.zip
In this time, the wrong printed characters is "O[O" (line 31506 in tmux-server-5077.log).

[fengyichui]

The strace -vvtttostrace.out tmux new can't capture all tmux IO input.

I recaptured the strace data: tmux_strace_log_1.zip

The strace log:

1688029382.904042 readv(6, [{iov_base="O[O\33[I\33[O\33[I", iov_len=12}], 1) = 12

The tmux log:

1688029382.911194 /dev/pts/3: keys are 12 (O[O\033[I\033[O\033[I)
1688029382.911567 /dev/pts/3: next key is 12 (O[O\033[I\033[O\033[I) (expired=0)
1688029382.911889 /dev/pts/3: complete key O 0x4f

[fengyichui]

I strace wslbridge2-backend process:

1688030444.843932 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}, {fd=6, events=POLLIN}], 3, -1) = 1 ([{fd=3, revents=POLLIN}])
1688030444.938320 recvfrom(3, "[[O", 1024, 0, NULL, NULL) = 3
1688030444.938598 write(7, "[[O", 3)    = 3
1688030444.939003 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}, {fd=6, events=POLLIN}], 3, -1) = 1 ([{fd=6, revents=POLLIN}])
1688030444.941066 read(6, "[[O", 1024)  = 3
1688030444.941463 sendto(4, "[[O", 3, 0, NULL, 0) = 3

[mintty]

I had interpreted the reported [[O to be in fact \033[O as ESC is preprocessed in the command line and escape sequences typically don't show up in their original form.
@fengyichui, can you please run cat -v in tmux and then repeat the test? And is it possible to create a reproducible test case without 3rd-party tools?

[fengyichui]

@mintty The strace log is cat -v: strace_log_1.zip (line 2685)

1688031068.877065 ioctl(5, FIONREAD, [3]) = 0
1688031068.877221 readv(5, [{iov_base="[[I", iov_len=3}], 1) = 3
1688031068.877404 time(NULL)            = 1688031068 (2023-06-29T17:31:08+0800)
1688031068.877544 time(NULL)            = 1688031068 (2023-06-29T17:31:08+0800)
1688031068.877774 gettimeofday({tv_sec=1688031068, tv_usec=877823}, NULL) = 0
1688031068.880638 time(NULL)            = 1688031068 (2023-06-29T17:31:08+0800)
1688031068.880972 gettimeofday({tv_sec=1688031068, tv_usec=881046}, NULL) = 0
1688031068.881128 time(NULL)            = 1688031068 (2023-06-29T17:31:08+0800)
1688031068.881252 gettimeofday({tv_sec=1688031068, tv_usec=881295}, NULL) = 0
1688031068.881354 clock_gettime(CLOCK_MONOTONIC_COARSE, {tv_sec=96485, tv_nsec=257886700}) = 0
1688031068.881440 poll([{fd=3, events=POLLIN}, {fd=8, events=POLLIN|POLLOUT}, {fd=7, events=POLLIN}, {fd=5, events=POLLIN}, {fd=6, events=POLLIN}], 5, 3452199) = 1 ([{fd=8, revents=POLLOUT}])
1688031068.881564 clock_gettime(CLOCK_MONOTONIC_COARSE, {tv_sec=96485, tv_nsec=258107500}) = 0
1688031068.881682 writev(8, [{iov_base="[[I", iov_len=3}], 1) = 3
1688031068.881829 time(NULL)            = 1688031068 (2023-06-29T17:31:08+0800)
1688031068.882117 clock_gettime(CLOCK_MONOTONIC_COARSE, {tv_sec=96485, tv_nsec=258676900}) = 0
1688031068.882247 poll([{fd=3, events=POLLIN}, {fd=8, events=POLLIN}, {fd=7, events=POLLIN}, {fd=5, events=POLLIN}, {fd=6, events=POLLIN}], 5, 3452199) = 1 ([{fd=8, revents=POLLIN}])
1688031068.882557 clock_gettime(CLOCK_MONOTONIC_COARSE, {tv_sec=96485, tv_nsec=259138600}) = 0
1688031068.883519 ioctl(8, FIONREAD, [3]) = 0
1688031068.883850 readv(8, [{iov_base="[[I", iov_len=3}], 1) = 3
1688031068.884292 gettimeofday({tv_sec=1688031068, tv_usec=886751}, NULL) = 0
1688031068.886892 time(NULL)            = 1688031068 (2023-06-29T17:31:08+0800)
1688031068.888704 gettimeofday({tv_sec=1688031068, tv_usec=888815}, NULL) = 0
1688031068.891334 ioctl(8, TIOCGPGRP, [8238]) = 0
1688031068.891645 openat(AT_FDCWD, "/proc/8238/cmdline", O_RDONLY) = 9
1688031068.891868 newfstatat(9, "", {st_dev=makedev(0, 0x5), st_ino=77732, st_mode=S_IFREG|0444, st_nlink=1, st_uid=1000, st_gid=1000, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1688030925 /* 2023-06-29T17:28:45.266692600+0800 */, st_atime_nsec=266692600, st_mtime=1688030925 /* 2023-06-29T17:28:45.266692600+0800 */, st_mtime_nsec=266692600, st_ctime=1688030925 /* 2023-06-29T17:28:45.266692600+0800 */, st_ctime_nsec=266692600}, AT_EMPTY_PATH) = 0
1688031068.892186 read(9, "cat\0-v\0", 4096) = 7
1688031068.892325 close(9)              = 0
1688031068.892496 clock_gettime(CLOCK_MONOTONIC_COARSE, {tv_sec=96485, tv_nsec=269051400}) = 0
1688031068.892623 poll([{fd=3, events=POLLIN}, {fd=6, events=POLLIN}, {fd=7, events=POLLIN}, {fd=5, events=POLLIN|POLLOUT}, {fd=8, events=POLLIN}], 5, 1) = 1 ([{fd=5, revents=POLLIN|POLLOUT}])
1688031068.897482 clock_gettime(CLOCK_MONOTONIC_COARSE, {tv_sec=96485, tv_nsec=287963100}) = 0
1688031068.912259 writev(5, [{iov_base="[[I", iov_len=3}], 1) = 3
1688031068.912589 ioctl(5, FIONREAD, [3]) = 0
1688031068.912840 readv(5, [{iov_base="\33[O", iov_len=3}], 1) = 3

I don't have a good way to automatically reproduce this issue without third-party tools.

The wslbridge2-backend also read wrong characters, Could it be an issue with wslbridge2 ?

[mintty]

I doubt this is WSL-specific but it would certainly help to repeat the test without WSL, i.e. with plain cygwin, mintty, tmux.
If you need a third-party tool to create the issue, it is essential you tell us what tool that is. A name is not sufficient, link please.

[fengyichui]

The tool link is: https://www.tinytask.net/.
It is a keyboard and mouse recording tool that can speed up and playback continuously.

The Windows Terminal has no this issue.

[mintty]

Which shell do you run? What's the startup profiles of that shell? What does grep 1004 ~/.??* say?

[fengyichui]

I use zsh and remove all its user config file. ~/.tmux.conf only keep set -g focus-events on.

grep 1004 ~/.??* say:

grep: /home/liqiang/.android: Is a directory
grep: /home/liqiang/.bin: Is a directory
grep: /home/liqiang/.bin.cygtools: Is a directory
grep: /home/liqiang/.bin.windows: Is a directory
grep: /home/liqiang/.cache: Is a directory
grep: /home/liqiang/.cargo: Is a directory
grep: /home/liqiang/.cgdb: Is a directory
grep: /home/liqiang/.clipboard: Is a directory
grep: /home/liqiang/.cmake: Is a directory
grep: /home/liqiang/.config: Is a directory
grep: /home/liqiang/.dbus: Is a directory
grep: /home/liqiang/.dotfiles: Is a directory
grep: /home/liqiang/.gnupg: Is a directory
grep: /home/liqiang/.js-packages: Is a directory
grep: /home/liqiang/.landscape: Is a directory
grep: /home/liqiang/.linuxpackage: Is a directory
grep: /home/liqiang/.local: Is a directory
grep: /home/liqiang/.npm: Is a directory
grep: /home/liqiang/.pip: Is a directory
grep: /home/liqiang/.ssh: Is a directory
grep: /home/liqiang/.subversion: Is a directory
grep: /home/liqiang/.swt: Is a directory
grep: /home/liqiang/.sysbench: Is a directory
grep: /home/liqiang/.termux: Is a directory
grep: /home/liqiang/.tmuxinator: Is a directory
grep: /home/liqiang/.vim: Is a directory
/home/liqiang/.viminfo::grep -S -G "(?i:.*\.([ch](pp)?\|cc\|s)$)" -- "1004l"
/home/liqiang/.viminfo:|2,0,1687783238,,"grep -S -G \"(?i:.*\\.([ch](pp)?\\|cc\\|s)$)\" -- \"1004l\""
/home/liqiang/.viminfo:?/1004l
/home/liqiang/.viminfo:|2,1,1687783217,47,"1004l"
grep: /home/liqiang/.vimundo: Is a directory
grep: /home/liqiang/.w3m: Is a directory
grep: /home/liqiang/.whereami: Is a directory
grep: /home/liqiang/.zcompcache: Is a directory
/home/liqiang/.zsh_history:: 1688086247:0;grep 1004 ~/.??*

The TinyTask continuous playback to reproduce this issue that look like follow:

[mintty]

The video does not give as what is called a reproducible test case. How to configure and how to run the test tool is necessary to be known.

[mintty]

Other missing information, although likely irrelevant: Which WSL distribution do you run?
Now let's do this: In you WSL shortcut, or a copy of it, add a logging parameter like -l C:\tmp\mintty%d.log to the command line:
C:\Users\towo\AppData\Local\wsltty\bin\mintty.exe -l C:\tmp\mintty%d.log --WSL="Debian" --configdir="C:\Users\towo\AppData\Roaming\wsltty" -~ -
For C:\tmp use a directory that exists, of course. Then, in the log file, the enabling sequence \033[?1004h should appear somewhere. Maybe from its context it can be guessed from where it comes, so upload the log file.

[fengyichui]

@mintty, the mintty log: mintty1342.log. The wrong characters is "[[O"

[fengyichui]

Reproduce step:

1. Open a mittty terminal, and run tmux (contains at least: set -g focus-events on).
2. Click the Rec button of TinyTask.
3. Quickly alternate clicking on the icons of mintty and other opened apps on the Windows status bar several times. Look like above video.
4. Click the Rec button of TinyTask again.
5. Click Prefs->Play Speed 100x and Prefs->Continuous Playback.
6. Click Save button to backup the recording.
7. Click Play button to playback. And until wrong characters appear on the screen.

[mintty]

So you run tmux from your login profile or how does it get involved? There is no "tmux" in the log.
I see a screenful of line clearing, then some sequences which include focus enabling (1004h) three times - could that be from tmux? - then another screenful of line clearing, then a greeting from Ubuntu, then some more control sequences, inmidst of them the "[[O" which I suspect to be actually \033[O - can you please take out zsh from the scenario for a cross-test (change your default shell if necessary).

[nicm]

tmux will enable focus three times yes as it processes TERM then DA response then XDA response. It doesn't remember it already turned it on.

[fengyichui]

The tmux involved from my ~/.zshrc.

I change the default shell to bash and remove my ~/.bashrc. Tmux only includes set -g focus-events on setting. The mintty log: mitty1368.log

[mintty]

In that log, focus reporting is enabled once, and the stray sequence appears while it is enabled.
Neither mintty nor tmux ever sends a mangled sequence like [[O or O[O directly; tmux uses a function bufferevent_write to send it, maybe that has a problem?

[nicm]

If it was a problem with libevent then strace would not show the incorrect data since it gets it before tmux even reads it. I do not know the architecture of WSL, what is in between mintty and tmux here? Can you reproduce this if instead of running tmux locally you ssh from mintty to a Linux host and run (the same version of) tmux there?

[fengyichui]

I use ssh from mintty to my remote linux server (local is WSL, remote is real linux, tmux run on remote server), the issue is exist. And I try Cygwin in local, the issue is still exist.

[mintty]

I could reproduce the issue with a process stack of
mintty (bash)
tmux (bash)
echo -e '\e[?1004h'; stty raw; cat -v

(no WSL or ssh involved). This is not strictly significant as it occurs very rarely, roughly estimated once in 150 focus cycles.

[mintty]

I could not reproduce it (so far) with dash instead of bash, either
mintty - dash - tmux - dash - ...
or
mintty - tmux - dash - ...

[mintty]

Hmm, it seems to occur only if tty traffic is piped through the ncurses library...

[ThomasDickey]

ncurses doesn't do anything with that -- but some terminal descriptions may use mode 1004. I'd check what infocmp tells me.

[mintty]

I've narrowed down the issue. It does occur without tmux involved, so I think the issue here can be closed.
It occurs more often however with tmux, also it occurs with different frequency on different machines, so it might be a timing issue.
In case you're interested: I can produce the issue with only mintty and a dedicated minimal monitoring program that behaves like cat -v. I traced mintty where the focus reporting sequences is passed into the pty toward the child/client program, also monitoring the return value of read(3) there, and everything is fine on this side. The monitoring however detects [[O or O[O once in a few hundred instances. This sounds like a glitch in pty handling which is also unlikely as you would expect more problems in that case, but I think I'll report it to the cygwin mailing list.

[fengyichui]

I closed this issue and tracked this issue at: mintty/wsltty#335.

[github-actions]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.