【質問】注文約定照会の情報が更新されない場合がある

[flamingo4096]

注文約定照会API（/orders?id=XXX）をリクエストしても、情報が更新されない場合があり困っています。
おそらくですが、kabuステーション自体も約定できたことを認識できてないように見えるため、情報を更新する何かトリガがあれば教えていただきたいです。

概要

環境

Windows10、Python 3.10.11からurllib.requestを使用してAPIリクエストを実行。
注文発注後は、/ordersを使い約定したかをチェックしています。

状況

信用デイトレ新規成行買い発注後、即約定したにも関わらず、注文約定照会APIを実行しても
　State：2 処理中（発注送信中）
　OrderState：2 処理中（発注送信中）
　detail：[0]RecType：1 受付, State：3 処理済、[1]RecType：4 発注, State：2 処理中（発注送信中・訂正送信中・取消送信中）
が返ってくる場合がある。
この状況が3分間継続しました。

全約定した場合、
　OrderState：5 終了（発注エラー・取消済・全約定・失効・期限切れ）
となることを期待しています。

買えなかった場合、3分後にキャンセルするコードのため、3分以上放置した場合の状況は不明です。

考慮点

同じ情報が返ってくる状況のため、以下の点について考慮しています。
・流量制限
秒間10件までのため、1回リクエストするたびに0.1秒インターバルを空けています。
・リクエストのキャッシュ①
同一リクエストによるライブラリ内でのキャッシュ回避のため、実際のリクエストは
/orders?id=XXX&dummy=1721265272474848600
のように、毎回変化するダミーデータ(エポックナノ秒)を付加しています。
・リクエストのキャッシュ②
Pythonライブラリでのキャッシュクリア（urllib.request.urlcleanup()）をリクエスト毎に呼び出しています。

想定される発生条件？

起動後、しばらくは問題なく、今日は30分ぐらいしたら発生しました。
前日も起動直後は問題なく、しばらくしたら発生しました。
再現性はありそうです。

ログなど

ordersの結果

{'CashMargin': 2, 'MarginTradeType': 3, 'MarginPremium': None, 'ID': '20240718A02N18591828', 'State': 2, 'OrderState': 2, 'OrdType': 1, 'RecvTime': '2024-07-18T10:10:13.9905085+09:00', 'Symbol': '2897', 'SymbolName': '日清食品ホールディングス', 'Exchange': 1, 'ExchangeName': '東証プ', 'Price': 0.0, 'OrderQty': 100.0, 'CumQty': 0.0, 'Side': '2', 'AccountType': 4, 'DelivType': 0, 'ExpireDay': 20240718, 'Details': [{'SeqNum': 1, 'ID': '20240718A02N18591828', 'RecType': 1, 'ExchangeID': None, 'State': 3, 'TransactTime': '2024-07-18T10:10:13.9905085+09:00', 'OrdType': 1, 'Price': 0.0, 'Qty': 100.0, 'ExecutionID': None, 'ExecutionDay': None, 'DelivDay': 20240722, 'Commission': 0.0, 'CommissionTax': 0.0}, {'SeqNum': 3, 'ID': '20240718B02N18591829', 'RecType': 4, 'ExchangeID': None, 'State': 2, 'TransactTime': '2024-07-18T10:10:13.9905085+09:00', 'OrdType': 1, 'Price': 0.0, 'Qty': 100.0, 'ExecutionID': None, 'ExecutionDay': None, 'DelivDay': 20240722, 'Commission': 0.0, 'CommissionTax': 0.0}]}

状況発生時のKabuステーション上の表示

買い発注が注文中のステータスで、フル板に「消」ボタンが有効でした。
押してみたら、注文取り消しの遷移はしましたが、約定済みのためエラーになりました。

Kabuステーションのログ

新規買い発注したところからのログになります。
3分後に買えていないと判断してキャンセル発注するがエラー。
10:23:43にKabuステGUIから手動キャンセル発注するがエラー。

10:11:32.4117,I,7900,0010 ワンショットチェック : 2897/T/日清食品ホールディングス/1 : amount=200, qty=
10:11:32.4117,I,7900,0010 KabuSApiManager.PreRelationCheck=CHECK_OK
10:11:32.4127,I,7900,0010 発注パラメータ：[新規] 成行
10:11:32.4127,I,7900,0010 OrderManager.Order Start:OrderParam: Account=********,CheckMode=1,Symbol=2897,Exchange=1,SecurityType=1,Side=2,CashMargin=2,MarginTradeType=3,OrderCapacity=,Price=0,Qty=100,OrdType=1,AdjustPrice=False,SellingShot=DelivType=0,FundType=11,AccountType=4,EffectiveDay=20240718,ExpireDay=20240718,Trigger=[],OrderReferenceCommand=[],ClosePositions=[],PriceType=0,TimeInForce=0,ExpireSession=0,Password=xxx,FrontInfo=0,UsePoint=FrontInfo=[Key=FrontChannelID/Value=240,Key=Trader/Value=000000A7,Key=Channel/Value=0,Key=ClientCode/Value=***.***.***.***,Key=Branch/Value=000,],SettCurrency=0
10:11:32.6266,I,7900,0010 OrderManager.Order End  :Result=0,ID=20240718A02N18591828,ClOrdID=202407180AB54r043808,Detail=20240718B02N18591829,ResultMessage=[Key=KC_CommissionTable/Value=2001100,Key=KC_ConsignmentDepositRate/Value=30,Key=KC_Consideration/Value=490200,Key=KC_Commission/Value=0,Key=KC_CommissionTax/Value=0,Key=KC_DeliveryPrice/Value=490200,Key=KC_DepositRequirements/Value=147060.0,]
10:11:32.6266,I,7900,0010 UpdateOrderAndDetail Order.ID=20240718A02N18591828
10:11:32.6266,I,7900,0010 発注結果 : Result=0,ID=20240718A02N18591828,ClOrdID=202407180AB54r043808,Detail=20240718B02N18591829,ResultMessage=[Key=KC_CommissionTable/Value=2001100,Key=KC_ConsignmentDepositRate/Value=30,Key=KC_Consideration/Value=490200,Key=KC_Commission/Value=0,Key=KC_CommissionTax/Value=0,Key=KC_DeliveryPrice/Value=490200,Key=KC_DepositRequirements/Value=147060.0,]
10:13:10.5867,I,7900,0042 UpdateService.UpdateCheck : start
10:13:13.4570,I,7900,0037 KeepSession at 2024/07/18 10:11:54
10:14:32.4748,I,7900,0010 OrderManager.Cancel Start:CancelParam: Account=********,CheckMode=1,SecurityType=1,OrderID=20240718A02N18591828,Trigger=[],OrderReferenceCommand=[],Password=xxx,FrontInfo=FrontInfo=[Key=FrontChannelID/Value=240,Key=Trader/Value=000000A7,Key=Channel/Value=0,Key=ClientCode/Value=***.***.***.***,Key=Branch/Value=000,]
10:14:32.5062,I,7900,0010 OrderManager.Cancel End  :Result=43,ID=,ClOrdID=,Detail=,ResultMessage=Empty
10:14:32.5062,I,7900,0010 取消結果 Result=43,ClOrdID=,OrderID=,DetailID=
10:16:33.4573,I,7900,0015 KeepSession at 2024/07/18 10:15:14
10:19:53.4807,I,7900,0037 KeepSession at 2024/07/18 10:18:34
10:22:27.4011,I,7900,0001 SeriesDataProvider.Regist_Tick(SeriesKey : { Symbol=2897, Exchange=1, SecurityType=1,BidAsk= })
10:22:27.4311,I,7900,0005 GetTickServiceUrl UseSecurePort=False
10:22:33.8977,I,7900,0001 SOR利用不可のためSORは抽出しない : 2897/SOR
10:22:33.8977,I,7900,0001 SymbolSearcher.GetSymbolDetail() : missing QuoteCode : [2897/SOR]
10:22:33.8977,I,7900,0001 SOR利用不可のためSORは抽出しない : 1605/SOR
10:22:33.8977,I,7900,0001 SOR利用不可のためSORは抽出しない : 1332/SOR
10:22:33.8977,I,7900,0001 SOR利用不可のためSORは抽出しない : 5401/SOR
10:22:33.8977,I,7900,0001 SOR利用不可のためSORは抽出しない : 3402/SOR
10:22:33.8977,I,7900,0001 SOR利用不可のためSORは抽出しない : 4543/SOR
10:22:33.8977,I,7900,0001 SOR利用不可のためSORは抽出しない : 2212/SOR
10:22:33.8977,I,7900,0001 SymbolSearcher.GetSymbolDetail() : missing QuoteCode : [2212/SOR]
10:22:33.8977,I,7900,0001 SOR利用不可のためSORは抽出しない : 4661/SOR
10:22:33.8977,I,7900,0001 SymbolSearcher.GetSymbolDetail() : missing QuoteCode : [4661/SOR]
10:22:37.8003,I,7900,0033 SeriesDataProvider.Regist_Chart(SeriesKey : { Symbol=2897, Exchange=1, SecurityType=1,BidAsk= })
10:22:37.8266,I,7900,0037 GetTickServiceUrl UseSecurePort=False
10:22:44.5071,I,7900,0033 SeriesDataProvider.Regist_Chart(SeriesKey : { Symbol=2897, Exchange=1, SecurityType=1,BidAsk= })
10:22:44.5226,I,7900,0005 GetTickServiceUrl UseSecurePort=False
10:23:10.5937,I,7900,0006 UpdateService.UpdateCheck : start
10:23:13.4711,I,7900,0016 KeepSession at 2024/07/18 10:21:54
10:23:43.5227,I,7900,0001 OrderLog.Cancel: フル板(パネル)[10280673]/一覧から取消
10:23:44.5073,I,7900,0001 OrderLog.Confirm: 簡易訂正取消BOX[28694912]/はい
10:23:50.8496,I,7900,0001 OrderManager.Cancel Start:CancelParam: Account=********,CheckMode=1,SecurityType=1,OrderID=20240718A02N18591828,Trigger=[],OrderReferenceCommand=[],Password=xxx,FrontInfo=FrontInfo=[Key=FrontChannelID/Value=195,Key=Channel/Value=0,Key=ClientCode/Value=***.***.***.***,Key=Branch/Value=000,Key=Trader/Value=00000020,]
10:23:50.8812,I,7900,0001 OrderManager.Cancel End  :Result=43,ID=,ClOrdID=,Detail=,ResultMessage=Empty
10:23:50.8812,I,7900,0001 取消実行:完了省略=False,ID=20240718A02N18591828,result=Result=43,ID=,ClOrdID=,Detail=,ResultMessage=Empty
10:23:50.8812,I,7900,0001 取消実行Exit:result=Result=43,ID=,ClOrdID=,Detail=,ResultMessage=Empty
10:23:50.8812,I,7900,0001 result.OrderID=, result.Result=43, ResultMessage=Result=43,ID=,ClOrdID=,Detail=,ResultMessage=Empty

気になる点

①情報取得が正常なときは、Kabuステーションログに
　OrderDetail.ID=～～～
　のログが出ているようなので、Python側でリクエストが返されている可能性はある。

②①であったとしても、正常なときは、Kabuステーションログに
　「UpdatePosition=ID=～～～」
　で残高が更新されているはずだが、異常時はそのログがない。
　そのため、kabuステーション上の表示においても更新されていないのかもしれない。

[yasuyuki-nakazawa]

カブステｰションは日次で再起動されておりますでしょうか

[flamingo4096]

カブステｰションは日次で再起動されておりますでしょうか

はい。当日起動しております。

[flamingo4096]

@yasuyuki-nakazawa
本日また再現しましたので、追加ログを添付いたします。

Kabuステーション起動からのログ（アカウント等をマスクしたのみでそれ以外は編集なし）です。
20230723_kabslog.txt
09:14:44 に起動して、4回目の買い 09:29:32.4839 で再現しております。
今回もKabuステーション側のGUI表示は、買いの「依頼中」状態で止まっています。ただし、フル板の気配は随時更新されています。

口座のWeb板で注文を確認すると、
09:28 に注文受付・発注・全約定（分単位しか表示されない）、発注所要時間 21ミリ秒 とのことです。

今回は、Wiresharkで自作アプリ→Kabuステーションへのリクエストのログも併せて取得したところ、
20240723_localhostpcap.txt
買い発注後、orders のGETリクエストを定期的に実行し発注送信中状態のレスポンスが返ってきているため、自作アプリ側でリクエストが止まっていることはないと言えます。

ご確認よろしくお願い致します。

[flamingo4096]

同時刻のPC⇔インターネット側のログから、関係ありそうな20000ポートのログを抜粋しました。
データの内容はわかりませんが、文字列で見えているものを右側に記載しました。

なんとなく、状態が更新されるとEXECUTIONのpushが来るように感じますが、
ORDERRECVの直後に来たパケットが1件だけで、その後のpushが無いようです。

パケットLength=63は実際のデータ部は9byteです。

[satosato125]

@flamingo4096
添付いただいたログを確認いたしましたが、kabuステーション側で注文データの状態が変わったことを示すログが出力されていない場合があることを確認しております。
一方で、別途調査したサーバ側のログには同じデータを送信したログが残っておりましたので、これが未達となっている可能性がございます。

ネットワーク的な要因も一因として考えられるのですが、kabuステーションのメニューバーにある接続状態や受信状態を示すアイコンが赤くなったりすることはございますでしょうか？

また、詳細な調査のため、可能でしたらログのご提供をお願いしたいと思っております。
kabuステーションのメニューバーのAPIアイコンの右クリックメニューから、ログのアップロードをお願いいたします。
アップロードが完了いたしましたら、アップロードした日時をお知らせいただけますでしょうか。

[flamingo4096]

@satosato125
サーバ側もご確認いただきありがとうございます。
ログを先ほどアップロードしました。
この↓情報があればよろしいでしょうか
11:43:19.1636,I,7872,0001 ログファイルアップロード開始 : d5319f3240c62c72ed130866f8f40f06_20240724_OPE.zip / 83,918 bytes.

再現時のメニューバーの表示状態は見ていなかったので、次回再現時は確認するようにいたします。

[satosato125]

@flamingo4096
ログのアップロードありがとうございます。
申し訳ございませんが、調査に少しお時間いただきますこと、ご容赦ください。

[flamingo4096]

@satosato125

状況いかがでしょうか？
相場がよろしくなく、久しぶりに実行しましたが、再現しました。

前回発生時は、発注後に即約定したケースでしたが、今日は指値発注後、しばらくして約定したケースでも発生しました。

＞ネットワーク的な要因も一因として考えられるのですが、kabuステーションのメニューバーにある接続状態や受信状態を示すアイコンが赤くなったりすることはございますでしょうか？
赤くなっていませんでした。

前回同様ネットワークログを取っていましたが、約定したと思われるタイミングで、EXECUTIONのpushが来ています。
よって、
＞一方で、別途調査したサーバ側のログには同じデータを送信したログが残っておりましたので、
これは正しくて、kabustationアプリ側での取りこぼしがあるように思います。

＞これが未達となっている可能性がございます。
TCPなので未達パケットがあれば続きのパケット受信時にRetransmissionが出るはずなので、無いと考えます。

注文番号：20240813A02N44865464
d5319f3240c62c72ed130866f8f40f06_20240813_OPE.zip / 66,902 bytes

必要であればパケットの内容解析等できますので、ご連絡いただければと思います。