10:22 p.m.
I've been using connman in an application involving doing miracast
connections. I've been using libwds and connman 1.34 as well as
wpa_supplicant V2.6.
I'm encountering a problem where I can establish a miracast connection
with an android device, but after 30 mins. the entire connection drops.
This is the messages I see when that happens:
---------------------------------------------
Jul 14 22:54:48 cr-400-2ac2 wpa_supplicant[945]: wlan0: Failed to
initiate sched scan
Jul 14 23:17:01 cr-400-2ac2 CRON[1523]: (root) CMD ( cd / && run-parts
--report /etc/cron.hourly)
Jul 14 23:20:01 cr-400-2ac2 connmand[926]: Peer DHCP server: Received
REQUEST NIP 0
Jul 14 23:20:01 cr-400-2ac2 kernel: [ 1884.087547] DHCP - REQUEST [RX]
Jul 14 23:20:03 cr-400-2ac2 kernel: [ 1886.228326] DHCP - REQUEST [RX]
Jul 14 23:20:11 cr-400-2ac2 kernel: [ 1894.311831] DHCP - REQUEST [RX]
Jul 14 23:20:28 cr-400-2ac2 kernel: [ 1911.745592] DHCP - REQUEST [RX]
Jul 14 23:19:48 cr-400-2ac2 wpa_supplicant[945]: message repeated 5
times: [ wlan0: Failed to initiate sched scan]
Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: p2p-wlan0-1:
AP-STA-DISCONNECTED b6:ef:39:39:5b:df p2p_dev_addr=b6:ef:39:39:db:df
Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: AP-STA-DISCONNECTED
b6:ef:39:39:5b:df p2p_dev_addr=b6:ef:39:39:db:df
Jul 14 23:20:29 cr-400-2ac2 cpn: * Source unavailable
Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: P2P-GROUP-REMOVED
p2p-wlan0-1 GO reason=REQUESTED
Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: p2p-wlan0-1: interface
state ENABLED->DISABLED
Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: p2p-wlan0-1:
AP-DISABLED
Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: p2p-wlan0-1:
CTRL-EVENT-DISCONNECTED bssid=02:04:4b:58:aa:c0 reason=3
locally_generated=1
Jul 14 23:20:28 cr-400-2ac2 connmand[926]: message repeated 3 times:
[ Peer DHCP server: Received REQUEST NIP 0]
Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {RX} 367084
packets 399923565 bytes
Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {TX} 156 packets
19838 bytes
Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {update} flags
102403 <UP,LOWER_UP>
Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {newlink} index
10 address 02:04:4B:58:AA:C0 mtu 1500
Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {newlink} index
10 operstate 5
Jul 14 23:20:29 cr-400-2ac2 connman-vpnd[940]: p2p-wlan0-1 {update}
flags 102403 <UP,LOWER_UP>
Jul 14 23:20:29 cr-400-2ac2 connman-vpnd[940]: p2p-wlan0-1 {newlink}
index 10 address 02:04:4B:58:AA:C0 mtu 1500
Jul 14 23:20:29 cr-400-2ac2 connman-vpnd[940]: p2p-wlan0-1 {newlink}
index 10 operstate 5
Jul 14 23:20:29 cr-400-2ac2 kernel: [ 1912.126009] [07-14 23:20:29.280]
wl_notify_connect_status_ap: event WLC_E_DEAUTH_IND(6) status 0 reason 3
Jul 14 23:20:29 cr-400-2ac2 kernel: [ 1912.126039] [07-14 23:20:29.280]
wl_notify_connect_status_ap: event WLC_E_DISASSOC_IND(12) status 0
reason 8
Jul 14 23:20:29 cr-400-2ac2 kernel: [ 1912.128488]
wl_cfg80211_del_station : Disconnect STA : b6:ef:39:39:5b:df scb_val.val
3
Jul 14 23:20:29 cr-400-2ac2 kernel: [ 1912.132741]
wl_cfg80211_del_station : Disconnect STA : ff:ff:ff:ff:ff:ff scb_val.val
3
Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: nl80211: deinit
ifname=p2p-wlan0-1 disabled_11b_rates=0
Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {RX} 367084
packets 399923565 bytes
Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {TX} 157 packets
19904 bytes
Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {update} flags
102467 <UP,RUNNING,LOWER_UP>
Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {newlink} index
10 address 02:04:4B:58:AA:C0 mtu 1500
Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {newlink} index
10 operstate 6
Jul 14 23:20:29 cr-400-2ac2 connman-vpnd[940]: p2p-wlan0-1 {update}
flags 102467 <UP,RUNNING,LOWER_UP>
Jul 14 23:20:29 cr-400-2ac2 connman-vpnd[940]: p2p-wlan0-1 {newlink}
index 10 address 02:04:4B:58:AA:C0 mtu 1500
Jul 14 23:20:29 cr-400-2ac2 connman-vpnd[940]: p2p-wlan0-1 {newlink}
index 10 operstate 6
Jul 14 23:20:29 cr-400-2ac2 kernel: [ 1912.251941]
dhd_cfg80211_clean_p2p_info : Clean : op_mode=0x0005
Jul 14 23:20:29 cr-400-2ac2 kernel: [ 1912.253235] 'cfg p2p_ifdis' error
-23
Jul 14 23:20:29 cr-400-2ac2 connman-vpnd[940]: p2p-wlan0-1 {update}
flags 36866
Jul 14 23:20:29 cr-400-2ac2 connman-vpnd[940]: p2p-wlan0-1 {newlink}
index 10 address 02:04:4B:58:AA:C0 mtu 1500
Jul 14 23:20:29 cr-400-2ac2 connman-vpnd[940]: p2p-wlan0-1 {newlink}
index 10 operstate 2
Jul 14 23:20:29 cr-400-2ac2 avahi-daemon[471]: Interface
p2p-wlan0-1.IPv6 no longer relevant for mDNS.
Jul 14 23:20:29 cr-400-2ac2 avahi-daemon[471]: Leaving mDNS multicast
group on interface p2p-wlan0-1.IPv6 with address fe80::4:4bff:fe58:aac0.
Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {update} flags
36866
Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {newlink} index
10 address 02:04:4B:58:AA:C0 mtu 1500
Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {newlink} index
10 operstate 2
Jul 14 23:20:29 cr-400-2ac2 avahi-daemon[471]: Interface
p2p-wlan0-1.IPv4 no longer relevant for mDNS.
Jul 14 23:20:29 cr-400-2ac2 avahi-daemon[471]: Leaving mDNS multicast
group on interface p2p-wlan0-1.IPv4 with address 192.168.0.1.
Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {del} route
fe80:: gw :: scope 0
Jul 14 23:20:29 cr-400-2ac2 kernel: [ 1912.259164]
"dhd->iflist[*ifidx] != NULL": file "dhd_linux.c", line 8106
Jul 14 23:20:29 cr-400-2ac2 kernel: [ 1912.260405] deleting interface
'p2p-wlan0-1' idx 1
Jul 14 23:20:29 cr-400-2ac2 kernel: [ 1912.260429] dhd_get_stats: BAD_IF
Jul 14 23:20:29 cr-400-2ac2 kernel: [ 1912.260873] dhd_get_stats: BAD_IF
Jul 14 23:20:29 cr-400-2ac2 kernel: [ 1912.261266] dhd_get_stats: BAD_IF
Jul 14 23:20:29 cr-400-2ac2 kernel: [ 1912.261289]
wl_cfg80211_netdev_notifier_call : [NETDEV_DOWN] wait for complete of
cleanup_work (0 th)
Jul 14 23:20:30 cr-400-2ac2 connmand[926]: Inconsistent IP pool
management (start not found)
Jul 14 23:20:30 cr-400-2ac2 connmand[926]: (null) {del} address
192.168.0.1/24 label p2p-wlan0-1
Jul 14 23:20:30 cr-400-2ac2 kernel: [ 1913.255689] dhd_get_stats: BAD_IF
Jul 14 23:20:30 cr-400-2ac2 kernel: [ 1913.255817] Cannot find ifidx
for(p2p-wlan0-1) set to 0
Jul 14 23:20:30 cr-400-2ac2 kernel: [ 1913.263179] dhd_get_stats: BAD_IF
Jul 14 23:20:30 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {dellink} index
10 operstate 2
Jul 14 23:20:30 cr-400-2ac2 connman-vpnd[940]: p2p-wlan0-1 {dellink}
index 10 operstate 2
Jul 14 23:20:30 cr-400-2ac2 connman-vpnd[940]: p2p-wlan0-1 {remove}
index 10
Jul 14 23:20:30 cr-400-2ac2 connmand[926]: (null) {remove} index 10
Jul 14 23:20:30 cr-400-2ac2 avahi-daemon[471]: IP_DROP_MEMBERSHIP
failed: No such device
Jul 14 23:20:30 cr-400-2ac2 connmand[926]: Remove interface (null)
[ wifi ]
Jul 14 23:20:30 cr-400-2ac2 avahi-daemon[471]: Withdrawing address
record for fe80::4:4bff:fe58:aac0 on p2p-wlan0-1.
Jul 14 23:20:30 cr-400-2ac2 avahi-daemon[471]: Withdrawing address
record for 192.168.0.1 on p2p-wlan0-1.
Jul 14 23:20:30 cr-400-2ac2 avahi-daemon[471]: Withdrawing workstation
service for p2p-wlan0-1.
Jul 14 23:20:30 cr-400-2ac2 kernel: [ 1913.325494] dhd_get_stats: BAD_IF
Jul 14 23:20:30 cr-400-2ac2 kernel: [ 1913.325699] DHD-MON:
dhd_del_monitor IF not found in monitor array, is this a monitor IF?
0xffffffc0f4f2a800
Jul 14 23:20:30 cr-400-2ac2 kernel: [ 1913.326204] wl_dealloc_netinfo :
Unknown wdev freeed!
Jul 14 23:21:23 cr-400-2ac2 wpa_supplicant[945]: P2P-DEVICE-LOST
p2p_dev_addr=b6:ef:39:39:db:df
Jul 14 23:21:23 cr-400-2ac2 wpa_supplicant[945]: dbus: Unregister peer
object '/fi/w1/wpa_supplicant1/Interfaces/1/Peers/b6ef3939dbdf'
Jul 14 23:21:23 cr-400-2ac2 cpn: * Peer removed: SAMSUNG-SM-G360V
-----------------------------------------
I originally thought it had something to do with miracast and asked this
question at that site, but the people there thought it might be an issue
with connman.
It seems like there might be some issue with DHCP renewal. Does anybody
know what's happening here?
12:16 p.m.
Hi Carl,
On 07/21/2017 12:22 AM, Carl D. Blake wrote:
I've been using connman in an application involving doing
miracast
connections. I've been using libwds and connman 1.34 as well as
wpa_supplicant V2.6.
I'm encountering a problem where I can establish a miracast connection
with an android device, but after 30 mins. the entire connection drops.
This is the messages I see when that happens:
---------------------------------------------
Jul 14 22:54:48 cr-400-2ac2 wpa_supplicant[945]: wlan0: Failed to
initiate sched scan
Jul 14 23:17:01 cr-400-2ac2 CRON[1523]: (root) CMD ( cd / && run-parts
--report /etc/cron.hourly)
Jul 14 23:20:01 cr-400-2ac2 connmand[926]: Peer DHCP server: Received
REQUEST NIP 0
Jul 14 23:20:01 cr-400-2ac2 kernel: [ 1884.087547] DHCP - REQUEST [RX]
Jul 14 23:20:03 cr-400-2ac2 kernel: [ 1886.228326] DHCP - REQUEST [RX]
Jul 14 23:20:11 cr-400-2ac2 kernel: [ 1894.311831] DHCP - REQUEST [RX]
Jul 14 23:20:28 cr-400-2ac2 kernel: [ 1911.745592] DHCP - REQUEST [RX]
Jul 14 23:19:48 cr-400-2ac2 wpa_supplicant[945]: message repeated 5
times: [ wlan0: Failed to initiate sched scan]
Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: p2p-wlan0-1:
AP-STA-DISCONNECTED b6:ef:39:39:5b:df p2p_dev_addr=b6:ef:39:39:db:df
Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: AP-STA-DISCONNECTED
b6:ef:39:39:5b:df p2p_dev_addr=b6:ef:39:39:db:df
Jul 14 23:20:29 cr-400-2ac2 cpn: * Source unavailable
Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: P2P-GROUP-REMOVED
p2p-wlan0-1 GO reason=REQUESTED
Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: p2p-wlan0-1: interface
state ENABLED->DISABLED
Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: p2p-wlan0-1:
AP-DISABLED
Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: p2p-wlan0-1:
CTRL-EVENT-DISCONNECTED bssid=02:04:4b:58:aa:c0 reason=3
locally_generated=1
Jul 14 23:20:28 cr-400-2ac2 connmand[926]: message repeated 3 times:
[ Peer DHCP server: Received REQUEST NIP 0]
Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {RX} 367084
packets 399923565 bytes
Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {TX} 156 packets
19838 bytes
Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {update} flags
102403 <UP,LOWER_UP>
Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {newlink} index
10 address 02:04:4B:58:AA:C0 mtu 1500
Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {newlink} index
10 operstate 5
Jul 14 23:20:29 cr-400-2ac2 connman-vpnd[940]: p2p-wlan0-1 {update}
flags 102403 <UP,LOWER_UP>
Jul 14 23:20:29 cr-400-2ac2 connman-vpnd[940]: p2p-wlan0-1 {newlink}
index 10 address 02:04:4B:58:AA:C0 mtu 1500
Jul 14 23:20:29 cr-400-2ac2 connman-vpnd[940]: p2p-wlan0-1 {newlink}
index 10 operstate 5
Jul 14 23:20:29 cr-400-2ac2 kernel: [ 1912.126009] [07-14 23:20:29.280]
wl_notify_connect_status_ap: event WLC_E_DEAUTH_IND(6) status 0 reason 3
This is the out of tree module for Edison's bcm43340? Anyway, the reason
code says 3, which is according the spec (if my 802.11 spec reading foo
hasn't left me completely):
"Deauthenticated because sending STA is leaving (or has left)
IBSS or ESS"
Table 8-36.
-----------------------------------------
I originally thought it had something to do with miracast and asked this
question at that site, but the people there thought it might be an issue
with connman.
It seems like there might be some issue with DHCP renewal. Does anybody
know what's happening here?
It doesn't look like DHCP, because the wireless driver receives a
DEAUTH. Why this is happening? I have no clue. Maybe it is possible to
increase the verbosity of the driver and you might see what is going on.
Maybe ConnMan is also doing something wrong but I would first check if
the driver is behaving according the specification. If it is this
version I found on github[1] I wouldn't be surprised if there are still
bugs in it. Just one commit and no changes since 2015.
Thanks,
Daniel
[1] https://github.com/01org/edison-bcm43340
4:22 p.m.
Daniel,
On Fri, 2017-07-21 at 14:16 +0200, Daniel Wagner wrote:
Hi Carl,
On 07/21/2017 12:22 AM, Carl D. Blake wrote:
> I've been using connman in an application involving doing miracast
> connections. I've been using libwds and connman 1.34 as well as
> wpa_supplicant V2.6.
>
> I'm encountering a problem where I can establish a miracast connection
> with an android device, but after 30 mins. the entire connection drops.
> This is the messages I see when that happens:
>
> ---------------------------------------------
>
> Jul 14 22:54:48 cr-400-2ac2 wpa_supplicant[945]: wlan0: Failed to
> initiate sched scan
> Jul 14 23:17:01 cr-400-2ac2 CRON[1523]: (root) CMD ( cd / && run-parts
> --report /etc/cron.hourly)
> Jul 14 23:20:01 cr-400-2ac2 connmand[926]: Peer DHCP server: Received
> REQUEST NIP 0
> Jul 14 23:20:01 cr-400-2ac2 kernel: [ 1884.087547] DHCP - REQUEST [RX]
> Jul 14 23:20:03 cr-400-2ac2 kernel: [ 1886.228326] DHCP - REQUEST [RX]
> Jul 14 23:20:11 cr-400-2ac2 kernel: [ 1894.311831] DHCP - REQUEST [RX]
> Jul 14 23:20:28 cr-400-2ac2 kernel: [ 1911.745592] DHCP - REQUEST [RX]
> Jul 14 23:19:48 cr-400-2ac2 wpa_supplicant[945]: message repeated 5
> times: [ wlan0: Failed to initiate sched scan]
> Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: p2p-wlan0-1:
> AP-STA-DISCONNECTED b6:ef:39:39:5b:df p2p_dev_addr=b6:ef:39:39:db:df
> Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: AP-STA-DISCONNECTED
> b6:ef:39:39:5b:df p2p_dev_addr=b6:ef:39:39:db:df
> Jul 14 23:20:29 cr-400-2ac2 cpn: * Source unavailable
> Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: P2P-GROUP-REMOVED
> p2p-wlan0-1 GO reason=REQUESTED
> Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: p2p-wlan0-1: interface
> state ENABLED->DISABLED
> Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: p2p-wlan0-1:
> AP-DISABLED
> Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: p2p-wlan0-1:
> CTRL-EVENT-DISCONNECTED bssid=02:04:4b:58:aa:c0 reason=3
> locally_generated=1
> Jul 14 23:20:28 cr-400-2ac2 connmand[926]: message repeated 3 times:
> [ Peer DHCP server: Received REQUEST NIP 0]
> Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {RX} 367084
> packets 399923565 bytes
> Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {TX} 156 packets
> 19838 bytes
> Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {update} flags
> 102403 <UP,LOWER_UP>
> Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {newlink} index
> 10 address 02:04:4B:58:AA:C0 mtu 1500
> Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {newlink} index
> 10 operstate 5
> Jul 14 23:20:29 cr-400-2ac2 connman-vpnd[940]: p2p-wlan0-1 {update}
> flags 102403 <UP,LOWER_UP>
> Jul 14 23:20:29 cr-400-2ac2 connman-vpnd[940]: p2p-wlan0-1 {newlink}
> index 10 address 02:04:4B:58:AA:C0 mtu 1500
> Jul 14 23:20:29 cr-400-2ac2 connman-vpnd[940]: p2p-wlan0-1 {newlink}
> index 10 operstate 5
> Jul 14 23:20:29 cr-400-2ac2 kernel: [ 1912.126009] [07-14 23:20:29.280]
> wl_notify_connect_status_ap: event WLC_E_DEAUTH_IND(6) status 0 reason 3
This is the out of tree module for Edison's bcm43340? Anyway, the reason
code says 3, which is according the spec (if my 802.11 spec reading foo
hasn't left me completely):
"Deauthenticated because sending STA is leaving (or has left)
IBSS or ESS"
Table 8-36.
This is kernel 3.10.96 on an Nvidia Tegra X1. The driver is the bcmdhd
module for the BCM4354. I don't believe it is out of tree, but I could
be wrong. Of course, this is on ubuntu 14.04 which is a couple years
old, so I suppose the drivers might need to be updated.
> -----------------------------------------
>
> I originally thought it had something to do with miracast and asked this
> question at that site, but the people there thought it might be an issue
> with connman.
>
> It seems like there might be some issue with DHCP renewal. Does anybody
> know what's happening here?
It doesn't look like DHCP, because the wireless driver receives a
DEAUTH. Why this is happening? I have no clue. Maybe it is possible to
increase the verbosity of the driver and you might see what is going on.
Maybe ConnMan is also doing something wrong but I would first check if
the driver is behaving according the specification. If it is this
version I found on github[1] I wouldn't be surprised if there are still
bugs in it. Just one commit and no changes since 2015.
I'll increase the verbosity. The thing is I'm getting this same exact
behavior on an Nvidia Tegra K1 using an AC7260 mini PCIe card, so I
figured it had to be something other than the drivers.
Thanks for your help,
Carl
Thanks,
Daniel
[1] https://github.com/01org/edison-bcm43340
6 p.m.
Daniel,
On Fri, 2017-07-21 at 09:22 -0700, Carl D. Blake wrote:
Daniel,
On Fri, 2017-07-21 at 14:16 +0200, Daniel Wagner wrote:
> Hi Carl,
>
> On 07/21/2017 12:22 AM, Carl D. Blake wrote:
> > I've been using connman in an application involving doing miracast
> > connections. I've been using libwds and connman 1.34 as well as
> > wpa_supplicant V2.6.
> >
> > I'm encountering a problem where I can establish a miracast connection
> > with an android device, but after 30 mins. the entire connection drops.
> > This is the messages I see when that happens:
> >
> > ---------------------------------------------
> >
> > Jul 14 22:54:48 cr-400-2ac2 wpa_supplicant[945]: wlan0: Failed to
> > initiate sched scan
> > Jul 14 23:17:01 cr-400-2ac2 CRON[1523]: (root) CMD ( cd / && run-parts
> > --report /etc/cron.hourly)
> > Jul 14 23:20:01 cr-400-2ac2 connmand[926]: Peer DHCP server: Received
> > REQUEST NIP 0
> > Jul 14 23:20:01 cr-400-2ac2 kernel: [ 1884.087547] DHCP - REQUEST [RX]
> > Jul 14 23:20:03 cr-400-2ac2 kernel: [ 1886.228326] DHCP - REQUEST [RX]
> > Jul 14 23:20:11 cr-400-2ac2 kernel: [ 1894.311831] DHCP - REQUEST [RX]
> > Jul 14 23:20:28 cr-400-2ac2 kernel: [ 1911.745592] DHCP - REQUEST [RX]
> > Jul 14 23:19:48 cr-400-2ac2 wpa_supplicant[945]: message repeated 5
> > times: [ wlan0: Failed to initiate sched scan]
> > Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: p2p-wlan0-1:
> > AP-STA-DISCONNECTED b6:ef:39:39:5b:df p2p_dev_addr=b6:ef:39:39:db:df
> > Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: AP-STA-DISCONNECTED
> > b6:ef:39:39:5b:df p2p_dev_addr=b6:ef:39:39:db:df
> > Jul 14 23:20:29 cr-400-2ac2 cpn: * Source unavailable
> > Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: P2P-GROUP-REMOVED
> > p2p-wlan0-1 GO reason=REQUESTED
> > Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: p2p-wlan0-1: interface
> > state ENABLED->DISABLED
> > Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: p2p-wlan0-1:
> > AP-DISABLED
> > Jul 14 23:20:29 cr-400-2ac2 wpa_supplicant[945]: p2p-wlan0-1:
> > CTRL-EVENT-DISCONNECTED bssid=02:04:4b:58:aa:c0 reason=3
> > locally_generated=1
> > Jul 14 23:20:28 cr-400-2ac2 connmand[926]: message repeated 3 times:
> > [ Peer DHCP server: Received REQUEST NIP 0]
> > Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {RX} 367084
> > packets 399923565 bytes
> > Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {TX} 156 packets
> > 19838 bytes
> > Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {update} flags
> > 102403 <UP,LOWER_UP>
> > Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {newlink} index
> > 10 address 02:04:4B:58:AA:C0 mtu 1500
> > Jul 14 23:20:29 cr-400-2ac2 connmand[926]: p2p-wlan0-1 {newlink} index
> > 10 operstate 5
> > Jul 14 23:20:29 cr-400-2ac2 connman-vpnd[940]: p2p-wlan0-1 {update}
> > flags 102403 <UP,LOWER_UP>
> > Jul 14 23:20:29 cr-400-2ac2 connman-vpnd[940]: p2p-wlan0-1 {newlink}
> > index 10 address 02:04:4B:58:AA:C0 mtu 1500
> > Jul 14 23:20:29 cr-400-2ac2 connman-vpnd[940]: p2p-wlan0-1 {newlink}
> > index 10 operstate 5
> > Jul 14 23:20:29 cr-400-2ac2 kernel: [ 1912.126009] [07-14 23:20:29.280]
> > wl_notify_connect_status_ap: event WLC_E_DEAUTH_IND(6) status 0 reason 3
>
> This is the out of tree module for Edison's bcm43340? Anyway, the reason
> code says 3, which is according the spec (if my 802.11 spec reading foo
> hasn't left me completely):
>
> "Deauthenticated because sending STA is leaving (or has left)
> IBSS or ESS"
>
> Table 8-36.
This is kernel 3.10.96 on an Nvidia Tegra X1. The driver is the bcmdhd
module for the BCM4354. I don't believe it is out of tree, but I could
be wrong. Of course, this is on ubuntu 14.04 which is a couple years
old, so I suppose the drivers might need to be updated.
> > -----------------------------------------
> >
> > I originally thought it had something to do with miracast and asked this
> > question at that site, but the people there thought it might be an issue
> > with connman.
> >
> > It seems like there might be some issue with DHCP renewal. Does anybody
> > know what's happening here?
>
> It doesn't look like DHCP, because the wireless driver receives a
> DEAUTH. Why this is happening? I have no clue. Maybe it is possible to
> increase the verbosity of the driver and you might see what is going on.
>
> Maybe ConnMan is also doing something wrong but I would first check if
> the driver is behaving according the specification. If it is this
> version I found on github[1] I wouldn't be surprised if there are still
> bugs in it. Just one commit and no changes since 2015.
>
I'll increase the verbosity. The thing is I'm getting this same exact
behavior on an Nvidia Tegra K1 using an AC7260 mini PCIe card, so I
figured it had to be something other than the drivers.
Thanks for your help,
Carl
> Thanks,
> Daniel
>
> [1] https://github.com/01org/edison-bcm43340
Here's further logs with debug enabled on the bcmhd driver
--------------------------
Jul 21 17:43:51 cr-400-2ac2 kernel: [ 1863.303183]
wl_cfgp2p_listen_complete :Listen DONE for ramain on channel expired
Jul 21 17:43:51 cr-400-2ac2 kernel: [ 1863.303460]
wl_cfg80211_mgmt_frame_register :frame_type: 40, reg: 0
Jul 21 17:43:51 cr-400-2ac2 cpn: TVMR: FrameRate = 30.001920
Jul 21 17:43:53 cr-400-2ac2 kernel: [ 1864.797351]
wl_cfg80211_mgmt_frame_register :frame_type: 40, reg: 1
Jul 21 17:43:53 cr-400-2ac2 kernel: [ 1864.797399]
wl_cfg80211_remain_on_channel :Enter, channel: 1, duration ms (500)
SCANNING ?? NO
Jul 21 17:43:53 cr-400-2ac2 kernel: [ 1864.797409] CFGP2P-INFO)
wl_cfgp2p_enable_discovery : DISCOVERY is already initialized, we have
nothing to do
Jul 21 17:43:53 cr-400-2ac2 kernel: [ 1864.797416] CFGP2P-DEBUG)
wl_cfgp2p_discover_listen : Enter Listen Channel : 1, Duration : 500
Jul 21 17:43:53 cr-400-2ac2 kernel: [ 1864.798289] CFGP2P-DEBUG)
wl_cfgp2p_set_p2p_mode :enter
Jul 21 17:43:53 cr-400-2ac2 kernel: [ 1864.798970]
wl_cfg80211_remain_on_channel : Success
Jul 21 17:43:53 cr-400-2ac2 kernel: [ 1865.305856]
wl_cfg80211_event :event_type (55):WLC_E_WLC_E_P2P_DISC_LISTEN_COMPLETE
Jul 21 17:43:53 cr-400-2ac2 kernel: [ 1865.305887]
wl_event_handler :event type (55), if idx: 0
Jul 21 17:43:53 cr-400-2ac2 kernel: [ 1865.305898] CFGP2P-DEBUG)
wl_cfgp2p_listen_complete : Enter
Jul 21 17:43:53 cr-400-2ac2 kernel: [ 1865.305906]
wl_cfgp2p_listen_complete :Listen DONE for ramain on channel expired
Jul 21 17:43:53 cr-400-2ac2 kernel: [ 1865.306040]
wl_cfg80211_mgmt_frame_register :frame_type: 40, reg: 0
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1866.798942]
wl_cfg80211_mgmt_frame_register :frame_type: 40, reg: 1
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1866.798989]
wl_cfg80211_remain_on_channel :Enter, channel: 1, duration ms (500)
SCANNING ?? NO
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1866.799000] CFGP2P-INFO)
wl_cfgp2p_enable
_discovery : DISCOVERY is already initialized, we have nothing to do
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1866.799007] CFGP2P-DEBUG)
wl_cfgp2p_discover_listen : Enter Listen Channel : 1, Duration : 500
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1866.805570] CFGP2P-DEBUG)
wl_cfgp2p_set_p2p_mode :enter
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1866.806217]
wl_cfg80211_remain_on_channel : Success
Jul 21 17:39:01 cr-400-2ac2 wpa_supplicant[917]: message repeated 5
times: [ wlan0: Failed to initiate sched scan]
Jul 21 17:43:55 cr-400-2ac2 wpa_supplicant[917]: p2p-wlan0-0:
AP-STA-DISCONNECTED b6:ef:39:39:5b:df p2p_dev_addr=b6:ef:39:39:db:df
Jul 21 17:43:55 cr-400-2ac2 wpa_supplicant[917]: AP-STA-DISCONNECTED
b6:ef:39:39:5b:df p2p_dev_addr=b6:ef:39:39:db:df
Jul 21 17:43:55 cr-400-2ac2 cpn: * Source unavailable
Jul 21 17:43:55 cr-400-2ac2 wpa_supplicant[917]: P2P-GROUP-REMOVED
p2p-wlan0-0 GO reason=REQUESTED
Jul 21 17:43:55 cr-400-2ac2 wpa_supplicant[917]: p2p-wlan0-0: interface
state ENABLED->DISABLED
Jul 21 17:43:55 cr-400-2ac2 wpa_supplicant[917]: p2p-wlan0-0:
AP-DISABLED
Jul 21 17:43:55 cr-400-2ac2 wpa_supplicant[917]: p2p-wlan0-0:
CTRL-EVENT-DISCONNECTED bssid=02:04:4b:58:aa:c0 reason=3
locally_generated=1
Jul 21 17:43:37 cr-400-2ac2 connmand[902]: message repeated 2 times:
[ Peer DHCP server: Received REQUEST NIP 0]
Jul 21 17:43:55 cr-400-2ac2 connmand[902]: p2p-wlan0-0 {RX} 644798
packets 774844458 bytes
Jul 21 17:43:55 cr-400-2ac2 connmand[902]: p2p-wlan0-0 {TX} 151 packets
22432 bytes
Jul 21 17:43:55 cr-400-2ac2 connmand[902]: p2p-wlan0-0 {update} flags
102403 <UP,LOWER_UP>
Jul 21 17:43:55 cr-400-2ac2 connmand[902]: p2p-wlan0-0 {newlink} index 9
address 02:04:4B:58:AA:C0 mtu 1500
Jul 21 17:43:55 cr-400-2ac2 connmand[902]: p2p-wlan0-0 {newlink} index 9
operstate 5 <DORMANT>
Jul 21 17:43:55 cr-400-2ac2 connman-vpnd[912]: p2p-wlan0-0 {update}
flags 102403 <UP,LOWER_UP>
Jul 21 17:43:55 cr-400-2ac2 connman-vpnd[912]: p2p-wlan0-0 {newlink}
index 9 address 02:04:4B:58:AA:C0 mtu 1500
Jul 21 17:43:55 cr-400-2ac2 connman-vpnd[912]: p2p-wlan0-0 {newlink}
index 9 operstate 5 <DORMANT>
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.246164]
wl_cfg80211_event :event_type (6):WLC_E_DEAUTH_IND
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.246184]
wl_cfg80211_event :event_type (12):WLC_E_DISASSOC_IND
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.246331]
wl_cfg80211_event :event_type (5):WLC_E_DEAUTH
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.246343]
wl_cfg80211_event :event_type (5):WLC_E_DEAUTH
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.246526]
wl_event_handler :event type (6), if idx: 1
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.246754]
wl_notify_connect_status_ap :event 6 status 0 reason 3
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.246764] [07-21 17:43:55.569]
wl_notify_connect_status_ap: event WLC_E_DEAUTH_IND(6) status 0 reason 3
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.246783]
wl_event_handler :event type (12), if idx: 1
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.246790]
wl_notify_connect_status_ap :event 12 status 0 reason 8
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.246798] [07-21 17:43:55.569]
wl_notify_connect_status_ap: event WLC_E_DISASSOC_IND(12) status 0
reason 8
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.246811]
wl_event_handler :event type (5), if idx: 1
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.246818]
wl_notify_connect_status_ap :event 5 status 0 reason 7
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.246826] [07-21 17:43:55.569]
wl_notify_connect_status_ap: event WLC_E_DEAUTH(5) status 0 reason 7
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.246838]
wl_event_handler :event type (5), if idx: 1
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.246845]
wl_notify_connect_status_ap :event 5 status 0 reason 7
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.246852] [07-21 17:43:55.569]
wl_notify_connect_status_ap: event WLC_E_DEAUTH(5) status 0 reason 7
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.247141]
wl_cfg80211_del_key :Enter
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.247151]
wl_cfg80211_del_key :key index (0)
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.247649]
wl_cfg80211_del_key :Enter
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.247658]
wl_cfg80211_del_key :key index (0)
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.248116]
wl_cfg80211_change_station :SCB_AUTHORIZE
mac_addr:b6:ef:39:39:5b:dfsta_flags_mask:0x2 sta_flags_set:0x0
iface:p2p-wlan0-0
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.248597]
wl_cfg80211_del_station :Entry
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.248605] CFGP2P-DEBUG)
wl_cfgp2p_discover_enable_search : Enter
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.248611] CFGP2P-DEBUG)
wl_cfgp2p_discover_enable_search :already : 0
Jul 21 17:43:55 cr-400-2ac2 kernel: [ 1867.249372]
wl_cfg80211_del_station : Disconnect STA : b6:ef:39:39:5b:df scb_val.val
3
--------------------------------------
I don't see any further messages that indicate why the driver is
deauthorizing. I do notice that I get the message from wpa_supplicant
that it failed to initiate sched scan right before the disconnect
occurs. Could this have something to do with it? I'm unconvinced that
this is a problem with the driver. The disconnect occurs reliably after
30 minutes of being connected. I can set my watch by it.
_______________________________________________
connman mailing list
connman(a)lists.01.org
https://lists.01.org/mailman/listinfo/connman
1:06 p.m.
Hi Carl,
On 07/21/2017 08:00 PM, Carl D. Blake wrote:
I don't see any further messages that indicate why the driver is
deauthorizing. I do notice that I get the message from wpa_supplicant
that it failed to initiate sched scan right before the disconnect
occurs.
wpa_s is always good for some trouble. So one thing you could do is to
start wpa_s by hand and enable the debug options and see what wpa_s doing:
# wpa_supplicant -c /etc/wpa_supplicant/wpa_supplicant.conf -u -s -dd
Could this have something to do with it?
The DHCP code in ConnMan is not really driving anything directly. That
means we would see something from service.c which tells us it decided to
disconnect. But we don't see that either. So we should look at wpa_s.
I'm unconvinced that
this is a problem with the driver. The disconnect occurs reliably after
30 minutes of being connected. I can set my watch by it.
I agree, if you see can reproduce this with different wifi cards it is
probably not the drivers.
Thanks,
Daniel
5:35 p.m.
Daniel,
On Mon, 2017-07-24 at 15:06 +0200, Daniel Wagner wrote:
Hi Carl,
On 07/21/2017 08:00 PM, Carl D. Blake wrote:
> I don't see any further messages that indicate why the driver is
> deauthorizing. I do notice that I get the message from wpa_supplicant
> that it failed to initiate sched scan right before the disconnect
> occurs.
wpa_s is always good for some trouble. So one thing you could do is to
start wpa_s by hand and enable the debug options and see what wpa_s doing:
# wpa_supplicant -c /etc/wpa_supplicant/wpa_supplicant.conf -u -s -dd
It looks to me like connman is starting wpa_supplicant. Is this true?
I've been setting debug options in the various /etc files for
wpa_supplicant, but I always get one wpa_supplicant running in the
background which does not have its debug options set. This
wpa_supplicant always starts after connman starts and I can't locate any
other places in /etc where wpa_supplicant is started.
> Could this have something to do with it?
The DHCP code in ConnMan is not really driving anything directly. That
means we would see something from service.c which tells us it decided to
disconnect. But we don't see that either. So we should look at wpa_s.
> I'm unconvinced that
> this is a problem with the driver. The disconnect occurs reliably after
> 30 minutes of being connected. I can set my watch by it.
I agree, if you see can reproduce this with different wifi cards it is
probably not the drivers.
Thanks,
Daniel
5:45 p.m.
Daniel,
On Mon, 2017-07-24 at 10:35 -0700, Carl D. Blake wrote:
Daniel,
On Mon, 2017-07-24 at 15:06 +0200, Daniel Wagner wrote:
> Hi Carl,
>
> On 07/21/2017 08:00 PM, Carl D. Blake wrote:
> > I don't see any further messages that indicate why the driver is
> > deauthorizing. I do notice that I get the message from wpa_supplicant
> > that it failed to initiate sched scan right before the disconnect
> > occurs.
>
> wpa_s is always good for some trouble. So one thing you could do is to
> start wpa_s by hand and enable the debug options and see what wpa_s doing:
>
> # wpa_supplicant -c /etc/wpa_supplicant/wpa_supplicant.conf -u -s -dd
>
It looks to me like connman is starting wpa_supplicant. Is this true?
I've been setting debug options in the various /etc files for
wpa_supplicant, but I always get one wpa_supplicant running in the
background which does not have its debug options set. This
wpa_supplicant always starts after connman starts and I can't locate any
other places in /etc where wpa_supplicant is started.
Never mind, I found it being started by dbus
in /usr/share/dbus-1/system-services.
> > Could this have something to do with it?
>
> The DHCP code in ConnMan is not really driving anything directly. That
> means we would see something from service.c which tells us it decided to
> disconnect. But we don't see that either. So we should look at wpa_s.
>
> > I'm unconvinced that
> > this is a problem with the driver. The disconnect occurs reliably after
> > 30 minutes of being connected. I can set my watch by it.
>
> I agree, if you see can reproduce this with different wifi cards it is
> probably not the drivers.
>
> Thanks,
> Daniel
_______________________________________________
connman mailing list
connman(a)lists.01.org
https://lists.01.org/mailman/listinfo/connman
7:39 a.m.
>> # wpa_supplicant -c /etc/wpa_supplicant/wpa_supplicant.conf
-u -s -dd
>>
>
> It looks to me like connman is starting wpa_supplicant. Is this true?
> I've been setting debug options in the various /etc files for
> wpa_supplicant, but I always get one wpa_supplicant running in the
> background which does not have its debug options set. This
> wpa_supplicant always starts after connman starts and I can't locate any
> other places in /etc where wpa_supplicant is started.
>
Never mind, I found it being started by dbus
in /usr/share/dbus-1/system-services.
Sorry, forgot to mention that you first stop ConnMan and kill wpa_s and
hope that it wont be restarted immediately. Then you can start wpa_s by
hand.
1 p.m.
Hi Carl,
On 07/21/2017 06:22 PM, Carl D. Blake wrote:
This is kernel 3.10.96 on an Nvidia Tegra X1. The driver is the
bcmdhd
module for the BCM4354. I don't believe it is out of tree, but I could
be wrong. Of course, this is on ubuntu 14.04 which is a couple years
old, so I suppose the drivers might need to be updated.
According the wifi wiki it is supported via the brcmsmac.
https://wireless.wiki.kernel.org/en/users/drivers/brcm80211
If it is possible I would give a current Linux kernel a try. If the
problems goes away we know where to look at. But if doesn't go away we
are as smart as before.
>> -----------------------------------------
>>
>> I originally thought it had something to do with miracast and asked this
>> question at that site, but the people there thought it might be an issue
>> with connman.
>>
>> It seems like there might be some issue with DHCP renewal. Does anybody
>> know what's happening here?
>
> It doesn't look like DHCP, because the wireless driver receives a
> DEAUTH. Why this is happening? I have no clue. Maybe it is possible to
> increase the verbosity of the driver and you might see what is going on.
>
> Maybe ConnMan is also doing something wrong but I would first check if
> the driver is behaving according the specification. If it is this
> version I found on github[1] I wouldn't be surprised if there are still
> bugs in it. Just one commit and no changes since 2015.
>
I'll increase the verbosity. The thing is I'm getting this same exact
behavior on an Nvidia Tegra K1 using an AC7260 mini PCIe card, so I
figured it had to be something other than the drivers.
Ah, so different driver and hardware but the same behavior. Indeed, that
sounds like a higher level problem.
Thanks,
Daniel
1519
days inactive
1524
days old
8 comments
2 participants
participants (2)
-
Carl D. Blake -
Daniel Wagner