Hello. I encountered with a problem: Connman randomly is getting inadequate.
Symptoms (simultaneously):
1. All existing connections stop working, cannot establish new.
2. Connman uses 1 CPU core.
3. Creates temporary file /var/lib/connman/stats.<6 random characters>.tmp
4. Connman don't responding to CLI or GUI, and signal SIGTERM.
I have a guess, that bug occurs when Connman tries to reconnect to Wi-Fi network.
$ top
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
3281 root 20 0 42988 32504 31352 R 99,3 0,9 2:38.19 connmand
Temporary files:
$ ls -l /var/lib/connman | grep "tmp"
-rw------- 1 root root 23592960 окт 22 10:38 stats.0W91C2.tmp
-rw------- 1 root root 21585920 окт 22 11:46 stats.25A7C2.tmp
-rw------- 1 root root 67358720 окт 22 10:35 stats.UD8ED2.tmp
Connman writes to a temporary file until free disk space is end.
If free space is end, then systemd kills Connman and restart it.
"stats.<>.tmp" contains 'header' and 'record', that infinity repeated.
'header' contains:
position 0x8-0xB for every file differs.
00000000 16 B9 00 FA 14 00 00 00 94 85 41 01 FF FF FF FF
00000010 FF FF FF FF 00 00 00 00 00 00 00 00 00 00 00 00
00000020 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00000030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
repeated 'record' contains:
00000040 00 00 00 00 D4 5B 05 00 32 F4 35 63 00 00 00 00
00000050 4B 30 25 00 3E DB 18 00 C9 A0 C0 6E 6B E0 59 31
00000060 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00000070 BE 0A 06 00 00 00 00 00 2C DB 27 00 FF 4E 1A 00
00000080 35 70 EC 7C CC 64 0E 32 00 00 00 00 00 00 00 00
00000090 00 00 00 00 00 00 00 00 8A 5C 07 00 08 55 39 63
syslog (when bug occured and I try to stop Connman, MAC adress removed):
Oct 23 11:46:44 debian-gateway connman-vpnd[9104]: wlan0 {update} flags 36867 <UP>
Oct 23 11:46:44 debian-gateway connman-vpnd[9104]: wlan0 {newlink} index 3 address #WLAN_MAC# mtu 1500
Oct 23 11:46:44 debian-gateway connman-vpnd[9104]: wlan0 {newlink} index 3 operstate 2 <DOWN>
Oct 23 11:46:44 debian-gateway connmand[9092]: wlan0 {RX} 289974 packets 415132327 bytes
Oct 23 11:46:44 debian-gateway connmand[9092]: wlan0 {TX} 139436 packets 15087832 bytes
Oct 23 11:46:44 debian-gateway kernel: rtlwifi: AP off, try to reconnect now
Oct 23 11:46:44 debian-gateway kernel: wlan0: Connection to AP #AP_MAC# lost
Oct 23 11:46:44 debian-gateway wpa_supplicant[532]: wlan0: CTRL-EVENT-DISCONNECTED bssid=#AP_MAC# reason=4 locally_generated=1
Oct 23 11:46:44 debian-gateway wpa_supplicant[532]: BSSID #AP_MAC# ignore list count incremented to 2, ignoring for 10 seconds
Oct 23 11:46:44 debian-gateway wpa_supplicant[532]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
Oct 23 11:46:50 debian-gateway kernel: wlan0: authenticate with #AP_MAC#
Oct 23 11:46:50 debian-gateway kernel: wlan0: 80 MHz not supported, disabling VHT
Oct 23 11:46:50 debian-gateway wpa_supplicant[532]: wlan0: SME: Trying to authenticate with #AP_MAC# (SSID=#SSID_NAME# freq=2462 MHz)
Oct 23 11:46:50 debian-gateway kernel: wlan0: send auth to #AP_MAC# (try 1/3)
Oct 23 11:46:50 debian-gateway wpa_supplicant[532]: wlan0: Trying to associate with #AP_MAC# (SSID=#SSID_NAME# freq=2462 MHz)
Oct 23 11:46:50 debian-gateway kernel: wlan0: authenticated
Oct 23 11:46:50 debian-gateway kernel: wlan0: associate with #AP_MAC# (try 1/3)
Oct 23 11:46:50 debian-gateway kernel: wlan0: associate with #AP_MAC# (try 2/3)
Oct 23 11:46:50 debian-gateway connman-vpnd[9104]: wlan0 {update} flags 102403 <UP,LOWER_UP>
Oct 23 11:46:50 debian-gateway connman-vpnd[9104]: wlan0 {newlink} index 3 address #WLAN_MAC# mtu 1500
Oct 23 11:46:50 debian-gateway connman-vpnd[9104]: wlan0 {newlink} index 3 operstate 5 <DORMANT>
Oct 23 11:46:50 debian-gateway kernel: wlan0: RX AssocResp from #AP_MAC# (capab=0x431 status=0 aid=48)
Oct 23 11:46:50 debian-gateway kernel: wlan0: associated
Oct 23 11:46:50 debian-gateway wpa_supplicant[532]: wlan0: Associated with #AP_MAC#
Oct 23 11:46:50 debian-gateway wpa_supplicant[532]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Oct 23 11:46:50 debian-gateway wpa_supplicant[532]: wlan0: WPA: Key negotiation completed with #AP_MAC# [PTK=CCMP GTK=CCMP]
Oct 23 11:46:50 debian-gateway wpa_supplicant[532]: wlan0: CTRL-EVENT-CONNECTED - Connection to #AP_MAC# completed [id=2 id_str=]
Oct 23 11:46:50 debian-gateway connman-vpnd[9104]: wlan0 {update} flags 102467 <UP,RUNNING,LOWER_UP>
Oct 23 11:46:50 debian-gateway connman-vpnd[9104]: wlan0 {newlink} index 3 address #WLAN_MAC# mtu 1500
Oct 23 11:46:50 debian-gateway connman-vpnd[9104]: wlan0 {newlink} index 3 operstate 6 <UP>
Oct 23 11:46:50 debian-gateway wpa_supplicant[532]: bgscan simple: Failed to enable signal strength monitoring
Oct 23 11:47:37 debian-gateway dbus-daemon[757]: [session uid=1001 pid=755] Activating service name='org.xfce.Xfconf' requested by ':1.9' (uid=1001 pid=839 comm="Thunar --daemon")
Oct 23 11:47:37 debian-gateway dbus-daemon[757]: [session uid=1001 pid=755] Successfully activated service 'org.xfce.Xfconf'
Oct 23 11:47:56 debian-gateway connman-vpnd[9104]: Terminating
Oct 23 11:47:56 debian-gateway systemd[1]: Stopping connman-vpn.service - ConnMan VPN service...
Oct 23 11:47:56 debian-gateway connman-vpnd[9104]: eth0 {remove} index 2
Oct 23 11:47:56 debian-gateway connman-vpnd[9104]: tether {remove} index 4
Oct 23 11:47:56 debian-gateway connman-vpnd[9104]: wlan0 {remove} index 3
Oct 23 11:47:56 debian-gateway connman-vpnd[9104]: Exit
Oct 23 11:47:56 debian-gateway systemd[1]: connman-vpn.service: Deactivated successfully.
Oct 23 11:47:56 debian-gateway systemd[1]: Stopped connman-vpn.service - ConnMan VPN service.
Oct 23 11:48:04 debian-gateway systemd[1]: connman-wait-online.service: Deactivated successfully.
Oct 23 11:48:04 debian-gateway systemd[1]: Stopped connman-wait-online.service - Wait for network to be configured by ConnMan.
Oct 23 11:48:04 debian-gateway systemd[1]: Stopping connman.service - Connection service...
Oct 23 11:49:34 debian-gateway systemd[1]: connman.service: State 'stop-sigterm' timed out. Killing.
Oct 23 11:49:34 debian-gateway systemd[1]: connman.service: Killing process 9092 (connmand) with signal SIGKILL.
Oct 23 11:49:34 debian-gateway systemd[1]: connman.service: Main process exited, code=killed, status=9/KILL
Oct 23 11:49:34 debian-gateway systemd[1]: connman.service: Failed with result 'timeout'.
Oct 23 11:49:34 debian-gateway systemd[1]: Stopped connman.service - Connection service.
Oct 23 11:49:34 debian-gateway systemd[1]: connman.service: Consumed 2min 46.813s CPU time.
Command "sudo service connman restart" has no effect - after restart bug immediately repeats.
I uses combination "sudo service connman-vpn stop" and "sudo service connman restart".
When bug occurs, Connman VPN has no active VPN connections. More, Connman VPN don't have configured VPN connections at all.
Architecture: amd64
library versions:
libc6: 2.36-9+deb12u3
libglib2.0-0: 2.78.0-2
libdbus-1-3: 1.14.10-1~deb12u1
libxtables12: 1.8.9-2
I try to use various kernels, and found that bug may occurs on kernels 5.16, 6.1, 6.5.
I have used 1.41-3 and kernel 6.1 without this problem for a long time.
I got a backtrace when bug have occurred.
(gdb) backtrace
#0 IO_validate_vtable (vtable=0x7f6dfadba9e0 <_IO_helper_jumps>)
at ../libio/libioP.h:943
#1 outstring_func (done=0, length=104,
string=0x55b1a369a410 "\n(connmand:525): GLib-CRITICAL **: 21:20:35.691: g_date_set_time: assertion 'localtime() == NULL' failed", s=0x7ffd508cd470)
at ./stdio-common/vfprintf-internal.c:239
#2 __vfprintf_internal (s=s@entry=0x7ffd508cd470,
format=0x7f6dfb11d7a2 "%s\n", ap=0x7ffd508cf5b0, mode_flags=2)
at ./stdio-common/vfprintf-process-arg.c:421
#3 0x00007f6dfac4a7fd in buffered_vfprintf (
s=0x7f6dfadbf680 <_IO_2_1_stderr_>,
format=format@entry=0x7f6dfb11d7a2 "%s\n", args=args@entry=0x7ffd508cf5b0,
mode_flags=mode_flags@entry=2) at ./stdio-common/vfprintf-internal.c:1748
#4 0x00007f6dfac49863 in __vfprintf_internal (s=<optimized out>,
format=0x7f6dfb11d7a2 "%s\n", ap=ap@entry=0x7ffd508cf5b0,
mode_flags=mode_flags@entry=2) at ./stdio-common/vfprintf-internal.c:740
#5 0x00007f6dfad0282f in ___fprintf_chk (
fp=fp@entry=0x7f6dfadbf680 <_IO_2_1_stderr_>, flag=flag@entry=1,
format=format@entry=0x7f6dfb11d7a2 "%s\n") at ./debug/fprintf_chk.c:33
#6 0x00007f6dfb0c79bc in fprintf (__fmt=0x7f6dfb11d7a2 "%s\n",
__stream=0x7f6dfadbf680 <_IO_2_1_stderr_>)
at /usr/include/x86_64-linux-gnu/bits/stdio2.h:79
#7 g_log_writer_standard_streams (
log_level=log_level@entry=G_LOG_LEVEL_CRITICAL,
fields=fields@entry=0x7ffd508cf740, n_fields=n_fields@entry=4,
user_data=user_data@entry=0x0) at ../../../glib/gmessages.c:2604
#8 0x00007f6dfb0c7ace in g_log_writer_default (
log_level=G_LOG_LEVEL_CRITICAL, fields=0x7ffd508cf740, n_fields=4,
user_data=0x0) at ../../../glib/gmessages.c:2787
#9 0x00007f6dfb0c54b1 in g_log_structured_array (n_fields=4,
fields=0x7ffd508cf740, log_level=G_LOG_LEVEL_CRITICAL)
at ../../../glib/gmessages.c:1984
#10 g_log_structured_array (log_level=G_LOG_LEVEL_CRITICAL,
fields=0x7ffd508cf740, n_fields=4) at ../../../glib/gmessages.c:1957
#11 0x00007f6dfb0c59a2 in g_log_default_handler (
log_domain=log_domain@entry=0x7f6dfb11a00e "GLib",
log_level=log_level@entry=G_LOG_LEVEL_CRITICAL,
message=message@entry=0x55b1a36ad6e0 "g_date_set_time: assertion 'localtime() == NULL' failed", unused_data=unused_data@entry=0x0)
at ../../../glib/gmessages.c:3284
#12 0x00007f6dfb0c5c10 in g_logv (log_domain=0x7f6dfb11a00e "GLib",
log_level=G_LOG_LEVEL_CRITICAL, format=<optimized out>,
args=args@entry=0x7ffd508cf890) at ../../../glib/gmessages.c:1392
#13 0x00007f6dfb0c5ec3 in g_log (
log_domain=log_domain@entry=0x7f6dfb11a00e "GLib",
log_level=log_level@entry=G_LOG_LEVEL_CRITICAL,
format=format@entry=0x7f6dfb11c2a0 "%s: assertion '%s' failed")
at ../../../glib/gmessages.c:1461
#14 0x00007f6dfb0c6dbd in g_return_if_fail_warning (
log_domain=log_domain@entry=0x7f6dfb11a00e "GLib",
pretty_function=pretty_function@entry=0x7f6dfb11ace4 "g_date_set_time",
expression=expression@entry=0x7f6dfb11acd0 "localtime() == NULL")
at ../../../glib/gmessages.c:2930
#15 0x00007f6dfb09c477 in g_date_set_time_t (date=date@entry=0x7ffd508cf9f8,
timet=<optimized out>) at ../../../glib/gdate.c:1485
#16 0x000055b1a2eb6a38 in process_file (iter=iter@entry=0x7ffd508cfa90,
temp_file=temp_file@entry=0x7ffd508cfb10, cur=<optimized out>,
cur@entry=0x0,
date_change_step_size=date_change_step_size@entry=0x7ffd508cfa68,
account_period_offset=1) at ../src/stats.c:488
#17 0x000055b1a2eb7059 in summarize (temp_file=0x7ffd508cfb10,
history_file=0x7ffd508cfab0, data_file=0x55b1a366ed70)
at ../src/stats.c:568
#18 stats_file_history_update (data_file=0x55b1a366ed70) at ../src/stats.c:664
#19 __connman_stats_update (service=service@entry=0x55b1a366f440,
roaming=<optimized out>, data=0x55b1a366f5c8) at ../src/stats.c:766
#20 0x000055b1a2eef26f in __connman_service_notify (
service=service@entry=0x55b1a366f440, rx_packets=2912530,
tx_packets=3563329, rx_bytes=780332579, tx_bytes=<optimized out>,
rx_errors=<optimized out>, tx_errors=0, rx_dropped=0, tx_dropped=0)
at ../src/service.c:2473
#21 0x000055b1a2effcee in update_stats (
ipdevice=ipdevice@entry=0x55b1a3662710,
ifname=ifname@entry=0x55b1a36a1860 "wlan0",
stats=stats@entry=0x7ffd508cfe10) at ../src/ipconfig.c:540
#22 0x000055b1a2f001db in __connman_ipconfig_newlink (index=index@entry=3,
type=type@entry=1, flags=flags@entry=36867,
address=address@entry=0x7ffd508cfec0 "**WLAN_MAC_REMOVED**",
mtu=<optimized out>, stats=0x7ffd508cfe10) at ../src/ipconfig.c:590
#23 0x000055b1a2f12b69 in process_newlink (bytes=<optimized out>,
msg=0x7ffd508cff00, change=0, flags=36867, index=3, type=1)
at ../src/rtnl.c:454
#24 rtnl_newlink (hdr=0x7ffd508cfef0) at ../src/rtnl.c:970
#25 rtnl_message (len=1480, buf=0x7ffd508cfef0) at ../src/rtnl.c:1406
#26 netlink_event (chan=<optimized out>, cond=<optimized out>,
data=<optimized out>) at ../src/rtnl.c:1466
#27 0x00007f6dfb0ba099 in g_main_dispatch (
context=context@entry=0x55b1a3659440) at ../../../glib/gmain.c:3476
#28 0x00007f6dfb0bd2d7 in g_main_context_dispatch_unlocked (
context=0x55b1a3659440) at ../../../glib/gmain.c:4284
#29 g_main_context_iterate_unlocked (context=0x55b1a3659440,
block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>)
at ../../../glib/gmain.c:4349
#30 0x00007f6dfb0bdbdf in g_main_loop_run (loop=0x55b1a363e530)
at ../../../glib/gmain.c:4551
#31 0x000055b1a2eab188 in main (argc=<optimized out>, argv=<optimized out>)
at ../src/main.c:972
Hi, Please could you test with connman 1.42-1 in sid and see if you still see the issue. Thanks. Regards, Vignesh
Hi, Please could you test with connman 1.42-1 in sid and see if you still see the issue. Thanks. Regards, Vignesh
Hello. I will try to test it, but it may be difficult. Because, I got the issue with Wi-Fi that located in another city. I never got this issue with home Wi-Fi.
Hi, Thank you. I will reduce the severity of this bug from critical to important since it is only observed with a particular Wi-Fi network. Regards, Vignesh
Hello. I got access to Wi-Fi that caused this bug in past time. Some new information: 1) Ver 1.42-3 also have the issue. 2) I tested some old versions: 1.37+repack-1+b1, 1.36-2.4, 1.35-7, 1.34-1, 1.33-3+deb9u3. They also have the issue. 3) If connman-vpn is not running, issue also may appears. 4) This Wi-Fi uses DNS-server 77.88.8.8. When using 8.8.8.8 issue also appears. 5) Issue appears very often - ~1-30 minutes. 6) I use Connman with default config files.
Hello. Some new information: 1) Bug appears rarely, if installed IWD instead of wpasupplicant. Also, now bug appears rarely after reinstalling wpasupplicant. 2) I use gdb to find where Connman fallen into endless loop. In normal work, execution don't enter in function stats_file_history_update(). When bug occurs, execution entered in stats_file_history_update()->summarize()->process_file(), and in process_file() fallen into endless loop ( stats.c:476 ), because function get_next_record(iter) in stats.c:527 always return the same pointer. If I make a force return from process_file(), then Connman will continue normal execution. 3) Another backtrace (in attachment).