Hi, could you help triage this issue ?

customer info: https://drive.google.com/open?id=1MbgZ_-3o-i17Jb8RghdIu66b4o9Mx5wR04vdw5_RaQ0
other logs from different version:
https://drive.google.com/open?id=1Wcu_wHCUcP7pVKi-e4imUWE4kUhEB2VU

Hi josafat@, could you please update this issue?

marcore@ can you include more information on what flex mode actually is and if there's any expectation that it should be supported or that it's a Chrome OS issue that it's not working?

as explained by the customer:
The flex connect option just keeps the dhcp and IP traffic local to the router at the site.  This means the traffic does not need to pass through the wireless controller to route.
also in the cisco documentation:
https://www.cisco.com/c/en/us/td/docs/wireless/controller/8-2/config-guide/b_cg82/b_cg82_chapter_010010101.html#ID17

Jay, customer is asking for update.
Is anything needed from his side for the bug?

1) does this feature work with other Chromebook models and only daisy fails?
2) The logs are pretty large and it makes it difficult to find the disconnect events relevant to the case. Can we get a timeline that corresponds with the logs? E.g. a) booted device at 10:05am b) wifi shown as connected at 10:06am c) wifi disconnected and reconnected at 10:08am

jayhlee@
Please refer the answers from the customer regarding your question.

1-A) this only happens with Daisy devices.

2-A) logs were provided back in November and admin does not remember exact time stamps, to create additional logs would be challenging as would need to again change the network infrastructure with old Cisco routers, as at this time they are using the new Cisco AP which are not working with Daisy devices, admin mentioned that he created short logs of about 4 minutes just showing the behavior to avoid any extra data showing. 

jayhlee@
Is there any update that can be shared with the customer?
Please let us know if you have any additional question.

cernekee: any ideas on this? Do we have a Cisco AP we can test Flex mode with?

@marchuk is going to report back with details of customer WiFi (PSK, TLS, Open, etc)

> The flex connect option just keeps the dhcp and IP traffic local to the router at the site.  This means the traffic does not need to pass through the wireless controller to route.

How is this visible to the client?

> Do we have a Cisco AP we can test Flex mode with?

Suggest checking with Harpreet.

The logs show some kernel issues where the Marvell wifi device (mlan0) vanishes and reappears:

2017-11-30T10:11:21.832175-07:00 ERR kernel: [  192.671526] mwifiex_sdio mmc2:0001:1: invalid rx_len=4642
2017-11-30T10:11:50.923133-07:00 ERR shill[991]: [ERROR:netlink_manager.cc(274)] OnNetlinkMessageError: Message (seq: 14) failed: NETLINK_ERROR 0xe: Bad address
2017-11-30T10:11:50.971489-07:00 ERR kernel: [  221.762174] mwifiex_sdio mmc2:0001:1: mwifiex_cmd_timeout_func: Timeout cmd id (1512061910.922131) = 0xa4, act = 0x0
2017-11-30T10:11:50.971514-07:00 ERR kernel: [  221.762189] mwifiex_sdio mmc2:0001:1: num_data_h2c_failure = 0
2017-11-30T10:11:50.971519-07:00 ERR kernel: [  221.762199] mwifiex_sdio mmc2:0001:1: num_cmd_h2c_failure = 0
2017-11-30T10:11:50.971522-07:00 ERR kernel: [  221.762207] mwifiex_sdio mmc2:0001:1: num_cmd_timeout = 1
2017-11-30T10:11:50.971526-07:00 ERR kernel: [  221.762215] mwifiex_sdio mmc2:0001:1: num_tx_timeout = 0
2017-11-30T10:11:50.971529-07:00 ERR kernel: [  221.762223] mwifiex_sdio mmc2:0001:1: last_cmd_index = 4
2017-11-30T10:11:50.971532-07:00 DEBUG kernel: [  221.762232] last_cmd_id: 00000000: 16 00 a4 00 7f                                   .....
2017-11-30T10:11:50.971535-07:00 DEBUG kernel: [  221.762238] last_cmd_act: 00000000: 00 00 00 00 00                                   .....
2017-11-30T10:11:50.971538-07:00 ERR kernel: [  221.762245] mwifiex_sdio mmc2:0001:1: last_cmd_resp_index = 3
2017-11-30T10:11:50.971541-07:00 DEBUG kernel: [  221.762252] last_cmd_resp_id: 00000000: 16 80 a4 80 7f                                   .....
2017-11-30T10:11:50.971545-07:00 ERR kernel: [  221.762258] mwifiex_sdio mmc2:0001:1: last_event_index = 4
2017-11-30T10:11:50.971548-07:00 DEBUG kernel: [  221.762265] last_event: 00000000: 0a 00 0b 00 0a                                   .....
2017-11-30T10:11:50.971551-07:00 ERR kernel: [  221.762271] mwifiex_sdio mmc2:0001:1: data_sent=0 cmd_sent=0
2017-11-30T10:11:50.971554-07:00 ERR kernel: [  221.762280] mwifiex_sdio mmc2:0001:1: ps_mode=1 ps_state=0
2017-11-30T10:11:50.971557-07:00 ERR kernel: [  221.762297] mwifiex_sdio mmc2:0001:1: cmd timeout
2017-11-30T10:11:50.971560-07:00 WARNING kernel: [  221.762309] ------------[ cut here ]------------
2017-11-30T10:11:50.971563-07:00 WARNING kernel: [  221.762333] WARNING: at /mnt/host/source/src/third_party/kernel/v3.8/drivers/net/wireless-3.4/mwifiex/sdio.c:1881 mwifiex_sdio_card_reset+0x34/0x5c [mwifiex_sdio]()
2017-11-30T10:11:50.971567-07:00 NOTICE kernel: [  221.762341] Modules linked in: nls_iso8859_1 nls_cp437 vfat fat uinput cmac rfcomm isl29018(C) btmrvl_sdio btmrvl rtc_s3c ip6t_REJECT i2c_dev zram(C) zsmalloc(C) bluetooth fuse nf_conntrack_ipv6 nf_defrag_ipv6 ip6table_filter snd_seq_midi ip6_tables snd_seq_midi_event snd_rawmidi snd_seq snd_seq_device mwifiex_sdio mwifiex cfg80211 uvcvideo videobuf2_vmalloc joydev
2017-11-30T10:11:50.971570-07:00 NOTICE kernel: [  221.762508] Backtrace:
2017-11-30T10:11:50.971573-07:00 NOTICE kernel: [  221.762530] [<c010d0e4>] (unwind_backtrace+0x0/0x110) from [<c0648388>] (dump_stack+0x28/0x30)
2017-11-30T10:11:50.971576-07:00 NOTICE kernel: [  221.762544] [<c0648388>] (dump_stack+0x28/0x30) from [<c01229bc>] (warn_slowpath_null+0x24/0x34)
2017-11-30T10:11:50.971580-07:00 NOTICE kernel: [  221.762559] [<c01229bc>] (warn_slowpath_null+0x24/0x34) from [<bf084c68>] (mwifiex_sdio_card_reset+0x34/0x5c [mwifiex_sdio])
2017-11-30T10:11:50.971583-07:00 NOTICE kernel: [  221.762586] [<bf084c68>] (mwifiex_sdio_card_reset+0x34/0x5c [mwifiex_sdio]) from [<bf062e14>] (mwifiex_cmd_timeout_func+0x210/0x26c [mwifiex])
2017-11-30T10:11:50.971586-07:00 NOTICE kernel: [  221.762608] [<bf062e14>] (mwifiex_cmd_timeout_func+0x210/0x26c [mwifiex]) from [<c0130a18>] (call_timer_fn+0x74/0x114)
2017-11-30T10:11:50.971590-07:00 NOTICE kernel: [  221.762621] [<c0130a18>] (call_timer_fn+0x74/0x114) from [<c0132a84>] (run_timer_softirq+0x20c/0x25c)
2017-11-30T10:11:50.971593-07:00 NOTICE kernel: [  221.762634] [<c0132a84>] (run_timer_softirq+0x20c/0x25c) from [<c012b1e4>] (__do_softirq+0x100/0x208)
2017-11-30T10:11:50.971597-07:00 NOTICE kernel: [  221.762645] [<c012b1e4>] (__do_softirq+0x100/0x208) from [<c012b5f8>] (irq_exit+0x54/0x98)
2017-11-30T10:11:50.971600-07:00 NOTICE kernel: [  221.762657] [<c012b5f8>] (irq_exit+0x54/0x98) from [<c0106978>] (handle_IRQ+0x80/0xa4)
2017-11-30T10:11:50.971603-07:00 NOTICE kernel: [  221.762669] [<c0106978>] (handle_IRQ+0x80/0xa4) from [<c01003f0>] (gic_handle_irq+0x48/0x6c)
2017-11-30T10:11:50.971606-07:00 NOTICE kernel: [  221.762681] [<c01003f0>] (gic_handle_irq+0x48/0x6c) from [<c0105d40>] (__irq_usr+0x40/0x60)
2017-11-30T10:11:50.971609-07:00 NOTICE kernel: [  221.762688] Exception stack(0xeced1fb0 to 0xeced1ff8)
2017-11-30T10:11:50.971612-07:00 NOTICE kernel: [  221.762696] 1fa0:                                     00000010 00000004 00016bac ffffffff
2017-11-30T10:11:50.971615-07:00 NOTICE kernel: [  221.762706] 1fc0: 00001000 66666000 308000f8 0000037f 3081bf80 3081bfa4 3081bf80 3081bfa5
2017-11-30T10:11:50.971618-07:00 NOTICE kernel: [  221.762713] 1fe0: 00000000 a9f86a80 b5d0bd23 b5d0bcb2 00030030 ffffffff
2017-11-30T10:11:50.971621-07:00 WARNING kernel: [  221.762721] ---[ end trace b3ec98e2db061dfb ]---
2017-11-30T10:11:50.971624-07:00 ERR kernel: [  221.762800] mwifiex_sdio mmc2:0001:1: failed to get signal information
2017-11-30T10:11:50.971627-07:00 INFO kernel: [  221.763258] mwifiex_sdio mmc2:0001:1: CCCR: 0000 0001 0002 0003 0004 0005 0006 0007 0008 0009 
2017-11-30T10:11:50.971630-07:00 INFO kernel: [  221.763733] mwifiex_sdio mmc2:0001:1: CCCR: 0043 0003 0006 0006 0007 0000 0000 0002 0003 0000 
2017-11-30T10:11:50.971633-07:00 INFO kernel: [  221.763747] mwifiex_sdio mmc2:0001:1: FN1: 0000 0001 0002 0003 0004 0005 0006 0007 0008 0009 
2017-11-30T10:11:50.971636-07:00 INFO kernel: [  221.763978] mwifiex_sdio mmc2:0001:1: FN1: 0000 003F 0003 0000 0010 0000 0001 0040 002A 0000 
2017-11-30T10:11:50.971639-07:00 INFO kernel: [  221.763991] mwifiex_sdio mmc2:0001:1: FN1 Status: 0028 0030 0034 0038 003C 
2017-11-30T10:11:50.971642-07:00 INFO kernel: [  221.764290] mwifiex_sdio mmc2:0001:1: FN1 Status: 0000 0008 0007 0000 0000 
2017-11-30T10:11:51.021265-07:00 INFO crash_reporter[3490]: Processing kernel warning: normal collection
2017-11-30T10:11:51.023449-07:00 INFO crash_reporter[3490]: Stored kernel warning into /var/spool/crash/kernel_warning.20171130.101151.0.kcrash
2017-11-30T10:11:51.027181-07:00 INFO kernel: [  221.864320] mwifiex_sdio mmc2:0001:1: FN1 Scratch: 0060 0061 0062 0063 0064 0065 0066 0067 0068 0069 006A 
2017-11-30T10:11:51.042522-07:00 INFO kernel: [  221.868128] mwifiex_sdio mmc2:0001:1: FN1 Scratch: 00DC 00FE 00DA 0000 00A3 0000 003F 0028 00DC 00FE 0030 
2017-11-30T10:11:51.129725-07:00 INFO avahi-daemon[1364]: Interface mlan0.IPv4 no longer relevant for mDNS.
2017-11-30T10:11:51.129752-07:00 INFO avahi-daemon[1364]: Leaving mDNS multicast group on interface mlan0.IPv4 with address 10.45.2.240.
2017-11-30T10:11:51.129952-07:00 ERR wpa_supplicant[546]: nl80211: Failed to open /proc/sys/net/ipv4/conf/mlan0/drop_unicast_in_l2_multicast: No such file or directory
2017-11-30T10:11:51.130592-07:00 ERR shill[991]: [ERROR:arp_client.cc(130)] Socket recvfrom failed: Network is down
2017-11-30T10:11:51.130984-07:00 ERR wpa_supplicant[546]: nl80211: Failed to set IPv4 unicast in multicast filter
2017-11-30T10:11:51.132553-07:00 INFO kernel: [  221.968210] mwifiex_sdio mmc2:0001:1: FN1 Scratch: 0060 0061 0062 0063 0064 0065 0066 0067 0068 0069 006A 
2017-11-30T10:11:51.132575-07:00 INFO kernel: [  221.969017] mwifiex_sdio mmc2:0001:1: FN1 Scratch: 00DC 00FE 00EA 0000 00B0 0000 003F 0028 00DC 00FE 0030 
2017-11-30T10:11:51.132581-07:00 ERR kernel: [  221.969029] mwifiex_sdio: Resetting card...
2017-11-30T10:11:51.132586-07:00 ERR kernel: [  221.969563] mwifiex_sdio mmc2:0001:1: PREP_CMD: card is removed
2017-11-30T10:11:51.155772-07:00 INFO avahi-daemon[1364]: Withdrawing address record for 10.45.2.240 on mlan0.
2017-11-30T10:11:51.173831-07:00 ERR wpa_supplicant[546]: nl80211: Failed to open /proc/sys/net/ipv4/conf/mlan0/drop_unicast_in_l2_multicast: No such file or directory
2017-11-30T10:11:51.173925-07:00 ERR wpa_supplicant[546]: nl80211: Failed to set IPv4 unicast in multicast filter
2017-11-30T10:11:51.212217-07:00 INFO kernel: [  222.047393] mmc2: card 0001 removed
2017-11-30T10:11:51.249484-07:00 INFO bluetoothd[1363]: adapter /org/bluez/hci0 has been disabled
2017-11-30T10:11:51.249750-07:00 INFO bluetoothd[1363]: Endpoint unregistered: sender=:1.24 path=/org/chromium/Cras/Bluetooth/A2DPSource
2017-11-30T10:11:51.251154-07:00 NOTICE dbus[400]: [system] Rejected send message, 3 matched rules; type="method_return", sender=":1.24" (uid=600 pid=1355 comm="/usr/bin/cras ") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.27" (uid=218 pid=1363 comm="/usr/libexec/bluetooth/bluetoothd --nodetach ")
2017-11-30T10:11:51.252455-07:00 INFO kernel: [  222.087294] mmc_host mmc2: Bus speed (slot 0) = 50000000Hz (slot req 400000Hz, actual 396825HZ div = 63)
2017-11-30T10:11:51.251312-07:00 NOTICE dbus[400]: [system] Rejected send message, 3 matched rules; type="method_return", sender=":1.24" (uid=600 pid=1355 comm="/usr/bin/cras ") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.27" (uid=218 pid=1363 comm="/usr/libexec/bluetooth/bluetoothd --nodetach ")
2017-11-30T10:11:51.277552-07:00 ERR shill[991]: [ERROR:object_proxy.cc(582)] Failed to call method: fi.w1.wpa_supplicant1.Interface.Disconnect: object_path= /fi/w1/wpa_supplicant1/Interfaces/1: fi.w1.wpa_supplicant1.NotConnected: This interface is not connected
2017-11-30T10:11:51.277669-07:00 ERR shill[991]: [ERROR:dbus_method_invoker.h(111)] CallMethodAndBlockWithTimeout(...): Domain=dbus, Code=fi.w1.wpa_supplicant1.NotConnected, Message=This interface is not connected
2017-11-30T10:11:51.280275-07:00 ERR shill[991]: [ERROR:chromeos_supplicant_interface_proxy.cc(196)] Failed to disconnect: fi.w1.wpa_supplicant1.NotConnected This interface is not connected
2017-11-30T10:11:51.292184-07:00 INFO kernel: [  222.130581] mmc_host mmc2: Bus speed (slot 0) = 50000000Hz (slot req 50000000Hz, actual 50000000HZ div = 0)
2017-11-30T10:11:51.297170-07:00 INFO kernel: [  222.134917] mmc2: new high speed SDIO card at address 0001
2017-11-30T10:11:51.305835-07:00 ERR wpa_supplicant[546]: nl80211: Failed to open /proc/sys/net/ipv4/conf/mlan0/drop_unicast_in_l2_multicast: No such file or directory
2017-11-30T10:11:51.305849-07:00 ERR wpa_supplicant[546]: nl80211: Failed to set IPv4 unicast in multicast filter
2017-11-30T10:11:51.307152-07:00 INFO kernel: [  222.143109] Bluetooth: vendor=0x2df, device=0x912a, class=255, fn=2
2017-11-30T10:11:51.337581-07:00 ERR wpa_supplicant[546]: nl80211: Failed to open /proc/sys/net/ipv4/conf/mlan0/drop_unicast_in_l2_multicast: No such file or directory
2017-11-30T10:11:51.337593-07:00 ERR wpa_supplicant[546]: nl80211: Failed to set IPv4 unicast in multicast filter
2017-11-30T10:11:51.363972-07:00 ERR wpa_supplicant[546]: Could not read interface mlan0 flags: No such device
2017-11-30T10:11:51.364352-07:00 ERR wpa_supplicant[546]: rmdir[ctrl_interface=/run/wpa_supplicant]: Permission denied
2017-11-30T10:11:51.768677-07:00 INFO avahi-daemon[1364]: Server startup complete. Host name is 2d961e181f4c29746adfa8c75a203bd7.local. Local service cookie is 2851489044.
2017-11-30T10:11:51.768712-07:00 INFO avahi-daemon[1364]: Changing host name to '2d961e181f4c29746adfa8c75a203bd7'.
2017-11-30T10:11:51.798554-07:00 NOTICE cros-machine-id-regen[3534]: Regenerated /var/lib/dbus/machine-id (reason: network).
2017-11-30T10:11:51.962183-07:00 INFO kernel: [  222.799559] Bluetooth: FW download over, size 460412 bytes
2017-11-30T10:11:52.347647-07:00 ERR chrome[1047]: [1047:1047:1130/101152.347565:INFO:remote_commands_invalidator.cc(45)] Shutdown RemoteCommandsInvalidator.
2017-11-30T10:11:52.348766-07:00 ERR chrome[1047]: [1047:1047:1130/101152.348688:INFO:remote_commands_invalidator.cc(68)] Stopping RemoteCommandsInvalidator.
2017-11-30T10:11:52.349764-07:00 ERR chrome[1047]: [1047:1047:1130/101152.349697:INFO:remote_commands_invalidator.cc(167)] Unregister RemoteCommandsInvalidator.
2017-11-30T10:11:52.697930-07:00 NOTICE kernel: [  223.532390] mwifiex_sdio mmc2:0001:1: Other intf already running! Skip FW download
2017-11-30T10:11:52.697956-07:00 NOTICE kernel: [  223.532497] mwifiex_sdio mmc2:0001:1: WLAN FW is active
2017-11-30T10:11:52.747173-07:00 INFO kernel: [  223.583504] mwifiex_sdio mmc2:0001:1: ignoring F/W country code US
2017-11-30T10:11:52.747191-07:00 NOTICE kernel: [  223.584169] mwifiex_sdio mmc2:0001:1: driver_version = mwifiex 1.0 (14.66.27.p17) 
2017-11-30T10:11:52.787183-07:00 INFO kernel: [  223.624589] IPv6: ADDRCONF(NETDEV_UP): mlan0: link is not ready


The "invalid RX len" 30s before the timeout leads me to wonder if it is unable to handle some sort of jumbo frame or packet aggregation setup.  Would be useful to get a monitor mode trace showing any huge packets during this time period.

Most Cisco APs that we have are the olders linksys / cisco APs which most likely do not have the flex mode feature. We can order the 2800 series cisco AP if we want to try repro in house but looks like we'll also need to get a Cisco wireless LAN controller to get it working. No one on the test team has experience with cisco controllers but we should be able to get it working if needed though there seems to be a large cost associated with getting 1 of these controllers.

So, let me know if the customer can't help with the needed logs, etc. and we want to try repro this in-house. 

Thanks

Matthew has a Cisco wireless LAN controller.  Not sure if his hardware supports flex mode.

Matthew - can you check with your cisco controller will work with 2800 series cisco AP including setting it up in flex mode? If so, we can order the AP.

I have a Cisco 3504 WLC running software version 8.5.103.0, which supports 2800 series Cisco APs. I'm not sure what flex mode is (I googled around and couldn't really find anything), but you're welcome to take a look at it if you want.

I ordered Cisco Aironet 2800i AP. Should be here Monday. We can work on getting that to work sometime next week with your controller.

Hi team,
Is there any update that can be shared with the customer?

aashutoshk@ is working with matthewmwang@ to get flex mode working on our setup to try repro this.

I got the flex-mode setup working on Cisco 2802 and 3802 series APs. I see some re-connections for Daisy. I will test other devices and also try to narrow it down to check if it is device or configuration related and report back.

Thanks aashutoshk@. Do you see anything similar in the logs as mentioned in comment 11?

I am not able to reproduce this issue. Earlier re-connections were due to switching between AP's under the same WLAN network. 
Tested on Daisy R67-10575.52.0
AP Model: 2802I  
AP Mode: Flexconnect
AP Sub Mode: None
The following options enabled on the  WLAN settings 
Flexconnect local switching, Learn IP address, and Central DHCP 

Assigning to snanda@ for re-assignment since cernekee@ is OOO.


Sameer, please let us know how you would like to proceed with this.

Hello

I'd like to know if there is any update that we can give the customer on this investigation or if there is any more information that I can ask from them that would help.

This bug has an owner, thus, it's been triaged. Changing status to "assigned".

Hello!
This bug is receiving this notice because there has been no acknowledgment of its existence in quite a bit of time
- If you are currently working on this bug, please provide an update.
- If you are currently affected by this bug, please update with your current symptoms and relevant logs.

If there has been no updates provided by EOD Wednesday, 12/19/18 (5pm EST), this bug will be archived and can be re-opened at any time deemed necessary.

Thank you!

Due to lack of action this bug has been Archived. If work is still being done on this issue or you are still experiencing this issue please feel free to re-open with the appropriate information.