【node.js】 ソケットのIDが意図せず変わってしまう件（解決？編） 【socket.io】

前回の記事では、socket.ioのソケットIDが頻繁に変わってしまう問題について調査しました。

その結果、何かしらの原因で接続が切断されているため、
その都度新しい接続扱いになりIDが変わってしまっているということがわかりました。

この問題は、テキストチャットのような比較的通信量の少ない（小さい）スクリプトでは発生しておらず、
頻繁に画像データをサーバに送信する通信量の多い（大きい）スクリプトでのみ発生しています。

今回はもう少し掘り下げて、なぜ接続が切断してしまうのかを調べてみたいと思います。
調査に使ったサンプルコードは、前回の記事を参照ください。

引き続き、調査

DEBUGモード

調査を進めるにあたり、もう少し詳細なログを見たいですね。

環境変数DEBUGに特定の値をセットした状態でnodeを起動するとdebugログを見ることができるそうです。
“*” をセットすればすべてのdebugログが出力されるとのことなので、
早速下記のコマンドを実行し、前回同様Google Chromeのタブを2つ開き、アクセスをしてみました。

実行コマンド

$ DEBUG=* node app.js > test.log 2>&1

ログを十分に溜めるため5分ほど放置した後でnodeのプロセスを終了し、test.logを開いてみます。
切断前後のログを探してみると、ありましたありました。何やらerrorという文字。
‘transport error’が発生したことによって、socketがcloseされているようです。

test.log

Mon, 07 Dec 2015 03:27:18 GMT engine:socket transport error
Mon, 07 Dec 2015 03:27:18 GMT socket.io:client client close with reason transport error
Mon, 07 Dec 2015 03:27:18 GMT socket.io:socket closing socket - reason transport error
Mon, 07 Dec 2015 03:27:18 GMT socket.io:client ignoring remove for 5rNqdjhf6tfhO7bQAAAA
Mon, 07 Dec 2015 03:27:18 GMT socket.io:socket closing socket - reason transport error
Mon, 07 Dec 2015 03:27:18 GMT socket.io:client ignoring remove for 5rNqdjhf6tfhO7bQAAAA
[disconnected] 5rNqdjhf6tfhO7bQAAAA

‘transport error’ について調べてみる

この’transport error’はどういうときに発生するのでしょうか。
node_module(npmでインストールしたモジュール群)の中をgrep(検索)してみます。

grepの結果

$ grep -nHr 'transport error' ./node_modules/
./node_modules/socket.io/History.md:308:  * Fixes manager.js failure to close connection after transport error has happened
./node_modules/socket.io/node_modules/engine.io/lib/socket.js:109: * Called upon transport error.
./node_modules/socket.io/node_modules/engine.io/lib/socket.js:116:  debug('transport error');
./node_modules/socket.io/node_modules/engine.io/lib/socket.js:117:  this.onClose('transport error', err);
./node_modules/socket.io/node_modules/engine.io/lib/socket.js:219:  // silence further transport errors and prevent uncaught exceptions
./node_modules/socket.io/node_modules/engine.io/lib/socket.js:229: * `transport error`, `server close`, `transport close`
./node_modules/socket.io/node_modules/engine.io/lib/transport.js:65: * Called with a transport error.
./node_modules/socket.io/node_modules/engine.io/lib/transport.js:79:    debug('ignored transport error %s (%s)', msg, desc);
./node_modules/socket.io/node_modules/socket.io-client/node_modules/engine.io-client/engine.io.js:654: * Called upon transport error
./node_modules/socket.io/node_modules/socket.io-client/node_modules/engine.io-client/engine.io.js:663:  this.onClose('transport error', err);
./node_modules/socket.io/node_modules/socket.io-client/node_modules/engine.io-client/History.md:386:  * socket: handle probe's transport errors [indutny]
./node_modules/socket.io/node_modules/socket.io-client/node_modules/engine.io-client/README.md:192:        try websocket. A connection attempt following a transport error will use the
./node_modules/socket.io/node_modules/socket.io-client/node_modules/engine.io-client/lib/socket.js:636: * Called upon transport error
./node_modules/socket.io/node_modules/socket.io-client/node_modules/engine.io-client/lib/socket.js:645:  this.onClose('transport error', err);
./node_modules/socket.io/node_modules/socket.io-client/socket.io.js:2159: * Called upon transport error
./node_modules/socket.io/node_modules/socket.io-client/socket.io.js:2168:  this.onClose('transport error', err);

クライアント、サーバ側両方のコードに’transport error’の文字列を発見することができました。
これまでの経緯により、なにやら「サーバによって通信が切断されている」ように思いますので、
サーバ側のコードを重点的に調べてみることにします。

./node_modules/socket.io/node_modules/engine.io/lib/socket.js

115 Socket.prototype.onError = function (err) {
116   debug('transport error');
117   this.onClose('transport error', err);
118 };

具体的に’transport error’をログ出力している部分は上記のようです。
この、onErrorメソッドの引数 ‘err’の中身がわかればもう少し詳細な理由がわかるかもしれません。
‘Socket.prototype.onError’の引数’err’の中身をのぞいてみたいと思います。
下記のようにコードを挿入しました。

./node_modules/socket.io/node_modules/engine.io/lib/socket.js

115 Socket.prototype.onError = function (err) {
116   debug('transport error');
117   console.log(err);  // 追加した行
118   this.onClose('transport error', err);
119 };

‘invalid compressed data’ について調べてみる

コードを挿入したら、再度スクリプトを立ち上げてアクセスしてみます。
debugログはとりあえず不要なので、node app.js で起動しました。

コンソール出力(console.log)

[interval] DGQvCfNqaXvogTI0AAAA
{ [Error: invalid compressed data] description: 1007 }
[disconnected] DGQvCfNqaXvogTI0AAAA

切断される寸前に、’err’の中身が出力されました。
‘transport error’の原因は’invalid compressed data’であるということがわかりましたので、
今度は’invalid compressed data’の出力箇所を探してみます。

grepの結果

$ grep -nHr 'invalid compressed data' ./node_modules/
./node_modules/socket.io/node_modules/engine.io/node_modules/ws/lib/Receiver.js:359:        callback(new Error('invalid compressed data'));
./node_modules/socket.io/node_modules/socket.io-client/node_modules/engine.io-client/node_modules/ws/lib/Receiver.js:358:        callback(new Error('invalid compressed data'));

ここでもクライアント側、サーバ側ともに該当がありました。
引き続き、サーバ側のコードを確認してみます。

./node_modules/socket.io/node_modules/engine.io/node_modules/ws/lib/Receiver.js

352 Receiver.prototype.applyExtensions = function(messageBuffer, fin, compressed, callback) {
353   var self = this;
354   if (compressed) {
355     this.extensions[PerMessageDeflate.extensionName].decompress(messageBuffer, fin, function(err, buffer) {
356       if (self.dead) return;
357       if (err) {
358         callback(new Error('invalid compressed data'));
359         return;
360       }
361       callback(null, buffer);
362     });
363   } else {
364     callback(null, messageBuffer);
365   }
366 };

ここでも’err’の中身を出力してみると、
下記のように数パターンの結果があることがわかりました。下記はその一例です。

{ [Error: invalid distance code] errno: -3, code: 'Z_DATA_ERROR' }
{ [Error: invalid block type] errno: -3, code: 'Z_DATA_ERROR' }

いずれの場合も共通しているのは ‘Z_DATA_ERROR’ですね。
‘Z_DATA_ERROR’はzlibでデータの伸長に失敗したときに発生するエラーとのこと。
データを圧縮した覚えはないのですが、なぜこのようなエラーが発生するのでしょう。

なぜ圧縮されているのか

WebSocketの仕様を眺めてみると、データを‘圧縮してもよい’ということになっており、
node.jsのWebSocket実装では、データ圧縮が採用されているようです。

WebSocketServerの初期化時のオプションに’perMessageDeflate: false’を設定すれば圧縮を無効にすることができそうなのですが、
‘./node_modules/socket.io/node_modules/engine.io/lib/server.js’で、
WebSocketServer の初期化を行う際は固定のオプションを設定するようになっており（下記参照）、
socket.ioをrequireするときにどのように設定変更すればよいかよくわかりませんでした。

./node_modules/socket.io/node_modules/engine.io/lib/server.js

 30 function Server(opts){
 31   if (!(this instanceof Server)) {
 32     return new Server(opts);
 33   }
 34
 35   this.clients = {};
 36   this.clientsCount = 0;
 37
 38   opts = opts || {};
 39   this.pingTimeout = opts.pingTimeout || 60000;
 40   this.pingInterval = opts.pingInterval || 25000;
 41   this.upgradeTimeout = opts.upgradeTimeout || 10000;
 42   this.maxHttpBufferSize = opts.maxHttpBufferSize || 10E7;
 43   this.transports = opts.transports || Object.keys(transports);
 44   this.allowUpgrades = false !== opts.allowUpgrades;
 45   this.allowRequest = opts.allowRequest;
 46   this.cookie = false !== opts.cookie ? (opts.cookie || 'io') : false;
 47
 48   // initialize websocket server
 49   if (~this.transports.indexOf('websocket')) {
 50     this.ws = new WebSocketServer({ noServer: true, clientTracking: false }); <-- 引数が固定
 51   }
 52 }

その為、49行目～を下記のように書き換えて強引に圧縮を無効にしてみます。

./node_modules/socket.io/node_modules/engine.io/lib/server.js

 49   if (~this.transports.indexOf('websocket')) {
 50     this.ws = new WebSocketServer({ noServer: true, clientTracking: false, perMessageDeflate: false });
 51     // this.ws = new WebSocketServer({ noServer: true, clientTracking: false });
 52   }

圧縮無効にした結果

圧縮を無効にしたうえで1時間ほど接続を続けてみましたが、切断されソケットIDが変わることはなくなりました。
CPU使用率（nodeのプロセス）を見ると、有効時の半分以下になっています。
（生のデータの送受信をすることになったため、回線には優しくなくなっています。）

なぜ圧縮データの伸長に失敗するのかはまだわかっていませんが、
サーバに対する負荷が関係しているような気がします。

というか、秒間に何度も画像データを送受信するという仕様がそもそも無茶なんでしょうね。。