Server does not send enough data per packet
Closed this issue · 10 comments
lovetox commented
testable on wormhole.chat
There seems to be a bug in the way the server sends stanzas, often it sends only small parts of a stanza
<
_____________
16.03.2019 15:01:44 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout removed for fd 700
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 55 seconds
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 120 seconds with function <bound method NonBlockingTransport.read_timeout2 of <nbxmpp.transports.NonBlockingTCP object at 0x0000000009569390>>
16.03.2019 15:01:44 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
iq
_____________
16.03.2019 15:01:44 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout removed for fd 700
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 55 seconds
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 120 seconds with function <bound method NonBlockingTransport.read_timeout2 of <nbxmpp.transports.NonBlockingTCP object at 0x0000000009569390>>
16.03.2019 15:01:44 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
_____________
16.03.2019 15:01:44 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout removed for fd 700
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 55 seconds
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 120 seconds with function <bound method NonBlockingTransport.read_timeout2 of <nbxmpp.transports.NonBlockingTCP object at 0x0000000009569390>>
16.03.2019 15:01:44 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
type
_____________
16.03.2019 15:01:44 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout removed for fd 700
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 55 seconds
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 120 seconds with function <bound method NonBlockingTransport.read_timeout2 of <nbxmpp.transports.NonBlockingTCP object at 0x0000000009569390>>
16.03.2019 15:01:44 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
="
_____________
16.03.2019 15:01:44 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout removed for fd 700
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 55 seconds
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 120 seconds with function <bound method NonBlockingTransport.read_timeout2 of <nbxmpp.transports.NonBlockingTCP object at 0x0000000009569390>>
16.03.2019 15:01:44 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
result
_____________
16.03.2019 15:01:44 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout removed for fd 700
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 55 seconds
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 120 seconds with function <bound method NonBlockingTransport.read_timeout2 of <nbxmpp.transports.NonBlockingTCP object at 0x0000000009569390>>
16.03.2019 15:01:44 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
"
_____________
16.03.2019 15:01:44 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout removed for fd 700
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 55 seconds
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 120 seconds with function <bound method NonBlockingTransport.read_timeout2 of <nbxmpp.transports.NonBlockingTCP object at 0x0000000009569390>>
16.03.2019 15:01:44 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
_____________
16.03.2019 15:01:44 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout removed for fd 700
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 55 seconds
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 120 seconds with function <bound method NonBlockingTransport.read_timeout2 of <nbxmpp.transports.NonBlockingTCP object at 0x0000000009569390>>
16.03.2019 15:01:44 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
id
_____________
16.03.2019 15:01:44 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout removed for fd 700
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 55 seconds
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 120 seconds with function <bound method NonBlockingTransport.read_timeout2 of <nbxmpp.transports.NonBlockingTCP object at 0x0000000009569390>>
16.03.2019 15:01:44 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
="
_____________
16.03.2019 15:01:44 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout removed for fd 700
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 55 seconds
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 120 seconds with function <bound method NonBlockingTransport.read_timeout2 of <nbxmpp.transports.NonBlockingTCP object at 0x0000000009569390>>
16.03.2019 15:01:44 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
72bfa1e8-7cfe-45ae-a9d8-bc25a6fd551b
_____________
16.03.2019 15:01:44 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout removed for fd 700
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 55 seconds
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 120 seconds with function <bound method NonBlockingTransport.read_timeout2 of <nbxmpp.transports.NonBlockingTCP object at 0x0000000009569390>>
16.03.2019 15:01:44 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
"
_____________
16.03.2019 15:01:44 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout removed for fd 700
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 55 seconds
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 120 seconds with function <bound method NonBlockingTransport.read_timeout2 of <nbxmpp.transports.NonBlockingTCP object at 0x0000000009569390>>
16.03.2019 15:01:44 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
_____________
16.03.2019 15:01:44 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout removed for fd 700
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 55 seconds
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 120 seconds with function <bound method NonBlockingTransport.read_timeout2 of <nbxmpp.transports.NonBlockingTCP object at 0x0000000009569390>>
16.03.2019 15:01:44 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
from
_____________
16.03.2019 15:01:44 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout removed for fd 700
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 55 seconds
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 120 seconds with function <bound method NonBlockingTransport.read_timeout2 of <nbxmpp.transports.NonBlockingTCP object at 0x0000000009569390>>
16.03.2019 15:01:44 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
="
_____________
16.03.2019 15:01:44 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout removed for fd 700
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 55 seconds
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 120 seconds with function <bound method NonBlockingTransport.read_timeout2 of <nbxmpp.transports.NonBlockingTCP object at 0x0000000009569390>>
16.03.2019 15:01:44 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
lovetox@wormhole.chat
_____________
16.03.2019 15:01:44 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout removed for fd 700
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 55 seconds
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 120 seconds with function <bound method NonBlockingTransport.read_timeout2 of <nbxmpp.transports.NonBlockingTCP object at 0x0000000009569390>>
16.03.2019 15:01:44 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
"
_____________
16.03.2019 15:01:44 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout removed for fd 700
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 55 seconds
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 120 seconds with function <bound method NonBlockingTransport.read_timeout2 of <nbxmpp.transports.NonBlockingTCP object at 0x0000000009569390>>
16.03.2019 15:01:44 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
_____________
16.03.2019 15:01:44 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout removed for fd 700
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 55 seconds
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 120 seconds with function <bound method NonBlockingTransport.read_timeout2 of <nbxmpp.transports.NonBlockingTCP object at 0x0000000009569390>>
16.03.2019 15:01:44 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
to
_____________
16.03.2019 15:01:44 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout removed for fd 700
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 55 seconds
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 120 seconds with function <bound method NonBlockingTransport.read_timeout2 of <nbxmpp.transports.NonBlockingTCP object at 0x0000000009569390>>
16.03.2019 15:01:44 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
="
_____________
16.03.2019 15:01:44 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout removed for fd 700
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 55 seconds
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 120 seconds with function <bound method NonBlockingTransport.read_timeout2 of <nbxmpp.transports.NonBlockingTCP object at 0x0000000009569390>>
16.03.2019 15:01:44 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
lovetox@wormhole.chat/gajim.4JHK9BLI
_____________
16.03.2019 15:01:44 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout removed for fd 700
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 55 seconds
16.03.2019 15:01:44 (I) nbxmpp.idlequeue | read timeout set for fd 700 on 120 seconds with function <bound method NonBlockingTransport.read_timeout2 of <nbxmpp.transports.NonBlockingTCP object at 0x0000000009569390>>
16.03.2019 15:01:44 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
"
_____________
ortuman commented
Please, could you add more context? Don´t know exactly how to reproduce this.
Besides, looks like it could also be some bug on client side
lovetox commented
Im not sure what i context i could provide
the server is able to put more data into the buffer as you can see on the first stanza
but after that he just puts not enough data into it anymore
im not sure how this is even possible it almost looks like some parser puts stuff into the buffer as he parses it, element after element
16.03.2019 20:39:33 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
<?xml version="1.0"?><stream:stream xmlns="jabber:client" xmlns:stream="http://etherx.jabber.org/streams" id="95f52c14-8e87-4fd0-8104-639aaeac246e" from="wormhole.chat" version="1.0"><stream:features xmlns:stream="http://etherx.jabber.org/streams" version="1.0"><mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"><mech
anism>PLAIN</mechanism><mechanism>DIGEST-MD5</mechanism><mechanism>SCRAM-SHA-1</mechanism><mechanism>SCRAM-SHA-1-PLUS</mechanism><mechanism>SCRAM-SHA-256</mechanism><mechanism>SCRAM-SHA-256-PLUS</mechanism><mechanism>SCRAM-SHA-512</mechanism><mechanism>SCRAM-SHA-512-PLUS</mechanism></mechanisms><register xmlns="http://
jabber.org/features/iq-register"/></stream:features>
_____________
16.03.2019 20:39:43 (I) nbxmpp.transports | Plugging fd 1128, W:True, R:True
16.03.2019 20:39:43 (I) nbxmpp.transports | pollout called, state == CONNECTED
16.03.2019 20:39:43 (I) nbxmpp.transports | Plugging fd 1128, W:False, R:True
16.03.2019 20:39:43 (I) nbxmpp.client | raising event from transport: :::::DATA SENT::::
_____________
<auth xmlns="urn:ietf:params:xml:ns:xmpp-sasl" mechanism="SCRAM-SHA-256-PLUS">cD10bHMtdW5pcXVlLCxuPWxvdmV0b3gscj0zNmE1YWY0MzAxODFjZWFhMGU4NTdkOGViYTViZmFlYjAyYTczODc4ZjM5Mjk4MjI=</auth>
_____________
16.03.2019 20:39:43 (D) gajim.c.ged | Raise event: stanza-sent
16.03.2019 20:39:43 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 20:39:43 (I) nbxmpp.idlequeue | read timeout removed for fd 1128
16.03.2019 20:39:43 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
<
_____________
16.03.2019 20:39:43 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 20:39:43 (I) nbxmpp.idlequeue | read timeout removed for fd 1128
16.03.2019 20:39:43 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
challenge
_____________
16.03.2019 20:39:43 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 20:39:43 (I) nbxmpp.idlequeue | read timeout removed for fd 1128
16.03.2019 20:39:43 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
_____________
16.03.2019 20:39:43 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 20:39:43 (I) nbxmpp.idlequeue | read timeout removed for fd 1128
16.03.2019 20:39:43 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
xmlns
_____________
16.03.2019 20:39:43 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 20:39:43 (I) nbxmpp.idlequeue | read timeout removed for fd 1128
16.03.2019 20:39:43 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
="
_____________
16.03.2019 20:39:43 (I) nbxmpp.transports | pollin called, state == CONNECTED
16.03.2019 20:39:43 (I) nbxmpp.idlequeue | read timeout removed for fd 1128
16.03.2019 20:39:43 (I) nbxmpp.client | raising event from transport: :::::DATA RECEIVED::::
_____________
urn:ietf:params:xml:ns:xmpp-sasl
_____________
ortuman commented
what kind of transport are you using? socket? websocket?
lovetox commented
no special transport, standard socket
ortuman commented
🤔 I see.
I think I can figure out where the problem is. I'll tackle the issue and make know as soon as the patch is ready.
lovetox commented
hm yes can you offer an account on a patched server?
i am a client dev i just observed this problem, its not my server
ortuman commented
Try registering an account on jackal.im
lovetox commented
yes works fine on that server, though we never know now if that bug was on that server in the first place.
but i guess you wouldnt push changes if you didnt think you found something
thanks
ortuman commented
You were right from the begining, data was being sent while perfoming serialization.
Current approach uses an intermediate buffer instead.
Thanks to you for reporting! 🙌 😃