Crashes in chromeos_supplicant_process_proxy.cc: "Failed to get interface wlan0" |
||||
Issue descriptionThe following Shill crash is causing failures in Chrome OS builders, notably the PFQ: FATAL:chromeos_supplicant_process_proxy.cc(168)] Failed to get interface wlan0: fi.w1.wpa_supplicant1.InterfaceUnknown wpa_supplicant knows nothing about this interface.#012/usr/lib64/libbase-core-369476.so(base::debug::StackTrace::StackTrace()+0x14) [0x7fdb745a9a54]#012 A recent failure along with a bunch of shill crash dumps can be found here: http://cautotest.corp.google.com/tko/retrieve_logs.cgi?job=/results/59502258-chromeos-test/chromeos4-row2-rack3-host19/debug/
,
Apr 19 2016
network_DefaultProfileServices/sysinfo/messages snippet (In https://pantheon.corp.google.com/storage/browser/chromeos-autotest-results/59502258-chromeos-test/chromeos4-row2-rack3-host19/network_DefaultProfileServices/sysinfo/) 2016-04-09T19:08:54.796966+00:00 ERR wpa_supplicant[545]: Could not set interface wlan0 flags (UP): Input/output error 2016-04-09T19:08:54.796992+00:00 ERR wpa_supplicant[545]: nl80211: Could not set interface 'wlan0' UP 2016-04-09T19:08:54.797015+00:00 ERR wpa_supplicant[545]: wlan0: Failed to initialize driver interface 2016-04-09T19:08:54.797655+00:00 ERR shill[21243]: [ERROR:object_proxy.cc(580)] Failed to call method: fi.w1.wpa_supplicant1.CreateInterface: object_path= /fi/w1/wpa_supplicant1: fi.w1.wpa_supplicant1.UnknownError: wpa_supplicant couldn't grab this interface. 2016-04-09T19:08:54.797682+00:00 ERR shill[21243]: [ERROR:dbus_method_invoker.h(111)] CallMethodAndBlockWithTimeout(...): Domain=dbus, Code=fi.w1.wpa_supplicant1.UnknownError, Message=wpa_supplicant couldn't grab this interface. 2016-04-09T19:08:54.797695+00:00 ERR shill[21243]: [ERROR:chromeos_supplicant_process_proxy.cc(130)] Failed to create interface: fi.w1.wpa_supplicant1.UnknownError wpa_supplicant couldn't grab this interface. 2016-04-09T19:08:54.799735+00:00 ERR shill[21243]: [ERROR:object_proxy.cc(580)] Failed to call method: fi.w1.wpa_supplicant1.GetInterface: object_path= /fi/w1/wpa_supplicant1: fi.w1.wpa_supplicant1.InterfaceUnknown: wpa_supplicant knows nothing about this interface. 2016-04-09T19:08:54.799761+00:00 ERR shill[21243]: [ERROR:dbus_method_invoker.h(111)] CallMethodAndBlockWithTimeout(...): Domain=dbus, Code=fi.w1.wpa_supplicant1.InterfaceUnknown, Message=wpa_supplicant knows nothing about this interface. 2016-04-09T19:08:54.799774+00:00 CRIT shill[21243]: [FATAL:chromeos_supplicant_process_proxy.cc(168)] Failed to get interface wlan0: fi.w1.wpa_supplicant1.InterfaceUnknown wpa_supplicant knows nothing about this interface.#012/usr/lib64/libbase-core-381699.so(base::debug::StackTrace::StackTrace()+0x14) [0x7f2f3e496d14]#012 2016-04-09T19:08:54.799791+00:00 ERR shill[21244]: [FATAL:chromeos_supplicant_process_proxy.cc(168)] Failed to get interface wlan0: fi.w1.wpa_supplicant1.InterfaceUnknown wpa_supplicant knows nothing about this interface. 2016-04-09T19:08:54.799803+00:00 ERR shill[21244]: /usr/lib64/libbase-core-381699.so(base::debug::StackTrace::StackTrace()+0x14) [0x7f2f3e496d14] Note: there are a bunch of kernel errors preceding that.
,
Apr 19 2016
I think shill crashes are just side effect of the wifi driver failing to bring up the interface, there is nothing shill can do without the WiFi interface. 2016-04-09T19:08:54.794586+00:00 ERR kernel: [ 296.827088] iwlwifi 0000:02:00.0: Microcode SW error detected. Restarting 0x2000000. 2016-04-09T19:08:54.794616+00:00 ERR kernel: [ 296.827116] iwlwifi 0000:02:00.0: CSR values: 2016-04-09T19:08:54.794624+00:00 ERR kernel: [ 296.827131] iwlwifi 0000:02:00.0: (2nd byte of CSR_INT_COALESCING is CSR_INT_PERIODIC_REG) 2016-04-09T19:08:54.794628+00:00 ERR kernel: [ 296.827164] iwlwifi 0000:02:00.0: CSR_HW_IF_CONFIG_REG: 0X40489204 2016-04-09T19:08:54.794633+00:00 ERR kernel: [ 296.827194] iwlwifi 0000:02:00.0: CSR_INT_COALESCING: 0X80000040 2016-04-09T19:08:54.794640+00:00 ERR kernel: [ 296.827224] iwlwifi 0000:02:00.0: CSR_INT: 0X00000000 2016-04-09T19:08:54.794643+00:00 ERR kernel: [ 296.827253] iwlwifi 0000:02:00.0: CSR_INT_MASK: 0X00000000 2016-04-09T19:08:54.794647+00:00 ERR kernel: [ 296.827282] iwlwifi 0000:02:00.0: CSR_FH_INT_STATUS: 0X00000000 2016-04-09T19:08:54.794651+00:00 ERR kernel: [ 296.827311] iwlwifi 0000:02:00.0: CSR_GPIO_IN: 0X00000000 2016-04-09T19:08:54.794664+00:00 ERR kernel: [ 296.827340] iwlwifi 0000:02:00.0: CSR_RESET: 0X00000000 2016-04-09T19:08:54.794667+00:00 ERR kernel: [ 296.827370] iwlwifi 0000:02:00.0: CSR_GP_CNTRL: 0X080403c5 2016-04-09T19:08:54.794671+00:00 ERR kernel: [ 296.827399] iwlwifi 0000:02:00.0: CSR_HW_REV: 0X00000144 2016-04-09T19:08:54.794677+00:00 ERR kernel: [ 296.827428] iwlwifi 0000:02:00.0: CSR_EEPROM_REG: 0X00000000 2016-04-09T19:08:54.794684+00:00 ERR kernel: [ 296.827458] iwlwifi 0000:02:00.0: CSR_EEPROM_GP: 0X80000000 2016-04-09T19:08:54.794687+00:00 ERR kernel: [ 296.827487] iwlwifi 0000:02:00.0: CSR_OTP_GP_REG: 0X803a0000 2016-04-09T19:08:54.794691+00:00 ERR kernel: [ 296.827516] iwlwifi 0000:02:00.0: CSR_GIO_REG: 0X00080042 2016-04-09T19:08:54.794695+00:00 ERR kernel: [ 296.827545] iwlwifi 0000:02:00.0: CSR_GP_UCODE_REG: 0X00000000 2016-04-09T19:08:54.794707+00:00 ERR kernel: [ 296.827575] iwlwifi 0000:02:00.0: CSR_GP_DRIVER_REG: 0X00000000 2016-04-09T19:08:54.794710+00:00 ERR kernel: [ 296.827604] iwlwifi 0000:02:00.0: CSR_UCODE_DRV_GP1: 0X00000000 2016-04-09T19:08:54.794714+00:00 ERR kernel: [ 296.827633] iwlwifi 0000:02:00.0: CSR_UCODE_DRV_GP2: 0X00000000 2016-04-09T19:08:54.794720+00:00 ERR kernel: [ 296.827663] iwlwifi 0000:02:00.0: CSR_LED_REG: 0X00000018 2016-04-09T19:08:54.794726+00:00 ERR kernel: [ 296.827692] iwlwifi 0000:02:00.0: CSR_DRAM_INT_TBL_REG: 0X881528d9 2016-04-09T19:08:54.794732+00:00 ERR kernel: [ 296.827721] iwlwifi 0000:02:00.0: CSR_GIO_CHICKEN_BITS: 0X27800200 2016-04-09T19:08:54.794736+00:00 ERR kernel: [ 296.827750] iwlwifi 0000:02:00.0: CSR_ANA_PLL_CFG: 0Xd55555d5 2016-04-09T19:08:54.794740+00:00 ERR kernel: [ 296.827821] iwlwifi 0000:02:00.0: CSR_MONITOR_STATUS_REG: 0X3d0801bc 2016-04-09T19:08:54.794777+00:00 ERR kernel: [ 296.827895] iwlwifi 0000:02:00.0: CSR_HW_REV_WA_REG: 0X0001001a 2016-04-09T19:08:54.794784+00:00 ERR kernel: [ 296.827930] iwlwifi 0000:02:00.0: CSR_DBG_HPET_MEM_REG: 0Xffff0000 2016-04-09T19:08:54.794788+00:00 ERR kernel: [ 296.827955] iwlwifi 0000:02:00.0: FH register values: 2016-04-09T19:08:54.794801+00:00 ERR kernel: [ 296.827998] iwlwifi 0000:02:00.0: FH_RSCSR_CHNL0_STTS_WPTR_REG: 0X14ff2400 2016-04-09T19:08:54.794805+00:00 ERR kernel: [ 296.828043] iwlwifi 0000:02:00.0: FH_RSCSR_CHNL0_RBDCB_BASE_REG: 0X014ff230 2016-04-09T19:08:54.794809+00:00 ERR kernel: [ 296.828089] iwlwifi 0000:02:00.0: FH_RSCSR_CHNL0_WPTR: 0X00000000 2016-04-09T19:08:54.795771+00:00 ERR kernel: [ 296.828136] iwlwifi 0000:02:00.0: FH_MEM_RCSR_CHNL0_CONFIG_REG: 0X00801114 2016-04-09T19:08:54.795786+00:00 ERR kernel: [ 296.828181] iwlwifi 0000:02:00.0: FH_MEM_RSSR_SHARED_CTRL_REG: 0X000000fc 2016-04-09T19:08:54.795791+00:00 ERR kernel: [ 296.828226] iwlwifi 0000:02:00.0: FH_MEM_RSSR_RX_STATUS_REG: 0X03030000 2016-04-09T19:08:54.795797+00:00 ERR kernel: [ 296.828271] iwlwifi 0000:02:00.0: FH_MEM_RSSR_RX_ENABLE_ERR_IRQ2DRV: 0X00000000 2016-04-09T19:08:54.795803+00:00 ERR kernel: [ 296.828316] iwlwifi 0000:02:00.0: FH_TSSR_TX_STATUS_REG: 0X07ff0001 2016-04-09T19:08:54.795808+00:00 ERR kernel: [ 296.828363] iwlwifi 0000:02:00.0: FH_TSSR_TX_ERROR_REG: 0X00000000 2016-04-09T19:08:54.795813+00:00 ERR kernel: [ 296.828509] iwlwifi 0000:02:00.0: Start IWL Error Log Dump: 2016-04-09T19:08:54.795818+00:00 ERR kernel: [ 296.828532] iwlwifi 0000:02:00.0: Status: 0x00000000, count: 6 2016-04-09T19:08:54.795823+00:00 ERR kernel: [ 296.828554] iwlwifi 0000:02:00.0: Loaded firmware version: 16.229726.0 2016-04-09T19:08:54.795829+00:00 ERR kernel: [ 296.828579] iwlwifi 0000:02:00.0: 0x00000034 | NMI_INTERRUPT_WDG 2016-04-09T19:08:54.795835+00:00 ERR kernel: [ 296.828602] iwlwifi 0000:02:00.0: 0x000002F0 | uPc 2016-04-09T19:08:54.795839+00:00 ERR kernel: [ 296.828622] iwlwifi 0000:02:00.0: 0x00000000 | branchlink1 2016-04-09T19:08:54.795845+00:00 ERR kernel: [ 296.828643] iwlwifi 0000:02:00.0: 0x0000099A | branchlink2 2016-04-09T19:08:54.795850+00:00 ERR kernel: [ 296.828664] iwlwifi 0000:02:00.0: 0x0000D21C | interruptlink1 2016-04-09T19:08:54.795855+00:00 ERR kernel: [ 296.828689] iwlwifi 0000:02:00.0: 0x0000D928 | interruptlink2 2016-04-09T19:08:54.795860+00:00 ERR kernel: [ 296.828710] iwlwifi 0000:02:00.0: 0x00000000 | data1 2016-04-09T19:08:54.795864+00:00 ERR kernel: [ 296.828730] iwlwifi 0000:02:00.0: 0x00000002 | data2 2016-04-09T19:08:54.795870+00:00 ERR kernel: [ 296.828751] iwlwifi 0000:02:00.0: 0x07030000 | data3 2016-04-09T19:08:54.795875+00:00 ERR kernel: [ 296.828785] iwlwifi 0000:02:00.0: 0x003C7B1B | beacon time 2016-04-09T19:08:54.795880+00:00 ERR kernel: [ 296.828806] iwlwifi 0000:02:00.0: 0x000384E3 | tsf low 2016-04-09T19:08:54.795885+00:00 ERR kernel: [ 296.828827] iwlwifi 0000:02:00.0: 0x00000000 | tsf hi 2016-04-09T19:08:54.795890+00:00 ERR kernel: [ 296.828847] iwlwifi 0000:02:00.0: 0x00000000 | time gp1 2016-04-09T19:08:54.795896+00:00 ERR kernel: [ 296.828868] iwlwifi 0000:02:00.0: 0x000384E4 | time gp2 2016-04-09T19:08:54.795900+00:00 ERR kernel: [ 296.828889] iwlwifi 0000:02:00.0: 0x00000000 | time gp3 2016-04-09T19:08:54.795905+00:00 ERR kernel: [ 296.828911] iwlwifi 0000:02:00.0: 0x00000010 | uCode version major 2016-04-09T19:08:54.795911+00:00 ERR kernel: [ 296.828933] iwlwifi 0000:02:00.0: 0x0003815E | uCode version minor 2016-04-09T19:08:54.795916+00:00 ERR kernel: [ 296.828955] iwlwifi 0000:02:00.0: 0x00000144 | hw version 2016-04-09T19:08:54.795921+00:00 ERR kernel: [ 296.828977] iwlwifi 0000:02:00.0: 0x40489204 | board version 2016-04-09T19:08:54.795961+00:00 ERR kernel: [ 296.829085] iwlwifi 0000:02:00.0: 0x0902006A | hcmd 2016-04-09T19:08:54.795966+00:00 ERR kernel: [ 296.829105] iwlwifi 0000:02:00.0: 0x00022080 | isr0 2016-04-09T19:08:54.795971+00:00 ERR kernel: [ 296.829125] iwlwifi 0000:02:00.0: 0x00000000 | isr1 2016-04-09T19:08:54.795976+00:00 ERR kernel: [ 296.829145] iwlwifi 0000:02:00.0: 0x00000002 | isr2 2016-04-09T19:08:54.795980+00:00 ERR kernel: [ 296.829165] iwlwifi 0000:02:00.0: 0x404000C0 | isr3 2016-04-09T19:08:54.795985+00:00 ERR kernel: [ 296.829185] iwlwifi 0000:02:00.0: 0x00000080 | isr4 2016-04-09T19:08:54.795990+00:00 ERR kernel: [ 296.829205] iwlwifi 0000:02:00.0: 0x01800112 | isr_pref 2016-04-09T19:08:54.795995+00:00 ERR kernel: [ 296.829226] iwlwifi 0000:02:00.0: 0x00000000 | wait_event 2016-04-09T19:08:54.796000+00:00 ERR kernel: [ 296.829247] iwlwifi 0000:02:00.0: 0x00000040 | l2p_control 2016-04-09T19:08:54.796023+00:00 ERR kernel: [ 296.829285] iwlwifi 0000:02:00.0: 0x00000000 | l2p_duration 2016-04-09T19:08:54.796028+00:00 ERR kernel: [ 296.829307] iwlwifi 0000:02:00.0: 0x00000000 | l2p_mhvalid 2016-04-09T19:08:54.796034+00:00 ERR kernel: [ 296.829328] iwlwifi 0000:02:00.0: 0x00000000 | l2p_addr_match 2016-04-09T19:08:54.796044+00:00 ERR kernel: [ 296.829350] iwlwifi 0000:02:00.0: 0x00000007 | lmpm_pmg_sel 2016-04-09T19:08:54.796481+00:00 ERR kernel: [ 296.829372] iwlwifi 0000:02:00.0: 0x12101904 | timestamp 2016-04-09T19:08:54.796490+00:00 ERR kernel: [ 296.829393] iwlwifi 0000:02:00.0: 0x00340010 | flow_handler 2016-04-09T19:08:54.796495+00:00 ERR kernel: [ 296.829441] iwlwifi 0000:02:00.0: Failed to run INIT ucode: -5 2016-04-09T19:08:54.796966+00:00 ERR wpa_supplicant[545]: Could not set interface wlan0 flags (UP): Input/output error 2016-04-09T19:08:54.796992+00:00 ERR wpa_supplicant[545]: nl80211: Could not set interface 'wlan0' UP 2016-04-09T19:08:54.797015+00:00 ERR wpa_supplicant[545]: wlan0: Failed to initialize driver interface @ejcaruso, feel free to reassign someone in Chrome OS WiFi team to investigate further.
,
Apr 19 2016
,
Apr 19 2016
Do we know why the interface isn't coming up? Are we seeing this on all trickies/haswell/7260s or just specific DUTs?
,
Apr 19 2016
Good question. Scanning the failures blocked on issue 604759 , I see a range of DUTs affected, but several times where the same DUT will fail several times in a row. It is limited to tricky and cyan DUTs.
,
Apr 19 2016
Thanks for the quick response Peter! BTW, Steven, Peter's not on the WiFi team anymore (not even mine) so please don't assign directly to him anymore. You should find someone on the Chrome OS WiFi team to triage.
,
Apr 19 2016
He was on the blame list which was all I had to go on, but I'll try to remember :) I appreciate the quick responses all around, and thanks Eric for investigating.
,
Apr 27 2016
Creating partner tracker issue crosbug.com/p/52804 to help track this. Closing here.
,
Apr 27 2016
Naive comment - would it be preferable to have shill fail gracefully? if the wifi interface isn't being brought up for some reason, pretend that wifi is turned off instead of crashing?
,
Apr 27 2016
Fair question. My take on this is: as long as the shill crash isn't taking down the system, the current behavior is actually a good thing. Most Chromebooks are Wifi-only. On such systems, a shill crash (should) only affect Wifi. The user should still be able to access local/cached content, as normal. Since the crash doesn't affect the user, it's better to fail loudly. That way, we find out about lower-layer problems more quickly (as this bug demonstrates). Note that there's also some chance that a crash will fix the problem. When shill crashes, the init daemon will restart shill. If the root cause was that shill had corrupted its memory (and hence, was asking supplicant for wlan123, instead of wlan0), then the crash-and-restart would have recovered Wifi. |
||||
►
Sign in to add a comment |
||||
Comment 1 by steve...@chromium.org
, Apr 19 2016Crash snippet: 3 libbase-core-381699.so!logging::LogMessage::~LogMessage [logging.cc : 751 + 0x5] rbx = 0x00007fff4a328ab0 rbp = 0x00007fff4a328810 rsp = 0x00007fff4a328170 r12 = 0x00007f2f3e053220 r13 = 0x00007fff4a328ab8 r14 = 0x00007fff4a3281b0 r15 = 0x00007f2f3f3a7610 rip = 0x00007f2f3e4b63ae Found by: call frame info 4 shill!shill::ChromeosSupplicantProcessProxy::GetInterface [chromeos_supplicant_process_proxy.cc : 168 + 0x8] rbx = 0x00007f2f3e053220 rbp = 0x00007fff4a328c70 rsp = 0x00007fff4a328820 r12 = 0x00007f2f3f3ac7a0 r13 = 0x00007fff4a328a50 r14 = 0x00007fff4a328ab8 r15 = 0x00007fff4a328ab0 rip = 0x00007f2f3ea1207c Found by: call frame info 5 shill!shill::WiFi::ConnectToSupplicant [wifi.cc : 2323 + 0xe] rbx = 0x00007f2f3f3a81c0 rbp = 0x00007fff4a3294f0 rsp = 0x00007fff4a328c80 r12 = 0x00007f2f3e053220 r13 = 0x00007fff4a328d00 r14 = 0x00007fff4a328ce0 r15 = 0x00007f2f3f3a8708 rip = 0x00007f2f3ea911dd Found by: call frame info 6 shill!shill::WiFi::OnSupplicantAppear [wifi.cc : 2226 + 0x8] rbx = 0x00007f2f3f3a81c0 rbp = 0x00007fff4a3296a0 rsp = 0x00007fff4a329500 r12 = 0x00007fff4a329500 r13 = 0x00007f2f3f355c80 r14 = 0x00007fff4a329710 r15 = 0x00007fff4a329a50 rip = 0x00007f2f3ea91d1f Found by: call frame info 7 libbase-core-381699.so!base::debug::TaskAnnotator::RunTask [callback.h : 397 + 0x8] rbx = 0x00007fff4a329740 rbp = 0x00007fff4a3297b0 rsp = 0x00007fff4a3296b0 r12 = 0x00007f2f3e573404 r13 = 0x00007f2f3f355c80 r14 = 0x00007fff4a329710 r15 = 0x00007fff4a329a50 rip = 0x00007f2f3e497cda Found by: call frame info