На работе у нас есть старая программа C, которая работает с промышленными ручными терминалами от Honeywell.
У этого терминала есть собственный ssh-клиент для подключения к серверу Linux Redhat 6.6. После подключения к Linux-серверу (с использованием определенного пользователя) оболочка bash запускает программу на C со следующими параметрами:
export TERM=vt200
stty raw icrnl -echo
$APLI_EXEC/program param1 param2
так что поток похож на => клиент ssh -> ssh server-> bash -> программа c
Приложение (или кажется) работает нормально, но иногда (1-3-5 раз в неделю) случайным образом терминал перестает получать данные с сервера, но приложение получает от него входные данные. Это как если вы напишете Ctrl + S в оболочке.
Отлаживая приложение и процесс ssh с помощью strace, я понял кое-что странное:
Приложение strace в порядке
write(1, "1", 7) = 1
Но strace процесса ssh не в порядке (я думаю .. и да, я видел параметр ioctl no echo, но ...)
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
read(3, "\227\316\242\350\261\330)\300e\210\352\367\2VX\24\305\2474\272\371\34\273n{\323p.\211\17H\327"..., 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} <<<<
дескриптор файла, используемый процессом 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
В вызове select я пропускаю fd # 11 или fd # 13 там
Сравнивая это с другим звонком
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
read(3, "\365\354\354C\10|\336-\4\342\327B0P\275&\213)\367\32\24\333)#\364\355V\3\237\337\33\204"..., 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} <<<
Что происходит с fd # 13 в другом вызове?
Возможно ли, что программа на C что-то делает, чтобы заблокировать файловый дескриптор процесса ssh?
Возможно ли, что ручной терминал отправляет комбинацию клавиш ctrl, которая «вешает» стандартный вывод?
У меня закончились идеи. Может ли кто-нибудь направить меня в правильном направлении?
25 февраля. 2016 г.
У меня есть дополнительная информация об этом:
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, "\33[1;23H1\33[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, "\301\236W\250\333\260\r\204\316o]:*1K\203\242\204\257Vb,V\347l\242\352K\341,,\307d\273\277\202.l\32F\2471\257DJt3\36\303\5\256\21K6\27\212\253\326|l\33\270\262S", 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, "\7\33[1;16H \33[6;6H_______\33[7;1H -INFORME CANT. RECOGIDA-\33[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?
терминал получает «\ 7 \ 33 [1; 16H», а остальная часть строки «\ 33 [6; 6H _______ \ 33 [7; 1H -INFORME CANT. RECOGIDA- \ 33 [7; 26H»
не получено
Зачем?
когда приложение записывает в свой дескриптор выходного файла (fd # 1), sshd получает его (fd # 13) .. но очищается ли fd # 1 в этот момент? Или sshd читает из дескриптора файла char с помощью char, пока он отправляет / шифрует данные?
Я отвечаю себе за то, что я только что нашел проблему, надеюсь, следующее поможет кому-нибудь
Наконец, я перекомпилировал исходный код ssh (openssh-5.3p1), вставив несколько «ловушек» в код, чтобы посмотреть, что там происходит.
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 */
предельная переменная в начале (по умолчанию) 1024 * 1024
В нормальных условиях ограничивающая переменная регулирует размер своего окна каждый раз, когда вызывается функция channe_pre_open (пример с использованием 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
Но, если я сравниваю ту же трассу, когда ручной терминал подключается к приложению, я вижу, что буфер потребляет (он не пересматривается каждый раз) весь размер
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
и, наконец, предельная переменная достигает 0
Когда это происходит, fd # 10 теряется из readfds в вызове select
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})
Дело в том, что вызов select не включает этот файловый дескриптор в набор, потому что он заблокирован другой стороной до тех пор, пока буфер (client <-> sshd) не станет пустым (предполагается, что sshd не может отправить больше байтов клиенту ssh, потому что размер окна равен 0, поэтому fd должен быть заблокирован, чтобы предотвратить отправку дополнительной информации со стороны оболочки)
Такое поведение не происходит с использованием шпатлевки, и похоже, что это связанный с ним ssh-клиент ручного терминала Honeywell, основанный на Openssh (не знаю версию)
В любом случае, я только что подтвердил следующую версию: OpenSSH_3.8.1p1, OpenSSL 0.9.7d 17 марта 2004 г. не затронут (протестировано в Windows 10 против RHEL6 ssh-server 5.3.p1)
Начо.