[seasar-dotnet:1216] Re: Quill で複数データソースでのトランザクション制御に失敗する
takai
[E-MAIL ADDRESS DELETED]
2008年 12月 10日 (水) 14:43:07 JST
小谷様
高井です。
早速プログラムありがとうございます。
今現物が手元にないので、シンプルなソリューション (DB, ロジック, フォーム
の３プロジェクトから成る) を作成して DB を PostgreSQL で動かしてみると再
現しました。
下にログの抜粋を貼り付けてあります。
プログラムは 3つの DS を定義しておいて、うち２つの DS (Test2 → Test1 の
順) にアクセスして更新クエリをかけてトランザクション内でロールバックさせ
るというものです。
Test2DS は正常にロールバックできていますが、Test1DS の方はだめでした。
ちなみに呼び出し順を逆に (Test1 → Test2 の順) しても Test2DS が正常で
Test1DS はだめなままでした。
app.config の定義順を変更してもトランザクションが正常に動く DS は変わら
りませんでした。
データソースが格納されているハッシュでのデータソースの並び順なのかその辺
でトランザクションがうまくいく DS が１つに決まっていそうな雰囲気です。
ログを見るとだめな方の Connection 情報がトレースできていないようなので、
このあたりのコネクションの管理になにかありそうですね。
----------------------------------------------------
(Program#Main():19) start
(Logger#Log():0) True
(Logger#Log():0) Npgsql, version=2.0.1.0, Culture=neutral
(Logger#Log():0) TestLogic, version=0.0.0.0, Culture=neutral
(Logger#Log():0)
(Logger#Debug():0) TransactionContext.Current(48835636)が設定されました。
(Logger#Debug():0) TransactionContext.Current(24393646)が設定されました。
(Logger#Debug():0) TransactionContext.Current(2883140)が設定されました。
(Logger#Debug():0) SetDataSourceName is called.[Test2DS]
(Logger#Debug():0) SetDataSourceName=Test2DS
(Logger#Debug():0) DataSourceName=[Test2DS]
(Logger#Debug():0) TransactionContext=[2883140], Connection=[null], DataSource=[65117297]
(Logger#Log():0) 論理的なコネクションを取得しました
(Logger#Log():0) トランザクションを開始しました
(Logger#Debug():0) SetDataSourceName is called.[Test2DS]
(Logger#Debug():0) SetDataSourceName=Test2DS
(Test2S2DaoMetaDataFactoryImpl#GetDaoMetaData():86) ...Creating daoMetaData for 'Test2Dao'.
(Logger#Debug():0) DataSourceName=[Test2DS]
(Logger#Debug():0) TransactionContext=[47992654], Connection=[12185796], DataSource=[65117297]
(Test2S2DaoMetaDataExtension#GetSqlCommand():74) ...Initializing sqlCommand for Insert().
(Test2XLog#Log():19) SqlCommand Initialization Cost: [00m00s115ms]
(Test2XLog#Log():19) /================================================================================
(Test2XLog#Log():19) Test2Bhv.Insert()
(Test2XLog#Log():19) ==========================/
(Test2XLog#Log():19) Test2ServiceImpl.Insert() --> Test2Bhv.Insert() --> ...
(Logger#Debug():0) DataSourceName=[Test2DS]
(Logger#Debug():0) TransactionContext=[47992654], Connection=[12185796], DataSource=[65117297]
(Test2QLog#Log():20) INSERT INTO ....
(Logger#Debug():0) DataSourceName=[Test2DS]
(Logger#Debug():0) DataSourceName=[Test2DS]
(Test2XLog#Log():19) ===========/ [00m00s173ms - Result: 1]
(Test2XLog#Log():19)
(Logger#Log():0) トランザクションをロールバックしました
(Logger#Log():0) 論理的なコネクションを閉じました
(Logger#Debug():0) SetDataSourceName is called.[Test1DS]
(Logger#Debug():0) SetDataSourceName=Test1DS
(Logger#Debug():0) DataSourceName=[Test1DS]
(Logger#Debug():0) TransactionContext=[2883140], Connection=[null], DataSource=[27237168]
(Logger#Log():0) 論理的なコネクションを取得しました
(Logger#Log():0) トランザクションを開始しました
(Logger#Debug():0) SetDataSourceName is called.[Test1DS]
(Logger#Debug():0) SetDataSourceName=Test1DS
(Test1S2DaoMetaDataFactoryImpl#GetDaoMetaData():86) ...Creating daoMetaData for 'Test1Dao'.
(Logger#Debug():0) DataSourceName=[Test1DS]
(Logger#Debug():0) TransactionContext=[2883140], Connection=[null], DataSource=[27237168]
(Test1S2DaoMetaDataExtension#GetSqlCommand():74) ...Initializing sqlCommand for SelectNextVal().
(Test1XLog#Log():19) SqlCommand Initialization Cost: [00m00s057ms]
(Test1XLog#Log():19) /===============================================================================
(Test1XLog#Log():19) Test1Bhv.Insert()
(Test1XLog#Log():19) =========================/
(Test1XLog#Log():19) Test1ServiceImpl.Insert() --> Test1Bhv.Insert() --> ...
(Logger#Debug():0) DataSourceName=[Test1DS]
(Logger#Debug():0) TransactionContext=[2883140], Connection=[null], DataSource=[27237168]
(Logger#Log():0) 論理的なコネクションを取得しました
(Test1QLog#Log():20) select nextval ('test1_table_id_seq')
(Logger#Debug():0) DataSourceName=[Test1DS]
(Logger#Debug():0) DataSourceName=[Test1DS]
(Logger#Log():0) 論理的なコネクションを閉じました
(Test1XLog#Log():19) ===========/ [00m00s055ms - Result: 21]
(Test1XLog#Log():19)
(Logger#Debug():0) SetDataSourceName is called.[Test1DS]
(Logger#Debug():0) SetDataSourceName=Test1DS
(Test1S2DaoMetaDataExtension#GetSqlCommand():74) ...Initializing sqlCommand for Insert().
(Test1XLog#Log():19) SqlCommand Initialization Cost: [00m00s001ms]
(Test1XLog#Log():19) /===============================================================================
(Test1XLog#Log():19) Test1Bhv.Insert()
(Test1XLog#Log():19) =========================/
(Test1XLog#Log():19) Test1ServiceImpl.Insert() --> Test1Bhv.Insert() --> ...
(Logger#Debug():0) DataSourceName=[Test1DS]
(Logger#Debug():0) TransactionContext=[2883140], Connection=[null], DataSource=[27237168]
(Logger#Log():0) 論理的なコネクションを取得しました
(Test1QLog#Log():20) INSERT INTO TEST1....
(Logger#Debug():0) DataSourceName=[Test1DS]
(Logger#Debug():0) DataSourceName=[Test1DS]
(Logger#Log():0) 論理的なコネクションを閉じました
(Test1XLog#Log():19) ===========/ [00m00s199ms - Result: 1]
(Test1XLog#Log():19)
(Logger#Log():0) トランザクションをロールバックしました
(Logger#Log():0) 論理的なコネクションを閉じました
(Program#Main():23) end
----------------------------------------------------------
よろしくお願いします。
> 高井さん
>
> 小谷です。
>
> ご回答ありがとうございます。
> 設定面はまず問題なさそうですね。
>
> おっしゃる通りトランザクション発行時とSQL発行時で
> 別のコネクションが使われている可能性が高いです。
>
> 問題発生時の状況を確認するためにログ出力を追加したものをコミットしました。
>
> 「TransactionContext=[XXX], Connection=[XXX], DataSource=[XXX]」
> 「TransactionContext.Current(XXX)が設定されました。」
>
> というログが出力されるようになっているはずです。
> 「本当に別のコネクションが使われているのか？」
> 「同じコネクションが使われるための処理は呼ばれているか？」
> を確認するためのものです。
>
> XXXには使用しているクラスのインスタンスがnullであれば「null」
> そうでなければオブジェクトのハッシュ値が出力されます。
>
> 差し支えなければsvnで最新のコードを取得→コンパイルしたDLLを
> 使ってご確認をお願いします。
>
> -------------------------------------------------------------
> koyak
> [E-MAIL ADDRESS DELETED]
> -------------------------------------------------------------
>
> 2008/12/10 9:20 takai <[E-MAIL ADDRESS DELETED]>:
> > 小谷様
> > 高井です。
> >
> > 返信ありがとうございます。
> >
> >> １．
> >> >XxxTxSetting は DBFlute で生成されたままで
> >>
> >> このDBFluteが自動生成しているXxxTxSettingは
> >> (DBFluteで自動生成したプロジェクトの名前空間).AllCommon.S2Dao
> >> 下にあるTxSettingクラスという認識でよろしいしょうか。
> >
> > はい、この名前空間に作られる TxSetting です。
> >
> >> ２．
> >> > <datasource name="DS1">
> >> > sqlserver の接続情報
> >> > </datasource>
> >>
> >> このセクションには<class>という項目があるはずなのですが
> >> そこに設定されているクラスも差し支えなければ
> >> 教えていただけないでしょうか。
> >
> > <class>Seasar.Extension.Tx.Impl.TxDataSource</class> です。
> >
> >
> > ちょっと探っていたところ、少し進展というか不思議な現象がおきました。
> > 別スレッドで 10 秒毎に DS2 でトランザクションを利用するサービス処理を追
> > 加してみたところ、DS2 のデータソースに関してのみトランザクションがうまく
> > いくようになりました。
> >
> > 別スレッドで一旦コネクションを利用すればいけるのかと思い、他の DS に関し
> > ても同じようにダミー SQL をはくようなサービス処理を追加してみました。
> > しかし、他の DS ではトランザクションの制御がうまくいきませんでした。
> >
> > ちなみに、うまくトランザクションが制御されるときは SQL 発行直前の「論理
> > 的なコネクションを取得しました」というログが出ませんでした。
> >
> > ---------トランザクション成功ログ抜粋 -----------
> > - DataSourceName=DS1
> > - 論理的なコネクションを取得しました
> > - トランザクションを開始します
> > - MethodAaa Start
> > - # DBFlute のログが数行
> > - SQL ログ INSERT AaaTable .....
> > - 論理的なコネクションを閉じました
> > - MethodAaa End
> > - トランザクションをロールバックしました
> > - DataSourceName=DS1
> > - 論理的なコネクションを閉じました
> > -------------------------------------------------
> >
> >
> > よろしくお願いします。
> >
> >
> >> 高井さん
> >>
> >> 小谷です。
> >>
> >> ご回答ありがとうございます。
> >>
> >> データベースの指定の方は問題ないようですね。
> >>
> >> 恥ずかしながらこちらではまだ問題が再現できていない状態です。
> >> さすがにないと思いつつ念のためもう二点確認させてください。
> >>
> >> １．
> >> >XxxTxSetting は DBFlute で生成されたままで
> >>
> >> このDBFluteが自動生成しているXxxTxSettingは
> >> (DBFluteで自動生成したプロジェクトの名前空間).AllCommon.S2Dao
> >> 下にあるTxSettingクラスという認識でよろしいしょうか。
> >>
> >> ２．
> >> > <datasource name="DS1">
> >> > sqlserver の接続情報
> >> > </datasource>
> >>
> >> このセクションには<class>という項目があるはずなのですが
> >> そこに設定されているクラスも差し支えなければ
> >> 教えていただけないでしょうか。
> >>
> >> 以上です。
> >> よろしくお願いします。
> >>
> >> 2008/12/09 23:25 高井朋幸 <[E-MAIL ADDRESS DELETED]>:
> >> > 小谷様
> >> > 高井です。
> >> >
> >> > お忙しい中返信ありがとうございます。
> >> > 業務上ログや設定をそのままお見せできませんので、主要な部分をお伝えします。
> >> >
> >> >
> >> >> １．XxxTxSettingのDataSourceNameと
> >> >> _aaaBhv（aaaDao）で使われているXxxDaoSettingのDataSourceNameが
> >> >> 同じになっているか
> >> >
> >> > 同じになっています。
> >> > 各 DB へのアクセスはトランザクションを無視すれば正常に行われます。
> >> >
> >> >
> >> >> ２．app.config（Seasar.Quill.dll.config）のquillセクションの内容
> >> > 以下のように３つのデータソースが定義されています。
> >> > <quill>
> >> > <datasources>
> >> > <datasource name="DS1">
> >> > sqlserver の接続情報
> >> > </datasource>
> >> > <datasource name="DS2">
> >> > sqlserver2 の接続情報
> >> > </datasource>
> >> > <datasource name="DS3">
> >> > sqlserver3 の接続情報
> >> > </datasource>
> >> > </datasources>
> >> > <assemblys>
> >> > 読み込むアセンブリの記述
> >> > </assemblys>
> >> > </quill>
> >> >
> >> >
> >> >> ３．ログにはデータソース名も出力されているはずなので
> >> >> 出力されているデータソース名
> >> >
> >> > 今ログが手元にないのでデータソース名を付加したログを記述します。
> >> > 以下のように接続すべきデータソースからコネクションを取得できています。
> >> >
> >> > ---------------------- ログ抜粋 ------------------
> >> > - DataSourceName=DS1
> >> > - 論理的なコネクションを取得しました
> >> > - トランザクションを開始します
> >> > - MethodAaa Start
> >> > - # DBFlute のログが数行
> >> > - DataSourceName=DS1
> >> > - 論理的なコネクションを取得しました
> >> > - SQL ログ INSERT AaaTable .....
> >> > - 論理的なコネクションを閉じました
> >> > - DataSourceName=DS1
> >> > - MethodAaa End
> >> > - トランザクションをロールバックしました
> >> > - DataSourceName=DS1
> >> > - 論理的なコネクションを閉じました
> >> > -------------------------------------------------
> >> >
> >> > よろしくお願いします。
> >> >
> >> >
> >> >> 高井さん
> >> >>
> >> >> 小谷です。
> >> >>
> >> >> 現在すぐに確認するのは難しい状態なので
> >> >> 調査するのはもう少し後になると思いますが、
> >> >> 以下の点について教えていただけますでしょうか。
> >> >>
> >> >> １．XxxTxSettingのDataSourceNameと
> >> >> _aaaBhv（aaaDao）で使われているXxxDaoSettingのDataSourceNameが
> >> >> 同じになっているか
> >> >>
> >> >> ２．app.config（Seasar.Quill.dll.config）のquillセクションの内容
> >> >>
> >> >> ３．ログにはデータソース名も出力されているはずなので
> >> >> 出力されているデータソース名
> >> >>
> >> >> よろしくお願いします。
> >> >>
> >> >> 2008/12/09 13:45 高井朋幸 <[E-MAIL ADDRESS DELETED]>:
> >> >>> 高井です。
> >> >>> お世話になっております。
> >> >>>
> >> >>>
> >> >>> Quill+DBFlute の Windows アプリでインスタンスもスキーマの異なる複数のＤＢに
> >> >>> 接続する環境下でトランザクションの制御に失敗します。
> >> >>> もしかすると単数ＤＢでも datasource name="" の name 属性を使うと起きるかも
> >> >>> しれません。
> >> >>> 確認していただけると幸いです。
> >> >>>
> >> >>> ADO でベタなコードを書いて実行してみたところ正常にトランザクションが制御さ
> >> >>> れたので環境回りは大丈夫だと思います。
> >> >>>
> >> >>>
> >> >>> Transaction 属性をつけたメソッド内で DBFlute の Bhv を呼んで更新する処理が
> >> >>> あるのですが、ログにはトランザクションの開始とロールバックが記述されている
> >> >>> のに、実際のテーブルにはデータが書き込まれたままになってしまいます (下記参照)
> >> >>> 。
> >> >>> XxxTxSetting は DBFlute で生成されたままで LocalRequiredTxHandler が利用さ
> >> >>> れています。
> >> >>> このメソッドでは１つのデータベースにしかアクセスされません。
> >> >>>
> >> >>> SQL 実行前にもう一度コネクションを取得しているログが気になります。
> >> >>> ここで最初にトランザクションを作り出したコネクションと違うコネクションが割
> >> >>> り当てられているのではないかと思いました。
> >> >>>
> >> >>>
> >> >>> ブレークポイントを利用し SQL の実行直後にコミット・ロールバックする前で
> >> >>> 停止してテーブルのデータを見たところデータが入っていました。
> >> >>> それからもトランザクション制御されていないコネクションが利用されているよう
> >> >>> な感じでした。
> >> >>>
> >> >>>
> >> >>> ----------------------- コード -------------------
> >> >>> protected AaaBhv _aaaBhv;
> >> >>> [Transaction(XxxTxSetting)]
> >> >>> public virtual void MethodAaa() {
> >> >>> Logger.Info("MethodAaa Start");
> >> >>> try {
> >> >>> Aaa aaaEntity = CreateAaaEntity();
> >> >>> _aaaBhv.Insert(aaaEntity);
> >> >>> throw new Exception("test");
> >> >>> } finally {
> >> >>> Logger.Info("MethodAaa End");
> >> >>> }
> >> >>> }
> >> >>>
> >> >>> ---------------------- ログ抜粋 ------------------
> >> >>> - 論理的なコネクションを取得しました
> >> >>> - トランザクションを開始します
> >> >>> - MethodAaa Start
> >> >>> - # DBFlute のログが数行
> >> >>> - 論理的なコネクションを取得しました
> >> >>> - SQL ログ INSERT AaaTable .....
> >> >>> - 論理的なコネクションを閉じました
> >> >>> - MethodAaa End
> >> >>> - トランザクションをロールバックしました
> >> >>> - 論理的なコネクションを閉じました
> >> >>>
> >> >>> -------------------------------------------------
> >> >>>
> >> >>> よろしくお願いいたします。
> >> >>>
> >> >>> _______________________________________________
> >> >>> seasar-dotnet mailing list
> >> >>> [E-MAIL ADDRESS DELETED]
> >> >>> https://ml.seasar.org/mailman/listinfo/seasar-dotnet
> >> >>>
> >> >> _______________________________________________
> >> >> seasar-dotnet mailing list
> >> >> [E-MAIL ADDRESS DELETED]
> >> >> https://ml.seasar.org/mailman/listinfo/seasar-dotnet
> >> >>
> >> >
> >> >
> >> > --
> >> > Takai ICT 株式会社
> >> > 高井朋幸 <[E-MAIL ADDRESS DELETED]>
> >> > TEL: 090-6192-6789
> >> >
> >> > _______________________________________________
> >> > seasar-dotnet mailing list
> >> > [E-MAIL ADDRESS DELETED]
> >> > https://ml.seasar.org/mailman/listinfo/seasar-dotnet
> >> >
> >> _______________________________________________
> >> seasar-dotnet mailing list
> >> [E-MAIL ADDRESS DELETED]
> >> https://ml.seasar.org/mailman/listinfo/seasar-dotnet
> >
> > --
> > Takai ICT 株式会社
> > 高井朋幸 <[E-MAIL ADDRESS DELETED]>
> > TEL: 090-6192-6789
> > http://www.takaiict.com/
> > _______________________________________________
> > seasar-dotnet mailing list
> > [E-MAIL ADDRESS DELETED]
> > https://ml.seasar.org/mailman/listinfo/seasar-dotnet
> >
> _______________________________________________
> seasar-dotnet mailing list
> [E-MAIL ADDRESS DELETED]
> https://ml.seasar.org/mailman/listinfo/seasar-dotnet
--
Takai ICT 株式会社
高井朋幸 <[E-MAIL ADDRESS DELETED]>
TEL: 090-6192-6789
http://www.takaiict.com/
seasar-dotnet メーリングリストの案内