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