More data recieved than is allowed

[Anonymous]

My client keeps getting this error when trying to retrieve long data from the server, i.e. view a large log file

java.io.IOException: More data recieved than is allowed by the channel data window [session]
    at com.sshtools.j2ssh.connection.Channel.processChannelData(Channel.java:150)
    at com.sshtools.j2ssh.connection.ConnectionProtocol.onMsgChannelData(ConnectionProtocol.java:816)
    at com.sshtools.j2ssh.connection.ConnectionProtocol.onMessageReceived(ConnectionProtocol.java:613)
    at com.sshtools.j2ssh.transport.AsyncService.run(AsyncService.java:121)
    at java.lang.Thread.run(Thread.java:534)

Server side is Solaris 9 running OpenSSH 4.2p1. To make things more complicated, this only happens when i'm connecting with a iPlanet directory server defined user. It works fine when it's an /etc/passwd defined user. They both connect to the same sshd process though (verified pid).

I put sshd in debug mode, and see channel window adjustments

Jul  3 11:01:23 myhost sshd[9476]: debug2: channel 0: read 47 from efd 10
Jul  3 11:01:23 myhost sshd[9476]: debug2: channel 0: rwin 32648 elen 47 euse 1
Jul  3 11:01:23 myhost sshd[9476]: debug2: channel 0: sent ext data 47
Jul  3 11:02:18 myhost sshd[9476]: debug2: channel 0: rcvd adjust 31762
Jul  3 11:02:22 myhost sshd[9476]: debug2: channel 0: rcvd adjust 32164
Jul  3 11:02:22 myhost sshd[9476]: debug2: channel 0: rcvd adjust 31731
Jul  3 11:02:23 myhost sshd[9476]: debug2: channel 0: rcvd adjust 31788
Jul  3 11:02:23 myhost sshd[9476]: Received disconnect from 47.128.42.117: 11: Terminating connection

If I do the same actions from PuTTY, with the same user, i do not get disconnected.

[Sascha Hunold]

Hi Adam,

I don't have a solution yet.
I will have to dig into this code to figure out what the problem is.

You could do some experiments with various values in SessionChannelClient.java
    protected int getMaximumWindowSpace() {
        return 32648;
    }

and please add this logging statement to

Channel.java

    protected void processChannelData(SshMsgChannelExtendedData msg)
        throws IOException {
        synchronized (state) {
            if (msg.getChannelData().length > localWindow.getWindowSpace()) {

                log.debug("data length : " + msg.getChannelData().length
                        + " windows space : " + localWindow.getWindowSpace());

                throw new IOException(
                    "More data recieved than is allowed by the channel data window [" +
                    name + "]");
            }

Regards

Sascha

[Anonymous]

I will try that. I wonder if the overflow is the same amount each time. I also noticed that when SSHD is running in debug mode (-ddd), i get disconnected doing the same operation, even when I use my /etc/passwd defined user.

It's as if j2ssh isn't handling the extended data or debug data properly.

[Anonymous]

Ok I started by viewing a large log on the ssh server running in normal mode, connecting with a directory server user. Did it 4 times and got these overflows:

data length : 1450 windows space : 1448
data length : 3171 windows space : 3124
data length : 2273 windows space : 2226
data length : 1886 windows space : 1839

so the overflows are: 2, 47, 47, 47

Now i tried running my sshd in debug mode and using a /etc/passwd defined user, ran test twice:

Test1

Client side:
data length : 1300 windows space : 1230  (overflow is 70)

Server side:
debug1: server_input_channel_open: ctype session rchan 0 win 32648 max 32648
debug2: channel 0: read 30 from efd 10
debug2: channel 0: rwin 32648 elen 30 euse 1
debug2: channel 0: sent ext data 30
debug2: channel 0: read 41 from efd 10
debug2: channel 0: rwin 32618 elen 41 euse 1
debug2: channel 0: sent ext data 41
debug2: channel 0: read 40 from efd 10
debug2: channel 0: rwin 32577 elen 40 euse 1
debug2: channel 0: sent ext data 40
debug2: channel 0: read 13 from efd 10
debug2: channel 0: rwin 32537 elen 13 euse 1
debug2: channel 0: sent ext data 13
debug2: channel 0: read 171 from efd 10
debug2: channel 0: rwin 32524 elen 171 euse 1
debug2: channel 0: sent ext data 171
debug2: channel 0: read 137 from efd 10
debug2: channel 0: rwin 32353 elen 137 euse 1
debug2: channel 0: sent ext data 137
debug2: channel 0: rcvd adjust 32102
Received disconnect from 47.128.42.117: 11: Terminating connection

TEST2
Client side:
data length : 1594 windows space : 1162  (overflow is 432)

Server side:
debug1: server_input_channel_open: ctype session rchan 0 win 32648 max 32648
debug2: channel 0: read 30 from efd 10
debug2: channel 0: rwin 32648 elen 30 euse 1
debug2: channel 0: sent ext data 30
debug2: channel 0: read 41 from efd 10
debug2: channel 0: rwin 32618 elen 41 euse 1
debug2: channel 0: sent ext data 41
debug2: channel 0: read 40 from efd 10
debug2: channel 0: rwin 32577 elen 40 euse 1
debug2: channel 0: sent ext data 40
debug2: channel 0: read 13 from efd 10
debug2: channel 0: rwin 32537 elen 13 euse 1
debug2: channel 0: sent ext data 13
debug2: channel 0: read 169 from efd 10
debug2: channel 0: rwin 32524 elen 169 euse 1
debug2: channel 0: sent ext data 169
debug2: channel 0: read 139 from efd 10
debug2: channel 0: rwin 32355 elen 139 euse 1
debug2: channel 0: sent ext data 139
debug2: channel 0: rcvd adjust 32153
debug2: channel 0: rcvd adjust 32638
debug2: channel 0: rcvd adjust 31820
Received disconnect from 47.128.42.117: 11: Terminating connection

and finally, ran sshd in debug mode, and connected with my directory server user:

Test1
Client side:
data length : 2823 windows space : 1837 (so overflow is 986)

Server side:

debug1: server_input_channel_open: ctype session rchan 0 win 32648 max 32648
debug2: channel 0: read 30 from efd 10
debug2: channel 0: rwin 32648 elen 30 euse 1
debug2: channel 0: sent ext data 30
debug2: channel 0: read 41 from efd 10
debug2: channel 0: rwin 32618 elen 41 euse 1
debug2: channel 0: sent ext data 41
debug2: channel 0: read 40 from efd 10
debug2: channel 0: rwin 32577 elen 40 euse 1
debug2: channel 0: sent ext data 40
debug2: channel 0: read 148 from efd 10
debug2: channel 0: rwin 32537 elen 148 euse 1
debug2: channel 0: sent ext data 148
debug2: channel 0: read 167 from efd 10
debug2: channel 0: rwin 32389 elen 167 euse 1
debug2: channel 0: sent ext data 167
debug2: channel 0: read 144 from efd 10
debug2: channel 0: rwin 32222 elen 144 euse 1
debug2: channel 0: sent ext data 144
debug2: channel 0: read 319 from efd 10
debug2: channel 0: rwin 32078 elen 319 euse 1
debug2: channel 0: sent ext data 319
debug2: channel 0: read 50 from efd 10
debug2: channel 0: rwin 31759 elen 50 euse 1
debug2: channel 0: sent ext data 50
debug2: channel 0: read 47 from efd 10
debug2: channel 0: rwin 31709 elen 47 euse 1
debug2: channel 0: sent ext data 47
debug2: channel 0: rcvd adjust 31853
Received disconnect from 47.128.42.117: 11: Terminating connection

Test2
Client side:
data length : 2033 windows space : 1765  (overflow of 268)

Server side:
debug1: server_input_channel_open: ctype session rchan 0 win 32648 max 32648
debug2: channel 0: read 30 from efd 10
debug2: channel 0: rwin 32648 elen 30 euse 1
debug2: channel 0: sent ext data 30
debug2: channel 0: read 41 from efd 10
debug2: channel 0: rwin 32618 elen 41 euse 1
debug2: channel 0: sent ext data 41
debug2: channel 0: read 40 from efd 10
debug2: channel 0: rwin 32577 elen 40 euse 1
debug2: channel 0: sent ext data 40
debug2: channel 0: read 89 from efd 10
debug2: channel 0: rwin 32537 elen 89 euse 1
debug2: channel 0: sent ext data 89
debug2: channel 0: read 226 from efd 10
debug2: channel 0: rwin 32448 elen 226 euse 1
debug2: channel 0: sent ext data 226
debug2: channel 0: read 166 from efd 10
debug2: channel 0: rwin 32222 elen 166 euse 1
debug2: channel 0: sent ext data 166
debug2: channel 0: read 347 from efd 10
debug2: channel 0: rwin 32056 elen 347 euse 1
debug2: channel 0: sent ext data 347
debug2: channel 0: read 47 from efd 10
debug2: channel 0: rwin 31709 elen 47 euse 1
debug2: channel 0: sent ext data 47
debug2: channel 0: rcvd adjust 32316
debug2: channel 0: rcvd adjust 32197
debug2: channel 0: rcvd adjust 32308
debug2: channel 0: rcvd adjust 32095
Received disconnect from 47.128.42.117: 11: Terminating connection

I'm not sure what to make of this. The only situation where the ssh connection remains connected is when i connect using a /etc/passwd defined user, and the sshd server is NOT in debug mode.

[Anonymous]

Ok I found the problem.

In ConnectionProtocol.java:

   private void onMsgChannelExtendedData(SshMsgChannelExtendedData msg)
        throws IOException {
        Channel channel = getChannel(msg.getRecipientChannel());

        if (channel == null) {
            throw new IOException(
                "Remote computer sent data for non existent channel");
        }

>>>>>   channel.getLocalWindow().consumeWindowSpace(msg.getChannelData().length);
        channel.processChannelData(msg);
    }

and in Channel.java

    protected void processChannelData(SshMsgChannelExtendedData msg)
        throws IOException {
        synchronized (state) {
            if (msg.getChannelData().length > localWindow.getWindowSpace()) {
                throw new IOException(
                    "More data recieved than is allowed by the channel data window [" +
                    name + "]");
            }

>>>>>       long windowSpace = localWindow.consumeWindowSpace(msg.getChannelData().length);

            if (windowSpace < getMinimumWindowSpace()) {
                if (log.isDebugEnabled()) {
                    log.debug("Channel " + String.valueOf(localChannelId) +
                        " requires more window space [" + name + "]");
                }

                windowSpace = getMaximumWindowSpace() - windowSpace;
                connection.sendChannelWindowAdjust(this, windowSpace);
                localWindow.increaseWindowSpace(windowSpace);
            }

            onChannelExtData(msg);

            Iterator it = eventListeners.iterator();
            ChannelEventListener eventListener;

            while (it.hasNext()) {
                eventListener = (ChannelEventListener) it.next();

                if (eventListener != null) {
                    eventListener.onDataReceived(this, msg.getChannelData());
                }
            }
        }
    }

We consume extended data's length in window space TWICE! So I removed the first one, from ConnectionProtocol.java and now everything is fine.

Can someone open a bug report? I'm too busy myself.

[Sascha Hunold]

I added a bug report.

I will have a look at this.

Cheers

Sascha