hi-itabashi
2023年6月2日 11時57分
お世話になります。
現在、G3でビーコンから発信されるBLEアドバタイズを受信してデータ収集するためのソフトウェアをテストしています。
（Python3.11.2、Bleak 0.20.2）
長時間稼働テストで、大体27時間程度経過した時に、BLEアドバタイズを全く受信しなくなる現象が発生しております。
BLEモジュールが正常に動作し、BLEアドバタイズを受信している（正常に動作している）時は、
syslogに「Bluetooth: hci0: advertising data len corrected」が記録されつつも、データの取得は
出来ているようです。
一方、BLEアドバタイズを受信しなくなった状態においては、「Bluetooth: hci0: advertising data len corrected」
の代わりに、以下のログが頻繁発生している状態になります。
armadillo dbus-daemon[562]: [system] Connection ":1.3444" is not allowed to add more match rules
(increase limits in configuration file if required; max_match_rules_per_connection=2048)
現象が発生した場合は、G3を再起動すると、何事もなかったようにBLEアドバタイズの受信を行いますので
長時間稼働により、何らかの原因でBLEモジュールが停止したような状態になっているのだろうと
推測していますが、原因がわかっていません。
※現象が発生した個体とは別な個体で試しましたが、同様の現象が発生します。
※長時間稼働させると、必ず現象が発生します。
解決方法や原因の特定について、アドバイス頂きたく、よろしくお願いいたします。
コメント
hi-itabashi
2023年6月5日 18時27分
お世話になっております。
ご利用のArmadillo-IoT G3 の型番：AGX3140-D20Z
ソフトウェアバージョン：
root@armadillo:/var/log# hostnamectl
IPVS: Creating netns size=912 id=2
Static hostname: armadillo
Icon name: computer
Machine ID: f0f93cb938d0402db92ad211268fb36d
Boot ID: 936d0ac7a3504d968f92955d868c04bd
Operating System: 8;;https://www.debian.org/Debian GNU/Linux 10 (buster)8;;
Kernel: Linux 4.9.133-at28
Architecture: arm
bluetoothctl: 5.50
bluetoothctl listコマンドを実行するとフリーズし、OOMKillerが発動してしまいました。
systemd-journal invoked oom-killer: gfp_mask=0x26080c2(GFP_KERNEL|__GFP_HIGHMEM|
__GFP_ZERO|__GFP_NOTRACK), nodemask=0, order=0, oom_score_adj=0
systemd-journal cpuset=/ mems_allowed=0
CPU: 0 PID: 290 Comm: systemd-journal Not tainted 4.9.133-at28 #2
Hardware name: Freescale i.MX7 Dual (Device Tree)
[<8010f8e0>] (unwind_backtrace) from [<8010b470>] (show_stack+0x10/0x14)
[<8010b470>] (show_stack) from [<8040050c>] (dump_stack+0x78/0x8c)
[<8040050c>] (dump_stack) from [<80224290>] (dump_header+0x98/0x218)
[<80224290>] (dump_header) from [<801dc7b4>] (oom_kill_process+0x2c4/0x4a0)
[<801dc7b4>] (oom_kill_process) from [<801dcc78>] (out_of_memory+0x114/0x30c)
fec 30bf0000.ethernet eth0: MDIO read timeout
[<801dcc78>] (out_of_memory) from [<801e13f4>] (__alloc_pages_nodemask+0xd2c/0xd
74)
[<801e13f4>] (__alloc_pages_nodemask) from [<801fdbac>] (__pte_alloc+0x24/0x158)
[<801fdbac>] (__pte_alloc) from [<802014b0>] (handle_mm_fault+0xbf8/0xc80)
[<802014b0>] (handle_mm_fault) from [<8011502c>] (do_page_fault+0x2a0/0x38c)
[<8011502c>] (do_page_fault) from [<80101300>] (do_DataAbort+0x3c/0xb8)
[<80101300>] (do_DataAbort) from [<8010c1dc>] (__dabt_usr+0x3c/0x40)
Exception stack(0xa94c1fb0 to 0xa94c1ff8)
1fa0: 750a2008 750a2001 00000000 750a2000
1fc0: 000a1c3a 00201000 00201002 00200008 76edb000 76edb7f4 76edbb38 00000008
1fe0: 000000c0 7ef4b138 76e7ca97 76e39620 40030030 ffffffff
Mem-Info:
active_anon:192497 inactive_anon:5193 isolated_anon:0
active_file:99 inactive_file:123 isolated_file:0
unevictable:4 dirty:0 writeback:0 unstable:0
slab_reclaimable:2005 slab_unreclaimable:6128
mapped:954 shmem:5292 pagetables:715 bounce:0
free:44331 free_pcp:5 free_cma:43732
Node 0 active_anon:769988kB inactive_anon:20772kB active_file:312kB inactive_fil
e:356kB unevictable:16kB isolated(anon):0kB isolated(file):0kB mapped:3748kB dir
ty:0kB writeback:0kB shmem:21168kB writeback_tmp:0kB unstable:0kB pages_scanned:
418 all_unreclaimable? no
Normal free:176784kB min:3312kB low:4140kB high:4968kB active_anon:769988kB inac
tive_anon:20772kB active_file:584kB inactive_file:660kB unevictable:16kB writepe
nding:0kB present:1048576kB managed:1017960kB mlocked:16kB slab_reclaimable:8020
kB slab_unreclaimable:24512kB kernel_stack:1144kB pagetables:2860kB bounce:0kB f
ree_pcp:176kB local_pcp:16kB free_cma:174520kB
lowmem_reserve[]: 0 0 0
Normal: 4410*4kB (UMC) 3579*8kB (UMEC) 1693*16kB (UEC) 596*32kB (EC) 276*64kB (E
C) 135*128kB (EC) 79*256kB (C) 55*512kB (C) 1*1024kB (C) 0*2048kB 0*4096kB 0*819
2kB 0*16384kB 0*32768kB = 176784kB
5634 total pagecache pages
0 pages in swap cache
Swap cache stats: add 0, delete 0, find 0/0
Free swap = 0kB
Total swap = 0kB
262144 pages RAM
0 pages HighMem/MovableOnly
7654 pages reserved
81920 pages cma reserved
[ pid ] uid tgid total_vm rss nr_ptes nr_pmds swapents oom_score_adj name
[ 290] 0 290 8560 1104 36 0 0 0 systemd-journal
[ 302] 0 302 3848 201 7 0 0 -1000 systemd-udevd
[ 354] 101 354 5009 161 10 0 0 0 systemd-timesyn
[ 519] 0 519 6116 254 11 0 0 0 rsyslogd
[ 520] 104 520 1706 437 8 0 0 -900 dbus-daemon
[ 530] 0 530 2271 204 8 0 0 0 wpa_supplicant
[ 542] 0 542 2661 158 9 0 0 0 systemd-logind
[ 551] 0 551 104165 84773 232 0 0 0 NetworkManager
[ 552] 108 552 1263 82 6 0 0 0 avahi-daemon
[ 569] 0 569 1399 46 7 0 0 0 cron
[ 570] 0 570 6796 19 7 0 0 0 rngd
[ 630] 108 630 1232 65 6 0 0 0 avahi-daemon
[ 787] 0 787 2221 137 9 0 0 -1000 sshd
[ 834] 0 834 1392 71 7 0 0 0 connection-reco
[ 857] 0 857 12739 278 16 0 0 0 ModemManager
[ 931] 0 931 8994 179 13 0 0 0 polkitd
[ 2122] 0 2122 731 20 6 0 0 0 agetty
[ 2144] 0 2144 2012 114 9 0 0 0 login
[ 2469] 33 2469 1839 166 8 0 0 0 lighttpd
[ 2483] 105 2483 3077 164 10 0 0 0 exim4
[ 2533] 0 2533 317 10 3 0 0 0 brcm_patchram_p
[ 2616] 0 2616 17001 15115 36 0 0 0 bluetoothd
[ 2631] 0 2631 6647 1450 14 0 0 0 python3
[ 2685] 0 2685 3023 239 10 0 0 0 systemd
[ 2701] 0 2701 3524 404 10 0 0 0 (sd-pam)
[ 2734] 0 2734 1616 218 7 0 0 0 bash
[ 2208] 0 2208 36716 35514 78 0 0 0 bluetoothctl
[ 2789] 0 2789 354 11 4 0 0 0 sleep
[ 2796] 0 2796 67882 51843 116 0 0 0 python3
Out of memory: Kill process 551 (NetworkManager) score 334 or sacrifice child
Killed process 551 (NetworkManager) total-vm:416660kB, anon-rss:339092kB, file-r
ss:0kB, shmem-rss:0kB
IPVS: Creating netns size=912 id=3
IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
syslogにつきましては、取得を試みておりますのでしばらくお待ちください。
hi-itabashi
2023年6月5日 18時51分
お世話になります。
syslogを取得しましたので添付いたします。
長いのですが、6/5 8:53:22にログで、Pythonでのデータ送信が途絶えているログが出力されていることから、
この時間帯を境に減少が発生しているものと推測します。
| ファイル | ファイルの説明 |
|---|---|
| syslog.log | syslog |
at_syunya.ohshio
2023年6月7日 17時03分
大塩です。
> syslogを取得しましたので添付いたします。
> 長いのですが、6/5 8:53:22にログで、Pythonでのデータ送信が途絶えているログが出力されていることから、
> この時間帯を境に減少が発生しているものと推測します。
ログ送付、情報などありがとうございます。
OOMKiller が発生したこと、ログ内で常に「Connection ":1.6" is not allowed to add more match rules」が表示されていることが気になります。
OOMKiller はメモリ領域が足りていない状態で発生するものであるため、ご利用のプログラム内でメモリ領域の確保が大量に行われている可能性もあります。
以下内容についてお答えいただけますでしょうか。
・bluetoothctl list コマンドでの OOMKiller は、現象発生後のコマンド実行で起きるでしょうか。
・G3再起動後、「Connection ":1.6" is not allowed to add more match rules」は、どれぐらいから発生するでしょうか。
hi-itabashi
2023年6月8日 13時10分
大塩さま、お世話になります。
OOMKiller の件ですが、現象を発生させてコマンドを打ってみたところ、再現しませんでした。
正常に、bluetoothアダプタのリストが表示されました。
必ず発生するようではないようです。
「Connection ":1.6" is not allowed to add more match rules」が発生するタイミングですが、
1時間36分ほどで、発生しました。
その時のsyslog（抜粋）を添付いたします。
何度か試してみましたが、1時間から2時間の間で発生するようです。
※他、わかったこと
現象（BLEアドバタイズの情報が受信できない）が発生している状態で、プログラムの再起動をした場合、状況に変化はありませんでした。
また、現象（BLEアドバタイズの情報が受信できない）が発生している状態で、bluetooth.serviceを再起動すると、BLEアドバタイズの受信を再開しました。
| ファイル | ファイルの説明 |
|---|---|
| syslog.log | 09:43:42にプログラム起動、11:19:14に「Connection ":1.6" is not allowed to add more match rules」が発生。 |
at_syunya.ohshio
2023年6月5日 16時08分
大塩です。
現象の確認のため、以下内容についてお教え頂けますでしょうか。
・ご利用のArmadillo-IoT G3 の型番
・ソフトウェアバージョン(カーネルまたはインストールディスクイメージ)
また、可能であれば現象発生時のsyslog をお送りいただけますと幸いです。
以上です。