[改善] nRF52において、NRF_ERROR_INVALID_STATEにおけるレスポンス実行を回避する

概要

nRF52よりレスポンスする際、ソフトデバイスの sd_ble_gatts_hvx 関数を実行時、エラーコード＝0x08（NRF_ERROR_INVALID_STATE）により、プログラムが停止してしまうことがあります。

NRF_ERROR_INVALID_STATE 中は、nRF52からU2F管理ツールへのレスポンスを行うことが一切不可能になってしまうため、この状態においてレスポンス実行が行われないようにするよう、対策が必要になるかと存じます。

実機確認時のログ

具体的には下記ケースで発生するようです。 https://devzone.nordicsemi.com/f/nordic-q-a/17897/nrf_error_invalid_state-cases

Invalid Connection State
Notifications and/or indications not enabled in the CCCD
An ATT_MTU exchange is ongoing

小職が実機で確認できたのは、上記３番目の An ATT_MTU exchange is ongoing 時です。下記は確認時のログになります。（FDSのファイル削除処理を実行中）

APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x10)
：
APP:INFO:[APP]Connected.
APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x22)
nrf_ble_gatt:DEBUG:Data length updated to 71 on connection 0x0.
：
APP:INFO:[APP]Connection secured: role: 1, conn_handle: 0x0, procedure: 0.
ble_u2f_pairing_lesc:INFO:Security connection updated: Security Mode=1, Level=2
APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x55)
nrf_ble_gatt:DEBUG:Peer on connection 0x0 requested an ATT MTU of 1000 bytes.
nrf_ble_gatt:DEBUG:Updating ATT MTU to 67 bytes (desired: 67) on connection 0x0.
：
ble_u2f_control_point:DEBUG:ble_u2f_control_point_receive length=7
ble_u2f_control_point:DEBUG:INIT frame: CMD(0x83) LEN(4) SEQ(255)
ble_u2f_control_point_apdu:DEBUG:CLA(0x00) INS(0x40) P1(0x02) P2(0x00)
ble_u2f_command:DEBUG:get_command_type: initialize fstorage
ble_u2f_securekey:DEBUG:ble_u2f_securekey_erase start
ble_u2f_crypto_ecb:DEBUG:Generated random vector for AES password
APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x12)
ble_u2f_status:ERROR:u2f_response_send: sd_ble_gatts_hvx failed (err_code=8)
ble_u2f_securekey:DEBUG:ble_u2f_securekey_erase end
APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x3a)
nrf_ble_gatt:DEBUG:ATT MTU updated to 67 bytes on connection 0x0 (response).
：

ログを参照したところ、レスポンス実行時にsd_ble_gatts_hvx failed (err_code=8) のエラーを検知する直前に、on_ble_evt_dispatch called (evt_id=0x12) のイベントが確認されています。

すなわち、evt_id=0x12（BLE_GAP_EVT_CONN_PARAM_UPDATE）の発生により、An ATT_MTU exchangeが行われている状態で、sd_ble_gatts_hvxがコールされたため、NRF_ERROR_INVALID_STATEを検知した、という流れと判断しております。

ご参考

ログ全量再現.log
再現用のプログラム nRF5_SDK_v13.0.0

影響

One CardのBLE U2Fサービスでは、NRF_ERROR_INVALID_STATEが検知されると、レスポンスを実行することができず、処理は打ち切られます。 U2F管理ツール側ではレスポンス・タイムアウトを２０秒後に検知し、結果としてエラー・メッセージをポップアップ表示したのち、停止します。（Chromeエクステンションからの要求時は、Chromeブラウザーにブランク・メッセージがレスポンスされ、Chromeエクステンションが停止します）

取るべき対策

下記いずれかの対策を取るべきと考えております。

前述 An ATT_MTU exchange is ongoing 時は、レスポンス処理に入らないよう、何らかのガード・ロジックを実装
BLE U2Fサービスの処理中に、An ATT_MTU exchange 自体が実行されないようにする仕組みを検討する

ATT_MTU exchangeの動き

ATT_MTU exchange（macOS--->nRF52）

nRF52側へのリクエスト時、ATT_MTU exchange はソフトデバイスのsd_ble_gatts_exchange_mtu_reply関数の実行で開始されます。

これはBLE_GATTS_EVT_EXCHANGE_MTU_REQUEST（0x55）というイベント発生後に行われます。コードを確認したところ、これは nrf_ble_gatt.c というライブラリーの中で行われています。トリガーを引いているのは（確認時に使用した）macOS版U2F管理ツール側のようです。

nRF52のBLE U2Fサービスでは、この時点で

APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x55)
nrf_ble_gatt:DEBUG:Peer on connection 0x0 requested an ATT MTU of 1000 bytes.
nrf_ble_gatt:DEBUG:Updating ATT MTU to 67 bytes (desired: 67) on connection 0x0.

というログを出力します。

このあと、nRF52は接続パラメーターを更新し、下記のログを出力します。（0x12はBLE_GAP_EVT_CONN_PARAM_UPDATEというイベントになります）

APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x12)

ATT_MTU exchange（nRF52--->macOS）

他方、nRF52側からのレスポンス時、ATT_MTU exchange はソフトデバイスのsd_ble_gattc_exchange_mtu_request関数の実行で開始されます。

コードを確認したところ、これは nrf_ble_gatt.c というライブラリーの中で行われています。トリガーを引いているのはnRF52側のようです。

ATT_MTU exchange は完了すると、BLE_GATTC_EVT_EXCHANGE_MTU_RSP というイベントを受領します。

nRF52のBLE U2Fサービスでは、この時点で、

APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x3a)
nrf_ble_gatt:DEBUG:ATT MTU updated to 67 bytes on connection 0x0 (response).

というログを出力します。

取るべき対策

原因の推測

本件のNRF_ERROR_INVALID_STATE発生は、上記のATT_MTU exchangeの流れが未完了であり、接続パラメーターが更新未了の段階で、sd_ble_gatts_hvxを実行しレスポンス送信を試みた結果の事象と考えております。

原因はログからは読み取れないのですが、何らかのリソース要因で、ATT_MTU exchange処理が遅延してしまったものと考えております。本件の直接原因は不明ですが、（動作確認時に実行した）FDSファイル削除--->同更新といった比較的重たい処理を、連続して実行した時に、ATT_MTU exchange処理ステップがペンディング等されてしまい、結果NRF_ERROR_INVALID_STATEが発生する可能性がある、と推測します。

回避案

Nordicのinfocenter を調査しましたところ、An ATT_MTU exchange is ongoingという状態は、実際にsd_ble_gatts_hvxを実行しないと判定できないようです。上記シーケンスチャートのイベントが発生していたかどうかをフラグ管理する方法があるかもしれませんが、クライアントのOSによりATT_MTU exchangeの動きが異なる可能性もあり、現実的ではないと考えます。

ですので回避策としては、sd_ble_gatts_hvxを実行時にNRF_ERROR_INVALID_STATEを検知した場合、An ATT_MTU exchange is ongoing状態であると判断し、指定された時間ウェイト後、sd_ble_gatts_hvxを再実行・・・というのが最善策であると考えております。

対応後の確認

af88d7a の修正により、NRF_ERROR_INVALID_STATEを検知した場合、３秒待ってレスポンスが再送されるのを確認しました。

この対応により、処理が正常に完了したにもかかわらず、レスポンスタイムアウトになってしまう不具合は解消されます。

画面の状況

NRF_ERROR_INVALID_STATEを検知した場合、３秒待ってレスポンスが再送されたときの画面の状況です。 U2F管理ツール画面でもレスポンスタイムアウトは発生せず、処理は正常終了しました。

nRF52側のログ

対象の処理（ble_u2f_securekey_erase。FDSファイル削除処理--->ファイル書込処理を実行）は正常完了していますが、「sd_ble_gatts_hvx failed (err_code=8)」のログが出力され、送信処理（ble_u2f_status_response_send）が失敗してしまいます。このあと、送信処理がリトライされ、再送処理が正常に完了したことがログ「ble_u2f_status_response_send retry: err_code=0x00」で確認できます。

APP:INFO:[APP]Connected.
APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x22)
nrf_ble_gatt:DEBUG:Data length updated to 71 on connection 0x0.
:
APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x55)
nrf_ble_gatt:DEBUG:Peer on connection 0x0 requested an ATT MTU of 1000 bytes.
nrf_ble_gatt:DEBUG:Updating ATT MTU to 67 bytes (desired: 67) on connection 0x0.
:
ble_u2f_securekey:DEBUG:ble_u2f_securekey_erase start
ble_u2f_crypto_ecb:DEBUG:Generated random vector for AES password
APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x12)
ble_u2f_status:ERROR:u2f_response_send: sd_ble_gatts_hvx failed (err_code=8)
ble_u2f_securekey:DEBUG:ble_u2f_securekey_erase end
APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x3a)
nrf_ble_gatt:DEBUG:ATT MTU updated to 67 bytes on connection 0x0 (response).
ble_u2f_status:DEBUG:u2f_response_send (5bytes)
ble_u2f_status_retry:DEBUG:ble_u2f_status_response_send retry: err_code=0x00
APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x57)
:

U2F管理ツールのログ

前述「ble_u2f_securekey_erase」に対するリクエストを [10:44:53.807608] に実行しましたが、NRF_ERROR_INVALID_STATEを検知し、３秒待ってレスポンスが再送されたであろうことが、レスポンスを受領した時刻 [10:44:56.808044] から確認できます。

default 10:44:53.662366 +0900   U2FMaintenanceTool  FIDO U2Fデバイスに接続しました。
default 10:44:53.668441 +0900   U2FMaintenanceTool  FIDO BLE U2Fサービスが見つかりました。
default 10:44:53.730493 +0900   U2FMaintenanceTool  受信データの監視を開始します。
default 10:44:53.807508 +0900   U2FMaintenanceTool  Sent request [frame=0] <83000400 400200>
default 10:44:53.807608 +0900   U2FMaintenanceTool  リクエストを送信しました。
default 10:44:56.808044 +0900   U2FMaintenanceTool  Received response <83000290 00>
default 10:44:56.810214 +0900   U2FMaintenanceTool  Erase secure key and certificate end

対応が完了したのでクローズします。

diverta / onecard-fido