知識創造技術者の日々: 作業ログ：GAE/J + BlazeDS 4 環境について考えてみた。

以下、GAE/J + BlazeDS 4 環境について考えてみた作業ログ。

方針

以前、GAE 上で普通に remoting や messaging をしようと思ったところGAE/J + BlazeDS 環境の DuplicateSessionDetected 問題に突き当たりました。また、security 機能を利用しようとした際には後GAE/J + BlazeDS3 環境の HttpSessionListener 問題に突き当たりました。

これらの経緯を考えると、今後も多くの問題に突き当たることが考えられます。これより先に進むのであれば、それなりの覚悟が必要になります。しかし、オープンソースのソフトウェアである限り、手詰まりに可能性が低く、最終的に詰むというリスクは低く抑えられています。これはやるしかないでしょう。

となると、どこまでやるかという問題がありますが、自分たちが必要な機能についてはすべて自分たちで理解したうえでコントロールするというところが落としどころかとおもいます。具体的には、GAE 上で動作すればよく、まずはロールなしのセッションレベルの認証ができればいいし、通常の AMF で remoting ができればOKです。今後メッセージングも必要になるかもしれないとか、GAE上なのでストリーミングが必要になることは当面ありえないだろうとか。そんな感じです。少なくともその時点で必要な機能かつ問題のあるソースはすべて把握しておく必要があり、そのためには全体の構成と主要なクラスについては、ソースレベルで完全に把握する必要があります。

(｀・ω・´) さて、どこから手をつけようか？

まずは環境整理

これから作業をする上で、クリーンな環境を維持することは重要になります。そのため、環境整備の手順を整理しておく必要があります。

ということで、GAE/J + BlazeDS 4 環境の構築に内容をまとめました。

GAE/J + BlazeDS 環境の DuplicateSessionDetected 問題を再び追いながら情報収集

Servletのバージョン

BlazeDS は Servlet2.3以上（TODO:出典明記）
GAE は Servlet2.4（TODO:出典明記）

Application Lifecycle Event

BlazeDS 4 では web.xml で以下のように flex.messaging.HttpFlexSession を Application Lifecycle Event のリスナーとして設定しています。

<!-- Http Flex Session attribute and binding listener support -->
<listener>
  <listener-class>flex.messaging.HttpFlexSession</listener-class>
</listener>

このクラスは以下のインタフェースを実装しています。

javax.servlet.http.HttpSessionAttributeListener
javax.servlet.http.HttpSessionBindingListener
javax.servlet.http.HttpSessionListener

HttpFlexSession が実装するリスナーのメソッドと、実行内容の概要を以下に示します。

void valueBound(HttpSessionBindingEvent event)

何もしません。

void valueUnbound(HttpSessionBindingEvent event)

HttpSessionの属性が削除された場合に flexSession.superInvalidate() を呼びます。。
isHttpSessionListener が true の場合、つまり通常は何もしません。
~~GAE 環境では、呼ばれたら実行されるはずです。~~（追記：GAE環境でも実行されません）
属性が削除されただけでなぜ flexSession.superInvalidate() を呼ぶ必要があるのか？

void sessionCreated(HttpSessionEvent event)

isHttpSessionListener フラグを true にします。

void sessionDestroyed(HttpSessionEvent event)

HttpSessionが削除されたらFlexSessionも削除されるようにします。
attributeRemovedイベントよりよりこちらが先に行われる場合の対策として、attributeRemovedこちらからもattributeRemovedを呼びに行っています。
void attributeAdded(HttpSessionBindingEvent event)
属性変更イベント名が"__flexSession"の場合のみ、flexSession.notifyAttributeBound(name, value)とnotifyAttributeAdded(name, value)を呼びに行く。
必要な属性だけコピーするということですね。

void attributeRemoved(HttpSessionBindingEvent event)

属性変更イベント名が"__flexSession"の場合のみ、flexSession.notifyAttributeUnbound(name, value) と flexSession.notifyAttributeRemoved(name, value) を呼びに行く。

void attributeReplaced(HttpSessionBindingEvent event)

属性変更イベント名が"__flexSession"の場合のみ、flexSession.notifyAttributeUnbound(name, value) と flexSession.notifyAttributeReplaced(name, value) と flexSession.notifyAttributeBound(name, newValue) を呼びに行く。

ログを仕込んで、ローカル環境で実行してみました。

// 初回
MessageBrokerServlet#service() : begin
HttpFlexSession#sessionCreated() : sessionId = 13x3l8s1hg56a
HttpFlexSession#valueBound() : name = __flexSession : sessionId = 13x3l8s1hg56a
HttpFlexSession#attributeAdded() : name = __flexSession : sessionId = 13x3l8s1hg56a
MessageBrokerServlet#service() : end
MessageBrokerServlet#service() : begin
EchoService#echo() : sessionId = 13x3l8s1hg56a
MessageBrokerServlet#service() : end

// 二回目
MessageBrokerServlet#service() : begin
EchoService#echo() : sessionId = 1l72bdhrrlfvy
MessageBrokerServlet#service() : end

デバッガでも追ったところ、Sevletコンテナ側から正しく呼び出されていました。（正しく動作するということが、GAE的にはバグなんですね。）

初回は２回serviceが呼ばれてますね。TODO：要調査

今度はサーバ側にデプロイして同様のことをしてみます。

// 一回目のアクセス（例のセッション重複で失敗）
04-15 02:56PM 55.052 MessageBrokerServlet#service() : begin
04-15 02:56PM 55.283 MessageBrokerServlet#service() : end

04-15 02:56PM 55.555 MessageBrokerServlet#service() : begin
04-15 02:56PM 55.587 HttpFlexSession#sessionDestroyed() : sessionId = CRls4b-kT7-DCbJSV6yFbw
04-15 02:56PM 55.587 FlexSession#invalidate()
04-15 02:56PM 55.870 HttpFlexSession#sessionDestroyed() : sessionId = CRls4b-kT7-DCbJSV6yFbw
04-15 02:56PM 55.961 MessageBrokerServlet#service() : end

// 二回目のアクセス（成功）
04-15 03:17PM 18.307 MessageBrokerServlet#service() : begin
04-15 03:17PM 18.526 HttpFlexSession#sessionCreated() : sessionId = V1pWQsjzwKuDKYUS5IlpZg
04-15 03:17PM 18.527 HttpFlexSession#valueBound() : name = __flexSession : sessionId = V1pWQsjzwKuDKYUS5IlpZg
04-15 03:17PM 18.527 HttpFlexSession#attributeAdded() : name = __flexSession : sessionId = V1pWQsjzwKuDKYUS5IlpZg
04-15 03:17PM 19.251 MessageBrokerServlet#service() : end

04-15 03:17PM 19.719 MessageBrokerServlet#service() : begin
04-15 03:17PM 19.790 HttpFlexSession#sessionDestroyed() : sessionId = V1pWQsjzwKuDKYUS5IlpZg
04-15 03:17PM 19.790 FlexSession#invalidate()
04-15 03:17PM 19.790 HttpFlexSession#valueUnbound() : NOP : name = __flexSession : sessionId = V1pWQsjzwKuDKYUS5IlpZg
04-15 03:17PM 19.790 HttpFlexSession#attributeRemoved() : name = __flexSession : sessionId = V1pWQsjzwKuDKYUS5IlpZg
04-15 03:17PM 19.889 HttpFlexSession#sessionDestroyed() : sessionId = V1pWQsjzwKuDKYUS5IlpZg
04-15 03:17PM 19.976 MessageBrokerServlet#service() : end

04-15 03:20PM 00.169 MessageBrokerServlet#service() : begin
04-15 03:20PM 00.465 HttpFlexSession#sessionCreated() : sessionId = 0Gqlzdy3J_I2n281ANfQmQ
04-15 03:20PM 00.466 HttpFlexSession#valueBound() : name = __flexSession : sessionId = 0Gqlzdy3J_I2n281ANfQmQ
04-15 03:20PM 00.466 HttpFlexSession#attributeAdded() : name = __flexSession : sessionId = 0Gqlzdy3J_I2n281ANfQmQ
04-15 03:20PM 02.255 EchoService#echo() : sessionId = 0Gqlzdy3J_I2n281ANfQmQ
04-15 03:20PM 02.375 MessageBrokerServlet#service() : end

おや？

HttpFlexSession#sessionCreated() は、Servletコンテナのライフサイクルイベントとして以外には絶対に呼ばれないということはソースから確認できます。なのに呼ばれているということは、GAE上でもライフサイクルイベントが呼ばれるということですね。

ということで、GAE/J 環境の Application Lifecycle Listener の実験をしてみたところ、やはり GAE 上でもライフサイクルイベントは呼ばれるようです。

ということで、今度は上記テストのリスナーをコンテナに配備して、埋め込んだデバッグ情報を一度ほぼクリアにしてから、再度動作検証をしていくことにします。ブラウザのcookieは事前に削除しておきます。念のため、_ah_SESSION 情報も削除しておきます。関係ないと思いつつもWeb サイトのプライバシー設定パネルから flash のローカルクッキーも削除します。

開発サーバでの実行

// 一回目のアクセス
sessionCreated : id = 1snep0z5nb1pd
attributeAdded : name = __flexSession, value = flex.messaging.HttpFlexSession@14a18d
EchoService#echo() : sessionId = 1snep0z5nb1pd

// 二回目のアクセス
EchoService#echo() : sessionId = 1snep0z5nb1pd

// 三回目のアクセス
EchoService#echo() : sessionId = 1snep0z5nb1pd

本番サーバでの実行

// UIから一回目のアクセス /messagebroker/amf
04-16 05:16AM 04.683 sessionCreated : id = EmVdv905Ogr0kGuoKMfVHA
04-16 05:16AM 04.690 attributeAdded : name = __flexSession, value = flex.messaging.HttpFlexSession@165547d
// UIから一回しかアクセスしていないけどなぜか二回目のアクセスが行われている。/messagebroker/amf;jsessionid=EmVdv905Ogr0kGuoKMfVHA
04-16 05:16AM 05.584 sessionDestroyed : id = EmVdv905Ogr0kGuoKMfVHA
04-16 05:16AM 05.584 attributeRemoved : name = __flexSession, value = flex.messaging.HttpFlexSession@165547d
04-16 05:16AM 05.861 sessionDestroyed : id = EmVdv905Ogr0kGuoKMfVHA
【結果】Detected duplicate HTTP-based FlexSessions で失敗

// UIから二回目のアクセス /messagebroker/amf;jsessionid=EmVdv905Ogr0kGuoKMfVHA
04-16 05:18AM 19.795 sessionCreated : id = uqSuxURP-RXL1hsdcp2c0A
04-16 05:18AM 19.795 attributeAdded : name = __flexSession, value = flex.messaging.HttpFlexSession@34a1c8
04-16 05:18AM 19.830 sessionDestroyed : id = EmVdv905Ogr0kGuoKMfVHA
04-16 05:18AM 19.850 sessionDestroyed : id = uqSuxURP-RXL1hsdcp2c0A
04-16 05:18AM 19.850 attributeRemoved : name = __flexSession, value = flex.messaging.HttpFlexSession@34a1c8
04-16 05:18AM 20.008 sessionCreated : id = SaKtj72k_5tVABGvK7vOAg
04-16 05:18AM 20.008 attributeAdded : name = __flexSession, value = flex.messaging.HttpFlexSession@1e514a9
【結果】Detected duplicate HTTP-based FlexSessions で失敗）

// 三回目のアクセス /messagebroker/amf;jsessionid=SaKtj72k_5tVABGvK7vOAg
04-16 05:20AM 34.078 EchoService#echo() : sessionId = SaKtj72k_5tVABGvK7vOAg 
【結果】成功

現状のデータからの考察

開発環境上の動作は、意図したとおりのものです。しかし、本番環境上の動作は、意図とはかなり異なる動きをしています。

まず flash クライアントからの初回のアクセスが2回に分けて行われています。これ自体理由が分からないので調査したいところですが、何回アクセスがきたところで、セッション管理に影響するというのは問題です。まずは最初のアクセスからソースを追いつつ、仮定を立ててみます。

・仮定１：初回アクセスの２回目のHTTP呼び出しにて、BaseHTTPEndpoint#setupFlexClient() の432行で DuplicateSessionException が throw されている。
・仮定２：上記は同クラス400行にてflexClient.getFlexSessions()のサイズを2として受け取っている。
・仮定３：仮定２の直接の原因は、FlexClient の 1119 行目で複数の FlexSession が登録されてしまうこと。

とりあえず、ここまでを確認してみたところ、仮定１，２は正解。仮定３は可能性ありです。二回目のアクセスで、一回目で生成された FlexClient を使用しているのであれば、仮定３はほぼクロです。

ということで、ログを仕込んで再実行。

開発環境

// 初回（成功）
04-16 08:52AM 37.279 [beyondseeker-mixi-01/1.341297705342737136].: MessagingConfiguration#createFlexClientManager() : FlexClientManager is created with problem!
04-16 08:52AM 38.068 [beyondseeker-mixi-01/1.341297705342737136].: MessageBrokerServlet#service() : begin
04-16 08:52AM 38.322 [beyondseeker-mixi-01/1.341297705342737136].: sessionCreated : id = zpE2j7OXspDhdA1-960ZCg
04-16 08:52AM 38.325 [beyondseeker-mixi-01/1.341297705342737136].: attributeAdded : name = __flexSession, value = flex.messaging.HttpFlexSession@187e184
04-16 08:52AM 38.644 [beyondseeker-mixi-01/1.341297705342737136].: FlexClient#registerFlexSession() : httpClient = flex.messaging.client.FlexClient@92de02
04-16 08:52AM 38.644 [beyondseeker-mixi-01/1.341297705342737136].: FlexClient#registerFlexSession() : httpClient = flex.messaging.client.FlexClient@92de02
04-16 08:52AM 38.659 [beyondseeker-mixi-01/1.341297705342737136].: EchoService#echo() : sessionId = zpE2j7OXspDhdA1-960ZCg
04-16 08:52AM 38.705 [beyondseeker-mixi-01/1.341297705342737136].: MessageBrokerServlet#service() : end

本番環境

// 初回（成功）
04-16 08:52AM 37.279 MessagingConfiguration#createFlexClientManager() : FlexClientManager is created with problem!
04-16 08:52AM 38.068 MessageBrokerServlet#service() : begin
04-16 08:52AM 38.322 sessionCreated : id = zpE2j7OXspDhdA1-960ZCg
04-16 08:52AM 38.325 attributeAdded : name = __flexSession, value = flex.messaging.HttpFlexSession@187e184
04-16 08:52AM 38.644 FlexClient#registerFlexSession() : httpClient = flex.messaging.client.FlexClient@92de02
04-16 08:52AM 38.644 FlexClient#registerFlexSession() : httpClient = flex.messaging.client.FlexClient@92de02
04-16 08:52AM 38.659 EchoService#echo() : sessionId = zpE2j7OXspDhdA1-960ZCg
04-16 08:52AM 38.705 MessageBrokerServlet#service() : end

// 二回目（失敗）
04-16 08:53AM 39.110 MessageBrokerServlet#service() : begin
04-16 08:53AM 39.112 flexClient is retrieved from in-memory flexClients repository.
04-16 08:53AM 39.112 FlexClient#registerFlexSession() : httpClient = flex.messaging.client.FlexClient@92de02
04-16 08:53AM 39.112 sessions.size() = 2
04-16 08:53AM 39.112 sessionId = zpE2j7OXspDhdA1-960ZCg
04-16 08:53AM 39.112 sessionId = zpE2j7OXspDhdA1-960ZCg
04-16 08:53AM 39.112 FlexClient#registerFlexSession() : httpClient = flex.messaging.client.FlexClient@92de02
04-16 08:53AM 39.128 sessionDestroyed : id = zpE2j7OXspDhdA1-960ZCg
04-16 08:53AM 39.129 attributeRemoved : name = __flexSession, value = flex.messaging.HttpFlexSession@187e184
04-16 08:53AM 39.250 sessionDestroyed : id = zpE2j7OXspDhdA1-960ZCg
04-16 08:53AM 39.343 MessageBrokerServlet#service() : end

開発環境、本番環境に関わらず、二回目のアクセスはオンメモリの情報を取得しています。

FlexClientManager では、取得できればオンメモリのものを使用し、できなければサーバ上のものを使用するので、GAE 環境でも問題なさそうです。

そして、問題なのは、同じ sessionId を二箇所登録している部分です。これは以前
GAE/J + BlazeDS 環境の DuplicateSessionDetected 問題で調べたとおりなので、同様に対処します。

本番環境

// 初回（成功）
04-16 09:38AM 51.550 MessagingConfiguration#createFlexClientManager() : FlexClientManager is created with problem!
04-16 09:38AM 52.813 MessageBrokerServlet#service() : begin
04-16 09:38AM 53.228 FlexClient#registerFlexSession() : httpClient = flex.messaging.client.FlexClient@1bb60ad
04-16 09:38AM 53.228 FlexClient#registerFlexSession() : httpClient = flex.messaging.client.FlexClient@1bb60ad
04-16 09:38AM 53.250 EchoService#echo() : sessionId = IHEyAtViGH3J9Et5RT48mg
04-16 09:38AM 53.300 MessageBrokerServlet#service() : end

// 二回目（成功）
04-16 09:39AM 49.765 MessageBrokerServlet#service() : begin
04-16 09:39AM 49.767 flexClient is retrieved from in-memory flexClients repository.
04-16 09:39AM 49.767 FlexClient#registerFlexSession() : httpClient = flex.messaging.client.FlexClient@1bb60ad
04-16 09:39AM 49.767 EchoService#echo() : sessionId = IHEyAtViGH3J9Et5RT48mg
04-16 09:39AM 49.769 MessageBrokerServlet#service() : end

という感じで、GAE/J 上でも最低限使える環境になったかなと思います。

知識創造技術者の日々

2010年4月17日土曜日

作業ログ：GAE/J + BlazeDS 4 環境について考えてみた。

0 件のコメント:

コメントを投稿

フォロワー

ブログアーカイブ