こんにちは、渕上です。

このブログの為にNode.js + Socket.io を使って疑似ビデオチャットを書いていたのですが、
socket接続中に「socketのidが変わってしまう」という現象が起こりました。

ブログのためだけのコードなので、大きな実害がなければいいかなーくらいに考えていたのですが（よくない）
残念ながら実害がありました。かなり大きな。

Socket.ioのルーム機能を使って下記のような実装を行っていたため、
socketのidが変わってしまうと、入室中のルームを特定することができなくなりました。弱った。

1. 初回のsocket接続時にsocket.idをルームにjoin(入室)させる
2. 同時にsocket.idとルーム名を関連付けるObjectを作成
3. 以降の通信ではsocket.idから現在入室しているルームを特定

まあでも、弱っていても仕方がない。

バグと喧嘩は江戸の華、転んでもただでは起きない精神で、
この問題の調査過程を今回の記事にしてみたいと思います！

問題調査

何が起こっているのかわからないことには問題の切り分けを行うことはできません。
今回はまず、問題と思われる部分を抜き出したシンプルなコードを作成して、
ログの追跡を行ってみることにします。

状況から、なんとなく画像データ(dataURL)の送信部分で問題が起きているような気がしましたので、
画像データ送受信だけを行うテストスクリプトを作成して見ることにしました。

具体的なコードは下記のようになりました。

サーバ側コード

サーバ側のコードでは’test’名前空間に’test_room’ルームを作成し、
接続してきたクライアントを入室させています。

実際にはルーム名は可変にしていましたが、
極力シンプルにするため、’test_room’固定にしました。

また、調査の手がかりとして利用するために、ログを出力(console.log)しています。
ログの出力については後述します。

  1 var express    = require('express');
  2 var app        = express();
  3 var http       = require('http').Server(app);
  4
  5 app.set('view engine', 'jade');
  6 app.set('views', __dirname + '/views');
  7 app.use(express.static(__dirname + '/public'));
  8
  9 var io = require('socket.io')(http);
 10 var ns = io.of('/test');
 11
 12 ns.on('connection', function(socket){
 13   console.log('[connected]', socket.id);
 14
 15   var roomName = 'test_room';
 16   socket.join(roomName);
 17
 18   socket.on('interval', function(data){
 19     console.log('[interval]', socket.id);
 20   });
 21 });
 22
 23 app.get('/', function (req, res){
 24   res.render('index');
 25 });
 26
 27 http.listen(3000);

クライアント側コード

クライアント側のコードでは、PCに接続されたカメラの映像をキャプチャし、
dataURL化してサーバに送信しています。

カメラの映像はvideoタグに流れており、
‘timeupdate’のタイミングで継続的にデータを送信しています。

  1 var socket = io('http://192.168.33.10:3000/test');
  2
  3 window.addEventListener('load', function(){
  4
  5   var video = document.createElement('video');
  6   video.setAttribute('width', 640);
  7   video.setAttribute('height', 480);
  8   var canvas = document.createElement('canvas');
  9   canvas.setAttribute('width', 640);
 10   canvas.setAttribute('height', 480);
 11
 12   navigator.getUserMedia = ( navigator.getUserMedia || navigator.webkitGetUserMedia || navigator.mozGetUserMedia || navigator.msGetUserMedia);
 13
 14   if (navigator.getUserMedia) {
 15     navigator.getUserMedia (
 16       { video: true, audio: true },
 17       function(localMediaStream) {
 18         video.src  = window.URL.createObjectURL(localMediaStream);
 19         video.addEventListener('timeupdate', function(){
 20           var ctx    = canvas.getContext('2d');
 21           ctx.drawImage(video,0,0);
 22           var data = canvas.toDataURL();
 23           socket.emit('interval', data);
 24         });
 25         video.play();
 26       },
 27       function(err) {
 28         console.log("The following error occured: " + err);
 29       }
 30     );
 31   }
 32   else {
 33      console.log("getUserMedia not supported");
 34   }
 35 });

ログ出力について

ひとまず、下記のような出力がされるようにしてみました。

1. クライアントが接続した（ブラウザがスクリプトを読み込んだ）タイミング [connected] {ソケットID}
2. クライアントから画像キャプチャを受信したタイミング [interval] {ソケットID}

この状態でブラウザから接続を行い、ソケットIDの遷移を追いかけてみたいと思います。
恐らく、どこかの[interval]のタイミングでソケットIDが変わるような気がします。

再現テスト（その1・クライアント1つ）

まずは1つのクライアント（ブラウザ）でテストを行ってみました。

サーバログ

vagrant@vagrant-ubuntu-trusty-64:~/workspace/so_test$ node app.js
[connected] Tg226xvUQO8I29igAAAA
[interval] Tg226xvUQO8I29igAAAA
[interval] Tg226xvUQO8I29igAAAA
(中略) [interval] Tg226xvUQO8I29igAAAA が延々つづく
[interval] Tg226xvUQO8I29igAAAA
[interval] Tg226xvUQO8I29igAAAA

うーん。。ナンデ？
5分位ほっておいたのですが、ソケットIDが変わることはありませんでした。

再現テスト（その2・クライアント2つ）

再現しないことには原因の特定もできません。

うーん、困った。

とはいえ実際にソケットIDが変わるという現象は起きたわけで、
何か条件が足りていないに違いません。きっとそうです。

というわけで、もう少し問題が起きた時の状況を思い出してみます。

問題が起きた時は一度に複数のブラウザから接続を行っていたような記憶があります。

テストコードに対しても、2つのクライアント（ブラウザ）で接続してみることにします。

サーバログ

[connected] mMONczJMn_RS_NYVAAAC <-- クライアント1で接続開始
[interval] mMONczJMn_RS_NYVAAAC
[interval] mMONczJMn_RS_NYVAAAC
[interval] mMONczJMn_RS_NYVAAAC
[connected] goHCXrDgQ7dEgmtzAAAD <-- クライアント2で接続開始
[interval] goHCXrDgQ7dEgmtzAAAD
[interval] mMONczJMn_RS_NYVAAAC
[interval] goHCXrDgQ7dEgmtzAAAD
[interval] goHCXrDgQ7dEgmtzAAAD
[interval] goHCXrDgQ7dEgmtzAAAD
[interval] goHCXrDgQ7dEgmtzAAAD
[interval] goHCXrDgQ7dEgmtzAAAD
[interval] goHCXrDgQ7dEgmtzAAAD
[interval] goHCXrDgQ7dEgmtzAAAD
[interval] goHCXrDgQ7dEgmtzAAAD
[interval] goHCXrDgQ7dEgmtzAAAD
[interval] goHCXrDgQ7dEgmtzAAAD
[interval] goHCXrDgQ7dEgmtzAAAD
[connected] 1IZnF6szHa27JW0sAAAE <-- ???
[interval] 1IZnF6szHa27JW0sAAAE
[interval] 1IZnF6szHa27JW0sAAAE
[interval] 1IZnF6szHa27JW0sAAAE
[connected] QMSaTA0JUs5ToZCNAAAF <-- ???
[interval] QMSaTA0JUs5ToZCNAAAF
[interval] 1IZnF6szHa27JW0sAAAE
[interval] QMSaTA0JUs5ToZCNAAAF
[interval] QMSaTA0JUs5ToZCNAAAF
[interval] QMSaTA0JUs5ToZCNAAAF
[interval] QMSaTA0JUs5ToZCNAAAF
[interval] QMSaTA0JUs5ToZCNAAAF
[interval] QMSaTA0JUs5ToZCNAAAF
[interval] QMSaTA0JUs5ToZCNAAAF
[connected] t6m5fghfQ3880x_qAAAG <-- ???
[interval] QMSaTA0JUs5ToZCNAAAF
[interval] t6m5fghfQ3880x_qAAAG

変わった、変わりました！ソケットIDが変わっています。
というか、”ソケットが再接続”することによって”新たなソケットIDが発行”されているように見えます。
・・・特に再接続処理など書いてないはずなんだけど。

クライアントログ

WebSocket is already in CLOSING or CLOSED state.
  (anonymous function) @ socket.io.js:3475
  exports.encodePacket @ socket.io.js:4188
  WS.write @ socket.io.js:3470
  Transport.send @ socket.io.js:2343
  Socket.flush @ socket.io.js:2066
  Socket.sendPacket @ socket.io.js:2107
  Socket.write.Socket.send @ socket.io.js:2085
  (anonymous function) @ socket.io.js:462
  Encoder.encode @ socket.io.js:5822
  Manager.packet @ socket.io.js:460
  Socket.packet @ socket.io.js:788
  Socket.emit @ socket.io.js:771
  (anonymous function) @ application.js:23

こんなこともあろうかと開いておいたChromeのconsoleを見てみたところ、
上記のようなエラーがいくつか出ていました。
どうやら、何らかの原因でsocketが切断されたことによって自動的に再接続が行われ、
その結果ソケットIDが変わったようです。

で、どうする？

これまでの問題切り分けから、
ソケットIDが変わってしまう原因はソケットの接続が閉じてしまうことにあると判明しました。
今後少し時間を使って、この問題の解決に注力してみたいと思います。
対策としては↓の2つを検討してみます。

1. 接続が閉じないようにする

至極まっとうな対策ですね。
実装の見直しをして、実装不備によって接続が閉じてしまっているのであれば修正を試みます。

2. 閉じてしまうものはしょうがない、閉じても問題が起きないような方法を考える

やや外角低めの対策ですね。
再接続が起こることを前提に、実装を変更していきます。
できるかはわかりませんが、再接続時ユーザに紐づけたソケットIDの洗い替えを行うとかでしょうか。