ＭＴ４用ＥＡ開発時代 － OrderSelect問題の再発？それとも新たな問題？

さて前回は、ＭＴ４用ＥＡ共通部品「ahfw」とＭＴ４障害監視システム「ahfw_hc」のスレッド障害対応に苦戦した様を書きました。今回は久しぶりに発生した問題２件のうちOrderSelectがらみの方について書いてみたいと思います。

今朝起きて見ると。警告メールが。

内容をぱっと見てみると。

「OrderSelect問題」が再発した！！

あれ？もう一個ヘンなのが来てるぞ？

今回発生した問題は２点で、記事の内容は下記のうち「１．」の方。

【発生事象】

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

１．ログ出力処理でOrderSelect(SELECT_BY_TICKET)がFALSEを返却

２．発注しようとしたバーで結局発注できなかった旨のメール受信

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

発生状況から言うと、「OrderSelect問題」への暫定対処として、start()を排他制御

する処理を入れていたけど、４つのデモ環境のうち１つだけ排他制御しない様に

パラメータ設定をしていた。今回問題発生したのはstart()の排他制御していなかったデモ環境。

【発生事象分析】

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

事象の大雑把に書くと、ＳＬにひっかかったのでＥＡが認識しているチケット番号で、

OrderSelect(SELECT_BY_TICKET)して、その結果をログ出力するという処理で発生。

でも、OrderSelect(SELECT_BY_TICKET)からFALSEが返却されたのでエラーとなった。

ついに「OrderSelect問題」が再発した！！

と思ってログを見てみると。

問題のログの箇所は一番下の赤色下線部分。他の赤色は、後ほど時刻の前後関係で登場。

●Expertタブ上のログ

05:01:29 Sample1 EURGBPfxf.,M5: [[INFO]][DEMO][FOREX.com Japan][TEST1]EURGBPfxf.(Sample1:51209945)(Ticket:5835746)FWClosePositions():OrderClose Retry cause IsTradeAllowed() return FALSE or another error was occurred.  Ticket(5835746):errno:146:trade context is busy

05:02:00 Sample1 EURGBPfxf.,M5: [[INFO]][DEMO][FOREX.com Japan][TEST1]EURGBPfxf.(Sample1:51209945)(Ticket:5835746)FWClosePositions():OrderClose Failed to OrderClose cause order was closed. Ticket(5835746):errno:2:common error

05:02:00 Sample1 EURGBPfxf.,M5: [[DEBUG]](1.1V):Tick(186865375)FWClosePositions():END(Success)!!

05:02:00 Sample1 EURGBPfxf.,M5: [[DEBUG]](1.1V):Tick(186865375)[[CLOSE]]:Ticket(5835746)

05:02:00 Sample1 EURGBPfxf.,M5: [[DEBUG]](1.1V):Tick(186865375)Order was closed

05:05:40 SmoothMADILong GBPUSDfxf.,M5: [[DEBUG]](1.1V):Tick(187085140)[[CALLBACK]]:EAOnBarChanged was called

05:05:40 Sample1 NZDJPYfxf.,M5: [[DEBUG]](1.1V):Tick(187085265)FWClosePositions():START!!

05:05:40 SmoothMADILong GBPUSDfxf.,M5: [[DEBUG]](1.1V):Tick(187085265)FWModifyOrder():START!!

05:05:40 SmoothMADILong GBPUSDfxf.,M5: [[DEBUG]](1.1V):Tick(187085265)FWModifyOrder():END!! : Specified SL price is far from previous SL 

05:05:40 Sample1 EURJPYfxf.,M5: [[DEBUG]](1.1V):Tick(187085375)FWToOrder() : Decided to order

05:05:40 Sample1 EURJPYfxf.,M5: [[DEBUG]](1.1V):Tick(187085375)FWSendOrderOrdinary():START!!

05:05:40 Sample1 EURJPYfxf.,M5: [[INFO]][DEMO][FOREX.com Japan][TEST1]EURJPYfxf.(Sample1:51209945)(Ticket:5836005)FWSendOrderOrdinary cmd(1),lots(0.02000000),openPrice(111.04000000),OrderSlippage(5),vSlPrice(110.85000000),vTpPrice(111.81000000),Ask(111.04000000),Bid(111.01000000) : Should re-calc:errno:136:off quotes

05:05:40 Sample1 EURJPYfxf.,M5: [[DEBUG]](1.1V):Tick(187087484)FWToOrder() : Decided to order

05:05:40 Sample1 EURJPYfxf.,M5: [[DEBUG]](1.1V):Tick(187087484)FWSendOrderOrdinary():START!!

05:05:42 Sample1 EURGBPfxf.,M5: [[DEBUG]](1.1V):Tick(187090296)FWToOrder() : Decided to order

05:05:42 Sample1 EURGBPfxf.,M5: [[DEBUG]](1.1V):Tick(187090296)FWSendOrderOrdinary():START!!

05:05:42 Sample1 EURGBPfxf.,M5: [[INFO]][DEMO][FOREX.com Japan][TEST1]EURGBPfxf.(Sample1:51209945)(Ticket:5836005)OrderSend : Retry cause IsTradeAllowed() return FALSE or another error was occurred.:errno:0:no error

05:05:42 SmoothMADILong GBPJPYfxf.,M5: [[DEBUG]](1.1V):Tick(187090296)[[CALLBACK]]:EAOnBarChanged was called

05:05:42 SmoothMADILong GBPJPYfxf.,M5: [[DEBUG]](1.1V):Tick(187090296)FWModifyOrder():START!!

05:05:42 SmoothMADILong GBPJPYfxf.,M5: [[INFO]][DEMO][FOREX.com Japan][TEST1]GBPJPYfxf.(SmoothMADILong:22301840)(Ticket:5835896)OrderModify : Retry cause IsTradeAllowed() return FALSE or another error was occurred.:errno:0:no error

05:05:42 Sample1 EURGBPfxf.,M5: [[INFO]][DEMO][FOREX.com Japan][TEST1]EURGBPfxf.(Sample1:51209945)(Ticket:5836005)OrderSend : Retry cause IsTradeAllowed() return FALSE or another error was occurred.:errno:0:no error

05:05:42 SmoothMADILong GBPJPYfxf.,M5: [[INFO]][DEMO][FOREX.com Japan][TEST1]GBPJPYfxf.(SmoothMADILong:22301840)(Ticket:5835896)OrderModify : Retry cause IsTradeAllowed() return FALSE or another error was occurred.:errno:0:no error

05:05:45 SmoothMADILong GBPJPYfxf.,M5: [[INFO]][DEMO][FOREX.com Japan][TEST1]GBPJPYfxf.(SmoothMADILong:22301840)(Ticket:5835896)OrderModify : Retry cause IsTradeAllowed() return FALSE or another error was occurred.:errno:0:no error

05:05:45 Sample1 EURGBPfxf.,M5: [[INFO]][DEMO][FOREX.com Japan][TEST1]EURGBPfxf.(Sample1:51209945)(Ticket:5836005)OrderSend : Retry cause IsTradeAllowed() return FALSE or another error was occurred.:errno:0:no error

05:05:45 SmoothMADILong GBPJPYfxf.,M5: [[INFO]][DEMO][FOREX.com Japan][TEST1]GBPJPYfxf.(SmoothMADILong:22301840)(Ticket:5835896)OrderModify : Retry cause IsTradeAllowed() return FALSE or another error was occurred.:errno:0:no error

05:05:45 Sample1 EURGBPfxf.,M5: [[INFO]][DEMO][FOREX.com Japan][TEST1]EURGBPfxf.(Sample1:51209945)(Ticket:5836005)OrderSend : Retry cause IsTradeAllowed() return FALSE or another error was occurred.:errno:0:no error

05:05:46 SmoothMADILong GBPJPYfxf.,M5: [[INFO]][DEMO][FOREX.com Japan][TEST1]GBPJPYfxf.(SmoothMADILong:22301840)(Ticket:5835896)OrderModify : Retry cause IsTradeAllowed() return FALSE or another error was occurred.:errno:0:no error

05:05:46 Sample1 EURGBPfxf.,M5: [[INFO]][DEMO][FOREX.com Japan][TEST1]EURGBPfxf.(Sample1:51209945)(Ticket:5836005)OrderSend : Retry cause IsTradeAllowed() return FALSE or another error was occurred.:errno:0:no error

05:05:47 SmoothMADILong GBPJPYfxf.,M5: [[INFO]][DEMO][FOREX.com Japan][TEST1]GBPJPYfxf.(SmoothMADILong:22301840)(Ticket:5835896)OrderModify : Retry cause IsTradeAllowed() return FALSE or another error was occurred.:errno:0:no error

05:05:47 Sample1 EURGBPfxf.,M5: [[INFO]][DEMO][FOREX.com Japan][TEST1]EURGBPfxf.(Sample1:51209945)(Ticket:5836005)OrderSend : Retry cause IsTradeAllowed() return FALSE or another error was occurred.:errno:0:no error

05:05:47 Sample1 USDCADfxf.,M5: [[DEBUG]](1.1V):Tick(187093109)Order was loss cutted:StatTicket(5835750) , FWOrderCond(0)

05:05:47 Sample1 USDCADfxf.,M5: [[WARN]][DEMO][FOREX.com Japan][TEST1]USDCADfxf.(Sample1:51209945)(Ticket:0)WriteTradeLog:OrderSelect:Ticket(5835750) OrderTicket(0):errno:4105:no order selected

という感じで、前回発生時とは異なり、別通貨ペアを操作した形跡はなし。

実際、口座履歴を見ると、OrderSelectで指定したチケット番号は正しい。

●口座履歴 

5835750 2011.07.13 04:30 buy 0.04 usdcadfxf. 0.9650 0.9656 0.9710  2011.07.13 05:04 0.9656 0 0 0 197 51209945 Sample11.1V[sl]

ちなみに、エラーを検出したロジックは以下。

●エラー検出したプログラム

// クローズしたオーダ情報を取得

if( (OrderSelect(StatTicket,SELECT_BY_TICKET)==FALSE) && (OrderTicket()!=StatTicket) )

{

    Errno = GetLastError();

    OnError(ERR_WARN , "WriteTradeLog:OrderSelect:Ticket("+StatTicket+") OrderTicket("+OrderTicket()+")");

    return;

}

あきらかに

OrderSelect()の

挙動がおかしい。

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

【仮説の検討】

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

次に、操作履歴上のエラー発生近辺ログを見ると。

●操作履歴ログ

05:01:58 '153141': order #5835746 sell 0.02 EURGBPfxf. closing at 0.8782 failed [Common error]

05:05:00 '153141': ping failed

05:05:00 '153141': connect failed [回線不通！]

05:05:06 '153141': login

05:05:20 '153141': login

05:05:49 Mail: '[[WARN]][DEMO][FOREX.com Japan][TEST1] USDCADfxf.(0):WriteTradeLog:OrderSelect:Ticket(5835750) OrderTicket(0)' has been sent

05:06:23 '153141': cannot connect to server

05:06:33 '153141': order #5835970 sell 0.01 NZDJPYfxf. closing at 65.01 failed [Trade context is busy]

05:06:33 TradeDispatcher: trade context is busy

05:06:34 '153141': order #5835970 sell 0.01 NZDJPYfxf. closing at 65.02 failed [Trade context is busy]

05:06:34 TradeDispatcher: trade context is busy

05:06:36 '153141': modify order #5835896 sell 0.68 GBPJPYfxf. at 126.44 sl: 127.11 tp: 0.00 -> sl: 127.10 tp: 0.00

05:06:36 '153141': request was accepted by server

05:06:36 '153141': request in process

05:06:36 '153141': order #5835896 sell 0.68 GBPJPYfxf. at 126.44 was modified -> sl: 127.10 tp: 0.00

ここで一番気になるのが、05:05:00から始まる通信障害と再ログイン。

＃「05:06:23」の状況を見ると、なんだかサーバが不安定な状況っぽい。。

ログから事象の流れを大雑把に書くと以下。

●事象の流れ

　１．回線不通状態発生

　２．USDCADの発注約定済みオーダがＳＬで決済

　３．回線状態復旧

　４．ＥＡがOrderSelect(SELECT_BY_POS)ループでUSDCADのオーダが

　　　無かったため、ＳＬ／ＴＰによる決済がされたと判断

　５．ログ出力の為のOrderSelect(SELECT_BY_TICKET)でFALSEが返却されエラー

そもそもＭＴ４起動時の動作を考えて見ると、「取引」タブや「口座履歴」タブの情報はサーバから取得されているはず。なのでＥＡ動作中の再ログイン時も同じ処理が走ってるんじゃないかと。

そして、OrderSelect()自身がGetLastError()にエラー情報を設定しないという事を考えると、OrderSelect()実行時は、メモリテーブルから取得している事が想定される。

とすると、OrderSelect()した時の取得元メモリテーブル上の情報は、ログイン時に再取得して、メモリテーブルを再構築するロジックが走るはず。

そして、そのメモリテーブルも「取引」タブ用と「口座履歴」タブ用に分かれている気がする。

理由は、OrderSelect(SELECT_BY_POS)の引数で、「MODE_TRADES」と「MODE_HISTORY」を指定できる点と、もし同じメモリテーブルであれば、OrderSelect(MODE_TRADES)をループさせる事が一般的な使い方だとすると、大量の口座履歴があった場合に、ループ速度が遅くなってしまうからそんなＭＴ４のツクリにはしないだろう、という妄想的且つ希望的理由。確証全くなし。

そして、今回の事象はそんなOrderSelect用メモリテーブル再構築中に発生した様に見える。

つまるところ、仮説としてはログイン直後のOrderSelect()の結果は不完全なタイミングがあるということ。実際ＳＬ決済されている点を踏まえると、不完全な状態になるのは「口座履歴」。

不完全な状態なのにstart()が開始してしまう様になってるとは普通は考えられない。

だけど、件数から考えると「口座履歴」はトレード履歴サーバから取得するのに時間がかかる。

なので、「取引」タブが完成すればstart()関数を動かし始めるのではないかと。

なので仮説を整理すると。

●仮説の整理

　仮説１．ＥＡ動作中に回線障害で再ログインが発生するとOrderSelect用テーブル

　　　　　　で不完全なタイミングがある。

　仮説２．ＥＡ動作中に回線障害で再ログインが発生すると「口座履歴」用のOrderSelect

　　　　　　テーブルだけで不完全なタイミングがある。

妄想を超えて、

暴走とも言う。。

少なくとも、前回の「OrderSelect問題」ではタイムアウト発生後に発生した事象で、再ログインは発生していない状態なので、状況が違う。しかも、今回の事象の仮説だと、start()関数を排他制御しても意味が無い事になってしまう。

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

【対処方法検討】

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

●処置内容１（仮説１の場合のみ）

　「取引」「口座履歴」両タブがで不完全なタイミングがあるという仮説の場合。

　ＳＬ／ＴＰ決済されていたかどうかのロジックで、OrderCloseTime()を見てない箇所があった。

　仮説が正しければ、ＳＬ／ＴＰに引っかかってなくても決済されたと誤判断される。

　OrderSelect(SELECT_BY_TICKET)してから、OrderCloseTime()がゼロじゃない事も確認する

　ロジックを追加する。

●処置内容２（仮説１の場合のみ）

　「取引」「口座履歴」両タブが不完全なタイミングがあるという仮説の場合。

　OrderSelect(SELECT_BY_POS)している箇所が２つあるが、これをどうするか。

　まずは、利用箇所。

　１．決済処理でMAGICと通貨ペアが一致するオーダを全て削除するFWClosePositions()という関数。

　２．前述のFWOrderCondを設定する、保有中ポジション状態を確認する

　　　FWGetCurrentOrderCondition()という関数。

　・上記「１．」の場合は、処理成功時に内部管理しているチケット番号でOrderSelect

　　(SELECT_BY_TICKET)のOrderCloseTime()がゼロになっているかを確認するロジック

　　を追加する。

　・上記「２．」の場合は、関数自体は処置しないけど、前述「処置内容１」のOrderCloseTime()

　　チェック追加で対応される事になる。

●処置内容２（仮説２の場合のみ）

　「口座履歴」だけに不完全なタイミングがある場合。

　OrderSelect(SELECT_BY_TICKET)では、スリープ＆リトライする。

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

【仮説を検証する】

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

仮説検証として、以下のＥＡを作成して検証してみた。

●検証１

　１．大量の取引履歴（３０００件程度）を表示させる様に設定

　２．履歴上のチケット番号の最初と最後をstart()直後にOrderSelect()を無限ループさせる

　　　→チケット番号が見つからなければその旨を表示させる。

　３．通信障害発生させる。（WirelessのスイッチをOFFにする）

　４．通信障害を復活させる。

　何回か実施してみたけど、再現せず。。。。

●検証２

　１．大量の取引履歴（３０００件程度）を表示させる様に設定

　２．SL/TPにひっかかる様にして成行きでOrderSend。OrderSend成功時に取得したチケット番号

　　　でOrderSelect()を無限ループするEAを複数通貨ペアで実行

　３．６つ程度の発注に成功したら、通信障害を発生させる

　４．ＭＴ４が回線障害を認識してて５分程度経過したら通信障害を復活させる

　　　→通信障害中にＳＬ／ＴＰによる決済がされてる。

　５．OrderSelect失敗の旨のログが出てれば仮説が実証されたと考える。

　何回か実施してみたけど、再現せず。。。

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

うーん。わからん。。。。

これ以上は時間のムダ！！

なんしか、４つのデモ口座環境のうち１つのＭＴ４で

start()排他制御中トレード数：3796トレード

start()排他制御を外して今回事象までのトレード数：1667トレード

という状況。他の３つのデモ口座環境ではおかしな事は発生してない！

＃ビルド番号は違うけど。。。でも１つは今回発生したビルドより古いんよね。。

なので、start()排他制御した状態で本番に臨む！

処置なんてせぇへん！！

元々のテスト計画を優先する！

＃もしかしたらそこでバグに気付くかもしれんし。。。

ヤケクソやん。。

そして、開き直って、「FXシステムトレード初心者奮闘記」の「ＭＴ４用ＥＡ開発時代」は、もう１つの警告メール調査に進むのでした。

＃ちなみに事象が発生したソースは前回記事でリリースしたバージョンです。。