Comportamento estranho ssh - bash - (tty no echo) - programa c?

Question

No trabalho, temos um programa C antigo que funciona com terminais manuais industriais da Honeywell.

Esse terminal tem seu próprio cliente ssh para conectar-se a um servidor linux redhat 6.6. Uma vez conectado à caixa linux (usando um determinado usuário), um programa C é lançado pelo shell bash com os seguintes parâmetros

export TERM=vt200
stty raw icrnl -echo
$APLI_EXEC/program param1 param2

, então o fluxo é como = > cliente ssh - > ssh server- > bash - > programa c

O aplicativo (ou parece) está funcionando bem, mas às vezes (1-3-5 vezes por semana) um terminal aleatório pára de receber dados do servidor, mas o aplicativo recebe as entradas dele. É como se você escrevesse Ctrl + S em um shell.

Depurando o aplicativo e o processo ssh usando strace eu percebi algo estranho:

O app strace está bem

write(1, "1", 7) = 1

Mas o strace do processo ssh não está bem (eu acho .. e sim eu vi o ioctl no echo param, mas ...)

rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
read(3, "762010)0e027VX574213n{3p.1H7"..., 16384) = 48
select(14, [3 9], [11], NULL, {900, 0}) = 1 (out [11], left {899, 999996})
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
write(11, "1", 1)         = 1
ioctl(11, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 -opost -isig -icanon -echo ...}) = 0
select(14, [3 9], [], NULL, {900, 0}                   <<<<

descritor de arquivo usado pelo processo ssh:

lr-x------ 1 root     root 64 Feb 15 17:12 9 -> pipe:[383586491]
lr-x------ 1 root     root 64 Feb 15 17:12 8 -> /var/lib/sss/mc/group
lrwx------ 1 root     root 64 Feb 15 17:12 7 -> socket:[383586484]
lrwx------ 1 root     root 64 Feb 15 17:12 6 -> socket:[383586478]
lrwx------ 1 root     root 64 Feb 15 17:12 5 -> socket:[383586458]
lrwx------ 1 root     root 64 Feb 15 17:12 4 -> socket:[383586457]
lrwx------ 1 root     root 64 Feb 15 17:12 3 -> socket:[383585929]
lrwx------ 1 root     root 64 Feb 15 17:12 2 -> /dev/null
lrwx------ 1 root     root 64 Feb 15 17:12 14 -> /dev/ptmx
lrwx------ 1 root     root 64 Feb 15 17:12 13 -> /dev/ptmx
lrwx------ 1 root     root 64 Feb 15 17:12 11 -> /dev/ptmx
l-wx------ 1 root     root 64 Feb 15 17:12 10 -> pipe:[383586491]
lrwx------ 1 root     root 64 Feb 15 17:12 1 -> /dev/null
lrwx------ 1 root     root 64 Feb 15 17:12 0 -> /dev/null

Na chamada de seleção, eu sinto falta do fd # 11 ou fd # 13 lá

Comparando isso com outra chamada

rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
read(3, "544C|6-27B0P5&3)73)#45V774"..., 16384) = 52
select(14, [3 9 13], [11], NULL, {900, 0}) = 1 (out [11], left {899, 999997})
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
write(11, "a", 1)         = 1
ioctl(11, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig -icanon -echo ...}) = 0
select(14, [3 9 13], [], NULL, {900, 0}          <<<

O que está acontecendo com o fd # 13 na outra chamada?

É possível que o programa C esteja fazendo algo para bloquear o descritor de arquivo do processo ssh?

É possível que o terminal manual envie uma combinação de teclas ctrl que "suspende" a saída padrão?

Eu fiquei sem ideias. Alguém pode me levar na direção certa?

Fevereiro, dia 25. 2016

Eu tenho mais algumas informações sobre isso:

select(14, [3 9 13], [], NULL, {900, 0})       = 1 (in [13], left {899, 998835}) <<- sshd realizes about data in fd #13 from C application
read(13, "[1;23H1[1;24H", 16384) = 15          <<- sshd check data from th fd#13
select(14, [3 9 13], [3], NULL, {900, 0}) = 1 (out [3], left {899, 999998}) <<- sshd sends data to fd#3 (socket)
write(3, "16W030\r46o]:*1K3247Vb,V7l22K1,,7d372.lF717DJt336K6236|l02S", 64) = 64 (1)  <<- sshd encrypts data to be sent
select(14, [3 9 13], [3], NULL, {900, 0}) = 1 (out [3], left {899, 999998})   <<-- sshd sends data thru the socket
select(14, [3 9 13], [], NULL, {900, 0}) = 1 (in [13], left {899, 998569})    <<- sshd realizes about data in fd #13 from C application 
read(13, "[1;16H        [6;6H_______[7;1H -INFORME CANT. RECOGIDA-[7;26H", 16384) = 67   <<- sshd check data from th fd#13
select(14, [3 9], [], NULL, {900, 0}) = 1 (in [3], left {892, 12016})  <<- sshd sends data to fd#3 (socket) but... where is fd#13 where sshd has to read it from?  

read it from?            

o terminal recebe     "\ 7 \ 33 [1; 16H" mas o resto da corda     "\ 33 [6; 6H

ssh bash debug

por user3834683 20.02.2016 / 11:00

Answer 1

Eu respondo a mim mesmo por dizer que acabei de encontrar o problema Espero que o seguinte ajude a qualquer pessoa

Finalmente eu recompilei o código fonte do ssh (openssh-5.3p1) inserindo vários 'traps' dentro do código para ver o que estava acontecendo lá

channel_pre_open(Channel *c, fd_set *readset, fd_set *writeset)
{
u_int limit = compat20 ? c->remote_window : packet_get_maxsize();

int aux = buffer_len(&c->input);
debugtrap("en pre_open c-istate: %d limit %d buffer_len %d c_ostate %d
ctl_fd %d\n",c->istate,limit,aux,c->ostate,c->ctl_fd);

/* the rest of the function code */

variável limite no início (por padrão) é 1024 * 1024

Em condições normais, a variável limite está ajustando seu tamanho de janela toda vez que a função channe_pre_open é chamada (exemplo usando putty)

En pre_open c-istate: 0 limit 1048576 buffer_len 0 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 1048576 buffer_len 0 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 1048495 buffer_len 0 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 1048495 buffer_len 0 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 1048415 buffer_len 0 c_ostate 0   ctl_fd -1
...... time later
En pre_open c-istate: 0 limit 1002267 buffer_len 0 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 1002267 buffer_len 0 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 1002267 buffer_len 0 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 998560 buffer_len 0 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 998560 buffer_len 0 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 1048576 buffer_len 0 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 1048576 buffer_len 0 c_ostate 0   ctl_fd -1

Mas, se eu comparar o mesmo traço quando o terminal manual se conecta ao aplicação eu posso ver o buffer está consumindo (não é renegociar cada vez) todo o tamanho

En pre_open c-istate: 0 limit 1048576 buffer_len 0 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 1048576 buffer_len 0 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 1048476 buffer_len 0 c_ostate 0   ctl_fd -1
......
En pre_open c-istate: 0 limit 985 buffer_len 0 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 647 buffer_len 0 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 647 buffer_len 0 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 647 buffer_len 0 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 647 buffer_len 0 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 632 buffer_len 0 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 322 buffer_len 0 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 322 buffer_len 0 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 0 buffer_len 16 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 0 buffer_len 16 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 0 buffer_len 16 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 0 buffer_len 16 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 0 buffer_len 16 c_ostate 0   ctl_fd -1
En pre_open c-istate: 0 limit 0 buffer_len 16 c_ostate 0   ctl_fd -1

e finalmente a variável limite chega a 0

Quando acontece, o fd # 10 é perdido de readfds na chamada selecionada

0.000025 select(11, [3 6 10], [3], NULL, {900, 0}) = 1 (in [10], left {899, 999997})
0.000025 select(11, [3 6 10], [3], NULL, {900, 0}) = 1 (in [10], left {899, 999994})
0.000025 select(11, [3 6 10], [3], NULL, {900, 0}) = 1 (in [10], left {899, 999995})
0.000025 select(11, [3 6], [3], NULL, {900, 0}) = 1 (out [3], left {899, 908736})  
0.000026 select(11, [3 6], [3], NULL, {900, 0}) = 1 (out [3], left {899, 986906})  
0.000025 select(11, [3 6], [3], NULL, {900, 0}) = 1 (out [3], left {899, 992061})

O fato é que select call não inclui este descritor de arquivo no conjunto porque ele é bloqueado pelo outro lado até que o buffer (client < - > sshd) fique vazio (ele supõe que o sshd não pode enviar mais bytes para o cliente ssh porque o tamanho da janela é 0, então o fd tem que ser bloqueado para evitar enviar mais informações do lado do shell)

Este comportamento não acontece com o putty client, e parece que o seu cliente ssh da Honeywell hand-terminal é baseado no Openssh (não sei a versão)

Enfim, acabei de confirmar a seguinte versão: OpenSSH_3.8.1p1, OpenSSL 0.9.7d 17 de março de 2004 não é afetado (testado no Windows 10 contra o RHEL6 ssh-server 5.3.p1)

Nacho.