Re: HMAC error - help pls

[Aris Adamantiadis <aris@xxxxxxxxxxxx>]

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)
>>>>>>>>
>>>>>>>
>>>>>>
>>>>>
>>>>>
>>>>
>>>
>>