Strange behaviour with ptmx file descriptors

Sat Apr 16 19:11:32 AEST 2016

Hi again

I think I didn't explain the problem properly

I'll try to explain it using an example of what it happened last time in
Feb, the 23th

This is the point of view of the C application, running in the linux box,
when answering to the client:

4911  1456244042.324336 write(1, "\7", 1) = 1
4911  1456244042.324610 write(1, "\33[1;16H        \33[6;6H_______\33[7;1H
-INFORME CANT. RECOGIDA-\33[7;26H", 66) = 66

This is the point of view of the ssh process in the linux box:

6647  1456244042.323463 select(14, [3 9 13], [], NULL, {900, 0}) = 1 (in
[13], left {899, 998569})
6647  1456244042.324971 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8)  = 0
6647  1456244042.325010 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
6647  1456244042.325033 read(13, "\7\33[1;16H
\33[6;6H_______\33[7;1H -INFORME CANT. RECOGIDA-\33[7;26H", 16384) = 67
6647  1456244042.325126 select(14, [3 9], [3], NULL, {900, 0}) = 1 (out
[3], left {899, 999998})
6647  1456244042.325203 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8)  = 0
6647  1456244042.325240 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
6647  1456244042.325264 write(3,
"P\247\244}\277\322\260\21\3314\7\227\223~\317\360\35\334\232\372\237\250\320\312\1;\25\37\23\363\363O&0\355i{zUbr\365,\362yyl\222",
48) = 48
6647  1456244042.325310 select(14, [3 9], [], NULL, {900, 0}) = 1 (in [3],
left {892, 12016})       <<-- where id fd#13 ?

This is the point of view of the ssh client:

  74539.285          0BE6003A            I-ITE       38:VT220_IO:
tohost:0x31='1'

  74539.300          0BE6003A            I-ITE       52:ANSITERM:
charin:<ASCII(27)>

  74539.300          0BE6003A            I-ITE       53:ANSITERM:
charin:<[>

  74539.300          0BE6003A            I-ITE       54:ANSITERM:
charin:<1>

  74539.300          0BE6003A            I-ITE       55:ANSITERM:
charin:<;>

  74539.300          0BE6003A            I-ITE       56:ANSITERM:
charin:<2>

  74539.300          0BE6003A            I-ITE       57:ANSITERM:
charin:<3>

  74539.300          0BE6003A            I-ITE       58:ANSITERM:
charin:<H>

  74539.301          0BE6003A            I-ITE       59:ANSITERM:
charin:<1>

  74539.301          0BE6003A            I-ITE       63:ANSITERM:
charin:<ASCII(27)>

  74539.301          0BE6003A            I-ITE       64:ANSITERM:
charin:<[>

  74539.301          0BE6003A            I-ITE       65:ANSITERM:
charin:<1>

  74539.301          0BE6003A            I-ITE       66:ANSITERM:
charin:<;>

  74539.302          0BE6003A            I-ITE       67:ANSITERM:
charin:<2>

  74539.302          0BE6003A            I-ITE       68:ANSITERM:
charin:<4>

  74539.302          0BE6003A            I-ITE       69:ANSITERM:
charin:<H>

  74539.302          0BE6003A            I-ITE       70:ANSITERM:
charin:<ASCII(7)>

  74539.346          0BE6003A            I-ITE       71:ANSITERM:
        charin:<ASCII(27)>

  74539.347          0BE6003A            I-ITE       72:ANSITERM:
charin:<[>

  74539.347          0BE6003A            I-ITE       73:ANSITERM:
charin:<1>

  74539.347          0BE6003A            I-ITE       74:ANSITERM:
charin:<;>

  74539.347          0BE6003A            I-ITE       75:ANSITERM:
charin:<1>

  74539.347          0BE6003A            I-ITE       76:ANSITERM:
charin:<6>

  74539.347          0BE6003A            I-ITE       77:ANSITERM:
charin:<H>

  74539.347          0BE6003A            I-ITE       78:ANSITERM:
charin:< >

  74539.348          0BE6003A            I-ITE       82:ANSITERM:
charin:< >

  74539.348          0BE6003A            I-ITE       86:ANSITERM:
charin:< >

  74547.277          0BE6003A            I-ITE       97:VT220_IO:
tohost:0x08='.'            <-- here the client stops receiving data

  74547.779          0BE6003A            I-ITE       08:VT220_IO:
tohost:0x08='.'

  74547.821          0BE6003A            I-ITE       19:VT220_IO:
tohost:0x08='.'

  74547.864          0BE6003A            I-ITE       30:VT220_IO:
tohost:0x08='.'

  74547.907          0BE6003A            I-ITE       41:VT220_IO:
tohost:0x08='.'

  74547.950          0BE6003A            I-ITE       52:VT220_IO:
tohost:0x08='.'

  74547.993          0BE6003A            I-ITE       63:VT220_IO:
tohost:0x08='.'

  74548.036          0BE6003A            I-ITE       74:VT220_IO:
tohost:0x08='.'

And when it happens, the ssh client still working properly, it continues
sending keystrokes to the the application, the application receives these
keystrokes, it answers to the client, but the answer is not yet received by
the sshd process (so it seems the application is frozen... when it is not
¿true?)

One time, the operator tried to reset the connection from the ssh client,
but no way

The C program works properly thru telnet.. no incident has been reported
ever

I hope this information helps

Many thanks

Regards

Nacho.

2016-04-15 23:53 GMT+02:00 Ángel González <keisial at gmail.com>:

> El 15/04/16 11:28, Nacho del Rey escribió:
>
> Hi Angel and many thanks for your answer
>
> The application still sending & receiving data
>   .- strace over the application:
>
> I asked for the corresponding strace of the client ssh, where the data
> should have been received and printed to the console.
>
> The strange thing is all file descriptors of all processes are in place
> but it seems for any strange reason, something happen to fd#13 ( C Program
> fd #1 --> ssd read fd #13) because it disappears from the select call (it
> won't be available in the read fd set ever)
>
> Interesting. I wonder if that's expected and sshd waits for acknowledgment
> from the remote ssh before reading again.
>
>
> Also, seems you missed this suggestion:
>
> What's the terminal emulator used in the client side? Does resetting it
>> (from a menu option) make it receive the server output again?
>>
>> Cheers
>>
>
> Best regards
>
>