2011/07/29

MT4用EA開発時代 - OrderSelect問題パート2が再発。絶対MT4のバグ!



さて前回は、トレード用PCで障害が発生した場合に、予備のPCに切り替えるための設計バグデモ口座期限切れ時の作業効率化対策について書きました。今回は予定から外れて、以前の「OrderSelect問題の再発?それとも新たな問題?」という記事で書いた問題が再発した話を書いてみたいと思います。

そもそも、「OrderSelect問題パート2」ってなんやったんかというと、SL決済されたオーダをOrderSelect(SELECT_BY_TICKET)するとみつからなかったのでエラーになったという話。その時は通信障害が発生していた。

その時のブログ記事では、「通信障害復活後のOrderSelect(MODE_HISTORY)が不完全な状態となるタイミングがありそう。start()関数の排他制御をしていない事が起因していたのではないか」と結論付けていて、start()の排他制御をする事で、他の対処しないことにしていた。





しかし。





今回発生したのは、start()関数を排他利用する設定していたデモ環境で、しかも発生したデモ環境のFX会社も違う。MT4クライアントのビルド番号も、前回はBuild229で、今回はBuild392。でも、通信障害発生後という点が共通している。


さて、今回もつまんないけど、まずは各種ログから。

【発生状況と各種ログ】
----------------------------
今回は2件のオーダでほぼ同時に発生。おおきな流れで言うと、以下の通り。

●発生事象の大まかな流れ
 16:34:36 通信障害検出
       IsConnected()が、2100ミリ秒単位で150回連続でFALSEを返却したのでメール送信
       (つまり、5分15秒間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 OrderModify2回成功
 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 SL 
16:34:35 AHFW_HC EURUSD,Monthly: [[AHFW_HC]][[WARN]][DEMO][FXDD Malta][TEST3](AHFW_HC) Connection was closed.:errno:0:no error
16: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 SL 
16:35:16 SmoothMADILong USDCHF,M5: [[DEBUG]](1.1Z):Tick(329061109)[[CALLBACK]]:EAOnBarChanged was called
16: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 error
16: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 timeout
16:36:16 SmoothMADILong USDCHF,M5: [[INFO]][DEMO][FXDD Malta][TEST3]USDCHF(SmoothMADILong:22301840)(Ticket:107084375)Wait for next tick to OrderModify().:errno:0:no error
16:36:16 SmoothMADILong GBPJPY,M5: [[DEBUG]](1.1Z):Tick(329121843)[[CALLBACK]]:EAOnBarChanged was called
16: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 SL 
16: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 ok
16: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 called
16: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 ok
16: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 selected
16:36:21 Sample1 EURCHF,M5: [[DEBUG]](1.1Z):Tick(329127609)Order was closed
16:36:22 SmoothMADILong USDJPY,M5: [[DEBUG]](1.1Z):Tick(329127968)[[CALLBACK]]:EAOnPendingOrderOpened was called
16:36:22 SmoothMADILong USDJPY,M5: [[DEBUG]](1.1Z):Tick(329127968)[[CALLBACK]]:EAOnBarChanged was called
16: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 SL 
16: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 selected
16: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.00000
16:29:21 '67010737': request was accepted by server
16:29:21 '67010737': request in process
16:29:21 '67010737': order #107083830 sell 0.25 EURUSD at 1.43346 was modified -> sl: 1.43790 tp: 0.00000
16:34:36 Mail: '[[AHFW_HC]][[WARN]][DEMO][FXDD Malta][TEST3](AHFW_HC) Connection was closed.' has been sent
16:34:38 '67010737': login
16: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 sent
16: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.00000
16:36:20 '67010737': request was accepted by server
16:36:20 '67010737': request in process
16:36:20 '67010737': pending order #107084375 buy stop 0.34 USDCHF was modified -> price: 0.80276 sl: 0.80005 tp: 0.00000
16:36:21 '67010737': modify order #107083111 sell 0.35 GBPUSD at 1.63156 sl: 1.63474 tp: 0.00000 -> sl: 1.63470 tp: 0.00000
16:36:22 '67010737': request was accepted by server
16:36:22 '67010737': request in process
16:36:22 '67010737': order #107083111 sell 0.35 GBPUSD at 1.63156 was modified -> sl: 1.63470 tp: 0.00000
16:36:23 Mail: '[[WARN]][DEMO][FXDD Malta][TEST3] EURCHF(0):WriteTradeLog:OrderSelect:Ticket(107083791) OrderTicket(0)' has been sent
16:36:25 '67010737': instant order sell 0.01 CHFJPY at 96.814 sl: 96.984 tp: 96.756
16:36:25 '67010737': request was accepted by server
16:36:25 '67010737': request in process
16:36:25 '67010737': order was opened : #107084895 sell 0.01 CHFJPY at 96.814 sl: 96.984 tp: 96.756
16:36:26 Mail: '[[WARN]][DEMO][FXDD Malta][TEST3] CHFJPY(0):WriteTradeLog:OrderSelect:Ticket(107083110) OrderTicket(0)' has been sent
--------------------------------------




さて、問題はここから。


MT4クライアントの「取引」タブと、「口座履歴」タブ上で、問題となった二つのチケット番号(107083791 / 107083110)を探して見た。








無い。





【口座履歴の状況】
-------------------------------
以下、口座履歴を注文番号で昇順にソートして、問題となったチケット番号付近の行を選択している。

1.チケット番号:107083791  
2.チケット番号:107083110
-------------------------------




むむむ。。。


サーバから「口座履歴」の情報を取得するのに失敗してる??


そして、「口座履歴」タブから、「詳細レポートの保存」して、確証を保存。
HTML形式ファイルをブラウザで開いて、該当チケット番号を検索してみてもやっぱり無い。


ログも再取得したし、該当チケット番号が結局いつどうなったのかを確認したいので、
MT4を再起動。


そして、「口座履歴」タブを見てみると。


【MT4再起動後の口座履歴の状況】
-------------------------------
以下、口座履歴を注文番号で昇順にソートして、問題となったチケット番号を選択している。
#これも「詳細レポートの保存」して確認した~

1.チケット番号:107083791
2.チケット番号:107083110
-------------------------------





復活しとるやんけ。





MT4のバグやん。



【決済されたのはどのタイミングか調べてみた】
--------------------------
「口座履歴」上の時刻はサーバ時刻だと思うので、ログ出力時刻と時差がある。なので、約定時刻と決済時刻の差異から、想定されるSL/TP決済された、PC側時刻を求めて見ると。

1.チケット番号:107083791
  ●「操作履歴」タブ上での発注時ログ
16:09:56 '67010737': instant order sell 0.01 EURCHF at 1.15017 sl: 1.15228 tp: 1.14877
16:09:56 '67010737': request was accepted by server
16:09:56 '67010737': request in process
16:09:56 '67010737': order was opened : #107083791 sell 0.01 EURCHF at 1.15017 sl: 1.15228 tp: 1.14877
  
  発注後25分後にSL決済されているので、PC時刻に換算すると、16:34前後にSL決済  された模様。丁度IsConnected()がFALSEを返している間か、ログイン中。

2.チケット番号:107083110
  ●「操作履歴」タブ上での発注時ログ
15:49:13 '67010737': instant order sell 0.01 CHFJPY at 96.950 sl: 97.096 tp: 96.894
15:49:13 '67010737': request was accepted by server
15:49:13 '67010737': request in process
15:49:13 '67010737': order was opened : #107083110 sell 0.01 CHFJPY at 96.950 sl: 97.096 tp: 96.894

  発注後46分後にTP決済されているので、PC時刻に換算すると16:35前後にTP決済された模様。
  「DataCenter connecting failed [6]」発生してから、IsConnected()がTRUEを返却し
  始めた頃。
--------------------------




絶対MT4のバグ。




しかも、タチが悪いのは、MT4を再起動しないと正しい情報にならない点。






一体どうせよと??



【対応検討】
------------------------
「口座履歴」上に表示されてないデータをOrderSelect()できるわけないやん。
つまり、前回対応案で考えてた、OrderSelect(SELECT_BY_TICKET)をリトライしてもムダ。。。

それでも、対応案を4つ考えて見た。




案1.文句を言う

案2.苦情を言う

案3.やけ酒を飲む

案4.泣き寝入りをする







解決するんかい



そもそも、今回OrderSelect(SELECT_BY_TICKET)で失敗した箇所はログを出力するロジック。
そして、失敗した時は実際にサーバ障害中にSL/TP決済されていたのも事実。
期待を込めた仮説を立てると、OrderSelect(SELECT_BY_TICKET)が不正になるのは、SL/TPによる決済された場合のみ。

勘で言うと、サーバ側のバグなんじゃないかなと。

つまり、MT4クライアントに「口座履歴」情報を送るとき、ロック中のオーダが欠落してる感じ。
妄想だけど、前回の仮説検証結果を踏まえると、MT4クライアントじゃない雰囲気。





なので、「案4.泣き寝入りをする」に決定!!
------------------------

それはそれとして、ライブ口座で発生したらどうするか?

【発生時の運用】
------------------------
対処しようが無いので、それをよしとすると、実際にライブ口座で発生した場合どうするのか。

一番怖いのは、実は決済されていないパターン。

実は、MT4用EA開発共通部品「ahfw」にデモ口座期限切れ対策で追加した仕様があって、内部管理しているチケット番号がゼロ(つまり保有オーダが無いという認識)なのに、OrderSelectループで同じMAGIC+通貨ペアのオーダを発見したら、決済する機能を付けた。
#まだ公開してないけど。。

今回のケースだと、内部管理のチケット番号はゼロになるので、上記の仕様で実際にはSL/TPによる決済がされてなくても、自動で決済される事になる。

という事を踏まえると、実は決済されてないのに、決済されたと誤検知するケースがあったとしても、野放しになるオーダは残らない事になる。
#トレードパフォーマンスに影響は出るけど。。。

あと、しないといけない事は、システム停止判定に使う為に独自出力しているトレードログ。
これに出力されない結果になるので、後で手打ちで入力するぐらいしかない。
------------------------

なので、発生しても緊急で何かしないといけないって事は無い。




めでたしめでたし。






というか、MT4なおしてよ。



そして、start()排他制御では効果が無かった事にショックを受けながら、「FXシステムトレード初心者奮闘記」の「MT4用EA開発時代」は、今度こそ設計書書いてよかった事について進むのでした。
#ちなみに最初の「OrderSelect問題」はstart()排他制御設定後、再発してない!

0 件のコメント:

コメントを投稿