[android]BLE接続の不安定さに迫る！

迫れるのかどうか・・・。

お仕事でBLEをやっているのだが、しばしばBLE切断される。
そのほとんどが、BLE接続の段階だ。
ネットで検索しても、「接続段階がね－」みたいによく書かれている。

それで終わらせてしまいたいのだけど、今回はデバイス側も私が作っているので、どちらにも責任がないことを証明したいのだ。

---

CentralがBLE接続するときは、だいたいこうなると思う。

1. 接続したいPeripheralを探す
2. 見つかったら接続する

この図でいうところの、ScanningとInitiatingだ。
ScannninとInitiatingはシーケンスとしてはつながっていないので、Scannning無しでもInitiatingしてConnectionになることはできるはず。

が、だいたいは、探してつなぐ、だろう。
(こういう思い込みが、しばしば間違いにつながるのだが。。)

---

Androidでは、スキャンするところと、それ以降が分かれている。
(iOSはやっていないので、知らない。)

スキャンはBluetoothLeScannerが、それ以降はBluetoothGattが行う。
スキャンしたらデバイス情報が見つかるので、そこに対して接続を行うイメージだ。

接続要求(connectGatt())すると、コールバックが行われる。
BluetoothGattは非同期処理で、要求したらコールバックされる、という流れだ。

今回は接続の不安定さを見たいので、

• スキャンする
• 対象のデバイスが見つかったら接続する
• 接続成功したら切断して、スキャンする

を繰り返して、そのときのBLE状況をスニファで見てみることにする。

スニファはTIのドングルを使っているのだが、切断と接続の間隔が短いとうまく拾えないようなので、その間は数秒開けることにした。

---

こうやって無線のところをモニタしたのだけど、成功の時も失敗するときも同じだった。
ちゃんとADV_CONNECT_REQして、Version Indをやりとりして、Featureをやりとりして、AndroidからTerminate Ind(status=0x13)している。
Peripheralのログには0x13=相手が切断した、しか出てこない。

この時点で、Peripheral側の責任がなくなる。
やれやれ・・・。

 

では、あとはAndroid側だけ見ていけば良い。
Nexus5(Android 6.0.1)のlogcatを見ていくと、リアルタイムで見ていないのではっきりはしないのだが、前後で違いそうなところがある。

長いので、順番に見ていこう。

---

成功時から見ていく。

接続要求。

D/BluetoothGatt: connect() - device: xx:xx:xx:xx:xx:xx, auto: false

connectGatt()でautoConnectをfalseにしているので、こういうログになる。
そしてregisterApp()や、onClientRegistered()が出てくる。
たぶん、BluetoothGattの下に要求を投げるのが、これだろう。

D/BtGatt.GattService: clientConnect() - address=xx:xx:xx:xx:xx:xx, isDirect=true

そこから接続できたところのログが、これだと思う。
isDirectが気になるが、放置だ。
本来はAndroidのソースを追いながらやるべきなのだけど、もうちょっと疲れたので勘弁しておくれ。

I/TrustAgent.Tracker: [BluetoothConnectionTracker] Bluetooth connect broadast for yyyyyyyy xx:xx:xx:xx:xx:xx

yyyyyはDeviceNameだ。
そうすると次は階層が上がって、GattServiceとBluetoothGattのログになる。

D/BtGatt.GattService: onConnected() - clientIf=5, connId=5, address=xx:xx:xx:xx:xx:xx
D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=5 device=xx:xx:xx:xx:xx:xx

よくわからんけど、clientIfは5になっているのがほとんどのような気がする。

 

とにかく、この次でようやくBluetoothGattCallbackが呼ばれて、アプリの領域になる。
今回は、ここでdisconnect()を読んでいるためか、こういうログになる。

D/BluetoothGatt: cancelOpen() - device: xx:xx:xx:xx:xx:xx
D/BtGatt.GattService: clientDisconnect() - address=xx:xx:xx:xx:xx:xx, connId=5

続けて、こういうログになっている。

D/BtGatt.GattService: clientDisconnect() - address=xx:xx:xx:xx:xx:xx, connId=5
W/bt_btif: bta_gattc_conn_cback() - cif=3 connected=0 conn_id=3 reason=0x0016
W/bt_btif: bta_gattc_conn_cback() - cif=4 connected=0 conn_id=4 reason=0x0016
W/bt_btif: bta_gattc_conn_cback() - cif=5 connected=0 conn_id=5 reason=0x0016

reasonの0x13は「相手が切断した」で、0x16は「自分が切断した」だ。
だから、ここは自分で切断している。
正しい。

 

失敗したときだが、けっこう前の段階で違っていて、同じなのは「isDirect」のところくらいまでだ。
その後、どちらもbt_btif_configが2つくらいログを出すのだが、失敗した場合にはこのログになっている。

W/bt_btif: bta_gattc_conn_cback() - cif=3 connected=0 conn_id=3 reason=0x003e
W/bt_btif: bta_gattc_conn_cback() - cif=4 connected=0 conn_id=4 reason=0x003e
W/bt_btif: bta_gattc_conn_cback() - cif=5 connected=0 conn_id=5 reason=0x003e

reasonの0x3Eは、接続確立失敗、だ。
このログは、スニファでは出ていないし、接続しようともしていない。
スニファを信じるなら、Androidが勝手にやっているだけとなる。

その後、

I/bt_btm_sec: btm_sec_disconnected clearing pending flag handle:64 reason:62
D/BtGatt.GattService: onConnected() - clientIf=5, connId=0, address=xx:xx:xx:xx:xx:xx

などといって、最後には、

D/BluetoothGatt: onClientConnectionState() - status=133 clientIf=5 device=xx:xx:xx:xx:xx:xx

と、見慣れたstatus=133で終わる。
ちなみに、reason=62の62は、16進数で0x3Eだ。

---

うちにはスニファが1台しかないので、nRFの設定でAdvertisingをCH37だけに制限しているのだ。
だから、スニファが拾っているのはCH37だけになっている。

もしかしたら、Peripheralが設定に従わずにCH37以外にAdvertisingしたのかもしれない。
が・・・発生頻度からすると考えにくいと思っている。
少なくともスニファで見た限りでは、通常はCH37でしかAdvertisingしていない。

 

あるいは、CH37だけしかAdvertisingしないという不自然さが原因で、ということも考えられなくもない。
ただ、Advertisingってそういうものだろう、ということから考えると、それでおかしくなってはだめだろう。

そもそも、CH制限していない場合でも発生しているし。

---

あと、ほどほどの距離からApple系のものがAdvertisingしているのがあります。
おかげで、ログが見づらくてもうぅ。。。。。

電波暗室がほしいけど、庶民にはちょっとねぇ。
室内に発信源がいなければ、このくらいでけっこうはじけます。