[障害・解決済] BLEリクエストが送信されないことがある

概要

U2Fデモサイトで、U2F Authenticateを実行したところ、BLEリクエストが送信されないまま、U2F管理ツール側が接続を切断する事象が確認されております。

ログ

U2F管理ツールのログ

ディスカバリーは成功したが、その後のU2F Status（Characteristic）監視開始後、U2F管理ツール側から切断要求した様子。

default 16:01:07.504046 +0900   U2FMaintenanceTool  U2F Authentication start
default 16:01:07.504086 +0900   U2FMaintenanceTool  appIdHashWebSafeB64[MencZvKI5fpF6xulpivSP99k-9avciQy0M3BmUv1ea0]
default 16:01:07.504115 +0900   U2FMaintenanceTool  challengeWebSafeB64[gQTSby6VBBtkJq-vCBSV_tq_bvsrtR4-1jNz-1VRKKY]
default 16:01:07.504143 +0900   U2FMaintenanceTool  keyhandleWebSafeB64[KYdUFTMqTDhyOLYXnoqVAQccuT5g3krU7EoL9H-F6gIH2K30G_rMA8D254hKtZNEScTwFD0rDcZ0r7CEJgOK3Q]
default 16:01:07.504177 +0900   U2FMaintenanceTool  ver[U2F_V2]
default 16:01:07.504262 +0900   U2FMaintenanceTool  FIDO U2Fデバイスのスキャンを開始します
default 16:01:09.614108 +0900   U2FMaintenanceTool  FIDO U2Fデバイスのスキャンを完了しました
default 16:01:10.448748 +0900   U2FMaintenanceTool  FIDO U2Fデバイスに接続しました。
default 16:01:10.451347 +0900   U2FMaintenanceTool  FIDO BLE U2Fサービスが見つかりました。
default 16:01:11.889526 +0900   U2FMaintenanceTool  FIDO U2Fデバイスの接続を切断しました。

nRF52側のUARTログ

「Notification status changed to enabled」のログが出力されており、U2F Status（Characteristic）監視開始を受け付けたと思われます。

ただしその直後、U2F管理ツール側から切断要求があったようです。

APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x10) 
：
:INFO:[BLE]BLE_GAP_EVT_CONNECTED
APP:INFO:[APP]Connected.
：
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.
APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x12) 
APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x50) 
:INFO:[BLE]BLE_GATTS_EVT_WRITE
APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x50) 
:INFO:[BLE]BLE_GATTS_EVT_WRITE
APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x50) 
ble_u2f:DEBUG:on_cccd_write: Notification status changed to enabled 
APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x11) 
ble_u2f_command:DEBUG:ble_u2f_command_finalize_context done 
:INFO:[BLE]BLE_GAP_EVT_DISCONNECTED
APP:INFO:[APP]Disconnected.

画面状況

U2F管理ツールが応答不能状態となり、Chromeがハングしました。 U2F管理ツールでは、プログラムで捕捉できるエラーが発生時、画面側でその旨のメッセージを表示するのですが、メッセージは何も表示されませんでした。

この事象から、Issue #28 と同様、プログラムのフレームワーク（CBCentralManager）が、予期しない切断要求を発行してしまったと考えております。

問題絞り込み

上記ログを参照しても、何が問題なのか今ひとつ明確でないので、問題を絞り込むため、ひとまず以下の観点でリファクタリングを実施します。

BLE接続の切断が、アプリケーションにより行われたか、フレームワークにより行われたかを切り分けられるようにする
アプリケーションによりBLE接続切断された場合、何が引き金になったかを切り分けられるようにする
BLE接続の切断がどの時点で行われたか（処理の前後関係など）を切り分けられるようにする

リファクタリングが完了したら、再度本件障害について、再現試験およびログ採取・分析を行いたいと考えます。

リファクタリング後の再現ログ

11d5bac までの修正で再現させた時のログは下記の通りです。

Chromeハング時の状況

U2F管理ツールのログ

アプリケーションで捕捉できるエラーが発生時は、アプリケーションの手により明示的にBLE接続を切断させるとともに、同時点でエラーメッセージをログ出力させるよう、ロジックを変更しています。

#define MSG_U2F_DEVICE_DISCONNECTED         @"FIDO U2Fデバイスの接続を切断しました。"
：
    - (void)peripheral:(CBPeripheral *)peripheral
   didDiscoverServices:(NSError *)error {
        if (error) {
            // BLEサービスディスカバーに失敗の旨をAppDelegateに通知
            [[self delegate] notifyCentralManagerErrorMessage:MSG_BLE_SERVICE_NOT_DISCOVERED
                                                        error:error];
            [[self delegate] centralManagerDidFailConnection];
            return;
        }
        ：
    }

    - (void)centralManagerDidFailConnection {
        // 画面上のテキストエリアにメッセージを表示する
        [self appendLogMessage:MSG_OCCUR_BLECONN_ERROR];
        // 失敗メッセージを表示
        [ToolPopupWindow critical:MSG_OCCUR_BLECONN_ERROR informativeText:nil];
        // デバイス接続を切断
        [self.toolBLECentral centralManagerWillDisconnect];
    }

    - (void)centralManagerWillDisconnect {
        if (self.connectedPeripheral) {
            // スキャンを停止し、ペリフェラル接続を切断
            [self cancelScanForPeripherals];
            [self.manager cancelPeripheralConnection:self.connectedPeripheral];
        ：
        }
    }

    - (void)centralManager:(CBCentralManager *)central
   didDisconnectPeripheral:(CBPeripheral *)peripheral
                     error:(NSError *)error {
        ：
        // 切断完了
        [[self delegate] notifyCentralManagerMessage:MSG_U2F_DEVICE_DISCONNECTED];
        [[self delegate] centralManagerDidDisconnect];
    }

捕捉しているアプリケーション・エラーと、捕捉している順番は、以下の通りになります。

BLEが無効化されている
スキャンタイムアウト
ペリフェラル接続タイムアウト
ペリフェラル接続失敗
BLEサービスディスカバーに失敗
FIDO BLE U2Fサービスがない
キャラクタリスティックのディスカバーエラー
サービスにキャラクタリスティックが１件もない
U2F Status（レスポンス）監視開始エラー発生
U2F Statusの監視が停止している
リクエストタイムアウト発生
U2F Control Point（リクエスト）書込エラー発生
U2F Status取得エラー発生

にもかかわらず、上記のエラーメッセージがコンソール出力されていません。

default 12:04:01.608579 +0900   U2FMaintenanceTool  U2F Authentication start
default 12:04:01.608617 +0900   U2FMaintenanceTool  appIdHashWebSafeB64[MencZvKI5fpF6xulpivSP99k-9avciQy0M3BmUv1ea0]
default 12:04:01.608646 +0900   U2FMaintenanceTool  challengeWebSafeB64[06m7fu3-H8ctXUFaJQyyRXvIM-MHS6O5QpS14JngJIA]
default 12:04:01.608671 +0900   U2FMaintenanceTool  keyhandleWebSafeB64[KYdUFTMqTDhyOLYXnoqVAQccuT5g3krU7EoL9H-F6gImTkDj8Fd_1hj0Wj46f56JKO71SiNUkBMB4x8a1RZz9w]
default 12:04:01.608704 +0900   U2FMaintenanceTool  ver[U2F_V2]
default 12:04:01.608842 +0900   U2FMaintenanceTool  FIDO U2Fデバイスのスキャンを開始します
default 12:04:03.325586 +0900   U2FMaintenanceTool  FIDO U2Fデバイスのスキャンを完了しました
default 12:04:04.132746 +0900   U2FMaintenanceTool  FIDO U2Fデバイスに接続しました。
default 12:04:04.136308 +0900   U2FMaintenanceTool  didConnectPeripheral: already connected to peripheral
default 12:04:04.136423 +0900   U2FMaintenanceTool  FIDO BLE U2Fサービスが見つかりました。
default 12:04:04.354083 +0900   U2FMaintenanceTool  didConnectPeripheral: already connected to peripheral
default 12:04:05.694485 +0900   U2FMaintenanceTool  FIDO U2Fデバイスの接続を切断しました。
default 12:04:05.696199 +0900   U2FMaintenanceTool  Chrome native messaging host will terminate

これは想定通り、アプリケーションで捕捉できない切断が発生したことによるものと切り分けております。

nRF52側のUARTログ

「Notification status changed to enabled」のログが出力されており、U2F Status（Characteristic）監視開始した直後、U2F管理ツール側から切断要求があった動きは変わりません。

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.
APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x12) 
APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x50) 
:INFO:[BLE]BLE_GATTS_EVT_WRITE
APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x50) 
:INFO:[BLE]BLE_GATTS_EVT_WRITE
APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x50) 
ble_u2f:DEBUG:on_cccd_write: Notification status changed to enabled 
APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x11) 
ble_u2f_command:DEBUG:ble_u2f_command_finalize_context done 
:INFO:[BLE]BLE_GAP_EVT_DISCONNECTED
APP:INFO:[APP]Disconnected.

障害発生時点・箇所の推測

障害発生時点の推測

前述のログから、以下の流れが推測されます。

U2F管理ツール側でサービスディスカバリーが成功し、メッセージ「FIDO BLE U2Fサービスが見つかりました。」が出力

その後、U2F管理ツール側から、通知ステータス（Notification status）の更新を、nRF52に対して実行（＝U2F Statusキャラクタリスティックに対する監視を開始）

- (void)subscribeCharacteristic:(CBService *)service {
    ：
    // U2F Statusキャラクタリスティックに対する監視を開始
    if (self.u2fStatusChar) {
        [self.connectedPeripheral setNotifyValue:YES forCharacteristic:self.u2fStatusChar];
    }
}

nRF52側では「Notification status changed to enabled」のメッセージが出力され、通知ステータスの更新が行われた
通知ステータス更新が行われると、通常であればU2F管理ツール側から、以下のいずれかのメッセージが出力されるはず (1) MSG_BLE_NOTIFICATION_FAILED「FIDO BLE U2Fサービスからデータを受信できません。」 (2) MSG_BLE_NOTIFICATION_START「受信データの監視を開始します。」 (3) MSG_BLE_NOTIFICATION_STOP「受信データの監視を停止します。」

    - (void)peripheral:(CBPeripheral *)peripheral
        didUpdateNotificationStateForCharacteristic:(CBCharacteristic *)characteristic
        error:(NSError *)error {
        if (error) {
            // U2F Status監視開始エラー発生の旨をAppDelegateに通知
            [[self delegate] notifyCentralManagerErrorMessage:MSG_BLE_NOTIFICATION_FAILED
                                                        error:error];
            [[self delegate] centralManagerDidFailConnection];
            return;
        }
        if (characteristic.isNotifying) {
            // 一連の接続処理が完了したことをAppDelegateに通知
            [[self delegate] notifyCentralManagerMessage:MSG_BLE_NOTIFICATION_START];
            [self.delegate centralManagerDidConnect];
        } else {
            // 監視が停止している旨をAppDelegateに通知
            [[self delegate] notifyCentralManagerErrorMessage:MSG_BLE_NOTIFICATION_STOP
                                                        error:nil];
            [[self delegate] centralManagerDidFailConnection];
        }
    }

障害発生時は、上記３件のメッセージがいずれも出力されずにBLE切断が発生し、コールバック「CBCentralManager:didDisconnectPeripheral」が実行された（＝その結果、MSG_U2F_DEVICE_DISCONNECTED「FIDO U2Fデバイスの接続を切断しました。」のメッセージが出力された）
```
- (void)centralManager:(CBCentralManager *)central
didDisconnectPeripheral:(CBPeripheral *)peripheral
                 error:(NSError *)error {
    ：
    // 切断完了
    [[self delegate] notifyCentralManagerMessage:MSG_U2F_DEVICE_DISCONNECTED];
    [[self delegate] centralManagerDidDisconnect];
}
```

障害発生箇所の推測

前述の「CBCentralManager:didDisconnectPeripheral」が、アプリケーションでエラーを捕捉時に実行される「centralManagerWillDisconnect」を経由して呼び出されなかったことから、「CBPeripheral:setNotifyValue」の実行により、フレームワーク（CBCentralManager自身）がBLE接続切断を一方的に実施したと考えています。

ただし、その根本原因は未だ不明であるため、コールバック「CBCentralManager:didDisconnectPeripheral」実行時のエラー有無（およびその内容）をログ出力させるように修正し、再現検証を続けてみます。

リファクタリング後の再現ログ

8b812de までの修正で再現させた時のログは下記の通りです。

U2F管理ツールのログ

フレームワーク（CBCentralManager自身）がBLE接続切断を一方的に実施した流れは変わりません。参考までに、為念でログ出力を詳細化しています。

「blued EVENT: Disconnection Complete: Reason = 59」の時点で切断が発生し、それを検知したフレームワークが「CBCentralManager:didDisconnectPeripheral」を実行させた、という流れでした。

なお「CBCentralManager:didDisconnectPeripheral」に渡されたNSErrorは「The connection has timed out unexpectedly.」というものでした。

default 15:09:01.549130 +0900   U2FMaintenanceTool  FIDO BLE U2Fサービスが見つかりました。
default 15:09:01.550168 +0900   blued   ATTConnection: discoverCharacteristics Starthandle: 22 (0x16) endHandle: 33 (0x21)
default 15:09:01.615879 +0900   blued   CBManager: Automatically reading a characteristic of type 0x2A04
default 15:09:01.645164 +0900   blued   CBManager: Service change value: isServiceChanged :1
default 15:09:01.645259 +0900   blued   ATTConnection: Discover descriptors for characteristic: <GATTCharacteristic:0x7f9bc1c01740 handle:0x000b valueHandle:0x000c uuid:0x2A05 properties:0x20 ( Indicate )>
default 15:09:01.645303 +0900   blued   ATTConnection: Starthandle: 13 endHandle: 13
default 15:09:01.645367 +0900   blued   CBManager: Automatically reading a characteristic of type 0x2A04
default 15:09:01.645432 +0900   blued   CBManager: Service change value: isServiceChanged :1
default 15:09:01.645485 +0900   blued   ATTConnection: Discover descriptors for characteristic: <GATTCharacteristic:0x7f9bc1c01740 handle:0x000b valueHandle:0x000c uuid:0x2A05 properties:0x20 ( Indicate )>
default 15:09:01.645523 +0900   blued   ATTConnection: Starthandle: 13 endHandle: 13
default 15:09:01.735662 +0900   blued   Send CB client characteristics discovered: (
        {
        kCBMsgArgCharacteristicHandle = 23;
        kCBMsgArgCharacteristicProperties = 8;
        kCBMsgArgCharacteristicValueHandle = 24;
        kCBMsgArgUUID = <f1d0fff1 deaaecee b42fc9ba 7ed623bb>;
    },
        {
        kCBMsgArgCharacteristicHandle = 25;
        kCBMsgArgCharacteristicProperties = 16;
        kCBMsgArgCharacteristicValueHandle = 26;
        kCBMsgArgUUID = <f1d0fff2 deaaecee b42fc9ba 7ed623bb>;
    }
)
default 15:09:01.736364 +0900   blued   ATTConnection: Discover descriptors for characteristic: <GATTCharacteristic:0x7f9bc1e0c1a0 handle:0x0019 valueHandle:0x001a uuid:F1D0FFF2-DEAA-ECEE-B42F-C9BA7ED623BB properties:0x10 ( Notify )>
default 15:09:01.736426 +0900   blued   ATTConnection: Starthandle: 27 endHandle: 33
default 15:09:01.736468 +0900   blued   ATTConnection: Starthandle: 27 endHandle: 27
default 15:09:01.766393 +0900   blued   Primary Service Discovery completed with status: 0x0
default 15:09:01.766502 +0900   blued   Client Central jp.makmorit.tools.U2FMaintenanceTool:1033 devices to connect {(
    D0B47469-86D4-43C3-B7BE-4E3E2C6641F6
)} identifier D0B47469-86D4-43C3-B7BE-4E3E2C6641F6
default 15:09:01.766728 +0900   blued   Sending a device connected message to OneCard_Peripheral with role: 0
default 15:09:01.766921 +0900   blued   Client Central wirelessproxd:78 devices to connect {(
)} identifier D0B47469-86D4-43C3-B7BE-4E3E2C6641F6
default 15:09:01.766975 +0900   blued   Client Peripheral wirelessproxd:78 devices to connect {(
)} identifier D0B47469-86D4-43C3-B7BE-4E3E2C6641F6
default 15:09:01.767097 +0900   U2FMaintenanceTool  didConnectPeripheral: already connected to peripheral
default 15:09:01.767054 +0900   blued   Client Peripheral wirelessproxd:78 devices to connect {(
)} identifier D0B47469-86D4-43C3-B7BE-4E3E2C6641F6
default 15:09:01.767182 +0900   blued   Client Central wirelessproxd:78 devices to connect {(
)} identifier D0B47469-86D4-43C3-B7BE-4E3E2C6641F6
default 15:09:01.767276 +0900   blued   Client Central UserEventAgent:295 devices to connect {(
)} identifier D0B47469-86D4-43C3-B7BE-4E3E2C6641F6
default 15:09:01.767628 +0900   blued   ATTConnection: discoverCharacteristics Starthandle: 1 (0x1) endHandle: 9 (0x9)
default 15:09:01.767689 +0900   blued   ATTConnection: discoverCharacteristics Starthandle: 10 (0xa) endHandle: 13 (0xd)
default 15:09:01.921529 +0900   blued   EVENT: Disconnection Complete: Reason = 59
default 15:09:01.922172 +0900   UserEventAgent  [BTUserEventAgentController deviceDestroyed] count = 0 previousCount = 1
default 15:09:01.922255 +0900   UserEventAgent  [BTUserEventAgentController deviceDestroyed] seconds of numberConnectedDevices[1] = 14
default 15:09:01.922322 +0900   UserEventAgent  [BTUserEventAgentController messageTracerEventDriven] deviceDestroyed
default 15:09:01.922382 +0900   UserEventAgent  [BTUserEventAgentController messageTracerEventDriven]
default 15:09:01.923710 +0900   UserEventAgent  [BTUserEventAgentController messageTracerEventDriven] PowerSource 9720.000000 9720.000000
default 15:09:01.923757 +0900   UserEventAgent  [BTUserEventAgentController messageTracerEventDriven] SystemState 0xE0000300 0xE0000300
default 15:09:01.923787 +0900   UserEventAgent  [BTUserEventAgentController messageTracerEventDriven] LidStatus 0 0
default 15:09:01.923804 +0900   UserEventAgent  [BTUserEventAgentController messageTracerEventDriven] BluetoothState 1 1
default 15:09:01.923822 +0900   UserEventAgent  [BTUserEventAgentController messageTracerEventDriven] StateApple80211 4 4
default 15:09:01.923839 +0900   UserEventAgent  [BTUserEventAgentController messageTracerEventDriven] FlagsApple80211 0x00000008 0x00000008
default 15:09:01.923857 +0900   UserEventAgent  [BTUserEventAgentController messageTracerEventDriven] ConnectedDevices 1 0
default 15:09:01.923885 +0900   UserEventAgent  [BTUserEventAgentController messageTracerEventDriven] ConnectedDeviceTypes 0x0000000D 0x00000000
default 15:09:01.923908 +0900   UserEventAgent  [BTUserEventAgentController messageTracerEventDriven] update to latest event information
error   15:09:01.926131 +0900   AirPlayXPCHelper    df-ad-18-34-59-d3 has no service mask
default 15:09:01.930118 +0900   blued   Adding UUID D0B47469-86D4-43C3-B7BE-4E3E2C6641F6 with services in cache
default 15:09:01.930283 +0900   U2FMaintenanceTool  FIDO U2Fデバイスの接続を切断しました。 Error Domain=CBErrorDomain Code=6 "The connection has timed out unexpectedly." UserInfo={NSLocalizedDescription=The connection has timed out unexpectedly.}
default 15:09:01.931473 +0900   U2FMaintenanceTool  Chrome native messaging host will terminate

nRF52側のUARTログ

こちらもU2F管理ツール側から切断要求があった動きは変わりません。（通知ステータス更新は起きませんでしたが、本件とは無関係そうな印象です）

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.
APP:DEBUG:on_ble_evt_dispatch called (evt_id=0x11) 
ble_u2f_command:DEBUG:ble_u2f_command_finalize_context done 
:INFO:[BLE]BLE_GAP_EVT_DISCONNECTED
APP:INFO:[APP]Disconnected.

障害の特定

事象発生箇所の特定

「blued EVENT: Disconnection Complete: Reason = 59」とのメッセージから、nRF52側が「Connection Interval Unacceptable」を検知したための事象であると判断しています。

この「Reason = 59」イベントがnRF52から飛んできた結果、フレームワークにより、アプリケーションと何らの関係もなく「CBCentralManager:didDisconnectPeripheral」が実行されています。

他方、nRF52側で「Reason = 59」イベントを発生させるのは、直近のレスポンスから10秒間リクエストがない場合、無通信タイムアウトを発生させる、下記の処理になります。

static void communication_interval_timeout_handler(void *p_context) {
    if (p_context == NULL) {
        return;
    }

    // 直近のレスポンスから10秒を経過した場合、
    // nRF52から強制的にBLEコネクションを切断
    ble_u2f_t *p_u2f = (ble_u2f_t *)p_context;
    sd_ble_gap_disconnect(p_u2f->conn_handle, BLE_HCI_CONN_INTERVAL_UNACCEPTABLE);
}

事象発生原因の特定

無通信タイムアウトをスタートさせるのは、nRF52側から、U2F管理ツールに向けてレスポンスを実行する時点です。

static void communication_interval_timer_init(ble_u2f_t *p_u2f) {
    ：
    // 直近レスポンスからの経過秒数監視するためのタイマーを生成
    uint32_t err_code;
    err_code = app_timer_create(&m_ble_u2f_comm_interval_timer_id, APP_TIMER_MODE_SINGLE_SHOT, communication_interval_timeout_handler);
    ：
}

void ble_u2f_comm_interval_timer_start(ble_u2f_t *p_u2f) {
    // タイマー生成
    if (app_timer_created == false) {
        communication_interval_timer_init(p_u2f);
        ：
    // タイマーが既にスタートしている場合は停止させる
    if (app_timer_started == true) {
        ble_u2f_comm_interval_timer_stop(p_u2f);
    }

    // 直近レスポンスからの経過秒数監視を開始
    uint32_t err_code = app_timer_start(m_ble_u2f_comm_interval_timer_id, APP_TIMER_TICKS(COMMUNICATION_INTERVAL_MSEC), p_u2f);
    if (err_code != NRF_SUCCESS) {
    ：
}

uint32_t ble_u2f_status_response_send(ble_u2f_t *p_u2f) {
    ：
    while (send_info_t.sent_length < send_info_t.data_length) {
        ：
        // u2f_status_bufferに格納されたパケットを送信
        err_code = u2f_response_send(p_u2f);
        ：
        // 最終レコードの場合は、次回リクエストまでの経過秒数監視をスタート
        if (send_info_t.sent_length == send_info_t.data_length) {
            ble_u2f_comm_interval_timer_start(p_u2f);
        }
        ：
}

この無通信タイムアウト監視は、本来ですと次回のBLE通信が開始した時点で、監視をストップしなければならないものかと存じます。

そこで、BLE通信開始（ble_u2f_on_connect, evt_id=0x10[BLE_GAP_EVT_CONNECTED]）--->リクエスト受領（＝ble_u2f_control_point_receive関数実行, evt_id=0x50[BLE_GATTS_EVT_WRITE]）まで時点での処理を確認しました。

結果、無通信タイムアウトの監視をストップさせる処理は、別段見つかりませんでした。（U2F Control Pointのデータを取り出すところで初めて、監視ストップが実行されています）

static void on_ble_evt_dispatch(ble_evt_t * p_ble_evt) {
    NRF_LOG_DEBUG("on_ble_evt_dispatch called (evt_id=0x%02x) \r\n", p_ble_evt->header.evt_id);
    ：
    if (ble_u2f_on_ble_evt(&m_u2f, p_ble_evt) == false) {
        // FIDO U2Fで処理されたイベントは、
        // One Cardサービスで重複処理されないようにする
        ble_one_card_on_ble_evt(p_ble_evt);
    }
    ：
}

bool ble_u2f_on_ble_evt(ble_u2f_t * p_u2f, ble_evt_t * p_ble_evt) {
    ：
    switch (p_ble_evt->header.evt_id) {
        case BLE_GAP_EVT_CONNECTED:
            ble_u2f_on_connect(p_u2f, p_ble_evt);
            break;
    ：
        case BLE_GATTS_EVT_WRITE:
            ret = ble_u2f_on_write(p_u2f, p_ble_evt);
            break;
    ：
}

static void ble_u2f_on_connect(ble_u2f_t * p_u2f, ble_evt_t *p_ble_evt) {
    ：
    // 共有情報を初期化する
    ble_u2f_command_initialize_context();
}

void ble_u2f_command_initialize_context(void) {
    // 共有情報をゼロクリアする
    memset(&m_u2f_context, 0, sizeof(ble_u2f_context_t));
    NRF_LOG_DEBUG("ble_u2f_command_initialize_context done \r\n");

    // ユーザー所在確認のためのタイマーを起動する
    ble_u2f_user_presence_init(&m_u2f_context);

    // コマンド／リクエストデータ格納領域を初期化する
    ble_u2f_control_point_initialize();
}

static bool ble_u2f_on_write(ble_u2f_t *p_u2f, ble_evt_t *p_ble_evt) {
    ble_gatts_evt_write_t * p_evt_write = &p_ble_evt->evt.gatts_evt.params.write;

    if ((p_evt_write->handle == p_u2f->u2f_status_handles.cccd_handle)
     && (p_evt_write->len == 2)) {
        // U2F Statusについて、CCCD（2バイト）が書き込まれた場合は
        // Notificationステータスを更新する。
        if (ble_srv_is_notification_enabled(p_evt_write->data)) {
            p_u2f->is_notification_enabled = true;
            ：
        return true;

    } else if (p_evt_write->handle == p_u2f->u2f_control_point_handles.value_handle) {
        // Control Point（コマンドバッファ）の内容更新時の処理
        // コマンドバッファに入力されたリクエストデータを取得し、
        // その内容を判定し処理を実行
        ble_u2f_command_on_ble_evt_write(p_u2f, p_evt_write);
        return true;

    } else {
        // 他のBLEサービスに処理させる
        return false;
    }
}

void ble_u2f_command_on_ble_evt_write(ble_u2f_t *p_u2f, ble_gatts_evt_write_t *p_evt_write) {
    ：
    // コマンドバッファに入力されたリクエストデータを取得
    ble_u2f_control_point_receive(p_evt_write, &m_u2f_context);
   ：

void ble_u2f_control_point_receive(ble_gatts_evt_write_t *p_evt_write, ble_u2f_context_t *p_u2f_context) {
    // 無通信タイマーが既にスタートしている場合は停止させる
    ble_u2f_comm_interval_timer_stop(p_u2f_context->p_u2f);
   ：
}

すなわち、無通信タイムアウトの監視スタート時点から、１０秒が経過しないうちに次のBLE通信開始後、リクエストを受領（＝無通信タイムアウト監視ストップ）されるまでの短い時間帯で、タイムアウトが発生してしまった・・・というのが本件障害の根本事由であったようです。

為念で事象発生時のログを参照したところ、前回レスポンス完了 [15:08:51.905712] から約１０秒後に、タイムアウトが発生していた [15:09:01.921529] ことが確認できています。

default 15:08:51.830060 +0900   U2FMaintenanceTool  Received response <83004e01 0000001f 30450221 00e0d0ae 07688f01 6a61e8ec 04a223bb f26d9e3c 6f2340f4 70fb7087 c8d1e96b 6c02206a 0686da9a 50abfedd 64d55051 ceca4c7d>
default 15:08:51.905712 +0900   U2FMaintenanceTool  Received response <00113557 c8a367d1 96c37d61 6af937fc 9000>
default 15:08:51.907685 +0900   U2FMaintenanceTool  U2F response received
：
default 15:09:01.921529 +0900   blued   EVENT: Disconnection Complete: Reason = 59
：
default 15:09:01.930283 +0900   U2FMaintenanceTool  FIDO U2Fデバイスの接続を切断しました。 Error Domain=CBErrorDomain Code=6 "The connection has timed out unexpectedly." UserInfo={NSLocalizedDescription=The connection has timed out unexpectedly.}
default 15:09:01.931473 +0900   U2FMaintenanceTool  Chrome native messaging host will terminate

対策

BLE通信開始後--->リクエスト受領までには、下記のような重要な処理があります。

暗号化通信によるセキュア接続確立
通信フレーム（リクエスト／レスポンス）パラメーター更新
通信タイムアウトパラメーター更新
U2F Statusキャラクタリスティックの監視スタート
その他のGATTイベント（詳細は不明）

これらのやりとりが完了するまで、nRF52、PC双方のリソース事由により（長い時は数百ミリ〜２秒程度の）時間を要することがあるようです。本件障害で見られる通りですが、現状の実装ですと、この間にタイムアウトが発生する可能性が高いようです。

したがって、BLE通信開始後、すぐに無通信タイムアウトの監視をストップさせるよう、プログラムを修正させる必要があるかと存じます。

具体的には前述「ble_u2f_on_connect」関数内で、無通信タイムアウト監視をストップさせるようにします。

static void ble_u2f_on_connect(ble_u2f_t * p_u2f, ble_evt_t *p_ble_evt) {
    ：
    // 共有情報を初期化する
    ble_u2f_command_initialize_context();

    // 無通信タイマーが既にスタートしている場合は停止させる
    ble_u2f_comm_interval_timer_stop(p_u2f_context->p_u2f);
}

対応後の確認

36b0431 の修正により、前回レスポンス完了時点から10秒経過後、リクエスト受領前に無通信タイムアウトが発生する不具合が解消されていることを確認しました。

確認事例１

default 14:04:35.783894 +0900   U2FMaintenanceTool  Received response <83004f01 0000004d 30460221 00b749eb cdab8976 f55e9f66 32566aa0 278e2158 3f5e4ec1 8ab325e9 416733ab cb022100 f5df27e1 9ea5b059 dcc59a14 6f18212d>
default 14:04:35.784563 +0900   U2FMaintenanceTool  Received response <000b615b 447fbb22 6fead887 d0e06e1e 699000>
default 14:04:35.786121 +0900   U2FMaintenanceTool  U2F response received
：
default 14:04:45.629739 +0900   U2FMaintenanceTool  FIDO U2Fデバイスに接続しました。
default 14:04:45.636799 +0900   U2FMaintenanceTool  FIDO BLE U2Fサービスが見つかりました。
default 14:04:45.699405 +0900   U2FMaintenanceTool  受信データの監視を開始します。
default 14:04:45.950910 +0900   U2FMaintenanceTool  Sent request <83008a00 02030000 0081dc78 19f3bf6d 085213c7 4ad07334 cd1774de f27c4a1b 746d13f9 3d559022 651231e9 dc66f288 e5fa45eb 1ba5a62b d23fdf64 fbd6af72>
default 14:04:46.202472 +0900   U2FMaintenanceTool  Sent request <002432d0 cdc1994b f579ad40 29875415 332a4c38 7238b617 9e8a9501 071cb93e 60de4ad4 ec4a0bf4 7f85ea02 264e40e3 f0577fd6 18f45a3e 3a7f9e89 28eef54a>
default 14:04:46.453923 +0900   U2FMaintenanceTool  Sent request <01235490 1301e31f 1ad51673 f70000>
default 14:04:46.454056 +0900   U2FMaintenanceTool  リクエストを送信しました。
default 14:04:47.166262 +0900   U2FMaintenanceTool  Received response <82000102>

確認事例２

default 14:11:19.034231 +0900   U2FMaintenanceTool  Received response <83004e01 00000056 30450220 351b1c7e e6c696a5 b3b40ca9 763ec999 63a0438f b1d96147 d7400ffd 80db4144 022100af a9c7efe7 94965c12 9ed4b82c 04ee4d03>
default 14:11:19.108661 +0900   U2FMaintenanceTool  Received response <00293580 4b7240ce bb1affd9 54435cda 9000>
default 14:11:19.110674 +0900   U2FMaintenanceTool  U2F response received
：
default 14:11:29.106149 +0900   U2FMaintenanceTool  FIDO U2Fデバイスに接続しました。
default 14:11:29.108704 +0900   U2FMaintenanceTool  didConnectPeripheral: already connected to peripheral
default 14:11:29.108802 +0900   U2FMaintenanceTool  FIDO BLE U2Fサービスが見つかりました。
default 14:11:29.327208 +0900   U2FMaintenanceTool  didConnectPeripheral: already connected to peripheral
default 14:11:30.180755 +0900   U2FMaintenanceTool  受信データの監視を開始します。
default 14:11:30.433717 +0900   U2FMaintenanceTool  Sent request <83008a00 02030000 0081703c 3d07eece 66932a4b eb86e8e6 0457ccfb 6aca3e2e 7ea6bbf6 ac2135af 3d1431e9 dc66f288 e5fa45eb 1ba5a62b d23fdf64 fbd6af72>
default 14:11:30.685236 +0900   U2FMaintenanceTool  Sent request <002432d0 cdc1994b f579ad40 29875415 332a4c38 7238b617 9e8a9501 071cb93e 60de4ad4 ec4a0bf4 7f85ea02 264e40e3 f0577fd6 18f45a3e 3a7f9e89 28eef54a>
default 14:11:30.936727 +0900   U2FMaintenanceTool  Sent request <01235490 1301e31f 1ad51673 f70000>
default 14:11:30.936856 +0900   U2FMaintenanceTool  リクエストを送信しました。
default 14:11:31.605927 +0900   U2FMaintenanceTool  Received response <82000102>

問題が解消したのでクローズいたします。

diverta / onecard-fido