さて前回は、トレード用ＰＣで障害が発生した場合に、予備のＰＣに切り替えるための設計バグとデモ口座期限切れ時の作業効率化対策について書きました。今回は予定から外れて、以前の「OrderSelect問題の再発？それとも新たな問題？」という記事で書いた問題が再発した話を書いてみたいと思います。
そもそも、「OrderSelect問題パート２」ってなんやったんかというと、ＳＬ決済されたオーダをOrderSelect(SELECT_BY_TICKET)するとみつからなかったのでエラーになったという話。その時は通信障害が発生していた。
その時のブログ記事では、「通信障害復活後のOrderSelect(MODE_HISTORY)が不完全な状態となるタイミングがありそう。start()関数の排他制御をしていない事が起因していたのではないか」と結論付けていて、start()の排他制御をする事で、他の対処しないことにしていた。
しかし。
今回発生したのは、start()関数を排他利用する設定していたデモ環境で、しかも発生したデモ環境のＦＸ会社も違う。ＭＴ４クライアントのビルド番号も、前回はBuild229で、今回はBuild392。でも、通信障害発生後という点が共通している。
さて、今回もつまんないけど、まずは各種ログから。
【発生状況と各種ログ】
－－－－－－－－－－－－－－－－－－－－－－－－－－－－
今回は２件のオーダでほぼ同時に発生。おおきな流れで言うと、以下の通り。
●発生事象の大まかな流れ
16:34:36 通信障害検出
IsConnected()が、2100ミリ秒単位で150回連続でFALSEを返却したのでメール送信
IsConnected()が、2100ミリ秒単位で150回連続でFALSEを返却したのでメール送信
（つまり、５分１５秒間IsConnected()がFALSEなので、16:29:21から障害発生）
16:34:38 操作履歴タブ上で、「login」が出力
16:35:15 操作履歴タブ上で、「DataCenter connecting failed [6]」が出力
16:35:16 IsConnected()がTRUEを返却
16:36:16 操作履歴タブ上で、「cannot login [No connection]」が出力
16:36:20～16:36:22 OrderModify２回成功
16:36:23 今回事象がEURCHFで発生（チケット番号：107083791）
16:36:26 今回事象がCHFJPYで発生（チケット番号：107083110）
●メール
・受信日時 2011/7/28 16:32
[[WARN]][DEMO][FXDD Malta][TEST3]EURCHF(Sample1:51209945)(Ticket:0)WriteTradeLog:OrderSelect:Ticket(107083791) OrderTicket(0):errno:4105:no order selected
・受信日時 2011/7/28 16:32
[[WARN]][DEMO][FXDD Malta][TEST3]CHFJPY(Sample1:51209945)(Ticket:0)WriteTradeLog:OrderSelect:Ticket(107083110) OrderTicket(0):errno:4105:no order selected
●「Experts」タブ上のログ
16:29:22 SmoothMADILong GBPUSD,M5: [[DEBUG]](1.1Z):Tick(328708500)FWModifyOrder():END!! : Specified SL price is far from previous SL16:34:35 AHFW_HC EURUSD,Monthly: [[AHFW_HC]][[WARN]][DEMO][FXDD Malta][TEST3](AHFW_HC) Connection was closed.:errno:0:no error16:35:16 Sample1 CADJPY,M5: [[DEBUG]](1.1Z):Tick(329061093)FWModifyOrder():START!!16:35:16 Sample1 CADJPY,M5: [[DEBUG]](1.1Z):Tick(329061093)FWModifyOrder():END!! : Specified SL price is far from previous SL16:35:16 SmoothMADILong USDCHF,M5: [[DEBUG]](1.1Z):Tick(329061109)[[CALLBACK]]:EAOnBarChanged was called16:35:16 SmoothMADILong USDCHF,M5: [[DEBUG]](1.1Z):Tick(329061109)FWModifyOrder():START!!16:35:16 AHFW_HC EURUSD,Monthly: [[AHFW_HC]][[INFO]][DEMO][FXDD Malta][TEST3](AHFW_HC) Connection was opened.:errno:0:no error16:36:16 SmoothMADILong USDCHF,M5: [[INFO]][DEMO][FXDD Malta][TEST3]USDCHF(SmoothMADILong:22301840)(Ticket:107084375)FWModifyOrder Ticket(107084375) , SlPrice(0.80005000) , TargetPrice(0.00000000) Ask(0.80245000) Bid(0.80212000) : Retry after long time.:errno:128:trade timeout16:36:16 SmoothMADILong USDCHF,M5: [[INFO]][DEMO][FXDD Malta][TEST3]USDCHF(SmoothMADILong:22301840)(Ticket:107084375)Wait for next tick to OrderModify().:errno:0:no error16:36:16 SmoothMADILong GBPJPY,M5: [[DEBUG]](1.1Z):Tick(329121843)[[CALLBACK]]:EAOnBarChanged was called16:36:16 SmoothMADILong GBPJPY,M5: [[DEBUG]](1.1Z):Tick(329122875)FWModifyOrder():START!!16:36:16 SmoothMADILong GBPJPY,M5: [[DEBUG]](1.1Z):Tick(329122875)FWModifyOrder():END!! : Specified SL price is far from previous SL16:36:17 SmoothMADILong USDCHF,M5: [[DEBUG]](1.1Z):Tick(329124015)FWModifyOrder():START!!16:36:19 SmoothMADILong USDCHF,M5: modify #107084375 buy stop 0.34 USDCHF at 0.80276 sl: 0.80005 tp: 0.00000 ok16:36:19 SmoothMADILong USDCHF,M5: [[DEBUG]](1.1Z):Tick(329125609)FWModifyOrder():END!! SlPrice(0.80005000) , TargetPrice(0.00000000)16:36:19 SmoothMADILong GBPUSD,M5: [[DEBUG]](1.1Z):Tick(329125625)[[CALLBACK]]:EAOnBarChanged was called16:36:20 SmoothMADILong GBPUSD,M5: [[DEBUG]](1.1Z):Tick(329126687)FWModifyOrder():START!!16:36:21 SmoothMADILong GBPUSD,M5: modify #107083111 sell 0.35 GBPUSD at 1.63156 sl: 1.63470 tp: 0.00000 ok16:36:21 SmoothMADILong GBPUSD,M5: [[DEBUG]](1.1Z):Tick(329127156)FWModifyOrder():END!! SlPrice(1.63470000) , TargetPrice(0.00000000)16:36:21 Sample1 EURCHF,M5: [[DEBUG]](1.1Z):Tick(329127593)Order was loss cutted:StatTicket(107083791) , FWOrderCond(0)16:36:21 Sample1 EURCHF,M5: [[WARN]][DEMO][FXDD Malta][TEST3]EURCHF(Sample1:51209945)(Ticket:0)WriteTradeLog:OrderSelect:Ticket(107083791) OrderTicket(0):errno:4105:no order selected16:36:21 Sample1 EURCHF,M5: [[DEBUG]](1.1Z):Tick(329127609)Order was closed16:36:22 SmoothMADILong USDJPY,M5: [[DEBUG]](1.1Z):Tick(329127968)[[CALLBACK]]:EAOnPendingOrderOpened was called16:36:22 SmoothMADILong USDJPY,M5: [[DEBUG]](1.1Z):Tick(329127968)[[CALLBACK]]:EAOnBarChanged was called16:36:23 SmoothMADILong USDJPY,M5: [[DEBUG]](1.1Z):Tick(329129156)FWModifyOrder():START!!16:36:23 SmoothMADILong USDJPY,M5: [[DEBUG]](1.1Z):Tick(329129156)FWModifyOrder():END!! : Specified SL price is far from previous SL16:36:24 Sample1 CHFJPY,M5: [[DEBUG]](1.1Z):Tick(329130453)Order was loss cutted:StatTicket(107083110) , FWOrderCond(0)16:36:24 Sample1 CHFJPY,M5: [[WARN]][DEMO][FXDD Malta][TEST3]CHFJPY(Sample1:51209945)(Ticket:0)WriteTradeLog:OrderSelect:Ticket(107083110) OrderTicket(0):errno:4105:no order selected16:36:24 Sample1 CHFJPY,M5: [[DEBUG]](1.1Z):Tick(329130453)Order was closed
●「操作履歴」タブ上のログ
16:29:21 '67010737': modify order #107083830 sell 0.25 EURUSD at 1.43346 sl: 1.43793 tp: 0.00000 -> sl: 1.43790 tp: 0.0000016:29:21 '67010737': request was accepted by server16:29:21 '67010737': request in process16:29:21 '67010737': order #107083830 sell 0.25 EURUSD at 1.43346 was modified -> sl: 1.43790 tp: 0.0000016:34:36 Mail: '[[AHFW_HC]][[WARN]][DEMO][FXDD Malta][TEST3](AHFW_HC) Connection was closed.' has been sent16:34:38 '67010737': login16:35:15 '67010737': DataCenter connecting failed [6]16:35:16 Mail: '[[AHFW_HC]][[INFO]][DEMO][FXDD Malta][TEST3](AHFW_HC) Connection was opened.' has been sent16:36:16 '67010737': cannot login [No connection]16:36:20 '67010737': modify pending order #107084375 buy stop 0.34 USDCHF at 0.80276 sl: 0.80004 tp: 0.00000 -> price: 0.80276 sl: 0.80005 tp: 0.0000016:36:20 '67010737': request was accepted by server16:36:20 '67010737': request in process16:36:20 '67010737': pending order #107084375 buy stop 0.34 USDCHF was modified -> price: 0.80276 sl: 0.80005 tp: 0.0000016:36:21 '67010737': modify order #107083111 sell 0.35 GBPUSD at 1.63156 sl: 1.63474 tp: 0.00000 -> sl: 1.63470 tp: 0.0000016:36:22 '67010737': request was accepted by server16:36:22 '67010737': request in process16:36:22 '67010737': order #107083111 sell 0.35 GBPUSD at 1.63156 was modified -> sl: 1.63470 tp: 0.0000016:36:23 Mail: '[[WARN]][DEMO][FXDD Malta][TEST3] EURCHF(0):WriteTradeLog:OrderSelect:Ticket(107083791) OrderTicket(0)' has been sent16:36:25 '67010737': instant order sell 0.01 CHFJPY at 96.814 sl: 96.984 tp: 96.75616:36:25 '67010737': request was accepted by server16:36:25 '67010737': request in process16:36:25 '67010737': order was opened : #107084895 sell 0.01 CHFJPY at 96.814 sl: 96.984 tp: 96.75616:36:26 Mail: '[[WARN]][DEMO][FXDD Malta][TEST3] CHFJPY(0):WriteTradeLog:OrderSelect:Ticket(107083110) OrderTicket(0)' has been sent
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
さて、問題はここから。
ＭＴ４クライアントの「取引」タブと、「口座履歴」タブ上で、問題となった二つのチケット番号（107083791 / 107083110）を探して見た。
無い。
【口座履歴の状況】
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
以下、口座履歴を注文番号で昇順にソートして、問題となったチケット番号付近の行を選択している。
１．チケット番号：107083791
２．チケット番号：107083110
むむむ。。。
サーバから「口座履歴」の情報を取得するのに失敗してる？？
そして、「口座履歴」タブから、「詳細レポートの保存」して、確証を保存。
ＨＴＭＬ形式ファイルをブラウザで開いて、該当チケット番号を検索してみてもやっぱり無い。
ログも再取得したし、該当チケット番号が結局いつどうなったのかを確認したいので、
ＭＴ４を再起動。
ＭＴ４を再起動。
そして、「口座履歴」タブを見てみると。
【ＭＴ４再起動後の口座履歴の状況】
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
以下、口座履歴を注文番号で昇順にソートして、問題となったチケット番号を選択している。
＃これも「詳細レポートの保存」して確認した～
１．チケット番号：107083791
２．チケット番号：107083110
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
復活しとるやんけ。
ＭＴ４のバグやん。
【決済されたのはどのタイミングか調べてみた】
－－－－－－－－－－－－－－－－－－－－－－－－－－
「口座履歴」上の時刻はサーバ時刻だと思うので、ログ出力時刻と時差がある。なので、約定時刻と決済時刻の差異から、想定されるＳＬ／ＴＰ決済された、ＰＣ側時刻を求めて見ると。
１．チケット番号：107083791
●「操作履歴」タブ上での発注時ログ
16:09:56 '67010737': instant order sell 0.01 EURCHF at 1.15017 sl: 1.15228 tp: 1.1487716:09:56 '67010737': request was accepted by server16:09:56 '67010737': request in process16:09:56 '67010737': order was opened : #107083791 sell 0.01 EURCHF at 1.15017 sl: 1.15228 tp: 1.14877
発注後25分後にＳＬ決済されているので、ＰＣ時刻に換算すると、16:34前後にＳＬ決済 された模様。丁度IsConnected()がFALSEを返している間か、ログイン中。
２．チケット番号：107083110
●「操作履歴」タブ上での発注時ログ
15:49:13 '67010737': instant order sell 0.01 CHFJPY at 96.950 sl: 97.096 tp: 96.89415:49:13 '67010737': request was accepted by server15:49:13 '67010737': request in process15:49:13 '67010737': order was opened : #107083110 sell 0.01 CHFJPY at 96.950 sl: 97.096 tp: 96.894
発注後46分後にＴＰ決済されているので、ＰＣ時刻に換算すると16:35前後にＴＰ決済された模様。
「DataCenter connecting failed [6]」発生してから、IsConnected()がTRUEを返却し
始めた頃。
始めた頃。
－－－－－－－－－－－－－－－－－－－－－－－－－－
絶対ＭＴ４のバグ。
しかも、タチが悪いのは、ＭＴ４を再起動しないと正しい情報にならない点。
一体どうせよと？？
【対応検討】
－－－－－－－－－－－－－－－－－－－－－－－－
「口座履歴」上に表示されてないデータをOrderSelect()できるわけないやん。
つまり、前回対応案で考えてた、OrderSelect(SELECT_BY_TICKET)をリトライしてもムダ。。。
それでも、対応案を４つ考えて見た。
案１．文句を言う
案２．苦情を言う
案３．やけ酒を飲む
案４．泣き寝入りをする
解決するんかい
そもそも、今回OrderSelect(SELECT_BY_TICKET)で失敗した箇所はログを出力するロジック。
そして、失敗した時は実際にサーバ障害中にＳＬ／ＴＰ決済されていたのも事実。
期待を込めた仮説を立てると、OrderSelect(SELECT_BY_TICKET)が不正になるのは、ＳＬ／ＴＰによる決済された場合のみ。
勘で言うと、サーバ側のバグなんじゃないかなと。
つまり、ＭＴ４クライアントに「口座履歴」情報を送るとき、ロック中のオーダが欠落してる感じ。
妄想だけど、前回の仮説検証結果を踏まえると、ＭＴ４クライアントじゃない雰囲気。
なので、「案４．泣き寝入りをする」に決定！！
－－－－－－－－－－－－－－－－－－－－－－－－
それはそれとして、ライブ口座で発生したらどうするか？
【発生時の運用】
－－－－－－－－－－－－－－－－－－－－－－－－
対処しようが無いので、それをよしとすると、実際にライブ口座で発生した場合どうするのか。
一番怖いのは、実は決済されていないパターン。
実は、ＭＴ４用ＥＡ開発共通部品「ahfw」にデモ口座期限切れ対策で追加した仕様があって、内部管理しているチケット番号がゼロ（つまり保有オーダが無いという認識）なのに、OrderSelectループで同じMAGIC＋通貨ペアのオーダを発見したら、決済する機能を付けた。
＃まだ公開してないけど。。
今回のケースだと、内部管理のチケット番号はゼロになるので、上記の仕様で実際にはＳＬ／ＴＰによる決済がされてなくても、自動で決済される事になる。
という事を踏まえると、実は決済されてないのに、決済されたと誤検知するケースがあったとしても、野放しになるオーダは残らない事になる。
＃トレードパフォーマンスに影響は出るけど。。。
あと、しないといけない事は、システム停止判定に使う為に独自出力しているトレードログ。
これに出力されない結果になるので、後で手打ちで入力するぐらいしかない。
－－－－－－－－－－－－－－－－－－－－－－－－
なので、発生しても緊急で何かしないといけないって事は無い。
めでたしめでたし。
というか、ＭＴ４なおしてよ。
そして、start()排他制御では効果が無かった事にショックを受けながら、「FXシステムトレード初心者奮闘記」の「ＭＴ４用ＥＡ開発時代」は、今度こそ設計書書いてよかった事について進むのでした。
＃ちなみに最初の「OrderSelect問題」はstart()排他制御設定後、再発してない！
0 件のコメント:
コメントを投稿