Re: HMAC error - help pls

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

Hi Aris,

How're u doing?

Just wanted to know if you could recommend places in either my code or
libssh that may give us some clues as to what is causing this
behaviour.....I may not understand libssh internals as well but maybe
you could give me some pointers and I could collect data and that may
make it easier to figure this out.

Again I realize you guys are probably extremely tied up and am hoping
if you show me the way I can help in some small way.

Thanks so much :)

Bye for now

On Wed, Jun 15, 2011 at 3:01 PM, jeetu.golani@xxxxxxxxx
<jeetu.golani@xxxxxxxxx> wrote:
> 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)
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>
>>>>>
>>>>
>>
>