Переключение WiFi-соединения не удается с таймаутом dbus - PullRequest
Новая
       50

Переключение WiFi-соединения не удается с таймаутом dbus

0 голосов
/ 16 января 2020

Когда мы пытаемся переключить сеть Wi-Fi через интерфейс sd_bus_call_method (...), вызов завершается неудачно с сообщением тайм-аута dbus. Сначала отключение от текущего Wi-Fi и подключение работает, однако, таким образом, это не проблема с тем, как мы делаем часть подключения. Мы работаем над сборкой Warrior Yocto с Connman 1.37, systemd 2.41. Вот некоторые журналы с ошибочным соединением: 

Jan  8 20:05:22 rc8000-5e2b avahi-daemon[195]: Withdrawing address record for 192.168.170.128 on wlan0.
Jan  8 20:05:22 rc8000-5e2b avahi-daemon[195]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.170.128.
Jan  8 20:05:22 rc8000-5e2b wpa_supplicant[361]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:08:2f:ef:04:d3 reason=3 locally_generated=1
Jan  8 20:05:22 rc8000-5e2b systemd-networkd[217]: wlan0: Lost carrier
Jan  8 20:05:22 rc8000-5e2b avahi-daemon[195]: Interface wlan0.IPv4 no longer relevant for mDNS.
Jan  8 20:05:22 rc8000-5e2b avahi-daemon[195]: Withdrawing address record for fe80::76e1:82ff:fe08:5e2b on wlan0.
Jan  8 20:05:22 rc8000-5e2b connmand[5042]: wlan0 {del} address 192.168.170.128/22 label wlan0
Jan  8 20:05:22 rc8000-5e2b connmand[5042]: wlan0 {del} route 192.168.168.0 gw 0.0.0.0 scope 253 <LINK>
Jan  8 20:05:22 rc8000-5e2b connmand[5042]: wlan0 {RX} 11740 packets 1072648 bytes
Jan  8 20:05:22 rc8000-5e2b connmand[5042]: wlan0 {TX} 373 packets 56170 bytes
Jan  8 20:05:22 rc8000-5e2b connmand[5042]: wlan0 {update} flags 36867 <UP>
Jan  8 20:05:22 rc8000-5e2b connmand[5042]: wlan0 {newlink} index 3 address 74:E1:82:08:5E:2B mtu 1500
Jan  8 20:05:22 rc8000-5e2b connmand[5042]: wlan0 {newlink} index 3 operstate 2 <DOWN>
Jan  8 20:05:22 rc8000-5e2b connmand[5042]: wlan0 {del} route fe80:: gw :: scope 0 <UNIVERSE>Jan  8 20:05:22 rc8000-5e2b connmand[5042]: wlan0 {del} route ff00:: gw :: scope 0 <UNIVERSE>
Jan  8 20:05:23 rc8000-5e2b connmand[5042]: Skipping disconnect of 5769736572_managed_psk, network is connecting.
Jan  8 20:05:28 rc8000-5e2b wpa_supplicant[361]: wlan0: SME: Trying to authenticate with 00:08:2f:ef:04:d0 (SSID='SBSR&D_2.4' freq=2437 MHz)
Jan  8 20:05:29 rc8000-5e2b wpa_supplicant[361]: wlan0: Trying to associate with 00:08:2f:ef:04:d0 (SSID='SBSR&D_2.4' freq=2437 MHz)
Jan  8 20:05:29 rc8000-5e2b connmand[5042]: wlan0 {RX} 11741 packets 1072783 bytes
Jan  8 20:05:29 rc8000-5e2b wpa_supplicant[361]: wlan0: Associated with 00:08:2f:ef:04:d0
Jan  8 20:05:29 rc8000-5e2b connmand[5042]: wlan0 {TX} 373 packets 56170 bytes
Jan  8 20:05:29 rc8000-5e2b connmand[5042]: wlan0 {update} flags 102403 <UP,LOWER_UP>
Jan  8 20:05:29 rc8000-5e2b wpa_supplicant[361]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Jan  8 20:05:29 rc8000-5e2b connmand[5042]: wlan0 {newlink} index 3 address 74:E1:82:08:5E:2B mtu 1500
Jan  8 20:05:29 rc8000-5e2b connmand[5042]: wlan0 {newlink} index 3 operstate 5 <DORMANT>
Jan  8 20:05:29 rc8000-5e2b wpa_supplicant[361]: wlan0: WPA: Key negotiation completed with 00:08:2f:ef:04:d0 [PTK=CCMP GTK=CCMP]
Jan  8 20:05:29 rc8000-5e2b wpa_supplicant[361]: wlan0: CTRL-EVENT-CONNECTED - Connection to 00:08:2f:ef:04:d0 completed [id=1 id_str=]
Jan  8 20:05:29 rc8000-5e2b connmand[5042]: wlan0 {add} route ff00:: gw :: scope 0 <UNIVERSE>
Jan  8 20:05:29 rc8000-5e2b connmand[5042]: wlan0 {add} route fe80:: gw :: scope 0 <UNIVERSE>
Jan  8 20:05:29 rc8000-5e2b connmand[5042]: wlan0 {RX} 11742 packets 1072952 bytes
Jan  8 20:05:29 rc8000-5e2b systemd-networkd[217]: wlan0: Gained carrier
Jan  8 20:05:29 rc8000-5e2b connmand[5042]: wlan0 {TX} 375 packets 56458 bytes
Jan  8 20:05:29 rc8000-5e2b connmand[5042]: wlan0 {update} flags 102467 <UP,RUNNING,LOWER_UP>
Jan  8 20:05:29 rc8000-5e2b connmand[5042]: wlan0 {newlink} index 3 address 74:E1:82:08:5E:2B mtu 1500
Jan  8 20:05:29 rc8000-5e2b connmand[5042]: wlan0 {newlink} index 3 operstate 6 <UP>
Jan  8 20:05:30 rc8000-5e2b wpa_supplicant[361]: wlan0: CTRL-EVENT-SIGNAL-CHANGE above=0 signal=-48 noise=9999 txrate=58500
Jan  8 20:05:30 rc8000-5e2b avahi-daemon[195]: Joining mDNS multicast group on interface wlan0.IPv4 with address 10.175.79.251.
Jan  8 20:05:30 rc8000-5e2b avahi-daemon[195]: New relevant interface wlan0.IPv4 for mDNS.
Jan  8 20:05:30 rc8000-5e2b avahi-daemon[195]: Registering new address record for 10.175.79.251 on wlan0.IPv4.
Jan  8 20:05:30 rc8000-5e2b connmand[5042]: wlan0 {add} address 10.175.79.251/21 label wlan0 family 2Jan  8 20:05:30 rc8000-5e2b systemd-networkd[217]: wlan0: Gained IPv6LL
Jan  8 20:05:30 rc8000-5e2b avahi-daemon[195]: Registering new address record for fe80::76e1:82ff:fe08:5e2b on wlan0.*.
Jan  8 20:05:30 rc8000-5e2b connmand[5042]: wlan0 {add} route 10.175.72.0 gw 0.0.0.0 scope 253 <LINK>
Jan  8 20:05:30 rc8000-5e2b connmand[5042]: wlan0 {add} route 10.175.72.1 gw 0.0.0.0 scope 253 <LINK>
Jan  8 20:05:30 rc8000-5e2b connmand[5042]: wlan0 {add} route 0.0.0.0 gw 10.175.72.1 scope 0 <UNIVERSE>
Jan  8 20:05:47 rc8000-5e2b connman-client[5046]: Service Connect wifi_74e182085e2b_5342535226445f322e34_managed_psk: org.freedesktop.DBus.Error.Timeout

И трассировка dbus для той же проблемы: 

method call time=1578952131.483910 sender=:1.22 -> destination=net.connman serial=20 path=/net/connman/service/wifi_74e182085e2b_5342535226445f322e34_managed_psk; interface=net.connman.Service; member=Connect
method call time=1578952131.507736 sender=:1.21 -> destination=fi.w1.wpa_supplicant1 serial=3697 path=/fi/w1/wpa_supplicant1/Interfaces/5; interface=fi.w1.wpa_supplicant1.Interface; member=Disconnect
signal time=1578952131.512794 sender=:1.21 -> destination=(null destination) serial=3698 path=/net/connman/service/wifi_74e182085e2b_5769736572_managed_psk; interface=net.connman.Service; member=PropertyChanged
   string "Domains"
   variant       array [
      ]
signal time=1578952131.639802 sender=:1.21 -> destination=(null destination) serial=3699 path=/; interface=net.connman.Manager; member=PropertyChanged
   string "State"
   variant       string "ready"

... Trimmed because too long ...

signal time=1578952132.045699 sender=:1.21 -> destination=(null destination) serial=3713 path=/net/connman/service/wifi_74e182085e2b_5769736572_managed_psk; interface=net.connman.Service; member=PropertyChanged
   string "State"
   variant       string "association"
method call time=1578952132.054770 sender=:1.21 -> destination=fi.w1.wpa_supplicant1 serial=3714 path=/fi/w1/wpa_supplicant1/Interfaces/5; interface=fi.w1.wpa_supplicant1.Interface; member=RemoveNetwork
   object path "/fi/w1/wpa_supplicant1/Interfaces/5/Networks/0"signal time=1578952132.066571 sender=:1.21 -> destination=(null destination) serial=3715 path=/; interface=net.connman.Manager; 

... Trimmed because too long ...

signal time=1578952147.533836 sender=:1.21 -> destination=(null destination) serial=3750 path=/net/connman/technology/wifi; interface=net.connman.Technology; member=PropertyChanged
   string "Connected
   variant       boolean true
signal time=1578952147.536193 sender=:1.21 -> destination=(null destination) serial=3751 path=/; interface=net.connman.Manager; member=PropertyChanged
   string "State"
   variant       string "ready"
signal time=1578952147.536811 sender=:1.21 -> destination=(null destination) serial=3752 path=/net/connman/service/wifi_74e182085e2b_5342535226445f322e34_managed_psk; interface=net.connman.Service; member=PropertyChanged
   string "IPv4"
   variant       array [
      ]
signal time=1578952147.543999 sender=:1.21 -> destination=(null destination) serial=3753 path=/net/connman/service/wifi_74e182085e2b_5342535226445f322e34_managed_psk; interface=net.connman.Service; member=PropertyChanged
   string "IPv4"
   variant       array [
      ]

... Trimmed because too long ...```

Я заметил, что информация IP в трассировке dbus выглядит неполной, и штат Коннман никогда не попадает в онлайн. Я также заметил, что в системном журнале для успешного подключения добавлены дополнительные маршруты: 

Jan 12 20:33:54 rc8000-5e2b avahi-daemon[205]: Registering new address record for 192.168.171.81 on wlan0.IPv4.
Jan 12 20:33:54 rc8000-5e2b connmand[222]: wlan0 {add} address 192.168.171.81/22 label wlan0 family 2
Jan 12 20:33:54 rc8000-5e2b connmand[222]: wlan0 {add} route 192.168.168.0 gw 0.0.0.0 scope 253 <LINK>
Jan 12 20:33:54 rc8000-5e2b connmand[222]: wlan0 {add} route 192.168.171.254 gw 0.0.0.0 scope 253 <LINK>
Jan 12 20:33:54 rc8000-5e2b connmand[222]: wlan0 {add} route 8.8.8.8 gw 192.168.171.254 scope 0 <UNIVERSE>
Jan 12 20:33:54 rc8000-5e2b connmand[222]: wlan0 {add} route 8.8.4.4 gw 192.168.171.254 scope 0 <UNIVERSE>
Jan 12 20:33:54 rc8000-5e2b connmand[222]: wlan0 {add} route 0.0.0.0 gw 192.168.171.254 scope 0 <UNIVERSE>
Jan 12 20:33:54 rc8000-5e2b connmand[222]: wlan0 {add} route 212.227.81.55 gw 192.168.171.254 scope 0 <UNIVERSE>

Последний, по-видимому, IP-адрес "телефонный дом" для установления sh, что устройство подключено к сети. Через некоторое время он исчезает, и connman переходит в состояние онлайн.

Я довольно сильно озадачен тем, почему connman (или systemd?) Ведет себя так при попытке переключения между сетями Wi-Fi без предварительного отключения. Любая помощь будет оценена.

РЕДАКТИРОВАТЬ Следующая трассировка показывает 2 ассоциации, происходящие одновременно 

signal time=1578952132.045699 sender=:1.21 -> destination=(null destination) serial=3713 path=/net/connman/service/wifi_74e182085e2b_5769736572_managed_psk; interface=net.connman.Service; member=PropertyChanged
   string "State"
   variant       string "association"
method call time=1578952132.054770 sender=:1.21 -> destination=fi.w1.wpa_supplicant1 serial=3714 path=/fi/w1/wpa_supplicant1/Interfaces/5; interface=fi.w1.wpa_supplicant1.Interface; member=RemoveNetwork
   object path "/fi/w1/wpa_supplicant1/Interfaces/5/Networks/0"
signal time=1578952132.066571 sender=:1.21 -> destination=(null destination) serial=3715 path=/; interface=net.connman.Manager; member=ServicesChanged
....

signal time=1578952132.471595 sender=:1.21 -> destination=(null destination) serial=3718 path=/net/connman/service/wifi_74e182085e2b_5342535226445f322e34_managed_psk; interface=net.connman.Service; member=PropertyChanged
   string "State"
   variant       string "association"
signal time=1578952132.577805 sender=:1.21 -> destination=(null destination) serial=3719 path=/; interface=net.connman.Manager; member=ServicesChanged
....
method return time=1578952133.177367 sender=:1.10 -> destination=:1.21 serial=84264 reply_serial=3716
   object path "/fi/w1/wpa_supplicant1/Interfaces/5/Networks/0"
method call time=1578952133.181592 sender=:1.21 -> destination=fi.w1.wpa_supplicant1 serial=3720 path=/fi/w1/wpa_supplicant1/Interfaces/5; interface=fi.w1.wpa_supplicant1.Interface; member=SelectNetwork
   object path "/fi/w1/wpa_supplicant1/Interfaces/5/Networks/0"
signal time=1578952133.199893 sender=:1.10 -> destination=(null destination) serial=84265 path=/fi/w1/wpa_supplicant1/Interfaces/5; interface=fi.w1.wpa_supplicant1.Interface; member=NetworkAdded
   object path "/fi/w1/wpa_supplicant1/Interfaces/5/Networks/1"
...