SSL connect/disconnect loop

[DantePR]

Hi,

I'm experiencing the following only thru ssl , http connections are fine. but when connecting thru ssl I get disconnected saying "WARNING:root:iot.myHost.io:3001/socket.io [connection error] recv disconnected by SSL (('The read operation timed out',))" for every time that I execute socketIO.wait(seconds=1). I have tried running my socket.io server as http and using nginx for the ssl and also running native node https server both have same results. It would be great help any feedback.

BTW SSL works fine for everything else, certificate seems to be good. as I can curl and see correct response.

Im running socketIO-client on python 2.7.9 but it does same on 2.7.3 on raspbian.

socket.io server debug

This is log form socket.io, this is repeated for every socketIO.wait :
App connected
socket.io:socket joining room cloud +1ms
socket.io:socket joined room mGZgzNZ6gsAqycLoAAAF +0ms
socket.io:socket joined room cloud +0ms
engine upgrading existing transport +754ms
engine:socket might upgrade socket transport from "polling" to "websocket" +0ms
engine:ws received "2probe" +89ms
engine:ws writing "3probe" +0ms
engine:ws received "5" +100ms
engine:socket got upgrade packet - upgrading +0ms
engine:socket flushing buffer to transport +0ms
engine:ws writing "40" +0ms
engine:ws received "2" +1ms
engine:socket packet +0ms
engine:socket got ping +0ms
engine:socket sending packet "pong" (undefined) +0ms
engine:socket flushing buffer to transport +1ms
engine:ws writing "3" +0ms
socket.io:client client close with reason transport close +6s
socket.io:socket closing socket - reason transport close +1ms
socket.io:client ignoring remove for 0SV7_KSjY9OAc79rAAAE +0ms
Cloud App Dissconnected
socket.io:client client close with reason transport close +48ms
socket.io:socket closing socket - reason transport close +1ms
socket.io:client ignoring remove for mGZgzNZ6gsAqycLoAAAF +0ms

Socket.IO server :

var fs = require('fs');
var options = {
key: fs.readFileSync('/opt/certs/iot.myhost.io.key'),
cert: fs.readFileSync('/opt/certs/iot.myhost.io.chained.crt')
};
var app = require('https').createServer(options,handler)
var io = require('socket.io')(app);
app.listen(3001);

Python raspbian client

socketIO = SocketIO('https://iot.myhost.io,3001, params={"myID":'898989898',"type":"CLIENT"})
socketIO.on('on_test', on_test_response)
socketIO.wait(seconds=1)

Thanks,
Ray

[DantePR]

Hi I have traced back this issue to line #224 on init.py . While setting this timeout don't seem to cause issues the http , using https this would cause socket to be dropped. I'm not sure why is this line here as code is already unblocking recv on _reset_heartbeat.

Regards,
Ray

[invisibleroads]

@DantePR, I just tested your code on [email protected] with socketIO-client>=0.6.5 and it seems to work fine now (see #54).

# Generate server certificate
openssl req -new -newkey rsa:4096 -days 365 -nodes -x509 \
    -subj "/C=US/ST=New York/L=New York/O=CrossCompute/CN=localhost" \
    -keyout server.key -out server.crt
# Generate client certificate
openssl req -new -newkey rsa:4096 -days 365 -nodes -x509 \
    -subj "/C=US/ST=New York/L=New York/O=CrossCompute/CN=localhost" \
    -keyout client.key -out client.crt

var fs = require('fs');
var options = {
  key: fs.readFileSync('server.key'),
  cert: fs.readFileSync('server.crt')};
var app = require('https').createServer(options);
var io = require('socket.io')(app);
io.on('connection', function(socket) {
  socket.emit('on_test', {'x': 1});
});
app.listen(3000);

from socketIO_client import SocketIO

def on_test_response(*args):
    print('on_test_response', args)

socketIO = SocketIO(
    'https://localhost', 3000,
    verify='server.crt',
    cert=('client.crt', 'client.key'))
socketIO.on('on_test', on_test_response)
socketIO.wait(seconds=1)

You might want to see if pip install -U requests solves your issue.

[parmentelat]

I am experiencing something that may be similar:

2018-03-18 16:01:11,708 - socketIO-client - WARNING - r2lab.inria.fr:999/socket.io [connection error] recv disconnected by SSL ([SSL: SSLV3_ALERT_BAD_RECORD_MAC] sslv3 alert bad record mac (_ssl.c:2217))

This happens only with https as far as I can tell, and not all the time.
My use case is to open a connection, send one message, wait for one answer, and disconnect.
When I do this repeatedly, I end up with a failure after, it depends, something like 10 or 20 times, sometimes even sooner

My first question would be no know if that's the same issue or not, the error message being similar but not identical (sslv3 alert bad record mac)

Any other angle/tip/comment on this issue would be of tremendous help

Thanks in advance

---

PS.

I run on macOS 10.12.6

As far as other libs are concerned:

$ pip3 freeze | egrep 'requests|websocket-client'
requests==2.18.4
websocket-client==0.47.0

Also I am using the code from the tip at github, where I had to redirect get_log to logging.getLogger

tparment ~/git/socketIO-client (master *=) $ git log --oneline -5
1e58add (HEAD -> master, origin/master, origin/HEAD) Replace localhost with explicit 127.0.0.1
9a78f52 Move missions to https://crosscompute.com
82756be Use get_log
9e9e66c Bump version
3ae9cb5 Revise comments #133

---

Here's the complete log from the client side

python3 -m unittest tests.test_sidecar
/usr/local/lib/python3.6/site-packages/urllib3/connectionpool.py:858: InsecureRequestWarning: Unverified HTTPS request is being made. Adding certificate verification is strongly advised. See: https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings
  InsecureRequestWarning)
2018-03-18 16:01:11,656 - socketIO-client - DEBUG - r2lab.inria.fr:999/socket.io [socket.io packet sent] 2["request:nodes", "PLEASE"]
2018-03-18 16:01:11,707 - socketIO-client - DEBUG - r2lab.inria.fr:999/socket.io [engine.io message] b'0'
2018-03-18 16:01:11,708 - socketIO-client - DEBUG - r2lab.inria.fr:999/socket.io [socket.io packet received] b'0'
2018-03-18 16:01:11,708 - socketIO-client - DEBUG - r2lab.inria.fr:999/socket.io [socket.io connect]
2018-03-18 16:01:11,708 - socketIO-client - DEBUG - r2lab.inria.fr:999/socket.io [socket.io connected]
2018-03-18 16:01:11,708 - socketIO-client - WARNING - r2lab.inria.fr:999/socket.io [connection error] recv disconnected by SSL ([SSL: SSLV3_ALERT_BAD_RECORD_MAC] sslv3 alert bad record mac (_ssl.c:2217))
2018-03-18 16:01:12,710 - socketIO-client - WARNING - r2lab.inria.fr:999/socket.io [connection error] recv disconnected by SSL ([SSL: SSLV3_ALERT_BAD_RECORD_MAC] sslv3 alert bad record mac (_ssl.c:2217))
2018-03-18 16:01:12,710 - socketIO-client - DEBUG - r2lab.inria.fr:999/socket.io [socket.io disconnect]
2018-03-18 16:01:13,055 - socketIO-client - DEBUG - r2lab.inria.fr:999/socket.io [engine.io transport selected] websocket
2018-03-18 16:01:13,056 - socketIO-client - DEBUG - r2lab.inria.fr:999/socket.io [engine.io heartbeat reset]
2018-03-18 16:01:13,056 - socketIO-client - DEBUG - r2lab.inria.fr:999/socket.io [socket.io disconnect]
E