Re: HMAC error - help pls

[Aris Adamantiadis <aris@xxxxxxxxxxxx>]

Hi Jeetu,

Watching the output more carefully, I notice this:
[3] Decrypting 16 bytes
[3] Decrypting 16 bytes

It looks like the 16 first bytes were decrypted twice. And that the 
following packets somewhat decrypted correctly.
The HMAC is the algorithm that verifies the integrity of the received 
data. Bad Hmac means there was a corruption, probably because of the 
double decrypt.
The double decrypt may have two sources:
1.  A bug in libssh makes it possible to have the decryption happening 
twice. To be verified
2. Socket operation happening in concurrency in two threads on the same 
session. Can be something as trivial as a ssh_poll().
How are you doing the multiplexing of the different sockets/servers ?

I will verify we are not in #1, could you see if you are not in #2 ?

Kr,

Aris

Le 07/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)