Last send never happens

[nicklasb]

Hi,
I have this strange problem. I always have to trail a message with another one (I'll just send an empty one) to make server-side web socket react.
The result of this is 1,2,3:

    self.send(bytes(str("1"), encoding="UTF-8"))
    self.send(bytes(str("2"), encoding="UTF-8"))
    self.send(bytes(str("3"), encoding="UTF-8"))
    self.send(bytes(str(""), encoding="UTF-8"))

And the result of this is 1,2:

    self.send(bytes(str("1"), encoding="UTF-8"))
    self.send(bytes(str("2"), encoding="UTF-8"))
    self.send(bytes(str("3"), encoding="UTF-8"))

Is this expected behaviour? If so, yeah, It is quite easy to work around, but as I understand it, the protocol shouldn't require it?

[Lawouach]

Hi,

This isn't expected and ought to be considered a bug. I think it's been mentioned before.

[nicklasb]

Am I right to assume that the problem should be somewhere in streaming.receiver? I seems that sendall is more the normal socket?

[Lawouach]

It would be a good place to start indeed.

[nicklasb]

Hm, that part at least seems to work. As it gets a message, it properly identifies the frame.fin and sets completed and so on. Also, I that wouldn't work, one would get other problems as well, like with content mixing from previous messages, it is almost like there is some problem above that level. I will look around a little.

[nicklasb]

Strange. From the client, I am sending (socket.send):
\x81\xfe\x00\xf6\xbbW\x15\x93\xc0uf\xf0\xd32x\xf2\xf237\xa9\x9bu,\xa6\x89dp\xaa\x888\xa2\xde1v\xbe\x8fd-\xf7\x965 \xa7\xd8zs\xf1\x825w\xaa\x83c&\xf2\x837\xbf\x9buf\xe3\xda {\xf6\xdf\x15l\xb1\x81w7\xfd\xd25z\xb1\x97w7\xcc\xd237\xa9\x9bu \xa6\x8cat\xa2\x8bdt\xa6\xd85#\xa7\x8a1%\xa3\xddcp\xaa\x8967\xbf\x9buf\xea\xc8#p\xfe\xeb>q\xb1\x81w"\xaa\x88a9\xb3\x99$e\xf2\xcc9p\xf7\xec?p\xfd\x99m5\xb1\x89g$\xa6\x96g#\xbe\x8bn5\xa3\x83m$\xa4\x81g"\xbd\x89e'\xab\x8fn7\xbf\x9bu}\xfc\xc8#7\xa9\x9bu{\xfa\xd98%\xa2\x99{5\xb1\xd56x\xf6\x99m5\xb1\xfa0p\xfd\xcfw|\xfd\xc8#t\xfd\xd82=\xd2\xdc2{\xe7\x96f<\xb1\x97w7\xe0\xd4"g\xf0\xdeu/\xb3\x99\x16r\xf6\xd5#8\xa2\x99*'

But then am only receiving(in WebSocket.process):

b'\x81\xfe'

So there are only two bytes getting through the first time, I am obviously not that well versed in this implementation, seems to be some kind of control bytes.
This is of course if I only send() once.

Do you have any idea right away, or should I continue looking?

[Lawouach]

ws4py always read the first two bytes only to read the header.

The header contains the length of the frame which is used by ws4py to read more incoming bytes.

[nicklasb]

Aha, I see. Then I don't understand, really, it should work. I'll look into it more some other time.

[Lawouach]

The strategy I apply may not be the best for small frames though. It'd be nice if I could devise an appropriate test for it :)

[nicklasb]

The easiest way IMO, at least when it comes to complex systems, is to make mockups that inherits from the involved classes and simply overrides all involved methods so that no networking has to be involved. I found that out recently. So in this case, make subclass mockups of the frame, streaming and web socket classes that only sends the data, override everything else that that is involved in exactly what you are testing. But only what is involved. The rests can be left where it is.

I have used that approach to be able to write meaningful integration tests for my BPM system, which would be impossibly complex if I couldn't selectively do away with for example networking and multiprocessing when testing message parsing and routing.

[nicklasb]

The idea is; instead of making mockups that makes the involved classes feel like nothing has changed, instead override the classes so they don't use that functionality.
Yes, it is not as totally correct as mocking everything, but honestly, if they are at least not awfully designed in the first place, it works good enough. I haven't had any problems with that approach.

[Lawouach]

The good news is that ws4py was design around mocking up the socket provider :)

For instance:

https://github.com/Lawouach/WebSocket-for-Python/blob/master/test/test_websocket.py#L18

[nicklasb]

Yes, that works too. :-)
Basically, I just wanted to mention that if mocking for all thinkable cases is hard, the solution might be to not do it. I was soo happy when I realized I could do it that way. :-)

[decontamin4t0R]

Having this Problem also... Solution for me currently: Because the Client doesn't write much (one Thing per Connection), it is sended twice.

[Lawouach]

Mmmh, would you guys mind describing your setup a little more?

Which client backend (threaded, tornado, gevent?) and which server backend?

[nicklasb]

Hi,
CherryPy and from ws4py.client.threadedclient, if that is what you mean.

[Lawouach]

I guess I'm puzzled. I just ran the following code:

# -*- coding: utf-8 -*-
from ws4py.client.threadedclient import WebSocketClient

class EchoClient(WebSocketClient):
    def opened(self):
        self.send(bytes(str("1"), encoding="UTF-8"))
        self.send(bytes(str("2"), encoding="UTF-8"))
        self.send(bytes(str("3"), encoding="UTF-8"))

    def received_message(self, m):
        print("=> %d %s" % (len(m), str(m)))

if __name__ == '__main__':
    try:
        ws = EchoClient('ws://localhost:9000/ws', protocols=['http-only', 'chat'])
        ws.daemon = False
        ws.connect()
    except KeyboardInterrupt:
        ws.close()

against the stock CherryPy echo server in the examples directory and here is what I see:

=> 1 1
=> 1 2
=> 1 3

so the three messages were sent and echoed back as expected

[nicklasb]

Try to just send the first.

[nicklasb]

I run it on Linux, by the way.

[Lawouach]

Ubuntu 15.10 with Python 2.7.9 here (CherryPy 3.8.0) and I couldn't reproduce the pb with a single send.

[nicklasb]

Strange. I am running python 3.4, though. Have you tried that too?

[Lawouach]

I haven't client side no. Let me see.

[nicklasb]

3.7.0 of CherryPy, could be fixed, I will try if it works with 3.4 for you.
Haven't done much with that part of the code since this.

[Lawouach]

No dice I'm afraid.

Running both client and server on Python 3.4 using the code above, I do receive the echoed message without having to trigger one more message.

[nicklasb]

Ok, I will see if I can repeat with the basic example.

[nicklasb]

Dammit, I just realized that the problem is SSL. If I disable SSL, it works.
Very strange that I didn't think about that earlier. My debug-fu must have been extremely weak.

[Lawouach]

Right, this would make more sense. I'll try to see if I can it working.

[Lawouach]

Okay, reproduced it by enabling ssl :(

[nicklasb]

Sorry about the wild goose chase, if it's any consolation, I spent about 5 hours figuring out why the hell stuff didn't work.

Ok. Do you think that there is anything you can do about that?

[Lawouach]

No worries. Well, I'm going to investigate and we'll see :)

[nicklasb]

I once heard about a former customer that left the country and put up a sign "do not worry", on the door of their offices when their numbers one day failed to add up.

So I am not worried, this is the internet, after all. :-)

[nicklasb]

Oh, you meant about the goose chase. I'll redact the point but not the entertaining story. :-)

[Lawouach]

Here is my feeling.

ws4py always reads first two bytes in order to parse the frame header. From that header, it determines the payload lenght which is the next amount of data it will expect to read from the socket.

However, the next time the method once() is called is only when the udnerlying poller has received an event on that socket.

I believe that, in the case of a SSL wrapper, the event for the rest of the payload is never triggered. Well, not until an entirely new message is actually sent.

[nicklasb]

I would appear so. As I get the first bytes in my attempts. But would not that be a problem in the rest of CherryPy, some handling would be needed to work around that behaviour there as well?

[Lawouach]

I'm not sure. I'll need to test that further more.

[Lawouach]

This may help http://stackoverflow.com/a/12133807/1363905

[nicklasb]

Or this? That the first bytes look different? Perhaps it is the raw data, and it should skip some bytes, perhaps it mixes up the content type or version with the length? Or something to that effect?
https://en.wikipedia.org/wiki/Transport_Layer_Security#TLS_record

[decontamin4t0R]

My Environment: Python 3.4 on Ubuntu 14.04 LTS (or something like that) and client is generic JavaScript Websockets. Over SSL,because my Firewall only scans HTTP traffic and blocks it there. Also because its more secure.

[decontamin4t0R]

Ah, and something: The message gets delivered after some seconds, with a serious delay.

[EternityForest]

Just a thought, one of the first threads I found when looking for python SSL socket errors is this: http://stackoverflow.com/questions/3187565/select-and-ssl-in-python

They mention that reading some but not all the pending data from an SSL socket may cause the socket to internally read the rest and that makes future calls to select not notice there is further data.

And I did notice that there is a default read size of only 2.

EDIT: looks like Lawouach beat me to it by a month...

[vpaeder]

Hello everyone
As a temporary fix I patched my JS sockets this way:
var osend = socket.send;
socket.send = function(data) {
osend.call(this,data);
osend.call(this,"");
}
until something cleaner comes out (I'm not putting too much hope on myself for that!).

[Lawouach]

Well hopefully this will do it. Please, do test and report :)

Thanks to everyone for your patience.

[nicklasb]

Good stuff, I will check it out tomorrow!

[vpaeder]

nice, thanks!
this works fine.

[nicklasb]

@Lawouach :
Works fine here as well! Thanks a lot for the fix!

[Lawouach]

Cool. However, I hope this won't break other things in the meanwhile.

I'm not entirely happy with the "solution" but that's simplest I could agree on.

[nicklasb]

Actually, if one uses the workaround, it breaks stuff.
But it would be a weird bunch of users that would want to keep a workaround instead of a bug fix, hopefully there will be no complaints.
However, It could be worth mentioning this in the release and perhaps fix this in a minor instead of a patch version. It would appear to me that there has happened more than enough to motivate a 0.4.0 release since 0.3.4.

[Lawouach]

I agree regarding the release. In fact, I was waiting to fix that issue before a new release.

[EternityForest]

I tested the new commit and it works here under Linux Mint/Firefox/Python3. I couldn't find any problems by messing with it for a few minutes.

I'm not sure i understand how it works though. I thought ws.process could only handle reading_buffer_size at a time? Did something change or am I not getting how the parsing works?

[Lawouach]

With non-secured sockets, it works as usual, reading only reading_buffer_size at a time.

With secured sockets, even if I ask to read reading_buffer_size, the SSL object may decide to read more from the underlying socket. It keeps its own buffer. The issue is that, the poll loop will not trigger any read events and the buffer will not be made visible to the websocket interface. This is why you had to send an empty message before my fix. This would trigger the poller again and the websocket interface would finally read content from the SSL socket object (unaware it was reading its buffer actually).

What my fix does (based on that SO's article) is that I explicitly read the buffer at once. So, indeed we actually end up with more than reading_buffer_size in the bytes sent down to the parser.

This means, in effect, that the gradual reading from the socket mechanism the websocket interface uses, is no longer respected in the case of secure sockets (except for very large sockets that go beyond the size of a SSL frame).

Interestingly, this might mean that ws4py has better performances with SSL activated.