Android BLE onCharacteristicChangedが複数回呼び出される

Question

Bluetooth Low Energyを用いてプログラムを開発しています。
送信側にて64msec周期でキャラクタリスティックを更新し、更新通知が受信側に届いていることをパケットキャプチャ(nRF51 dongle ＋ Wireshark)で確認しました。
※受信間隔にバラツキはありますが、概ね64msec周期で受信できています。

2501 112.789743 Slave_0x283eb820 Master_0x283eb820 ATT 53 Rcvd Handle Value Notification, Handle: 0x0019 (Unknown)
2503 112.898854 Slave_0x283eb820 Master_0x283eb820 ATT 53 Rcvd Handle Value Notification, Handle: 0x0019 (Unknown)
2505 112.907883 Slave_0x283eb820 Master_0x283eb820 ATT 53 Rcvd Handle Value Notification, Handle: 0x0019 (Unknown)
2507 113.017212 Slave_0x283eb820 Master_0x283eb820 ATT 53 Rcvd Handle Value Notification, Handle: 0x0019 (Unknown)
2511 113.030233 Slave_0x283eb820 Master_0x283eb820 ATT 53 Rcvd Handle Value Notification, Handle: 0x0019 (Unknown)
2513 113.139254 Slave_0x283eb820 Master_0x283eb820 ATT 53 Rcvd Handle Value Notification, Handle: 0x0019 (Unknown)
2515 113.147382 Slave_0x283eb820 Master_0x283eb820 ATT 53 Rcvd Handle Value Notification, Handle: 0x0019 (Unknown)
2519 113.266009 Slave_0x283eb820 Master_0x283eb820 ATT 53 Rcvd Handle Value Notification, Handle: 0x0019 (Unknown)
2521 113.273321 Slave_0x283eb820 Master_0x283eb820 ATT 53 Rcvd Handle Value Notification, Handle: 0x0019 (Unknown)
2523 113.382328 Slave_0x283eb820 Master_0x283eb820 ATT 53 Rcvd Handle Value Notification, Handle: 0x0019 (Unknown)

気がかりな点として、１回の更新通知でonCharacteristicChanged()が複数回呼び出されています。
これは正常な動作(仕様)なのでしょうか？
もしくは、このような事象が発生したという方はいらっしゃいますでしょうか？

事象が発生した際のソースコードは以下の通りです。
※SERVICE_UUID、CHARACTERISTIC_UUIDは伏せ字にしてあります。

// import
import android.bluetooth.BluetoothAdapter;
import android.bluetooth.BluetoothDevice;
import android.bluetooth.BluetoothGatt;
import android.bluetooth.BluetoothGattCallback;
import android.bluetooth.BluetoothGattCharacteristic;
import android.bluetooth.BluetoothGattDescriptor;
import android.bluetooth.BluetoothGattService;
import android.bluetooth.BluetoothManager;
import android.bluetooth.BluetoothProfile;
import android.bluetooth.le.BluetoothLeScanner;
import android.bluetooth.le.ScanCallback;
import android.bluetooth.le.ScanResult;
import android.bluetooth.le.ScanFilter;
import android.bluetooth.le.ScanSettings;

import android.content.Context;
import android.os.ParcelUuid;
import android.support.v7.app.AppCompatActivity;
import android.os.Bundle;
import android.util.Log;

import java.util.ArrayList;
import java.util.Arrays;
import java.util.Locale;
import java.util.UUID;

import static android.bluetooth.BluetoothGatt.CONNECTION_PRIORITY_HIGH;


public class MainActivity extends AppCompatActivity {
    // グローバル変数定義
    private ArrayList mScanFilterList;
    private ScanSettings mScanSettings;
    private BluetoothLeScanner mBtLeScanner;
    private BluetoothDevice mBtDevice;
    private BluetoothGatt mBtGatt;
    private BluetoothGattCharacteristic mBtGattCharacteristic;
    private byte[] m_byReceiveData = new byte[20];
String strMsg;
long m_CntNG = 0;
long m_CntOK = 0;

    // UUID定義
    // 対象のサービスUUID.
    private static final String SERVICE_UUID               = "XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXX1";
    // キャラクタリスティックUUID.
    private static final String CHARACTERISTIC_UUID        = "XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXX2";
    // キャラクタリスティック設定UUID(固定値).
    private static final String CHARACTERISTIC_UUID_CONFIG = "00002902-0000-1000-8000-00805f9b34fb";

    // 初期処理
    @Override
    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);

        BluetoothManager btManager;
        BluetoothAdapter btAdapter;

        setContentView(R.layout.activity_main);

        // 前回受信データの初期化
        for(int i=0; i<m_byReceiveData.length; i++) {
            m_byReceiveData[i] = 0x00;
        }

        btManager = (BluetoothManager)getSystemService(Context.BLUETOOTH_SERVICE);
        btAdapter = btManager.getAdapter();

        // フィルタを設定する。
        ScanFilter scanFilter = new ScanFilter.Builder()
                .setServiceUuid(ParcelUuid.fromString(SERVICE_UUID)).build();
        mScanFilterList = new ArrayList();
        mScanFilterList.add(scanFilter);

        mScanSettings = new ScanSettings.Builder()
                .setScanMode(ScanSettings.SCAN_MODE_BALANCED).build();

        // スキャンを開始する。
        mBtLeScanner = btAdapter.getBluetoothLeScanner();
        mBtLeScanner.startScan(mScanFilterList, mScanSettings, mScanCallback);
    }

    // スキャン結果コールバック関数
    private final ScanCallback mScanCallback = new ScanCallback() {
        // スキャン結果通知処理
        @Override
        public void onScanResult(int callbackType, ScanResult result) {
            super.onScanResult(callbackType, result);

            // デバイスを発見した
            if((null != result) && (null != result.getDevice())) {
                mBtDevice = result.getDevice();

                // デバイスに接続する。
                mBtGatt = mBtDevice.connectGatt(getApplicationContext(), false, mGattCallback);
            }
        }
    };

    // GATTコールバック関数
    private final BluetoothGattCallback mGattCallback = new BluetoothGattCallback(){
        // 接続状態変化検出処理
        @Override
        public void onConnectionStateChange(BluetoothGatt gatt, int status, int newState){
            // 接続状況が変化したら実行.
            if(newState == BluetoothProfile.STATE_CONNECTED) {
                // 接続に成功したらサービスを検索する.
                gatt.discoverServices();
            } else if(newState == BluetoothProfile.STATE_DISCONNECTED) {
                // 接続が切れたらGATTを空にする.
                if(mBtGatt != null){
                    mBtGatt.close();
                    mBtGatt = null;
                }

                // スキャンを再開する。
                mBtLeScanner.startScan(mScanFilterList, mScanSettings, mScanCallback);
            }
        }

        // サービス検出処理
        @Override
        public void onServicesDiscovered(BluetoothGatt gatt, int status){
            BluetoothGattService bleService;
            boolean bRet;
            BluetoothGattDescriptor bleDescriptor;

            // Serviceが見つかったら実行.
            if(status == BluetoothGatt.GATT_SUCCESS) {
                // UUIDが同じかどうかを確認する.
                bleService = gatt.getService(UUID.fromString(SERVICE_UUID));
                if(bleService != null){
                    // 指定したUUIDを持つCharacteristicを確認する.
                    mBtGattCharacteristic = bleService.getCharacteristic(UUID.fromString(CHARACTERISTIC_UUID));
                    if(mBtGattCharacteristic != null) {
                        // Service, CharacteristicのUUIDが同じならBluetoothGattを更新する.
                        mBtGatt = gatt;

                        // Notifyを高速で受け取るための要求
                        mBtGatt.requestConnectionPriority(CONNECTION_PRIORITY_HIGH);

                        // キャラクタリスティックが見つかったら、Notificationをリクエスト.
                        bRet = mBtGatt.setCharacteristicNotification(mBtGattCharacteristic, true);

                        if(true == bRet) {
                            // Characteristic の Notificationを有効化する.
                            bleDescriptor = mBtGattCharacteristic.getDescriptor(UUID.fromString(CHARACTERISTIC_UUID_CONFIG));
                            if(null != bleDescriptor) {
                                bleDescriptor.setValue(BluetoothGattDescriptor.ENABLE_NOTIFICATION_VALUE);
                                mBtGatt.writeDescriptor(bleDescriptor);
                            }

                            // scan 終了
                            mBtLeScanner.stopScan(mScanCallback);
                        }
                    }
                }
            }
        }

        // 更新通知受信処理
        @Override
        public synchronized void onCharacteristicChanged(BluetoothGatt gatt, BluetoothGattCharacteristic characteristic){
            super.onCharacteristicChanged(gatt, characteristic);

            byte byReceiveData[];

            // キャラクタリスティックのUUIDをチェック(getUuidの結果が全て小文字で帰ってくるのでUpperCaseに変換)
            if(CHARACTERISTIC_UUID.equals(characteristic.getUuid().toString().toUpperCase())){
                // characteristicを取得する。
                byReceiveData = characteristic.getValue();

                // データ長が異なる場合は処理をスキップする。
                if(byReceiveData.length != m_byReceiveData.length) {
strMsg = String.format(Locale.US, "***** Length (%d:%d) *****", byReceiveData.length, m_byReceiveData.length);
Log.e("TAG", strMsg);
                    return;
                }

                // 前回と同一データの場合は処理スキップする。
                if(Arrays.equals(byReceiveData, m_byReceiveData)) {
m_CntNG++;
strMsg = String.format("xxx Receive NG(%d)", m_CntNG);
Log.e("TAG", strMsg);
                    return;
                }
                else {
m_CntOK++;
strMsg = String.format("ooo Receive OK(%d)", m_CntOK);
Log.e("TAG", strMsg);
                    System.arraycopy(byReceiveData, 0, m_byReceiveData, 0, m_byReceiveData.length);
                }
            }
        }
    };
}

実行結果は以下のように出力されています。
08-10 14:34:38.108 E: ooo Receive OK(1)
08-10 14:34:38.108 E: xxx Receive NG(1)
08-10 14:34:38.109 E: ooo Receive OK(2)
08-10 14:34:38.110 E: xxx Receive NG(2)
08-10 14:34:38.156 E: ooo Receive OK(3)
08-10 14:34:38.157 E: xxx Receive NG(3)
08-10 14:34:38.258 E: ooo Receive OK(4)
08-10 14:34:38.259 E: xxx Receive NG(4)
08-10 14:34:38.316 E: ooo Receive OK(5)
08-10 14:34:38.317 E: xxx Receive NG(5)

送信する更新通知は20byteです。
送信側、受信側共にAndroid(7.0)、Bluetooth V4.2です。
開発環境はAndroidStudio(3.0.1)です。

アドバイス、宜しく御願い致します。

Comments

[hillacken]

パケットキャプチャとは自作ソフトですか？

[hillacken]

伝送路上は１回だけ送信されています。というのは何で確認したのでしょうか？市販のBLEパケットスニファでしょうか？

[LS_Takao]

hillacken 様。御質問ありがとうございます。御推察の通りで、パケットキャプチャは「nRF51 dongle」＋「Wireshark」で行いました。

[hillacken]

送信は大丈夫そうですね。受信側のandroidのソースコードを貼らないと、Windさん以上の回答はないと思います。

[LS_Takao]

hillacken 様。アドバイスありがとうございます。掲載用にシンプルなコードに改めたところ、該当の事象が発生しなくなりました。実装ミスと思われます。お騒がせし申し訳ございませんでした。

[LS_Takao]

事象が発生するソースコードと実行結果を追記しました。事象が発生しなくなった環境との差分を調査中です。

[LS_Takao]

「該当の事象が発生しなくなった」というのは誤情報でした。申し訳ございません。

Answer 1

これは正常な動作(仕様)なのでしょうか？

正常な動作ではありません。
送信側が20bytesを1パケットとして送信しているのなら、
受信側は1回しか発生しません。

（追記）BLEの仕様を言うのであれば、ConnectionIntervalは1.25msec単位になるので、
正確に言えば64msec周期はあり得ないです。

Comments

[LS_Takao]

Wind 様
御回答ありがとうございます。

> 送信側が20bytesを1パケットとして送信しているのなら、
> 受信側は1回しか発生しません。
伝送路上は１回だけ送信されています。

送信側は タスク(TimerTask派生クラス)を起動しており、そのタスクで64msec周期毎に以下を行っています。
BluetoothGattCharacteristic.setValue(20byteのデータ)
BluetoothGattServer.notifyCharacteristicChanged(前述のCharacteristic)
上記処理にてパケットキャプチャでは送信間隔が不安定ですが、平均64msecでパケットが送信されていることは確認できています。
※Androidタブレット間では受信側で以下を行わないと100msec周期になる。
BluetoothGatt.requestConnectionPriority(CONNECTION_PRIORITY_HIGH);

受信パケット数が「１」に対して、onCharacteristicChanged()が複数回呼び出されているという状況です。
複数回呼び出された時のonCharacteristicChanged()の引数で渡されたデータは全く同一でした。
※データはBluetoothGattCharacteristic.getValue()で取得しています。

[Wind]

時間間隔を見ると1msec程度で連続しているので、送信側が同じパケットを多重送信しているってことは無さそうですね。
正常に動作したシンプルなコードも書いて貰えないでしょうか？

[LS_Takao]

Wind 様
御回答ありがとうございます。

「正常に動作した」「該当の事象が発生しなくなった」というのは誤情報でした。
申し訳ございません。
※「前回と同一データか？」のチェックに用いるバッファ(m_byReceiveData)を複数用意したのですが、その判定に誤りがあり、現状も該当の事象が発生しています。

ソースコードの内容としては最小限の機能になっているのですが、お気づきの点等アドバイスをいただけると助かります。
宜しくお願い致します。

[Wind]

サンプルコードのUUIDを変更して接続してみたところ、
こちらの環境ではmBtLeScannerで二重接続しました。
同様の現象が発生していませんでしょうか？

【Logcatの表示で、下記の通り2回ずつ表示された】
D/BluetoothAdapter: isLeEnabled(): ON
D/BluetoothAdapter: isLeEnabled(): ON

D/BluetoothGatt: close()
D/BluetoothGatt: close()

[LS_Takao]

Wind 様
御回答ありがとうございます。

Logcatに「D/BluetoothAdapter: isLeEnabled(): ON」は出力されていないのですが、onClientConnectionState()やwriteDescriptor()が複数回行ったログが出力されています。

D: connect() - device: XX:XX:XX:XX:XX:XX, auto: false
D: registerApp()
D: registerApp() - UUID=XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX
D: onClientRegistered() - status=0 clientIf=21
D: connect() - device: XX:XX:XX:XX:XX:XX, auto: false
D: registerApp()
D: registerApp() - UUID=XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX
D: onClientRegistered() - status=0 clientIf=22
D: onClientConnectionState() - status=0 clientIf=21 device=XX:XX:XX:XX:XX:XX
D: discoverServices() - device: XX:XX:XX:XX:XX:XX
D: onClientConnectionState() - status=0 clientIf=22 device=XX:XX:XX:XX:XX:XX
D: discoverServices() - device: XX:XX:XX:XX:XX:XX
D: onSearchComplete() = Device=XX:XX:XX:XX:XX:XX Status=0
D: requestConnectionPriority() - params: 1
D: setCharacteristicNotification() - uuid: XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX enable: true
D: onSearchComplete() = Device=XX:XX:XX:XX:XX:XX Status=0
D: requestConnectionPriority() - params: 1
D: setCharacteristicNotification() - uuid: XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX enable: true
D: writeDescriptor() - uuid: 00002902-0000-1000-8000-00805f9b34fb
D: stopScan
D: getLeState() returning 12
D: STATE_ON
D: writeDescriptor() - uuid: 00002902-0000-1000-8000-00805f9b34fb
D: writeDescriptor: mDeviceBusy = true, and return false
D: stopScan
D: getLeState() returning 12
D: STATE_ON
D: could not find callback wrapper
D: onDescriptorWrite() - Device=XX:XX:XX:XX:XX:XX handle=26
D: onNotify() - Device=XX:XX:XX:XX:XX:XX handle=25
D: onNotify() - Device=XX:XX:XX:XX:XX:XX handle=25
D: onNotify() - Device=XX:XX:XX:XX:XX:XX handle=25

お気づきの点等ございましたらアドバイスしていただけると助かります。

[Wind]

他に方法があるのかもしれませんが、
BLEはデバイスを見つけてから接続するまでに時間がかかり、
その間に同じデバイスを見つけることがあるので、
見つけたデバイスを内部で保存しておいてから接続した方が良いです。
例えば下記URLの「スキャンしたデバイスのリスト保存」を参考にしてみてください。
https://qiita.com/HideMatsu/items/6a6758eca86500881126

[LS_Takao]

ありがとうございます。
参考にさせていただきます。

Answer 2

onServicesDiscovered()内の

// Service, CharacteristicのUUIDが同じならBluetoothGattを更新する.
mBtGatt = gatt;

これを消すと
どう動きますか？

私が昔書いたコードでは、onServicesDiscovered()内でBluetoothGattへの代入は行っておりませんでした。

Comments

[LS_Takao]

hillacken 様。
アドバイスありがとうございます。
「mBtGatt = gatt;」をNOPにしたところ、該当事象が発生しなくなりました。
上記コードを元に戻すと該当事象が発生するため、アドバイスいただいた処理に起因していると思われます。
障害箇所の特定を行っていただきありがとうございました。

※補足
　複数回呼び出される事象は毎回必ず発生するのではなく、20回中15回程度の頻度で発生していました。
　NOPにした後の該当事象の発生回数は20回中0回でした。

mBtDevice.connectGatt()で受け取った「BluetoothGatt」とonServicesDiscovered()で受け取った「BluetoothGatt」は異なると言うことでしょうか？
onServicesDiscovered()で受け取った「BluetoothGatt」はサービスやUUIDのチェック用で、要求や指示に用いてはいけないということでしょうか？
(要求や指示に用いる「BluetoothGatt」はconnectGatt()で返却された物を用いる？)

お気づきの点等ございましたらアドバイスしていただけると助かります。

[hillacken]

異なると言うことでしょうね。
内部実装について詳しくはわかりません。

[hillacken]

＞要求や指示に用いる「BluetoothGatt」はconnectGatt()で返却された物を用いる
という事で良いと思います。
私はそのようにしていました。

[LS_Takao]

ありがとうございました。
参考にさせていただきます。

Answer 3

2018/08/16現在解消に至っておりません。
最新の確認結果は以下の通りです。
・送信パケット数：556
・ooo Receive OK：539
・xxx Receive NG：1078
OKが1回に対して、NGが2回発生しています。
※送信パケット数とOKの数が合わないのは受信側を強制終了したためと思われます。