gt777
2023年6月5日 11時08分
お世話になっております。
現在、コンテナ内のPythonアプリケーションにて周期的にBLEスキャンをするプログラムを作成しているのですが、
コンテナ起動から1時間程度経過すると以下のエラーが発生しスキャンが不可となります。
[org.freedesktop.DBus.Error.AccessDenied] Client tried to send a message other than Hello without being registered
Armadillo上で、何かBluetoothの連続稼働時間の制限等があるでしょうか？
もしくは、調査観点等心当たりがあればご教示いただけますと幸いです。
実行環境は以下です。
・コンテナイメージ：debian bullseye slim
・Python：Python3.11.3
コメント
gt777
2023年6月5日 15時10分
マルティネさん
> python のアプリケーションでのスキャンはどう行ってますでしょうか？
bleakを用いてスキャン実施しております。
少し修正しておりますが、概ね以下のようなコードを繰り返し呼び出しております。
from bleak import BleakScanner
（略）
async def _ble_scan(self):
try:
async with BleakScanner() as scanner:
#時間を区切ってスキャン
await asyncio.sleep(10)
scanned_data = scanner.discovered_devices_and_advertisement_data
except Exception as e:
logger.error(e)withブロックでクラスインスタンスを作成しているので
都度初期化をしている認識でしたが、bleakのログを有効化してみたところ、
確かに初期化がうまく動いていないように見えました。
（initial propertiesが表示されなくなり、dbusのエラー出力。※添付参照）
> そのエラーの前に別のエラーがありますでしょうか？ dmesg や bluetoothd の出力に何かあるかもしれません。
dmesgやbleakのログ上には特に予兆となるようなエラーはありませんでした。
ただ、事象が発生した状態でコンテナ上でbluetoothctlコマンドを投入したところ、
以下のエラーが表示されました。（事象発生前は正常にコマンド起動できていました）
記載いただいた「python の dbus モジュールで接続だけ復帰させて、interface の再作成が行われてないように見える」ことに起因するエラーかもしれません。
root@armadillo:/# bluetoothctl Waiting to connect to bluetoothd...dbus[313]: arguments to dbus_connection_get_object_path_data() were incorrect, assertion "connection != NULL" failed in file ../../../dbus/dbus-connection.c line 5905. This is normally a bug in some application using the D-Bus library. D-Bus not built with -rdynamic so unable to print a backtrace Aborted
> また、このエラーの後にスキャンできなくなっているとのことですが、コンテナの再起動等でもスキャンできないか、リスタートで再びできるようになるか、その場合ならクライアントのリスタートだけでも再びできるようになるかあたりの確認もお願いします。
・コンテナを再作成（podman_start）⇒スキャン可能
・コンテナを再起動⇒確認中
・クライアントのリスタート⇒確認中
環境の再現に時間がかかっているため後半部分が未確認なのですが、おそらくdbus-daemonとbluetoothdの接続がうまくできていなさそうなので、
/etc/init.d/dbus restart /usr/sbin/bluetoothd &
あたりのコマンドから打ち直してあげれば動きそうに見えております。
確認でき次第再度情報共有させていただきます。
| ファイル | ファイルの説明 |
|---|---|
| bleak_log_20230605.txt | Python bleakのログ(抜粋) |
at_dominique.m…
2023年6月5日 15時31分
gt777さん
追加情報ありがとうございます。
時間の節約のため、確認中の部分だけ返事します：
> ・コンテナを再作成（podman_start）⇒スキャン可能
> ・コンテナを再起動⇒確認中
podman_start での再作成は podman stop/start とほぼ変わらないので、出きるようになると思います。
クライアントの再起動だけも、bluetoothctl で接続できなかったのでそれも失敗すると思います。
これからログと bluetoothctl のエラーを確認しますが、
感としては dbus-daemon か bluetoothd の不具合になりそうですので、bluetoothd を bluetoothd -nd > /tmp/bluetoothd.log で起動してそのデバグ有効のログも取得できれば助かります。
また何か分かりましたら再び返事します。
よろしくお願いします。
gt777
2023年6月6日 10時26分
マルティネさん
ご確認いただきありがとうございます。
記載いただいたコマンドでbluetoothdのデバッグログを取得しました。
なぜかファイルに出力されなかったため、teratermのコンソールログで記録したものを添付します。
アプリのログ上では、10:06:25あたりまでは正常にスキャンできており、10:06:34にスキャンした際はエラーが発生しておりました。
また、アプリを起動したままdbusとbluetoothdを再起動させると、
再び正常にスキャンできるようになったため、やはりdbusかbluetooth側の問題のように見えております。
dbusの再起動に3～5秒ほど時間がかかっていたため（通常時は1秒未満で完了）、
dbus側が怪しそうですが、何か取得できるログ等ありましたらご教示ください。
| ファイル | ファイルの説明 |
|---|---|
| bluetoothd_nd.log |
at_dominique.m…
2023年6月6日 15時27分
gt777さん
> 記載いただいたコマンドでbluetoothdのデバッグログを取得しました。
> なぜかファイルに出力されなかったため、teratermのコンソールログで記録したものを添付します。
>
> アプリのログ上では、10:06:25あたりまでは正常にスキャンできており、10:06:34にスキャンした際はエラーが発生しておりました。
ログありがとうございます。
エラー発生時に出力が止めていたんですね。エラーが発生した後に bluetoothd まで新しいスキャン依頼がたどりつかなかったので、そこは分かりますが接続不可能になる直前のエラーがなさそうですね。
> また、アプリを起動したままdbusとbluetoothdを再起動させると、
> 再び正常にスキャンできるようになったため、やはりdbusかbluetooth側の問題のように見えております。
> dbusの再起動に3～5秒ほど時間がかかっていたため（通常時は1秒未満で完了）、
> dbus側が怪しそうですが、何か取得できるログ等ありましたらご教示ください。
そうですね、dbus でこういう不具合をみたことがないので、bluetoothd がどこかで固まっている (dead lock 等）可能性が高いと思います。
その場合、dbus がクライアントのメッセージを bluetoothd に提出したところで返事を待っているはずなので、dbus の再起動が少し長くなる理由にもなります。dbus だけの再起動で解決されなければ、ほぼ確実に bluetoothd 側の問題だと思います。
こから欲しい情報が少し案内しにくいので、ひとまずこちらで再現できないか試してみます。
(bleak をインストールして、提供してくださったループで実行しているところです）
お手数ですが、明日までに再現できなかったらまた色々聞かせていただきます。
よろしくお願いします
at_dominique.m…
2023年6月7日 7時59分
gt777さん
マルティネです。
> こから欲しい情報が少し案内しにくいので、ひとまずこちらで再現できないか試してみます。
> (bleak をインストールして、提供してくださったループで実行しているところです）
一晩中実行しても再現できなかったので、お手数ですが以下の様なコマンドで再現できた後の bluetoothd のバックトレースを取得できますでしょうか？
細かいコマンドで申し訳ございませんが、これで原因がはっきりして解決へ進めると思います。
準備として、debian-debug のリポを追加して gdb と bluez-dbgsym パッケージの追加
/etc/apt/sources.lroot@armadillo:/# echo deb http://deb.debian.org/debian-debug/ bullseye-debug main > /etc/apt/sources.list.d/debug.list root@armadillo:/# apt update root@armadillo:/# apt install bluez-dbgsym gdb procps
再現できた時：
root@armadillo:/# ps aux|grep bluetooth root 10 7.5 0.2 13376 4832 ? S Jun06 74:47 bluetoothd -nd root 964 0.0 0.0 2904 640 pts/0 S+ 07:35 0:00 grep bluetooth ^ bluetoothd の PID, ここでは 10, を次のコマンドに使います root@armadillo:/# gdb --pid 10 : 省略 (gdb) thread apply all bt Thread 1 (Thread 0xffff9ff24c30 (LWP 10) "bluetoothd"): #0 0x0000ffffa0493258 in __GI___poll (fds=0xaaaaf3725fc0, nfds=13, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:41 #1 0x0000ffffa074adf8 in ?? () from /usr/lib/aarch64-linux-gnu/libglib-2.0.so.0 #2 0x0000ffffa074b1b0 in g_main_loop_run () from /usr/lib/aarch64-linux-gnu/libglib-2.0.so.0 #3 0x0000aaaad8350fac in mainloop_run () at src/shared/mainloop-glib.c:79 #4 0x0000aaaad8351420 in mainloop_run_with_signal (func=func@entry=0xaaaad82e36b0 <signal_callback>, user_data=user_data@entry=0x0) at src/shared/mainloop-notify.c:201 #5 0x0000aaaad82939bc in main (argc=<optimized out>, argv=<optimized out>) at src/main.c:971
正常な状態では bluetoothd は poll で dbus からの連絡を待っているはずですが、固まっている時に違うところで動かないかなと推測しています。
この推測で正しいなら、「generate-core-file」コマンドで コンテナに core. ファイルが作成されますが、そのファイルを解析すれば止まった理由も分かると思いますので大変お手数ですがご提供いただけたら助かります。（mac アドレスなどの bluetoothd のプロセス情報が漏れますので、ご心配でしたら直接なメールで連絡します）
逆に、bluetoothd が正常な poll で待っている状態の場合は dbus 側でもうちょっと正確に確認したいと思いますので、
以下のコマンドを試していただけたらと思います。
dbus-send --system --dest=org.bluez --type=method_call --print-reply / org.freedesktop.DBus.ObjectManager.GetManagedObjects
よろしくお願いします
gt777
2023年6月7日 9時42分
マルティネさん
色々とご確認いただきありがとうございます。
gdbコマンドの実行結果は以下となります。
root@armadillo:/# ps aux|grep bluetooth root 889 1.0 0.5 23540 9796 pts/0 S 08:16 0:38 /usr/sbin/bluetoothd root 1143 0.0 0.0 4928 648 pts/1 S+ 09:17 0:00 grep bluetooth root@armadillo:/# gdb --pid 889 （略） (gdb) thread apply all bt Thread 1 (Thread 0xffff89283c30 (LWP 889) "bluetoothd"): #0 0x0000ffff88e0a258 in __GI___poll (fds=0xaaaaec3b1a80, nfds=13, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:41 #1 0x0000ffff890c1df8 in ?? () from /usr/lib/aarch64-linux-gnu/libglib-2.0.so.0 #2 0x0000ffff890c21b0 in g_main_loop_run () from /usr/lib/aarch64-linux-gnu/libglib-2.0.so.0 #3 0x0000aaaac42a0fac in mainloop_run () at src/shared/mainloop-glib.c:79 #4 0x0000aaaac42a1420 in mainloop_run_with_signal (func=func@entry=0xaaaac42336b0 <signal_callback>, user_data=user_data@entry=0x0) at src/shared/mainloop-notify.c:201 #5 0x0000aaaac41e39bc in main (argc=<optimized out>, argv=<optimized out>) at src/main.c:971
記載いただいた例と変わらないように見えたため、
「generate-core-file」コマンドは実行しておりませんが、必要であればご連絡お願いいたします。
dbus側のコマンドは以下のようにエラーになってしまいました。
root@armadillo:/# dbus-send --system --dest=org.bluez --type=method_call --print-reply / org.freedesktop.DBus.ObjectManager.GetManagedObjects Failed to open connection to "system" message bus: The maximum number of active connections for UID 0 has been reached
参考情報として、Python側のエラーのtrackbackが取得できたため、記載します。
（事象発生後の環境で実行しています）
root@armadillo:/# python
Python 3.11.3 (main, Jun 1 2023, 23:25:03) [GCC 10.2.1 20210110] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import asyncio
>>> from bleak import BleakScanner
>>> async def ble_scan():
... async with BleakScanner() as scanner:
... await asyncio.sleep(10)
... scanned_data = scanner.discovered_devices_and_advertisement_data
...
>>> asyncio.run(ble_scan())
Traceback (most recent call last):
File "<stdin>", line 1, in <module>
File "/usr/local/lib/python3.11/asyncio/runners.py", line 190, in run
return runner.run(main)
^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/asyncio/runners.py", line 118, in run
return self._loop.run_until_complete(task)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/asyncio/base_events.py", line 653, in run_until_complete
return future.result()
^^^^^^^^^^^^^^^
File "<stdin>", line 2, in ble_scan
File "/usr/local/lib/python3.11/site-packages/bleak/__init__.py", line 152, in __aenter__
await self._backend.start()
File "/usr/local/lib/python3.11/site-packages/bleak/backends/bluezdbus/scanner.py", line 174, in start
manager = await get_global_bluez_manager()
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/bleak/backends/bluezdbus/manager.py", line 910, in get_global_bluez_manager
await instance.async_init()
File "/usr/local/lib/python3.11/site-packages/bleak/backends/bluezdbus/manager.py", line 204, in async_init
assert_reply(reply)
File "/usr/local/lib/python3.11/site-packages/bleak/backends/bluezdbus/utils.py", line 22, in assert_reply
raise BleakDBusError(reply.error_name, reply.body)
bleak.exc.BleakDBusError: [org.freedesktop.DBus.Error.AccessDenied] Client tried to send a message other than Hello without being registered| ファイル | ファイルの説明 |
|---|---|
| gdb_bluetoothd_20230607.log | gdbコマンドの実行結果 |
at_dominique.m…
2023年6月7日 11時04分
gt777さん
早速の返事ありがとうございます。
> 記載いただいた例と変わらないように見えたため、
> 「generate-core-file」コマンドは実行しておりませんが、必要であればご連絡お願いいたします。
はい、大丈夫です。bluetoothd に問題がなさそうですね。
> dbus側のコマンドは以下のようにエラーになってしまいました。
>
> root@armadillo:/# dbus-send --system --dest=org.bluez --type=method_call --print-reply / org.freedesktop.DBus.ObjectManager.GetManagedObjects > Failed to open connection to "system" message bus: The maximum number of active connections for UID 0 has been reached >
おぉ、これはもっとはやく試すべきでした。bluetoothctl と bleak のエラーとちがって、このエラーでやっと原因が分かります：現在の接続数が多すぎて新しい接続が断れています。
私が再現したときに scanned_data = scanner.discovered_devices_and_advertisement_data を捨てていただけなので、python が自動的に接続を閉じていましたが、その情報をどこかに使っていたらその掃除（gc）がうまく起動できていなかったかもしれません。
Bleak.scanner() で新しい dbus 接続を作り続いていますのでその scanner をどこかに保存して使い続けば解決されると思います。
client プログラムの /proc//fd/ を ls -l などで表示すれば、socket の数で一時間待たなくても確認できます。
それでもダメでしたらまた連絡ください。
よろしくお願いします。
at_dominique.m…
2023年6月7日 11時10分
> client プログラムの /proc//fd/ を ls -l などで表示すれば、socket の数で一時間待たなくても確認できます。
フォーラムが pid の部分を表示できてませんでしたが、pid をプログラムの pid にして /proc/pid/fd でした。
さっそく試しにスキャンの結果をリストに入れるだけに変えてみたら、256ソケット以降は失敗するようになりました。
max_connections_per_user の設定ですね：
/usr/share/dbus-1/system.conf: <!-- <limit name="max_connections_per_user">256</limit> -->
よろしくお願いします。
at_dominique.m…
2023年6月8日 9時48分
gt777 さん
マルティネです。
> Bleak.scanner()の使いまわしを試してみましたが、fdが増え続けているようです。
> scanner.discovered_devices_and_advertisement_dataを取得せずにそのまま捨ててみましたが、そちらもfdが増え続けてしまいました。
> bleakのライブラリ側の問題かもしれません。
こちらで試した時に無事に何回かスキャンしても同じ接続を使っていましたが、プログラムの構成の問題でしょうか？
同じエラーメッセージを bleak の github で検索してみたら (…最初からそうするべきでしたね…）、同じ問題が起きていた時の案内が参考になるかもしれません：
https://github.com/hbldh/bleak/discussions/1273
ようするに、scanner を一つの変数に保存しても asyncio.run() を何回か実行すると新しい接続するそうですね。
その人の解決は別のスレッドで定期的に実行し続けたことらしいですが、使えそうでしょうか？
gt777
2023年6月8日 11時27分
マルティネさん
githubも見ていたのですが該当のスレッドを見逃していたようです。情報ありがとうございます！
以下のようなコードでfdが増えずにループを回すことができるようになりました。
（loop = asyncio.new_event_loop()をwhileの内側に入れていたせいで、asyncio.run()と同様に新規接続となってしまっていたようです。
whileの外側に出すか、get_event_loop()にすれば問題が発生しなくなりました。）
import asyncio
from bleak import BleakScanner
async def ble_scan():
async with BleakScanner() as scanner:
await asyncio.sleep(1)
return scanner.discovered_devices_and_advertisement_data
def main():
loop = asyncio.new_event_loop()
while True:
scanned_data = loop.run_until_complete(ble_scan())
print(scanned_data)
if __name__=='__main__':
main()こちらのプログラム不備でお手数おかけして申し訳ありませんでした。
詳細なフォロー大変助かりました。ありがとうございました。
at_dominique.m…
2023年6月5日 11時39分
gt777さん、
お世話になっています、
アットマークテクノのマルティネです。
> Armadillo上で、何かBluetoothの連続稼働時間の制限等があるでしょうか？
python のアプリケーションでのスキャンはどう行ってますでしょうか？
Bluetooth の稼働制限はないはずですが、上記のエラーは dbus側のエラーで、サービス側の問題か dbus の制限でしたかもしれません。
具体的に、このエラーは dbus の接続が切断して、python の dbus モジュールで接続だけ復帰させて、interface の再作成が行われてないように見えます（最初は dbus.Interface を作って interface.hello() 等を読んでいると思います）が、切断した理由が不明ではちょっと気になります。
そのエラーの前に別のエラーがありますでしょうか？ dmesg や bluetoothd の出力に何かあるかもしれません。
また、このエラーの後にスキャンできなくなっているとのことですが、コンテナの再起動等でもスキャンできないか、リスタートで再びできるようになるか、その場合ならクライアントのリスタートだけでも再びできるようになるかあたりの確認もお願いします。
よろしくお願いします。