Re: HMAC error - help pls

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

Hi Aris,

> symptom of garbage in the decrypted packets, in fact I changed things in
> master to have it throw an error as soon as the packet size looks buggy.

read_packet apparently is complaining that that packet size is too long in
the ssh_log outputs I sent across with my tests using only a single client.
Any way you can think of that I can rule out that this error reported by
read_packet isn't being caused somehow by my code?

> I'll add an info in the ssh_log call to have the session uniquely
> identified, it will be easier to track down then.

Yes this would definitely make it easier to debug.

Please let me know any steps you think I should follow to narrow down
our scope as to where the problem lies.

Thanks a lot for looking into this Aris :)

Bye for now




On Wed, Jun 15, 2011 at 2:24 PM, Aris Adamantiadis <aris@xxxxxxxxxxxx> wrote:
> Hi Jeetu,
>
> I did not have the occasion to look futher. The HMAC error is simply a
> symptom of garbage in the decrypted packets, in fact I changed things in
> master to have it throw an error as soon as the packet size looks buggy.
> I'll add an info in the ssh_log call to have the session uniquely
> identified, it will be easier to track down then.
> Kr,
>
> Aris
>
> Le 11/06/11 13:37, jeetu.golani@xxxxxxxxx a écrit :
>> Hi Aris,
>>
>> I had a memory allocation doubt in my code, basically a memory
>> allocation/instantiation doubt in the ssh_session with the following
>> logic:
>>
>> -------------------------
>> - 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?)
>>
>> - upon authentication
>> -------------------------
>>
>> I have just tried replacing the above logic with a fixed array of
>> ssh_session and simply
>> instantiating it in the loop with a session[server_count] = ssh_new()
>> and upon authorization
>> I spawn a new thread that handles channel requests,etc
>>
>> I am also testing with just a single connect from ssh client.
>>
>> Unfortunately I still see the phenomena wherein the window soon loses
>> ability to refresh itself.
>> I am attaching the ssh log debugging output but the critical section
>> is as follows wherein
>> read_packet says that packet len too high.
>>
>> In none of the tests where I launch just a single ssh client to
>> connect do I get a HMAC error.
>> In a couple of tests I have done launching multiple sessions produces
>> this effect but with the
>> same read_packet error as below but no HMAC error.
>>
>> I'm attaching the full debug output of this current test. Pls let me
>> know your thoughts.
>>
>> 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=113716 remote win=2097152)
>> [1] placing 32 bytes into channel buffer (stderr=0)
>> [2] Channel windows are now (local win=113684 remote win=2097152)
>> [3] Decrypting 16 bytes
>> [3] Packet size decrypted: 597749705 (0x23a0efc9)
>> [1] Error : read_packet(): Packet len too high(597749705 23a0efc9)
>> [3] Decrypting 16 bytes
>> [3] Packet size decrypted: 4194306560 (0xfa000a00)
>> [1] Error : read_packet(): Packet len too high(4194306560 fa000a00)
>>
>> Bye for now
>>
>>
>> On Fri, Jun 10, 2011 at 12:00 AM, jeetu.golani@xxxxxxxxx
>> <jeetu.golani@xxxxxxxxx> wrote:
>>> Hi Aris,
>>>
>>>>>> 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.
>>>
>>> I ran a couple of tests with just a single ssh client connecting in.
>>> Once I ran xeyes
>>> and the next i ran xclock. Both applications failed when i kept moving
>>> the windows
>>> vigarously.
>>>
>>> The server has spewed out that both these times it was because
>>> read_packet reported
>>> that packet length was too large. This is something that if memory
>>> serves me right we
>>> saw even when I got the HMAC error. This time around though I did not
>>> get the HMAC
>>> errors.
>>>
>>> I am attaching text files of the libssh debug output in both these cases.
>>>
>>> Please let me know what you would like me to try next.
>>>
>>> Thanks again for your help.
>>>
>>> Bye for now
>>>
>>>
>>> On Thu, Jun 9, 2011 at 5:37 PM, jeetu.golani@xxxxxxxxx
>>> <jeetu.golani@xxxxxxxxx> wrote:
>>>> 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)
>>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>
>>>>>>
>>>>>
>>>>
>>>
>