2010年4月18日日曜日

作業ログ：login機能使用時の SessionDuplicate 問題

作業ログ：GAE/J + BlazeDS 4 環境について考えてみた。にて、同じ session id を持つ異なる FlexSession のインスタンスを同一とみなすパッチを当てることにより、セッション重複の誤検出をしないように変更しました。

しかし、 login / logout 機能周りでもセッション重複の誤検出が行われるようです。

以下、状況を確認するために仕込んだログ。
// 最初のアクセス(login)
04-17 05:50AM 29.350 MessageBrokerServlet#service() : begin
04-17 05:50AM 29.350 FlexContext#setThreadLocalObjects(): null is set.
04-17 05:50AM 29.350 FlexContext#setThreadLocalSession(): flex.messaging.HttpFlexSession@c1b161 is set. sessionId = BwbsdybycCfB7kDRSLErnw
04-17 05:50AM 29.350 HttpFlexSessionProvider#getOrCreateSession() : HttpFlexSession is retrieved from thread local. id = BwbsdybycCfB7kDRSLErnw
04-17 05:50AM 29.352 flexClient is retrieved from in-memory flexClients repository.
04-17 05:50AM 29.352 AbstractEndpoint#setupFlexClient(C4DB9840-340F-6FC7-5604-28ADF310987A) : flex.messaging.HttpFlexSession@1d952cdf
04-17 05:50AM 29.352 FlexClient#registerFlexSession() : httpClient = flex.messaging.client.FlexClient@d210ab, sessionId = BwbsdybycCfB7kDRSLErnw
04-17 05:50AM 29.359 doAuthentication
04-17 05:50AM 31.199 MessageBrokerServlet#service() : end


// 二回目のアクセス(logout)
04-17 05:50AM 33.584 MessageBrokerServlet#service() : begin
04-17 05:50AM 33.584 FlexContext#setThreadLocalObjects(): null is set.
04-17 05:50AM 33.584 FlexContext#setThreadLocalSession(): flex.messaging.HttpFlexSession@1601a4f is set. sessionId = BwbsdybycCfB7kDRSLErnw
04-17 05:50AM 33.584 HttpFlexSessionProvider#getOrCreateSession() : HttpFlexSession is retrieved from thread local. id = BwbsdybycCfB7kDRSLErnw
04-17 05:50AM 33.585 flexClient is retrieved from in-memory flexClients repository.
04-17 05:50AM 33.585 AbstractEndpoint#setupFlexClient(C4DB9840-340F-6FC7-5604-28ADF310987A) : flex.messaging.HttpFlexSession@1d952cdf
04-17 05:50AM 33.585 FlexClient#registerFlexSession() : httpClient = flex.messaging.client.FlexClient@d210ab, sessionId = BwbsdybycCfB7kDRSLErnw
04-17 05:50AM 33.586 logout
04-17 05:50AM 33.620 sessionDestroyed : id = BwbsdybycCfB7kDRSLErnw
04-17 05:50AM 33.620 attributeRemoved : name = __flexSession, value = flex.messaging.HttpFlexSession@1d952cdf
04-17 05:50AM 33.702 sessionDestroyed : id = BwbsdybycCfB7kDRSLErnw
04-17 05:50AM 33.758 FlexContext#setThreadLocalObjects(): null is set.
04-17 05:50AM 33.760 MessageBrokerServlet#service() : end


// 三回目のアクセス(?)
04-17 05:50AM 34.276 MessageBrokerServlet#service() : begin
04-17 05:50AM 34.276 FlexContext#setThreadLocalObjects(): null is set.
04-17 05:50AM 34.374 sessionCreated : id = KHeEJ_L9FBgQol3Hj15rlw
04-17 05:50AM 34.374 FlexContext#setThreadLocalSession(): flex.messaging.HttpFlexSession@e7b3cf is set. sessionId = KHeEJ_L9FBgQol3Hj15rlw
04-17 05:50AM 34.374 attributeAdded : name = __flexSession, value = flex.messaging.HttpFlexSession@e7b3cf
04-17 05:50AM 34.374 HttpFlexSessionProvider#getOrCreateSession() : HttpFlexSession is created. id = KHeEJ_L9FBgQol3Hj15rlw
04-17 05:50AM 34.375 flexClient is retrieved from in-memory flexClients repository.
04-17 05:50AM 34.375 AbstractEndpoint#setupFlexClient(C4DB9840-340F-6FC7-5604-28ADF310987A) : flex.messaging.HttpFlexSession@b89a50a6
04-17 05:50AM 34.375 FlexClient#registerFlexSession() : httpClient = flex.messaging.client.FlexClient@d210ab, sessionId = KHeEJ_L9FBgQol3Hj15rlw
04-17 05:50AM 34.376 sessions.size() = 2
04-17 05:50AM 34.376 sessionId = BwbsdybycCfB7kDRSLErnw
04-17 05:50AM 34.376 sessionId = KHeEJ_L9FBgQol3Hj15rlw
04-17 05:50AM 34.376 FlexClient#registerFlexSession() : httpClient = flex.messaging.client.FlexClient@d210ab, sessionId = KHeEJ_L9FBgQol3Hj15rlw
04-17 05:50AM 34.406 sessionDestroyed : id = BwbsdybycCfB7kDRSLErnw
04-17 05:50AM 34.420 sessionDestroyed : id = KHeEJ_L9FBgQol3Hj15rlw
04-17 05:50AM 34.420 attributeRemoved : name = __flexSession, value = flex.messaging.HttpFlexSession@b89a50a6
04-17 05:50AM 34.603 sessionCreated : id = tcnt9ZwRj6jAnqib-C9o0A
04-17 05:50AM 34.604 FlexContext#setThreadLocalSession(): flex.messaging.HttpFlexSession@1912a56 is set. sessionId = tcnt9ZwRj6jAnqib-C9o0A
04-17 05:50AM 34.604 attributeAdded : name = __flexSession, value = flex.messaging.HttpFlexSession@1912a56
04-17 05:50AM 34.604 HttpFlexSessionProvider#getOrCreateSession() : HttpFlexSession is created. id = tcnt9ZwRj6jAnqib-C9o0A
04-17 05:50AM 34.604 FlexContext#setThreadLocalObjects(): flex.messaging.HttpFlexSession@b8b7ad0d is set.
04-17 05:50AM 34.627 MessageBrokerServlet#service() : end

  • 一回目のアクセス
    • 問題なく普通にログインできてる感じです。
  • 二回目のアクセス
    • sessionDestroyed が二回呼ばれてますね。実害はなさそうですが。
  • 三回目のアクセス
    • FlexClientに古いsessionが残ってますね。それで、新規のsessionが追加されることによって重複が検出されているみたいです。
    • 二回目のアクセスで削除されたはずの BwbsdybycCfB7kDRSLErnw に sessionDestroyed が呼ばれてますね。
何気に、全アクセスのパスが /messagebroker/amf;jsessionid=BwbsdybycCfB7kDRSLErnw になってるなぁ。これが原因？ ということで、そうならない形で再実験。cookie 削除して、flashも新規にロードして、ついでに flash 側でもすべてのハンドラにログ仕込んで、さぁ、どうなるか？

logout 後にもう一度アクセスしに行って、そのときにエラーが返されてますね。上記の３回目のアクセスと同様と思われます。それが原因か？

いくつか気持ち悪い問題がありますね。
  • 二回目のアクセスで削除されたはずの BwbsdybycCfB7kDRSLErnw に対して sessionDestroyed が発行されるという問題。
  • 二回目のアクセスで BwbsdybycCfB7kDRSLErnw のセッションを削除したのに、オンメモリ上の FlexClient からは情報が削除されていない。
  • 開発環境では発生せずGAE環境だけで発生する。
ひとまず、一つ目の問題について、専用のテストプログラムを作成し、開発環境とGAE環境で動作させて見ることにします。

ローカルだと IllegalStateException で落ちますが、sessionDestroyedのハンドラは呼ばれました。


結局

振り返ってみると、調査開始時にはずいぶん勘違いがあったなぁ。
インメモリのリポジトリって何だよｗｗｗ

という感じで、上記からけっこう激しく試行錯誤した挙句、以下に落ち着きました。

flex.messaging.client.FlexClient クラスの registerFlexSession(FlexSession) メソッドについて、以下のように修正します。
public void registerFlexSession(FlexSession session)
{
    if (sessions.addIfAbsent(session))
    {
        session.addSessionDestroyedListener(this);
        session.registerFlexClient(this);
    }
    // for session serialization
    else if (session.getFlexClients().isEmpty())
    {
        session.addSessionDestroyedListener(this);
        session.registerFlexClient(this);
    }
}


(´・ω・`) しかし、稀に重複検出の例外が起きるのです。

ログを見る限り、サーバ上では、logout メッセージ でセッションを破棄し、, disconnect メッセージで再度セッションを生成しするのですが、次のログイン前の ping で HTTP レベルのセッションが取得できないことがあるようです。

2,3秒間隔で行うとこの問題は発生しません。

GAEではセッション情報を必ずデータストアから取得するようなので、データストア側で遅延があるのであれば、セッションを取得できないのは納得できます（TODO:要調査）。しかし、それだけでは問題にはなりません。なぜ以前のセッション情報として格納されていた FlexClient の情報が復活しているかということです。FlexClient は実際にはシリアライズされるわけではなく毎回復元されるものなので、以前の情報が残っていることはありえません。となると、この仮定が間違っているのか、ほかに見落としている点があるかのどちらかということになります（TODO:要調査）。

まぁ、今のところはログアウト後に速攻でログインしない限り発生しないので、しばらくは放置しようかと思います。

(´・ω・`) GAE環境は調査に時間がかかりすぎるのねん、、、。
投稿者 時刻:

0 件のコメント:

コメントを投稿

登録: コメントの投稿 (Atom)