Re: HMAC error - help pls

["jeetu.golani@xxxxxxxxx" <jeetu.golani@xxxxxxxxx>]

Hi Aris,

I'm still collecting more debugging information. I noticed that while
this behaviour is reproducible each time it doesn't always throw out
the HMAC error, I'm still trying to verify all of this.

In the mean time could you please verify if prima facie the logic i'm
using to code the server below makes sense to you and/or something
there could be causing this error. I had pasted this portion in a
previous thread to the list too.

Thanks so much, will get back with more data and after I review all
you've asked me in previous mails

Bye for now

--------------------------------------------------------------------------------------------------------------------------

To go through the server code:

Main thread :

- I am using gthreads for the threading and initialize gthread, call
ssh_threads_set_callbacks, ssh_init()

- I have a global ssh_session* (ssh_session is pointer to a pointer)
and I initiate this with a ssh_new (assuming this would allocate
memory).

- my ssh_bind and ssh_bind_listen is common for all ssh_sessions.

- I then enter a loop where I allocate a new
ssh_session[session_count] = ssh_new i.e. a new session, and move to
ssh_bind_accept (sshbind is common for all sessions, is this a
problem?)

- then public key authentication

- then i start a new thread and pass along session[session_count],
increment session_count.

- The server_thread sees which requests are coming along and calls
appropriate functions to open new channels or exec stuff.

- If SSH_CHANNEL_REQUEST_X11 is received it goes about setting up x11
forwarding, setting the x auth cookie, creating a port e.g. 6010 for
xclients to connect to, and listening for these connections on the
sockets.

- when a client connects to this socket, then I start a new thread
(wait_for_something function) and there is a select and if select goes
through then I accept() and get a client_socket.

- I then go about opening an x11 channel with ssh_channel_open_x11

*****these are steps I'm thinking maybe causing the crash*****

- wait for something thread has as a local variable the following
callback struct, since this is local and in a separate thread I'm
hoping this ensures that each thread / connection basically has it's
own callback and access to functions like copy_chan_to_fd etc and this
alone ensures that no threads or apps are overwriting/corrupting data.
is that correct?

struct ssh_channel_callbacks_struct cb =
       {
       .channel_data_function = copy_chan_to_fd,
       .channel_eof_function = chan_close,
       .channel_close_function = chan_close,
       .userdata = NULL
       };

- I then do a :

ssh_callbacks_init(&cb);
ssh_set_channel_callbacks(chan_x11, &cb);
events = POLLIN | POLLPRI | POLLERR | POLLHUP | POLLNVAL;
event = ssh_event_new();

- and after adding events, fd, etc as shown in samplesshd-tty.c i go
into a ssh_event_dopoll loop.

....am not confident about my call back structures and if there is
some kind of thread issues being caused there.....am not using mutexes
here and I've experimented with them but not sure where in the code I
need them (mutexes I've experimented with are in comments).

-----------------------------------------------------------------------------------------------------------------------




On Thu, Jun 9, 2011 at 2:51 PM, jeetu.golani@xxxxxxxxx
<jeetu.golani@xxxxxxxxx> wrote:
> Hi Aris,
>
> First, I'm extremely sorry for not following up on your previous mail
> - unfortunately things have been a little too chaotic.
>
> Thank you so much for taking the time to look into this, I truly and
> profusely appreciate it and will work with you and help as much as I
> can in ruling out libssh as the culprit. Of course I'm not too certain
> of what in my code could upset libssh and neither am I very confident
> of my own code at this point of time so may need to seek help from you
> - pls bare with me :)
>
> I have managed to reproduce this behaviour and collect some
> data.....will go through it and report back.....I want to see mainly
> if there is the Decrypting 16 bytes occurring one after the other this
> time around too.
>
> Bye for now
>
> On Thu, Jun 9, 2011 at 2:38 PM, Aris Adamantiadis <aris@xxxxxxxxxxxx> wrote:
>> Hi,
>>
>> I have inspected the code path, there is no possibility for "decrypting
>> 16 bytes" message to show up twice in a row. Are you using several
>> sessions ? If so, could you try again but with only one client ? I'm not
>> yet sure it's not a libssh problem so I prefer we investigate.
>>
>> Kr,
>>
>> Aris
>>
>> Le 7/06/11 13:22, jeetu.golani@xxxxxxxxx a écrit :
>>> Hi Aris,
>>>
>>> Thanks for replying.
>>>
>>> Unfortunately I copy pasted only this part of the log, will reproduce
>>> the error and paste the entire log.
>>>
>>> As for an estimation on the amount of data, gauging that the packet
>>> number above is 36519 and while most packets seemed to have a length
>>> of 32bytes, I did see some packets with a length of 668bytes too
>>> (about 10%).....am guessing approx 35 Megabytes of data.
>>>
>>> For the ssh client I am using a standard openssh client, the server is
>>> my own and creates a socket where an X client connects etc.
>>>
>>> Sincerely need your help. Thanks and sorry for the trouble.
>>>
>>> Bye for now
>>>
>>> On Tue, Jun 7, 2011 at 4:08 PM, Aris Adamantiadis <aris@xxxxxxxxxxxx> wrote:
>>>> Hi Jeetu,
>>>>
>>>> I did not have much time to read your email completely, but it seems in
>>>> first impression that server/client is sending garbage. Could you attach
>>>> the first hundreds lines of debugging output, especially the key exchange ?
>>>> Also, do you have an estimation of the number of bytes that have been
>>>> transmitted before the failure ? (i.e. does it approach gigabytes ?)
>>>>
>>>> Thanks,
>>>>
>>>> Aris
>>>>
>>>> Le 7/06/11 12:00, jeetu.golani@xxxxxxxxx a écrit :
>>>>> Hi guys,
>>>>>
>>>>> In continuation with my efforts to put together a libssh based server,
>>>>> I have had significant success and can say it is very impressive to
>>>>> see the effort you guys have put in the libssh library, thank you :)
>>>>>
>>>>> I could sincerely use some help though. All in all my server is
>>>>> behaving much more robust than it ever has. I have been testing with
>>>>> multiple X client applications being forwarded simultaneously and all
>>>>> in all it runs well. I had some previous issues I had mailed this list
>>>>> about (subject: multithreaded server issues) but an init of the buffer
>>>>> seems to have helped.
>>>>>
>>>>> I have noticed some behaviour I do not understand. Below is what the
>>>>> libssh log says when set to SSH_LOG_PACKET
>>>>>
>>>>> With multiple applications, after extensive use of the applications
>>>>> (for e.g. xeyes and xclock running) I have noticed that after sometime
>>>>> the applications are unable to refresh their window - there is no
>>>>> crash most of these times and if left alone maybe clock may eventually
>>>>> refresh part of the window etc. xeyes stops showing it's eyes moving
>>>>> around but still seems to be running - ssh client connected seems to
>>>>> show some activity too.
>>>>>
>>>>> The libssh log seems to suggest that there is packet corruption at
>>>>> this point. Two things stand out from the below log:
>>>>>
>>>>> I]
>>>>>
>>>>> [3] Decrypting 16 bytes
>>>>> [3] Packet size decrypted: 2754678753 (0xa4310fe1)
>>>>> [1] Error : read_packet(): Packet len too high(2754678753 a4310fe1)
>>>>>
>>>>> II]
>>>>> [3] Decrypting 96 bytes
>>>>> [1] Error : HMAC error
>>>>>
>>>>> Pls note this log is an excerpt of a long log taken once the strange
>>>>> behaviour has manifested.
>>>>>
>>>>> What is a HMAC error? can someone pls shed light on what could be
>>>>> causing the above?
>>>>>
>>>>> Thanks,
>>>>> Jeetu
>>>>>
>>>>>
>>>>> [3] Type 94
>>>>> [3] Dispatching handler for packet type 94
>>>>> [2] Channel receiving 32 bytes data in 0 (local win=72640 remote win=2095160)
>>>>> [1] placing 32 bytes into channel buffer (stderr=0)
>>>>> [2] Channel windows are now (local win=72608 remote win=2095160)
>>>>> [3] Decrypting 16 bytes
>>>>> [3] Packet size decrypted: 60 (0x3c)
>>>>> [3] Read a 60 bytes packet
>>>>> [3] Decrypting 48 bytes
>>>>> [3] 18 bytes padding, 59 bytes left in buffer
>>>>> [3] After padding, 41 bytes left in buffer
>>>>> [3] Final size 41
>>>>> [3] Type 94
>>>>> [3] Dispatching handler for packet type 94
>>>>> [2] Channel receiving 32 bytes data in 0 (local win=72608 remote win=2095160)
>>>>> [1] placing 32 bytes into channel buffer (stderr=0)
>>>>> [2] Channel windows are now (local win=72576 remote win=2095160)
>>>>> [3] Decrypting 16 bytes
>>>>> [3] Decrypting 16 bytes
>>>>> [3] Packet size decrypted: 2754678753 (0xa4310fe1)
>>>>> [1] Error : read_packet(): Packet len too high(2754678753 a4310fe1)
>>>>> [3] Packet size decrypted: 92 (0x5c)
>>>>> [3] Read a 92 bytes packet
>>>>> [3] Decrypting 96 bytes
>>>>> [1] Error : HMAC error
>>>>> [3] Writing on the wire a packet having 1993 bytes before
>>>>> [3] 1993 bytes after comp + 18 padding bytes = 2012 bytes packet
>>>>> [3] Encrypting packet with seq num: 36518, len: 2016
>>>>> [3] Enabling POLLOUT for socket
>>>>> [1] channel_write wrote 1984 bytes
>>>>> [3] Writing on the wire a packet having 17 bytes before
>>>>> [3] 17 bytes after comp + 10 padding bytes = 28 bytes packet
>>>>> [3] Encrypting packet with seq num: 36519, len: 32
>>>>> [3] Enabling POLLOUT for socket
>>>>> [1] channel_write wrote 8 bytes
>>>>> [3] Read a 92 bytes packet
>>>>> [3] Decrypting 176 bytes
>>>>> [1] Error : HMAC error
>>>>> [3] Read a 92 bytes packet
>>>>> [3] Decrypting 256 bytes
>>>>> [1] Error : HMAC error
>>>>> [3] Read a 92 bytes packet
>>>>> [3] Decrypting 336 bytes
>>>>> [1] Error : HMAC error
>>>>> [3] Read a 92 bytes packet
>>>>> [3] Decrypting 416 bytes
>>>>> [1] Error : HMAC error
>>>>> [3] Read a 92 bytes packet
>>>>> [3] Decrypting 496 bytes
>>>>> [1] Error : HMAC error
>>>>> [3] Read a 92 bytes packet
>>>>> [3] Decrypting 576 bytes
>>>>> [1] Error : HMAC error
>>>>> [3] Read a 92 bytes packet
>>>>> [3] Decrypting 656 bytes
>>>>> [1] Error : HMAC error
>>>>> [3] Read a 92 bytes packet
>>>>> [3] Decrypting 736 bytes
>>>>> [1] Error : HMAC error
>>>>> [3] Read a 92 bytes packet
>>>>> [3] Decrypting 816 bytes
>>>>> [1] Error : HMAC error
>>>>> [3] Read a 92 bytes packet
>>>>> [3] Decrypting 896 bytes
>>>>> [1] Error : HMAC error
>>>>> [3] Read a 92 bytes packet
>>>>> [3] Decrypting 976 bytes
>>>>> [1] Error : HMAC error
>>>>> [3] Read a 92 bytes packet
>>>>> [3] Decrypting 1056 bytes
>>>>> [1] Error : HMAC error
>>>>> [3] Read a 92 bytes packet
>>>>> [3] Decrypting 1136 bytes
>>>>> [1] Error : HMAC error
>>>>> [3] Read a 92 bytes packet
>>>>> [3] Decrypting 1216 bytes
>>>>> [1] Error : HMAC error
>>>>> [3] Read a 92 bytes packet
>>>>> [3] Decrypting 1296 bytes
>>>>> [1] Error : HMAC error
>>>>> [3] Read a 92 bytes packet
>>>>> [3] Decrypting 1376 bytes
>>>>> [1] Error : HMAC error
>>>>> [3] Writing on the wire a packet having 8605 bytes before
>>>>> [3] 8605 bytes after comp + 14 padding bytes = 8620 bytes packet
>>>>> [3] Encrypting packet with seq num: 885, len: 8624
>>>>> [3] Enabling POLLOUT for socket
>>>>> [1] channel_write wrote 8596 bytes
>>>>> [3] Writing on the wire a packet having 8605 bytes before
>>>>> [3] 8605 bytes after comp + 14 padding bytes = 8620 bytes packet
>>>>> [3] Encrypting packet with seq num: 886, len: 8624
>>>>> [3] Enabling POLLOUT for socket
>>>>> [1] channel_write wrote 8596 bytes
>>>>> [3] Decrypting 16 bytes
>>>>> [3] Packet size decrypted: 3661937450 (0xda44bb2a)
>>>>> [1] Error : read_packet(): Packet len too high(3661937450 da44bb2a)
>>>>>
>>>>
>>>
>>
>>
>