Server-side exception with test 12.2.1

[csaavedra]

This test happens to fail for the client I am testing it with (libsoup), but in the server-side I see this exception which I now wonder is expected at all. This is with the autobahn/latest Docker image. Reporting in case it's useful:

Running test case ID 12.2.1 for agent libsoup from peer tcp4:172.17.0.1:39250
Unhandled Error
Traceback (most recent call last):
  File "/usr/local/site-packages/twisted/python/log.py", line 103, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/usr/local/site-packages/twisted/python/log.py", line 86, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/usr/local/site-packages/twisted/python/context.py", line 122, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/usr/local/site-packages/twisted/python/context.py", line 85, in callWithContext
    return func(*args,**kw)
--- <exception caught here> ---
  File "/usr/local/site-packages/twisted/internet/posixbase.py", line 614, in _doReadOrWrite
    why = selectable.doRead()
  File "/usr/local/site-packages/twisted/internet/tcp.py", line 205, in doRead
    return self._dataReceived(data)
  File "/usr/local/site-packages/twisted/internet/tcp.py", line 211, in _dataReceived
    rval = self.protocol.dataReceived(data)
  File "/usr/local/site-packages/autobahn/twisted/websocket.py", line 135, in dataReceived
    self._dataReceived(data)
  File "/usr/local/site-packages/autobahn/websocket/protocol.py", line 1315, in _dataReceived
    self.consumeData()
  File "/usr/local/site-packages/autobahn/websocket/protocol.py", line 1330, in consumeData
    while self.processData() and self.state != WebSocketProtocol.STATE_CLOSED:
  File "/usr/local/site-packages/autobahn/websocket/protocol.py", line 1482, in processData
    return self.processDataHybi()
  File "/usr/local/site-packages/autobahn/websocket/protocol.py", line 1785, in processDataHybi
    fr = self.onFrameData(payload)
  File "/usr/local/site-packages/autobahn/websocket/protocol.py", line 1861, in onFrameData
    payload = self._perMessageCompress.decompressMessageData(payload)
  File "/usr/local/site-packages/autobahn/websocket/compress_deflate.py", line 614, in decompressMessageData
    return self._decompressor.decompress(data)
zlib.error: Error -3 while decompressing data: invalid distance too far back

The .json output for the test:

{
   "agent": "libsoup",
   "behavior": "FAILED",
   "behaviorClose": "FAILED",
   "case": 322,
   "closedByMe": false,
   "createStats": true,
   "createWirelog": false,
   "description": "Send 1000 compressed messages each of payload size 16, auto-fragment to 0 octets. Use default permessage-deflate offer.",
   "droppedByMe": false,
   "duration": 13,
   "expectation": "Receive echo'ed messages (with payload as sent). Timeout case after 60 secs.",
   "expected": {},
   "expectedClose": {
      "closeCode": [
         1000
      ],
      "closedByMe": true,
      "requireClean": true
   },
   "failedByMe": false,
   "httpRequest": "GET /runCase?case=322&agent=libsoup HTTP/1.1\r\nHost: localhost:9001\r\nUpgrade: websocket\r\nConnection: Upgrade\r\nSec-WebSocket-Key: GAXltkVlpWGVlg0PrwwSWA==\r\nSec-WebSocket-Version: 13\r\nSec-WebSocket-Extensions: permessage-deflate; client_max_window_bits\r\nAccept-Encoding: gzip, deflate\r\n\r\n",
   "httpResponse": "HTTP/1.1 101 Switching Protocols\r\nServer: AutobahnTestSuite/0.8.0-0.10.9\r\nX-Powered-By: AutobahnPython/0.10.9\r\nUpgrade: WebSocket\r\nConnection: Upgrade\r\nSec-WebSocket-Accept: Pxbewbqc7YR4235lmpvBfl6RzBU=\r\nSec-WebSocket-Extensions: permessage-deflate\r\n\r\n",
   "id": "12.2.1",
   "isServer": true,
   "localCloseCode": null,
   "localCloseReason": null,
   "received": [],
   "remoteCloseCode": null,
   "remoteCloseReason": null,
   "reportCompressionRatio": true,
   "reportTime": true,
   "result": "Case did not finish within 60 seconds.",
   "resultClose": "The connection was failed by the wrong endpoint",
   "rxFrameStats": {
      "2": 70
   },
   "rxOctetStats": {
      "14": 1,
      "15": 1,
      "17": 1,
      "20": 1,
      "23": 1,
      "24": 35,
      "30": 3,
      "31": 27,
      "33": 1,
      "285": 1
   },
   "started": "2019-08-26T13:49:00.566Z",
   "trafficStats": null,
   "txFrameStats": {
      "2": 71
   },
   "txOctetStats": {
      "10": 1,
      "11": 1,
      "13": 1,
      "16": 1,
      "19": 1,
      "20": 35,
      "21": 3,
      "22": 27,
      "24": 1,
      "252": 1
   },
   "wasClean": false,
   "wasCloseHandshakeTimeout": false,
   "wasNotCleanReason": "peer dropped the TCP connection without previous WebSocket closing handshake",
   "wasOpenHandshakeTimeout": false,
   "wasServerConnectionDropTimeout": false,
   "wirelog": [
      [
         "RO",
         [
            285,
            "474554202f72756e436173653f636173653d333232266167656e743d6c6962736f757020485454502f312e310d0a486f73743a206c6f63616c686f73743a3930 ..."
         ]
      ],
      [
         "TO",
         [
            252,
            "485454502f312e312031303120537769746368696e672050726f746f636f6c730d0a5365727665723a204175746f6261686e5465737453756974652f302e382e ..."
         ],
         false
      ],
      [
         "WLM",
         false
      ],
      [
         "TI",
         60
      ]
   ]
}

[bsergean]

Hi there, I'm trying to test the conformance of the client I wrote IXWebSocket because the server my client is hitting (python websockets) is giving me a very similar zlib error (invalid distance too far back).

https://github.com/aaugustin/websockets/issues/665

For what it's worth here is how my client behave when I try to hit the 'case 322' == your failing case.

$ ws connect -d 'ws://localhost:9001/runCase?case=322&agent=ixwebsocket'
Type Ctrl-D to exit prompt...
Connecting to url: ws://localhost:9001/runCase?case=322&agent=ixwebsocket
> ws_connect: connected
Uri: /runCase?case=322&agent=ixwebsocket
Handshake Headers:
Connection: Upgrade
Sec-WebSocket-Accept: KqiDNPfJQWMT5QBWf40ax2A1teY=
Sec-WebSocket-Extensions: permessage-deflate; server_max_window_bits=15
Server: AutobahnTestSuite/0.8.0-0.10.9
Upgrade: WebSocket
X-Powered-By: AutobahnPython/0.10.9
Received 18 bytes
ws_connect: received message: %PDF-1.2
%?쏢
6

It looks like the client should hit a 'url', receive a message, and when the connection is closed (by the server ?), try to hit the 'next url' ?

[bsergean]

Actually I figured out how to work with autobahn (generate url with test-case id inside them, and have a client just echo the message sent by the server until it is disconnected, and then move on to the next test case).

[csaavedra]

I found out this to be an actual corruption on the client-side code, fixing the corruption made the test pass and this exception is gone. I suppose that the exception was just zlib or similar having trouble to deflate the corrupted data. Feel free to close if you agree with this.