连接升级期间间歇性长时间延迟

摘要

我们正在使用socket.io JS客户端从运行python-socketio的后端接收常规服务状态更新。大多数情况下，它运行良好，但我们间歇性地看到一种情况，即连接升级过程中约有30秒的延迟，在此期间未收到任何消息。最终，连接被关闭（尽管该过程看起来有些混乱）并发生了重新连接，此后，一切再次正常。我试图弄清楚为什么会出现这种延迟。

我们可以通过单元测试相当轻松地重现此内容，该单元测试可以反复导航到相关页面并再次离开，从而强制重新创建套接字并每次都重新建立连接。经过几次迭代，我们可靠地遇到了这个问题。

我正在使用socket.io v2.3.0（尽管在2.2.0中也是如此）。

代码

客户代码的简化版本：

function admin_vm() {
const self = this;
self.socket = io.connect({
path: window.config.project_url + 'status/system/socket.io'
});
self.socket.on('connect',function() {
console.log('Socket connected,joining admin room');
self.socket.emit('join','admin');
});
self.socket.on('update',function (update) {
update = JSON.parse(update);
const u = update;
console.log(
'Update for system status left server [' + u.timestamp +
'] arrived here [' + new Date().toString() + '] update count [' + update_count++ + ']'
);
// Apply the update to the UI here...
});
}


日志

登录socket.io调试后，我们看到以下内容：

12:58:46.117 admin.js 113:12 "admin.js document ready - creating vm"
12:58:46.117 admin.js 32:12 "Creating admin socket"
12:58:46.119 socket.io.js 391:131 "socket.io-client:url parse %s +0ms" "https://..."
12:58:46.121 socket.io.js 391:131 "socket.io-client new io instance for %s +0ms" "https://..."
12:58:46.122 socket.io.js 391:131 "socket.io-client:manager readyState %s +0ms" "closed"
12:58:46.123 socket.io.js 391:131 "socket.io-client:manager opening %s +1ms" "https://..."
12:58:46.124 socket.io.js 391:131 "engine.io-client:socket creating transport \"%s\" +0ms" "polling"
12:58:46.125 socket.io.js 391:131 "engine.io-client:polling polling +0ms"
12:58:46.126 socket.io.js 391:131 "engine.io-client:polling-xhr xhr poll +0ms"
12:58:46.127 socket.io.js 391:131 "engine.io-client:polling-xhr xhr open %s: %s +1ms" "GET" "https://.../.../socket.io/?EIO=3&transport=polling&t=MxglP_k"
12:58:46.128 socket.io.js 391:131 "engine.io-client:polling-xhr xhr data %s +2ms" null
12:58:46.131 socket.io.js 391:131 "engine.io-client:socket setting transport %s +7ms" "polling"
12:58:46.132 socket.io.js 391:131 "socket.io-client:manager connect attempt will timeout after %d +9ms" 20000
12:58:46.133 socket.io.js 391:131 "socket.io-client:manager readyState %s +2ms" "opening"
12:58:46.164 socket.io.js 391:131 "engine.io-client:polling polling got data %s +39ms" ArrayBuffer(119)
12:58:46.166 socket.io.js 391:131 "engine.io-client:socket socket receive: type \"%s\",data \"%s\" +34ms" "open" "{\"sid\":\"6294b24868144273b4a9bceaf0e439f9\",\"upgrades\":[\"websocket\"],\"pingTimeout\":60000,\"pingInterval\":25000}"
12:58:46.167 socket.io.js 391:131 "engine.io-client:socket socket open +2ms"
12:58:46.168 socket.io.js 391:131 "socket.io-client:manager open +34ms"
12:58:46.169 socket.io.js 391:131 "socket.io-client:manager cleanup +1ms"
12:58:46.170 socket.io.js 391:131 "socket.io-client:socket transport is open - connecting +0ms"
12:58:46.171 socket.io.js 391:131 "engine.io-client:socket starting upgrade probes +4ms"
12:58:46.172 socket.io.js 391:131 "engine.io-client:socket probing transport \"%s\" +1ms" "websocket"
12:58:46.173 socket.io.js 391:131 "engine.io-client:socket creating transport \"%s\" +1ms" "websocket"
12:58:46.177 socket.io.js 391:131 "engine.io-client:socket socket receive: type \"%s\",data \"%s\" +4ms" "message" "0"
12:58:46.178 admin.js 46:16 "Socket connected,joining admin room"
12:58:46.179 socket.io.js 391:131 "socket.io-client:manager writing packet {\"type\":2,\"data\":[\"join\",\"admin\"],\"options\":{\"compress\":true},\"nsp\":\"/\"} +9ms"
12:58:46.180 socket.io.js 1646:132 "socket.io-parser encoding packet {\"type\":2,\"nsp\":\"/\"} +0ms"
12:58:46.181 socket.io.js 1646:132 "socket.io-parser encoded {\"type\":2,\"nsp\":\"/\"} as %s +0ms" "2[\"join\",\"admin\"]"
12:58:46.181 socket.io.js 391:131 "engine.io-client:socket flushing %d packets in socket +3ms" 1
12:58:46.182 socket.io.js 391:131 "engine.io-client:polling-xhr xhr open %s: %s +52ms" "POST" "https://.../.../socket.io/?EIO=3&transport=polling&t=MxglQ0a&sid=6294b24868144273b4a9bceaf0e439f9"
12:58:46.183 socket.io.js 391:131 "engine.io-client:polling-xhr xhr data %s +1ms" "18:42[\"join\",\"admin\"]"
12:58:46.183 socket.io.js 391:131 "engine.io-client:polling polling +19ms"
12:58:46.183 socket.io.js 391:131 "engine.io-client:polling-xhr xhr poll +1ms"
12:58:46.184 socket.io.js 391:131 "engine.io-client:polling-xhr xhr open %s: %s +0ms" "GET" "https://.../.../socket.io/?EIO=3&transport=polling&t=MxglQ0c&sid=6294b24868144273b4a9bceaf0e439f9"
12:58:46.184 socket.io.js 391:131 "engine.io-client:polling-xhr xhr data %s +1ms" null
12:58:46.193 socket.io.js 391:131 "engine.io-client:socket probe transport \"%s\" opened +13ms" "websocket"
12:58:46.211 socket.io.js 391:131 "engine.io-client:polling polling got data %s +28ms" ArrayBuffer(4)
12:58:46.212 socket.io.js 391:131 "engine.io-client:socket socket receive: type \"%s\",data \"%s\" +19ms" "noop" undefined
12:58:46.212 socket.io.js 391:131 "engine.io-client:polling polling +1ms"
12:58:46.213 socket.io.js 391:131 "engine.io-client:polling-xhr xhr poll +29ms"
12:58:46.213 socket.io.js 391:131 "engine.io-client:polling-xhr xhr open %s: %s +0ms" "GET" "https://.../.../socket.io/?EIO=3&transport=polling&t=MxglQ14&sid=6294b24868144273b4a9bceaf0e439f9"
12:58:46.214 socket.io.js 391:131 "engine.io-client:polling-xhr xhr data %s +1ms" null
12:58:46.220 socket.io.js 391:131 "engine.io-client:socket probe transport \"%s\" pong +7ms" "websocket"
12:58:46.220 socket.io.js 391:131 "engine.io-client:socket pausing current transport \"%s\" +1ms" "polling"
12:58:46.220 socket.io.js 391:131 "engine.io-client:polling we are currently polling - waiting to pause +8ms"
12:59:11.356 socket.io.js 391:131 "engine.io-client:socket writing ping packet - expecting pong within %sms +25s" 60000
12:59:17.224 socket.io.js 391:131 "engine.io-client:polling polling got data %s +31s" ArrayBuffer(0)
12:59:17.224 socket.io.js 391:131 "engine.io-client:polling pre-pause polling complete +2ms"
12:59:17.224 socket.io.js 391:131 "engine.io-client:polling paused +1ms"
12:59:17.224 socket.io.js 391:131 "engine.io-client:socket changing transport and sending upgrade packet +6s"
12:59:17.224 socket.io.js 391:131 "engine.io-client:socket setting transport %s +1ms" "websocket"
12:59:17.224 socket.io.js 391:131 "engine.io-client:socket clearing existing transport %s +0ms" "polling"
12:59:17.224 socket.io.js 391:131 "engine.io-client:polling ignoring poll - transport state \"%s\" +4ms" "paused"
12:59:17.224 socket.io.js 391:131 "engine.io-client:socket flushing %d packets in socket +3ms" 1
12:59:17.225 admin.js 79:16 "Update for system status left server [December 9th 2019,12:58:46 pm] arrived here [December 9th 2019,12:59:17 pm] update count [0]"
12:59:17.225 admin.js 97:20 "First update received"


完整日志（包括正常运行时的日志）是我在python-socketio：https://github.com/miguelgrinberg/python-socketio/issues/393

当它在12:58:46说we are currently polling - waiting to pause时（即30秒延迟开始的地方），会发生什么情况？还等什么呢？

我目前发现的唯一解决方法是直接使用websocket传输，而不是从轮询和升级开始。一旦我这样做，它就可以正常工作，但是显然，这意味着它不能在任何不支持websocket的地方使用。