Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

wpa_supplicant error on wifi enable. #29

Open
tmjwid opened this issue Mar 15, 2020 · 67 comments
Open

wpa_supplicant error on wifi enable. #29

tmjwid opened this issue Mar 15, 2020 · 67 comments

Comments

@tmjwid
Copy link

tmjwid commented Mar 15, 2020

Hi there,

I'm running latest KU with latest kfmon on a Glo HD with latest f/w (4.20.14622).
Whenever it autoclicks connect and initiates wifi enable, I get at wpa_supplicant failed to connect followed by WiFi did not enable (1). Aborting!

Here's the syslog.
Mar 15 19:14:32 UNCaGED: Mounting onboard
Mar 15 19:14:33 UNCaGED: Mounting SD card
Mar 15 19:14:33 UNCaGED: Enabling WiFi
Mar 15 19:14:35 wpa_supplicant[2894]: Successfully initialized wpa_supplicant
Mar 15 19:14:35 wpa_supplicant[2894]: rfkill: Cannot get wiphy information
Mar 15 19:14:41 UNCaGED: wpa_supplicant failed to connect
Mar 15 19:14:41 wpa_supplicant[2895]: eth0: CTRL-EVENT-TERMINATING
Mar 15 19:14:42 UNCaGED: WiFi did not enable (1). Aborting!

My kobo has the google analytics patch installed (redirect hostfile) and kfmon and that's it. Any other information I'll gladly supply.

@shermp
Copy link
Owner

shermp commented Mar 15, 2020

Have you previously connected to WiFi on your Kobo? KU reads whatever WiFi settings have been set in the Kobo interface.

Other than that, I'm not really sure what's going on. I'm rather suspicious of wpa_supplicant[2894]: rfkill: Cannot get wiphy information. Looking around online, it looks driver related perhaps?

@NiLuJe any ideas?

@NiLuJe
Copy link
Contributor

NiLuJe commented Mar 15, 2020

I'm not aware of any peculiarities with WiFi and the Glo HD (a couple of KOReader devs over the years have had a Glo HD, so it's seen a fair amount of testing).

@NiLuJe
Copy link
Contributor

NiLuJe commented Mar 15, 2020

I do get that same error message when nickel sets WiFi up on my H2O, but that doesn't appear to be fatal.

@NiLuJe
Copy link
Contributor

NiLuJe commented Mar 15, 2020

I'm not familiar enough with wpa_cli to grok how to actually use that, but there appears to be a level command to tweak debugging output verbosity ;).

@shermp
Copy link
Owner

shermp commented Mar 15, 2020

Ok, so a red herring then. I'll wait to confirm with @tmjwid that it isn't a lack of available credentials/configuration before trying to investigate further.

@tmjwid
Copy link
Author

tmjwid commented Mar 15, 2020

My kobo has WiFi credentials and can connect successful. No matter what state my device is in (WiFi disabled, enabled no connection, WiFi enable with connection) I get the error. I did not create a toml file nor have I edited any config files yet.

@shermp
Copy link
Owner

shermp commented Mar 15, 2020

Oh dear, something appears to be very wrong. My H2O (now on 4.20.whateverthelatestis), also isn't connecting to WiFi

Relevant bit of the syslog is:

Mar 16 11:45:23 UNCaGED: Mounting onboard
Mar 16 11:45:24 UNCaGED: Mounting SD card
Mar 16 11:45:24 UNCaGED: Enabling WiFi
Mar 16 11:45:26 wpa_supplicant[1691]: Successfully initialized wpa_supplicant
Mar 16 11:45:26 wpa_supplicant[1691]: rfkill: Cannot get wiphy information
Mar 16 11:45:26 wpa_supplicant[1691]: Could not read interface eth0 flags: No such device
Mar 16 11:45:26 wpa_supplicant[1691]: WEXT: Could not set interface 'eth0' UP
Mar 16 11:45:26 wpa_supplicant[1691]: eth0: Failed to initialize driver interface
Mar 16 11:45:31 UNCaGED: wpa_supplicant failed to connect
Mar 16 11:45:32 UNCaGED: WiFi did not enable (1). Aborting!
Mar 16 11:45:36 nickel: (   365.630 @ 0x1c0dc78 / ui.debug) void SyncFileSystemCommand::findFilesToParse(const QString&, QStringList&) skipping "/mnt/onboard/.adds" , matches "\.(?!kobo|adobe).*?"
Mar 16 11:45:36 nickel: (   365.797 @ 0x1c0dc78 / ui.debug) void SyncFileSystemCommand::findFilesToParse(const QString&, QStringList&) skipping "/mnt/onboard/.kobo/certificates" , matches "(\.kobo|koboExtStorage)/certificates"
Mar 16 11:45:36 nickel: (   365.798 @ 0x1c0dc78 / ui.debug) void SyncFileSystemCommand::findFilesToParse(const QString&, QStringList&) skipping "/mnt/onboard/.kobo/dict" , matches "(\.kobo|koboExtStorage)/dict"
Mar 16 11:45:36 nickel: (   365.808 @ 0x1c0dc78 / ui.debug) void SyncFileSystemCommand::findFilesToParse(const QString&, QStringList&) skipping "/mnt/onboard/.kobo/kepub" , matches "(\.kobo|koboExtStorage)/kepub"
Mar 16 11:45:36 nickel: (   365.814 @ 0x1c0dc78 / ui.debug) void SyncFileSystemCommand::findFilesToParse(const QString&, QStringList&) skipping "/mnt/onboard/.niluje" , matches "\.(?!kobo|adobe).*?"
Mar 16 11:45:36 nickel: (   365.815 @ 0x1c0dc78 / ui.debug) void SyncFileSystemCommand::findFilesToParse(const QString&, QStringList&) skipping "/mnt/onboard/.Trash-1000" , matches "\.(?!kobo|adobe).*?"
Mar 16 11:45:36 nickel: (   365.960 @ 0x1c0dc78 / ui.debug) Pruning file "file:///mnt/onboard/wpacli_log.txt"
Mar 16 11:45:36 nickel: (   365.960 @ 0x1c0dc78 / ui.debug) Pruning file "file:///mnt/onboard/kubooks/Lackey, Mercedes/Arrow_s Flight - Mercedes Lackey.epub"
Mar 16 11:45:36 nickel: (   365.961 @ 0x1c0dc78 / ui.debug) Pruning file "file://E:/.kobo/guide/userguide.pdf"
Mar 16 11:45:36 nickel: (   365.961 @ 0x1c0dc78 / ui.debug) Pruning file "file:///mnt/onboard/.kobo/guide/userguide.pdf"
Mar 16 11:45:36 nickel: (   365.961 @ 0x1c0dc78 / ui.debug) Pruning file "file:///mnt/onboard/kubooks/Lackey, Mercedes/Arrows of the Queen - Mercedes Lackey.epub"
Mar 16 11:45:36 nickel: (   365.961 @ 0x1c0dc78 / ui.debug) Pruning file "file:///mnt/onboard/kubooks/Lackey, Mercedes/Arrow_s Fall - Mercedes Lackey.epub"
Mar 16 11:45:38 wpa_supplicant[1943]: Successfully initialized wpa_supplicant
Mar 16 11:45:38 wpa_supplicant[1943]: rfkill: Cannot get wiphy information
Mar 16 11:45:38 wpa_supplicant[1943]: ioctl[SIOCSIWESSID]: Resource temporarily unavailable
Mar 16 11:45:38 dbus[571]: [system] Activating service name='name.marples.roy.dhcpcd' (using servicehelper)
Mar 16 11:45:38 dhcpcd[1946]: version 6.6.6 starting
Mar 16 11:45:38 dhcpcd[1946]: eth0: using /sys hwaddr: 70:25:59:e1:7a:79
Mar 16 11:45:38 dhcpcd[1946]: eth0: executing `/libexec/dhcpcd-run-hooks' PREINIT
Mar 16 11:45:38 dhcpcd-dbus: starting dhcpcd-dbus-0.6.0
Mar 16 11:45:38 dhcpcd[1946]: eth0: executing `/libexec/dhcpcd-run-hooks' NOCARRIER
Mar 16 11:45:38 dhcpcd[1946]: no interfaces have a carrier
Mar 16 11:45:38 dhcpcd[1946]: forking to background
Mar 16 11:45:38 dhcpcd[1946]: forked to background, child pid 1958
Mar 16 11:45:38 dhcpcd[1958]: eth0: waiting for carrier
Mar 16 11:45:38 dhcpcd-dbus: connected to dhcpcd-6.6.6
Mar 16 11:45:38 dhcpcd-dbus: retrieved interface eth0 (NOCARRIER)
Mar 16 11:45:38 dhcpcd-dbus: status changed to disconnected
Mar 16 11:45:38 dhcpcd-dbus: no DBus connection to notify of status change
Mar 16 11:45:38 dhcpcd-dbus: connected to wpa_supplicant on interface eth0
Mar 16 11:45:38 dhcpcd-dbus: scan results on interface eth0
Mar 16 11:45:38 dhcpcd-dbus: no DBus connection to notify of status change
Mar 16 11:45:38 dbus[571]: [system] Successfully activated service 'name.marples.roy.dhcpcd'
Mar 16 11:45:38 dhcpcd-dbus: init completed, waiting for events
Mar 16 11:45:38 dhcpcd-dbus: scan results on interface eth0
Mar 16 11:45:38 wpa_supplicant[1944]: eth0: Trying to associate with 64:70:02:98:8a:0d (SSID='p_wireless' freq=2462 MHz)
Mar 16 11:45:38 wpa_supplicant[1944]: Failed to add supported operating classes IE
Mar 16 11:45:39 wpa_supplicant[1944]: eth0: Associated with 64:70:02:98:8a:0d
Mar 16 11:45:39 wpa_supplicant[1944]: eth0: WPA: Key negotiation completed with 64:70:02:98:8a:0d [PTK=CCMP GTK=CCMP]
Mar 16 11:45:39 wpa_supplicant[1944]: eth0: CTRL-EVENT-CONNECTED - Connection to 64:70:02:98:8a:0d completed [id=0 id_str=]
Mar 16 11:45:39 dhcpcd[1958]: eth0: carrier acquired
Mar 16 11:45:39 dhcpcd[1958]: eth0: executing `/libexec/dhcpcd-run-hooks' CARRIER
Mar 16 11:45:39 dhcpcd[1958]: eth0: delaying IPv4 for 0.4 seconds
Mar 16 11:45:39 dhcpcd-dbus: event on interface eth0 (CARRIER)
Mar 16 11:45:39 dhcpcd[1958]: eth0: using ClientID 01:70:25:59:e1:7a:79
Mar 16 11:45:39 dhcpcd[1958]: eth0: reading lease `/var/db/dhcpcd-eth0-p_wireless.lease'
Mar 16 11:45:39 dhcpcd[1958]: eth0: rebinding lease of 192.168.1.194
Mar 16 11:45:39 dhcpcd[1958]: eth0: sending REQUEST (xid 0x39a5978b), next in 4.6 seconds
Mar 16 11:45:39 dhcpcd[1958]: eth0: acknowledged 192.168.1.194 from 192.168.1.1
Mar 16 11:45:39 dhcpcd[1958]: eth0: leased 192.168.1.194 for 43200 seconds
Mar 16 11:45:39 dhcpcd[1958]: eth0: renew in 21600 seconds, rebind in 37800 seconds
Mar 16 11:45:39 dhcpcd[1958]: eth0: writing lease `/var/db/dhcpcd-eth0-p_wireless.lease'
Mar 16 11:45:39 dhcpcd[1958]: eth0: adding IP address 192.168.1.194/24
Mar 16 11:45:39 dhcpcd[1958]: eth0: adding route to 192.168.1.0/24
Mar 16 11:45:39 dhcpcd[1958]: eth0: adding default route via 192.168.1.1
Mar 16 11:45:39 dhcpcd[1958]: eth0: executing `/libexec/dhcpcd-run-hooks' REBOOT
Mar 16 11:45:39 dhcpcd-dbus: event on interface eth0 (REBOOT)
Mar 16 11:45:39 fickel: bool FickelService::Start(const QString&) "eth0"
Mar 16 11:45:39 dhcpcd-dbus: status changed to connected

@shermp
Copy link
Owner

shermp commented Mar 15, 2020

And here's what I got on stdout/stderr

ifconfig: SIOCSIFADDR: No such device
wlarm_le: wl driver adapter not found
ifconfig: SIOCGIFFLAGS: No such device

@NiLuJe
Copy link
Contributor

NiLuJe commented Mar 15, 2020

I'm still on the first 4.20 release, I haven't checked in KU, but it still behaved in KOReader.

Will double-check on the latest 4.20 tomorrow ;).

@shermp
Copy link
Owner

shermp commented Mar 15, 2020

It looks like to me that the wifi drivers/modules haven't been loaded, but I'm not an expert.

The reason I haven't noticed anything until now, is that my Forma is still on FW 4.19, and my H2O had wifi set to forced on in developer mode.

It's when I disabled forced-on wifi that I noticed the issue.

@shermp
Copy link
Owner

shermp commented Mar 15, 2020

Ok, found the problem.

Wifi failed to connect because the sdio_wifi_pwr.ko was never loaded. sdio_wifi_pwr.ko was not loaded because the path to it could not be found. The path could not be found because the PLATFORM variable wasn't set. PLATFORM wasn't set because I hadn't slurped it up in the get_nickel_env function.

Why it ever worked in the first place I'm not sure. In previous firmwares, it must have been one of the environment variables already available. That's the only explanation I can think of.

@shermp
Copy link
Owner

shermp commented Mar 16, 2020

@tmjwid Here's a quick fix for the script in question, if you want to try it.

Simply replace the .adds/kobo-uncaged/scripts/nickel-usbms.sh file with the one attached here (you will have to rename it from .txt) and let me know if that solves your issue.

There's a couple more changes that I want to make for a release version a bit later.

@NiLuJe
Copy link
Contributor

NiLuJe commented Mar 16, 2020

@shermp: That's... strange.

It's definitely exported early by rcS (and as such KFMon). I definitely still have it on my end, and there hasn't been an rcS update in quite a while. :?

┌─(ROOT@(none):pts/0)──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────(/)─┐
└─(0.42:25%:04:33:78%:#)── cat /proc/$(pidof nickel)/environ | tr '\0' '\n'                                                                                                                                                                                                                                                                            ──(Mon, Mar 16)─┘
UBOOT_MMC=/etc/u-boot/mx50-ntx/u-boot.mmc
USER=root
prevlevel=N
LD_LIBRARY_PATH=/usr/local/Kobo
HOME=/
runlevel=S
DBUS_SESSION_BUS_ADDRESS=unix:path=/tmp/dbus-AgbU1SCTWQ,guid=03335ce40b8d7557ec5a5cfc5e67ddfb
NICKEL_HOME=/mnt/onboard/.kobo
UBOOT_RECOVERY=/etc/u-boot/mx50-ntx/u-boot.recovery
boot_port=2
waveform_p=0x8f989800
TERM=vt102
hwcfg_p=0x8ffffe00
WIFI_MODULE=dhd
PLATFORM=mx50-ntx
PATH=/sbin:/bin:/usr/sbin:/usr/bin:/usr/lib:
RUNLEVEL=mx50_1GHz
LANG=en_US.UTF-8
waveform_sz=6776288
WIFI_MODULE_PATH=/drivers/mx50-ntx/wifi/dhd.ko
SHELL=/bin/sh
hwcfg_sz=110
INTERFACE=eth0
PRODUCT=dahlia
PWD=/
LIBC_FATAL_STDERR_=1
┌─(ROOT@(none):pts/0)──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────(/)─┐
└─(0.39:25%:04:33:78%:#)── cat /proc/$(pidof kfmon)/environ | tr '\0' '\n'                                                                                                                                                                                                                                                                             ──(Mon, Mar 16)─┘
USER=root
UBOOT_MMC=/etc/u-boot/mx50-ntx/u-boot.mmc
prevlevel=N
HOME=/
runlevel=S
UBOOT_RECOVERY=/etc/u-boot/mx50-ntx/u-boot.recovery
boot_port=2
TERM=vt102
waveform_p=0x8f989800
hwcfg_p=0x8ffffe00
PLATFORM=mx50-ntx
PATH=/sbin:/bin:/usr/sbin:/usr/bin:/usr/lib:
RUNLEVEL=mx50_1GHz
waveform_sz=6776288
hwcfg_sz=110
SHELL=/bin/sh
PRODUCT=dahlia
PWD=/
LIBC_FATAL_STDERR_=1

EDIT: Yep, still there on 4.20.14622

@shermp
Copy link
Owner

shermp commented Mar 16, 2020

Yeah, it is in /proc/$(pidof nickel)/environ, which is where I get it from in get_nickel_env. And which I was failing to get from it, but it still worked anyway on previous firmwares.

@NiLuJe
Copy link
Contributor

NiLuJe commented Mar 16, 2020

My point being it's also in KFMon's env, as such you shouldn't need to siphon it at all o_O.

It's definitely still there in stuff launched by KFMon: e.g., after NiLuJe/kfmon@11b6641

**** Log dumped on 2020-03-16 @ 05:11:45 ****
**** FW 4.20.14622 on Linux 2.6.35.3-850-gbc67621+ (#3032 PREEMPT Mon Jan 9 13:37:40 CST 2017) ****
**** PRODUCT 'dahlia' on PLATFORM 'mx50-ntx' ****

@shermp
Copy link
Owner

shermp commented Mar 16, 2020

Ahh, that's why it worked. I haven't actually reinstalled KFmon after my H2O so rudely updated itself...

@shermp
Copy link
Owner

shermp commented Mar 16, 2020

So the issue seen by @tmjwid might be something else after all :(

@NiLuJe
Copy link
Contributor

NiLuJe commented Mar 16, 2020

Ah, okay, now it makes sense ;).

Because yeah, it isn't in the env for stuff launched via the udev loop0 trick ;).

e.g., my SSH shell:

SSH_CLIENT=192.168.0.42 47728 22
USER=root
LD_LIBRARY_PATH=/qte/lib:lib:
HOME=/tmp/root
QTDIR=/qte
SSH_TTY=/dev/pts/0
BOOTLOADER=1.1.4 (build Aug 01)
PS1=[\u@\h \W]\$ 
KERNEL=2.6.18 (build Aug 01)
QWS_KEYBOARD=EbrKeyboard:/dev/button
LOGNAME=root
TERM=xterm-256color
PATH=/sbin:/usr/sbin:/bin:/usr/bin
SHELL=/bin/sh
QWS_DISPLAY=EINK
PWD=/
SSH_CONNECTION=192.168.0.42 47728 192.168.0.50 22
QWS_MOUSE_PROTO=TPanel:/dev/ts0
SHLVL=1
OLDPWD=/
ZDOTDIR=/mnt/onboard/.niluje/usbnet/etc/zsh
LESSCOLOR=yes
HOSTTYPE=armv7l
EDITOR=nano
PAGER=less
MANPAGER=less
WORDCHARS=*?_[]~=&;!#$%^(){}
LS_COLORS=no=00:fi=00:di=34:ow=34;40:ln=35:pi=30;44:so=35;44:do=35;44:bd=33;44:cd=37;44:or=05;37;41:mi=05;37;41:ex=01;31:*.cmd=01;31:*.exe=01;31:*.com=01;31:*.bat=01;31:*.reg=01;31:*.app=01;31:*.txt=32:*.org=32:*.md=32:*.mkd=32:*.h=32:*.hpp=32:*.c=32:*.C=32:*.cc=32:*.cpp=32:*.cxx=32:*.objc=32:*.cl=32:*.sh=32:*.bash=32:*.csh=32:*.zsh=32:*.el=32:*.vim=32:*.java=32:*.pl=32:*.pm=32:*.py=32:*.rb=32:*.hs=32:*.php=32:*.htm=32:*.html=32:*.shtml=32:*.erb=32:*.haml=32:*.xml=32:*.rdf=32:*.css=32:*.sass=32:*.scss=32:*.less=32:*.js=32:*.coffee=32:*.man=32:*.0=32:*.1=32:*.2=32:*.3=32:*.4=32:*.5=32:*.6=32:*.7=32:*.8=32:*.9=32:*.l=32:*.n=32:*.p=32:*.pod=32:*.tex=32:*.go=32:*.sql=32:*.csv=32:*.sv=32:*.svh=32:*.v=32:*.vh=32:*.vhd=32:*.bmp=33:*.cgm=33:*.dl=33:*.dvi=33:*.emf=33:*.eps=33:*.gif=33:*.jpeg=33:*.jpg=33:*.JPG=33:*.mng=33:*.pbm=33:*.pcx=33:*.pdf=33:*.pgm=33:*.png=33:*.PNG=33:*.ppm=33:*.pps=33:*.ppsx=33:*.ps=33:*.svg=33:*.svgz=33:*.tga=33:*.tif=33:*.tiff=33:*.xbm=33:*.xcf=33:*.xpm=33:*.xwd=33:*.xwd=33:*.yuv=33:*.nef=33:*.NEF=33:*.aac=33:*.au=33:*.flac=33:*.m4a=33:*.mid=33:*.midi=33:*.mka=33:*.mp3=33:*.mpa=33:*.mpeg=33:*.mpg=33:*.ogg=33:*.opus=33:*.ra=33:*.wav=33:*.anx=33:*.asf=33:*.avi=33:*.axv=33:*.flc=33:*.fli=33:*.flv=33:*.gl=33:*.m2v=33:*.m4v=33:*.mkv=33:*.mov=33:*.MOV=33:*.mp4=33:*.mp4v=33:*.mpeg=33:*.mpg=33:*.nuv=33:*.ogm=33:*.ogv=33:*.ogx=33:*.qt=33:*.rm=33:*.rmvb=33:*.swf=33:*.vob=33:*.webm=33:*.wmv=33:*.doc=31:*.docx=31:*.rtf=31:*.odt=31:*.dot=31:*.dotx=31:*.ott=31:*.xls=31:*.xlsx=31:*.ods=31:*.ots=31:*.ppt=31:*.pptx=31:*.odp=31:*.otp=31:*.fla=31:*.psd=31:*.7z=1;35:*.apk=1;35:*.arj=1;35:*.bin=1;35:*.bz=1;35:*.bz2=1;35:*.cab=1;35:*.deb=1;35:*.dmg=1;35:*.gem=1;35:*.gz=1;35:*.iso=1;35:*.jar=1;35:*.msi=1;35:*.rar=1;35:*.rpm=1;35:*.tar=1;35:*.tbz=1;35:*.tbz2=1;35:*.tgz=1;35:*.tx=1;35:*.war=1;35:*.xpi=1;35:*.xz=1;35:*.z=1;35:*.Z=1;35:*.zip=1;35:*.ANSI-30-black=30:*.ANSI-01;30-brblack=01;30:*.ANSI-31-red=31:*.ANSI-01;31-brred=01;31:*.ANSI-32-green=32:*.ANSI-01;32-brgreen=01;32:*.ANSI-33-yellow=33:*.ANSI-01;33-bryellow=01;33:*.ANSI-34-blue=34:*.ANSI-01;34-brblue=01;34:*.ANSI-35-magenta=35:*.ANSI-01;35-brmagenta=01;35:*.ANSI-36-cyan=36:*.ANSI-01;36-brcyan=01;36:*.ANSI-37-white=37:*.ANSI-01;37-brwhite=01;37:*.log=01;32:*~=01;32:*#=01;32:*.bak=01;33:*.BAK=01;33:*.old=01;33:*.OLD=01;33:*.org_archive=01;33:*.off=01;33:*.OFF=01;33:*.dist=01;33:*.DIST=01;33:*.orig=01;33:*.ORIG=01;33:*.swp=01;33:*.swo=01;33:*,v=01;33:*.gpg=34:*.gpg=34:*.pgp=34:*.asc=34:*.3des=34:*.aes=34:*.enc=34:*.sqlite=34:
_=/usr/bin/env

Man, that LD_LIBRARY_PATH is whack as hell :D.

@shermp
Copy link
Owner

shermp commented Mar 16, 2020

It's a good idea for met to grab 'em anyway, in case KU isn't launched by kfmon, or your SSH.

(Eg, just tried launching KU from telnet on my Forma. It did not go well...)

@NiLuJe
Copy link
Contributor

NiLuJe commented Mar 16, 2020

@shermp: Definitely. Kept biting me on the ass with my USBNet toggle ;).

@shermp
Copy link
Owner

shermp commented Mar 16, 2020

Perhaps back to the original idea of inserting tee in the wpa_cli status to grep pipe to see what info we can get from @tmjwid 's attempts to connect to WiFi.

@shermp
Copy link
Owner

shermp commented Mar 16, 2020

Here's a new, more instrumented nickel-usbms.sh @tmjwid

It logs more wifi stuff to syslog, and logs the output of wpa_cli to a log file in the root of your kobo drive.

nickel-usbms.sh.txt

@tmjwid
Copy link
Author

tmjwid commented Mar 16, 2020

Sorry for lack of communication, I'm from the UK and had an early night. I'll take a look after work (my usb cable is power only and I do not have ssh set up) with the updated bash script. I can also provide a full syslog before and after, but from memory your log @shermp is very similar to mine in terms of network output.

@tmjwid
Copy link
Author

tmjwid commented Mar 16, 2020

Just as a side note, there were wifi changes in this release.

@shermp
Copy link
Owner

shermp commented Mar 16, 2020

No problem, I'm from NZ, so, timezones. I'm used to it.

The new script basically logs more stuff, and adds extra checks. Hopefully we can see exactly where it fails, and why. TBH, those checks and logging should have been there to begin with, but ah well. Basically, the new script should tell us whether the problem is with WPA supplicant, or a problem loading the wifi modules.

As a sidenote, it's a shell script, not a bash script, as the Kobo does not use bash as its shell, but rather ash (I think, it's whatever BusyBox uses anyway). Any script with bash specific features likely won't work.

@tmjwid
Copy link
Author

tmjwid commented Mar 16, 2020

Sounds good, I know that logging verbosity and exception tracking is a fine art.

Haha old habits die hard! I'll hopefully call them shell scripts one day but living in gnu land teaches bad habits.

@tmjwid
Copy link
Author

tmjwid commented Mar 16, 2020

Latest syslog from update shell script:

Mar 16 19:03:44 syslogd started: BusyBox v1.22.0.kobo
Mar 16 19:03:44 nickel: (     0.761 @ 0x14d62f0) FT_New_Face failed with index 0 : 0 
Mar 16 19:03:45 nickel: (     1.231 @ 0x14d62f0) FT_New_Face failed with index 0 : 0 
Mar 16 19:03:46 nickel: (     2.192 @ 0x14d62f0) loadPlugin: loaded plugin for QFontEngine
Mar 16 19:03:46 nickel: (     2.231 @ 0x14d62f0) loadPlugin: loaded plugin for QRawFont
Mar 16 19:03:46 nickel: (     2.232 @ 0x14d62f0) Loading iType.. true 
Mar 16 19:03:46 nickel: (     2.380 @ 0x14d62f0) loadPlugin: loaded plugin for QRasterPaintEngine
Mar 16 19:03:46 nickel: (     2.400 @ 0x14d62f0 / ui.warning) "4.20.14622 (8bb853a72a, 3/13/20)" 
Mar 16 19:03:46 nickel: (     2.402 @ 0x14d62f0 / ui.debug) Periodic sync scheduled for "00:52:08" 
Mar 16 19:03:53 nickel: (     9.338 @ 0x14d62f0 / powermanager.warning) total time spent asleep: 0 
Mar 16 19:03:53 nickel: (     9.342 @ 0x14d62f0 / powermanager.warning) total time spent awake: 0 
Mar 16 19:04:14 nickel: (    11.928 @ 0x14d62f0) QObject::disconnect: Unexpected null parameter
Mar 16 19:04:14 nickel: (    11.929 @ 0x14d62f0 / ui.warning) cancelled before full sync has started 
Mar 16 19:05:08 nickel: (    66.094 @ 0x14d62f0) FT_New_Face failed with index 0 : 0 
Mar 16 19:05:08 nickel: (    66.100 @ 0x14d62f0) FT_New_Face failed with index 0 : 0 
Mar 16 19:05:10 nickel: (    67.940 @ 0x19c1848 / ui.debug) void SyncFileSystemCommand::findFilesToParse(const QString&, QStringList&) skipping "/mnt/onboard/.kobo/certificates" , matches "(\.kobo|koboExtStorage)/certificates" 
Mar 16 19:05:10 nickel: (    67.940 @ 0x19c1848 / ui.debug) void SyncFileSystemCommand::findFilesToParse(const QString&, QStringList&) skipping "/mnt/onboard/.kobo/dict" , matches "(\.kobo|koboExtStorage)/dict" 
Mar 16 19:05:10 nickel: (    67.957 @ 0x19c1848 / ui.debug) void SyncFileSystemCommand::findFilesToParse(const QString&, QStringList&) skipping "/mnt/onboard/.kobo/kepub" , matches "(\.kobo|koboExtStorage)/kepub" 
Mar 16 19:05:10 nickel: (    68.072 @ 0x19c1848 / ui.debug) Pruning file "file:///mnt/onboard/Unknown/how-south-korea-is-composting-its-way-to-sustainability - Unknown.kepub.epub" 
Mar 16 19:05:10 nickel: (    68.072 @ 0x19c1848 / ui.debug) Pruning file "file:///mnt/onboard/icons/plato.png" 
Mar 16 19:05:10 nickel: (    68.073 @ 0x19c1848 / ui.debug) Pruning file "file:///mnt/onboard/Dick, Philip K_/Second Variety - Philip K. Dick.epub" 
Mar 16 19:05:10 nickel: (    68.073 @ 0x19c1848 / ui.debug) Pruning file "file:///mnt/onboard/Unknown/fairytail vol1 - Unknown.cbz" 
Mar 16 19:05:10 nickel: (    68.073 @ 0x19c1848 / ui.debug) Pruning file "file:///mnt/onboard/Gregory, Daryl/We Are All Completely Fine - Daryl Gregory.kepub.epub" 
Mar 16 19:05:10 nickel: (    68.073 @ 0x19c1848 / ui.debug) Pruning file "file:///mnt/onboard/.kobo/guide/userguide.pdf" 
Mar 16 19:05:10 nickel: (    68.074 @ 0x19c1848 / ui.debug) Pruning file "file:///mnt/onboard/Robinson, Andrew J_/Stitch in Time, A - Andrew J. Robinson.kepub.epub" 
Mar 16 19:05:10 nickel: (    68.074 @ 0x19c1848 / ui.debug) Pruning file "file:///mnt/onboard/koreader.png" 
Mar 16 19:05:10 nickel: (    68.074 @ 0x19c1848 / ui.debug) Pruning file "file:///mnt/onboard/KoboUncaged-v0.4.1-full/Kobo-UNCaGED.png" 
Mar 16 19:05:10 nickel: (    68.074 @ 0x19c1848 / ui.debug) Pruning file "file:///mnt/onboard/Kobo-UNCaGED.png" 
Mar 16 19:05:10 nickel: (    68.074 @ 0x19c1848 / ui.debug) Pruning file "file:///mnt/onboard/kfmon.png" 
Mar 16 19:05:14 nickel: (    71.937 @ 0x14d62f0) QObject::connect: No such slot ComicsReader::onResume()
Mar 16 19:05:14 nickel: (    71.938 @ 0x14d62f0) QObject::connect: No such slot ComicsReader::endPreview()
Mar 16 19:05:14 nickel: (    71.938 @ 0x14d62f0) QObject::connect:  (sender name:   'ReadingView')
Mar 16 19:05:14 nickel: (    71.939 @ 0x14d62f0) QObject::connect: No such slot ComicsReader::unload()
Mar 16 19:05:14 nickel: (    71.939 @ 0x14d62f0) QObject::connect:  (sender name:   'ReadingView')
Mar 16 19:05:14 nickel: (    71.940 @ 0x14d62f0) QObject::connect: No such slot ComicsReader::updateFooter()
Mar 16 19:05:14 nickel: (    71.940 @ 0x14d62f0) QObject::connect:  (sender name:   'ReadingView')
Mar 16 19:05:14 nickel: (    71.940 @ 0x14d62f0) QObject::connect: No such signal ComicsReader::previewEnd()
Mar 16 19:05:14 nickel: (    71.941 @ 0x14d62f0) QObject::connect:  (receiver name: 'ReadingView')
Mar 16 19:05:14 nickel: (    71.941 @ 0x14d62f0) QObject::connect: No such signal ComicsReader::lastChapter()
Mar 16 19:05:14 nickel: (    71.941 @ 0x14d62f0) QObject::connect:  (receiver name: 'ReadingView')
Mar 16 19:05:14 nickel: (    71.942 @ 0x14d62f0) QObject::connect: No such signal ComicsReader::totalPagesSet(int)
Mar 16 19:05:14 nickel: (    71.942 @ 0x14d62f0) QObject::connect:  (receiver name: 'ReadingView')
Mar 16 19:05:14 nickel: (    71.942 @ 0x14d62f0) QObject::connect: No such slot ComicsReader::calculateReadProgress()
Mar 16 19:05:14 nickel: (    71.942 @ 0x14d62f0) QObject::connect:  (sender name:   'ReadingView')
Mar 16 19:05:14 nickel: (    71.943 @ 0x14d62f0) QObject::connect: No such slot ComicsReader::calculateMergedTOCAndSpineIndex(int*)
Mar 16 19:05:14 nickel: (    71.943 @ 0x14d62f0) QObject::connect:  (sender name:   'ReadingView')
Mar 16 19:05:14 nickel: (    71.943 @ 0x14d62f0) QObject::connect: No such slot ComicsReader::calculateCurrentChapterCurrentPage(int*)
Mar 16 19:05:14 nickel: (    71.944 @ 0x14d62f0) QObject::connect:  (sender name:   'ReadingView')
Mar 16 19:05:14 nickel: (    71.944 @ 0x14d62f0) QObject::connect: No such slot ComicsReader::calculateCurrentChapterTotalPages(int*)
Mar 16 19:05:14 nickel: (    71.944 @ 0x14d62f0) QObject::connect:  (sender name:   'ReadingView')
Mar 16 19:05:14 nickel: (    71.945 @ 0x14d62f0) QObject::connect: No such slot ComicsReader::calculatePagesForChapter(const Shortcover&, int*)
Mar 16 19:05:14 nickel: (    71.945 @ 0x14d62f0) QObject::connect:  (sender name:   'ReadingView')
Mar 16 19:05:14 nickel: (    71.945 @ 0x14d62f0) QObject::connect: No such signal ComicsReader::closeFooterMenu()
Mar 16 19:05:14 nickel: (    71.945 @ 0x14d62f0) QObject::connect:  (receiver name: 'ReadingView')
Mar 16 19:05:14 nickel: (    71.946 @ 0x14d62f0) QObject::connect: No such signal ComicsReader::processDrag(DragGesture *)
Mar 16 19:05:14 nickel: (    71.946 @ 0x14d62f0) QObject::connect:  (receiver name: 'ReadingView')
Mar 16 19:05:14 nickel: (    71.947 @ 0x14d62f0) QObject::connect: No such signal ComicsReader::processPinch(PinchGesture *)
Mar 16 19:05:14 nickel: (    71.947 @ 0x14d62f0) QObject::connect:  (receiver name: 'ReadingView')
Mar 16 19:05:14 nickel: (    71.947 @ 0x14d62f0) QObject::connect: No such signal ComicsReader::propertiesUpdated()
Mar 16 19:05:14 nickel: (    71.947 @ 0x14d62f0) QObject::connect:  (receiver name: 'ReadingView')
Mar 16 19:05:14 nickel: (    71.948 @ 0x14d62f0) QObject::connect: No such signal ComicsReader::navigateToURL(const QUrl &)
Mar 16 19:05:14 nickel: (    71.948 @ 0x14d62f0) QObject::connect:  (receiver name: 'ReadingView')
Mar 16 19:05:14 nickel: (    71.948 @ 0x14d62f0) QObject::connect: No such slot ComicsReader::footerMenuClosed()
Mar 16 19:05:14 nickel: (    71.949 @ 0x14d62f0) QObject::connect:  (sender name:   'ReadingView')
Mar 16 19:05:14 nickel: (    71.949 @ 0x14d62f0) QObject::connect: No such slot ComicsReader::saveImageNote(QWidget*)
Mar 16 19:05:14 nickel: (    71.949 @ 0x14d62f0) QObject::connect:  (sender name:   'ReadingView')
Mar 16 19:05:14 nickel: (    71.949 @ 0x14d62f0) QObject::connect: No such slot ComicsReader::checkImageNote(Bookmark*)
Mar 16 19:05:14 nickel: (    71.950 @ 0x14d62f0) QObject::connect:  (sender name:   'ReadingView')
Mar 16 19:05:14 nickel: (    71.950 @ 0x14d62f0) QObject::connect: No such signal ComicsReader::imageNotesChanged()
Mar 16 19:05:14 nickel: (    71.950 @ 0x14d62f0) QObject::connect:  (receiver name: 'ReadingView')
Mar 16 19:05:14 nickel: (    71.951 @ 0x14d62f0) QObject::connect: No such slot ComicsReader::onAnnotationChanged(const Bookmark&)
Mar 16 19:05:14 nickel: (    71.951 @ 0x14d62f0) QObject::connect:  (sender name:   'ReadingView')
Mar 16 19:05:14 nickel: (    71.951 @ 0x14d62f0) QObject::connect: No such slot ComicsReader::onAnnotationRemoved(const Bookmark&)
Mar 16 19:05:14 nickel: (    71.951 @ 0x14d62f0) QObject::connect:  (sender name:   'ReadingView')
Mar 16 19:05:14 nickel: (    71.952 @ 0x14d62f0) QObject::connect: No such slot ComicsReader::refreshBookmarks()
Mar 16 19:05:14 nickel: (    71.952 @ 0x14d62f0) QObject::connect:  (sender name:   'ReadingView')
Mar 16 19:05:14 nickel: (    71.952 @ 0x14d62f0) QObject::connect: No such slot ComicsReader::highlightSearchResult(const Bookmark&)
Mar 16 19:05:14 nickel: (    71.952 @ 0x14d62f0) QObject::connect:  (sender name:   'ReadingView')
Mar 16 19:05:14 nickel: (    71.953 @ 0x14d62f0) QObject::connect: No such slot ComicsReader::unhighlightSearchResults()
Mar 16 19:05:14 nickel: (    71.953 @ 0x14d62f0) QObject::connect:  (sender name:   'ReadingView')
Mar 16 19:05:14 UNCaGED: Entering USBMS mode...
Mar 16 19:05:14 UNCaGED: Inserting USB
Mar 16 19:05:15 UNCaGED: Scanning for Button
Mar 16 19:05:15 nickel: (    73.630 @ 0x14d62f0) QObject::disconnect: Unexpected null parameter
Mar 16 19:05:15 nickel: (    73.630 @ 0x14d62f0 / ui.warning) cancelled before full sync has started 
Mar 16 19:05:16 nickel: (    74.051 @ 0x14d62f0 / performance.warning) static void QObjectUtil::repolishChildren(QWidget*, Qt::FindChildOptions, int) "statusbarContainer" repolish took 16 
Mar 16 19:05:21 UNCaGED: Mounting onboard
Mar 16 19:05:22 UNCaGED: Mounting SD card
Mar 16 19:05:22 UNCaGED: Enabling WiFi
Mar 16 19:05:22 UNCaGED: PLATFORM is mx6sl-ntx
Mar 16 19:05:22 UNCaGED: WIFI_MODULE is dhd
Mar 16 19:05:22 UNCaGED: WIFI_MODULE_PATH is /drivers/mx6sl-ntx/wifi/dhd.ko
Mar 16 19:05:22 UNCaGED: sdio_wifi_pwr killed
Mar 16 19:05:24 wpa_supplicant[1370]: Successfully initialized wpa_supplicant
Mar 16 19:05:24 wpa_supplicant[1370]: rfkill: Cannot get wiphy information
Mar 16 19:05:30 UNCaGED: wpa_supplicant failed to connect
Mar 16 19:05:30 wpa_supplicant[1371]: eth0: CTRL-EVENT-TERMINATING 
Mar 16 19:05:31 UNCaGED: WiFi did not enable (1). Aborting!
Mar 16 19:05:35 nickel: (    93.274 @ 0x1708348 / ui.debug) void SyncFileSystemCommand::findFilesToParse(const QString&, QStringList&) skipping "/mnt/onboard/.kobo/certificates" , matches "(\.kobo|koboExtStorage)/certificates" 
Mar 16 19:05:35 nickel: (    93.275 @ 0x1708348 / ui.debug) void SyncFileSystemCommand::findFilesToParse(const QString&, QStringList&) skipping "/mnt/onboard/.kobo/dict" , matches "(\.kobo|koboExtStorage)/dict" 
Mar 16 19:05:35 nickel: (    93.297 @ 0x1708348 / ui.debug) void SyncFileSystemCommand::findFilesToParse(const QString&, QStringList&) skipping "/mnt/onboard/.kobo/kepub" , matches "(\.kobo|koboExtStorage)/kepub" 
Mar 16 19:05:35 nickel: (    93.420 @ 0x1708348 / ui.debug) Pruning file "file:///mnt/onboard/Unknown/how-south-korea-is-composting-its-way-to-sustainability - Unknown.kepub.epub" 
Mar 16 19:05:35 nickel: (    93.420 @ 0x1708348 / ui.debug) Pruning file "file:///mnt/onboard/icons/plato.png" 
Mar 16 19:05:35 nickel: (    93.420 @ 0x1708348 / ui.debug) Pruning file "file:///mnt/onboard/Dick, Philip K_/Second Variety - Philip K. Dick.epub" 
Mar 16 19:05:35 nickel: (    93.420 @ 0x1708348 / ui.debug) Pruning file "file:///mnt/onboard/Unknown/fairytail vol1 - Unknown.cbz" 
Mar 16 19:05:35 nickel: (    93.421 @ 0x1708348 / ui.debug) Pruning file "file:///mnt/onboard/Gregory, Daryl/We Are All Completely Fine - Daryl Gregory.kepub.epub" 
Mar 16 19:05:35 nickel: (    93.421 @ 0x1708348 / ui.debug) Pruning file "file:///mnt/onboard/.kobo/guide/userguide.pdf" 
Mar 16 19:05:35 nickel: (    93.421 @ 0x1708348 / ui.debug) Pruning file "file:///mnt/onboard/Robinson, Andrew J_/Stitch in Time, A - Andrew J. Robinson.kepub.epub" 
Mar 16 19:05:35 nickel: (    93.421 @ 0x1708348 / ui.debug) Pruning file "file:///mnt/onboard/koreader.png" 
Mar 16 19:05:35 nickel: (    93.421 @ 0x1708348 / ui.debug) Pruning file "file:///mnt/onboard/KoboUncaged-v0.4.1-full/Kobo-UNCaGED.png" 
Mar 16 19:05:35 nickel: (    93.422 @ 0x1708348 / ui.debug) Pruning file "file:///mnt/onboard/Kobo-UNCaGED.png" 
Mar 16 19:05:35 nickel: (    93.422 @ 0x1708348 / ui.debug) Pruning file "file:///mnt/onboard/kfmon.png" 
Mar 16 19:05:47 nickel: (   104.076 @ 0x14d62f0) QObject::disconnect: Unexpected null parameter
Mar 16 19:05:47 nickel: (   104.077 @ 0x14d62f0 / ui.warning) cancelled before full sync has started 

@shermp
Copy link
Owner

shermp commented Mar 16, 2020

Ok, that log tells me the wifi module loaded ok.

Is there anything in the wpacli_log.txt file that should have written to the root (/mnt/onboard) of your kobo?

@tmjwid
Copy link
Author

tmjwid commented Mar 16, 2020

Just a bunch of Scanning and Disconnected states followed by my mac address for the device and a uuid. Nothing else.

@shermp
Copy link
Owner

shermp commented Mar 16, 2020

So in other words, wpa_supplicant never connected, and it doesn't tells us much useful :(

@shermp
Copy link
Owner

shermp commented Mar 17, 2020

Ok, it's possible to get a lot more logging out of wpa_supplicant, and might be easier to try that before an strace.

In the nickel-usbms.sh file, at line 155: wpa_supplicant -D wext -s -i "${INTERFACE}" ... , add -dd after wpa_supplicant.

The line should then read:
wpa_supplicant -dd -D wext -s -i "${INTERFACE}" -O /var/run/wpa_supplicant -c /etc/wpa_supplicant/wpa_supplicant.conf -B

That spits out a LOT more detail in the syslog.

(EDIT: and by a lot, I mean over 250 lines a lot... perhaps trying with -d instead of -dd might be sufficient)

@shermp
Copy link
Owner

shermp commented Mar 17, 2020

And actually, I doubt running an strace on wpa_cli will reveal much. It is just a tool to configure and obtain the status of a running wpa_supplicant instance. The only thing my script uses it for is a check to see whether wpa_supplicant is in a connected state or not.

As a sidenote, and I hate being that guy, but have your restarted your Kobo?

@tmjwid
Copy link
Author

tmjwid commented Mar 17, 2020

I have "powered off" my Kobo multiple times since I did the installation. I have not performed a factory reset though. I can try that if you think it'll help? The device had no evidence of it being previously modified and it came to me in a factory reset state.

@shermp
Copy link
Owner

shermp commented Mar 17, 2020

I figured you probably had, but just thought I'd double check. It's surprising how many unexplained issues can be resolved by a reboot :)

I might suggest a factory reset as a last resort if we can't figure it out, but it sounds like it probably won't help :(

@tmjwid
Copy link
Author

tmjwid commented Mar 17, 2020

Aye, shame it didn't work this time.

I'll modify the debug logging verbosity on wpa_supplication and get back to you today.

@NiLuJe
Copy link
Contributor

NiLuJe commented Mar 17, 2020

Sidebar: I also have a standalone strace binary available here if you don't want to bother with the whole shebang ;).

@tmjwid
Copy link
Author

tmjwid commented Mar 17, 2020

Adding -d didn't really add any extra output to the logs, so will try -dd in a second. I have got it to work though via a workaround. Turning on "force wifi on" in devmode makes it work.

@shermp
Copy link
Owner

shermp commented Mar 17, 2020

Yeah, forcing Wifi works via dev mode works, but a PITA for long term use. If you forget to disable it, bye bye battery!

@NiLuJe
Copy link
Contributor

NiLuJe commented Mar 17, 2020

Hmm, scan timeout on a Glo HD? That extremely vaguely rings a bell.

@shermp: A retry might be necessary to work around this, IIRC.

@tmjwid
Copy link
Author

tmjwid commented Mar 17, 2020

Yeah it's not really a great workaround.
Here's a log entry

Mar 17 19:03:10 UNCaGED: Entering USBMS mode...
Mar 17 19:03:10 UNCaGED: Inserting USB
Mar 17 19:03:10 UNCaGED: Scanning for Button
Mar 17 19:03:11 nickel: (  1415.461 @ 0x14d62f0) QObject::disconnect: Unexpected null parameter
Mar 17 19:03:11 nickel: (  1415.461 @ 0x14d62f0 / ui.warning) cancelled before full sync has started 
Mar 17 19:03:12 fickel: bool FickelService::Stop() "eth0" 
Mar 17 19:03:12 dhcpcd[4345]: received signal TERM from PID 4422, stopping
Mar 17 19:03:12 dhcpcd[4345]: eth0: removing interface
Mar 17 19:03:12 dhcpcd[4345]: eth0: executing `/libexec/dhcpcd-run-hooks' STOPPED
Mar 17 19:03:12 dhcpcd[4345]: exited
Mar 17 19:03:12 dhcpcd-dbus: lost connection to dhcpcd
Mar 17 19:03:12 dhcpcd-dbus: status changed to down
Mar 17 19:03:12 dhcpcd-dbus: status changed to down
Mar 17 19:03:12 wpa_supplicant[4334]: eth0: CTRL-EVENT-DISCONNECTED bssid=14:d6:4d:ca:4e:ca reason=3 locally_generated=1
Mar 17 19:03:12 wpa_supplicant[4334]: eth0: CTRL-EVENT-TERMINATING 
Mar 17 19:03:12 dhcpcd-dbus: lost connection to wpa_supplicant on interface eth0
Mar 17 19:03:16 UNCaGED: Mounting onboard
Mar 17 19:03:17 UNCaGED: Mounting SD card
Mar 17 19:03:17 UNCaGED: Enabling WiFi
Mar 17 19:03:18 UNCaGED: PLATFORM is mx6sl-ntx
Mar 17 19:03:18 UNCaGED: WIFI_MODULE is dhd
Mar 17 19:03:18 UNCaGED: WIFI_MODULE_PATH is /drivers/mx6sl-ntx/wifi/dhd.ko
Mar 17 19:03:18 UNCaGED: sdio_wifi_pwr killed
Mar 17 19:03:20 wpa_supplicant[4554]: wpa_supplicant v2.7-devel-hostap_2_6-1294-g37b21a1df+
Mar 17 19:03:20 wpa_supplicant[4554]: random: Trying to read entropy from /dev/random
Mar 17 19:03:20 wpa_supplicant[4554]: Successfully initialized wpa_supplicant
Mar 17 19:03:20 wpa_supplicant[4554]: Override interface parameter: ctrl_interface ('(null)' -> '/var/run/wpa_supplicant')
Mar 17 19:03:20 wpa_supplicant[4554]: Initializing interface 'eth0' conf '/etc/wpa_supplicant/wpa_supplicant.conf' driver 'wext' ctrl_interface '/var/run/wpa_supplicant' bridge 'N/A'
Mar 17 19:03:20 wpa_supplicant[4554]: Configuration file '/etc/wpa_supplicant/wpa_supplicant.conf' -> '/etc/wpa_supplicant/wpa_supplicant.conf'
Mar 17 19:03:20 wpa_supplicant[4554]: Reading configuration file '/etc/wpa_supplicant/wpa_supplicant.conf'
Mar 17 19:03:20 wpa_supplicant[4554]: ctrl_interface='/var/run/wpa_supplicant'
Mar 17 19:03:20 wpa_supplicant[4554]: update_config=1
Mar 17 19:03:20 wpa_supplicant[4554]: Priority group 0
Mar 17 19:03:20 wpa_supplicant[4554]:    id=0 ssid='hi there'
Mar 17 19:03:20 wpa_supplicant[4554]:    id=1 ssid='xxx'
Mar 17 19:03:20 wpa_supplicant[4554]: rfkill: Cannot get wiphy information
Mar 17 19:03:20 wpa_supplicant[4554]: WEXT: RFKILL status not available
Mar 17 19:03:20 wpa_supplicant[4554]: SIOCGIWRANGE: WE(compiled)=22 WE(source)=19 enc_capa=0xf
Mar 17 19:03:20 wpa_supplicant[4554]:   capabilities: key_mgmt 0xf enc 0x1f flags 0x0
Mar 17 19:03:20 wpa_supplicant[4554]: netlink: Operstate: ifindex=17 linkmode=1 (userspace-control), operstate=5 (IF_OPER_DORMANT)
Mar 17 19:03:20 wpa_supplicant[4554]: Add interface eth0 to a new radio N/A
Mar 17 19:03:20 wpa_supplicant[4554]: eth0: Own MAC address: 78:45:61:3a:e6:21
Mar 17 19:03:20 wpa_supplicant[4554]: wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
Mar 17 19:03:20 wpa_supplicant[4554]: wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0
Mar 17 19:03:20 wpa_supplicant[4554]: wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0
Mar 17 19:03:20 wpa_supplicant[4554]: wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0
Mar 17 19:03:20 wpa_supplicant[4554]: wpa_driver_wext_set_key: alg=0 key_idx=4 set_tx=0 seq_len=0 key_len=0
Mar 17 19:03:20 wpa_supplicant[4554]: wpa_driver_wext_set_key: alg=0 key_idx=5 set_tx=0 seq_len=0 key_len=0
Mar 17 19:03:20 wpa_supplicant[4554]: wpa_driver_wext_set_countermeasures
Mar 17 19:03:20 wpa_supplicant[4554]: eth0: RSN: flushing PMKID list in the driver
Mar 17 19:03:20 wpa_supplicant[4554]: eth0: Setting scan request: 0.100000 sec
Mar 17 19:03:20 wpa_supplicant[4554]: eth0: WPS: UUID based on MAC address: 372b83b7-2c2b-591a-8ccc-a79089ea852c
Mar 17 19:03:20 wpa_supplicant[4554]: EAPOL: SUPP_PAE entering state DISCONNECTED
Mar 17 19:03:20 wpa_supplicant[4554]: EAPOL: Supplicant port status: Unauthorized
Mar 17 19:03:20 wpa_supplicant[4554]: EAPOL: KEY_RX entering state NO_KEY_RECEIVE
Mar 17 19:03:20 wpa_supplicant[4554]: EAPOL: SUPP_BE entering state INITIALIZE
Mar 17 19:03:20 wpa_supplicant[4554]: EAP: EAP entering state DISABLED
Mar 17 19:03:20 wpa_supplicant[4554]: eth0: Added interface eth0
Mar 17 19:03:20 wpa_supplicant[4554]: eth0: State: DISCONNECTED -> DISCONNECTED
Mar 17 19:03:20 wpa_supplicant[4554]: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
Mar 17 19:03:20 wpa_supplicant[4554]: netlink: Operstate: ifindex=17 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
Mar 17 19:03:20 wpa_supplicant[4554]: Daemonize..
Mar 17 19:03:20 wpa_supplicant[4555]: random: Got 20/20 bytes from /dev/random
Mar 17 19:03:20 wpa_supplicant[4555]: RTM_NEWLINK: operstate=0 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
Mar 17 19:03:20 wpa_supplicant[4555]: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
Mar 17 19:03:20 wpa_supplicant[4555]: WEXT: if_removed already cleared - ignore event
Mar 17 19:03:20 wpa_supplicant[4555]: Wireless event: cmd=0x8b06 len=8
Mar 17 19:03:20 wpa_supplicant[4555]: RTM_NEWLINK: operstate=0 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
Mar 17 19:03:20 wpa_supplicant[4555]: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
Mar 17 19:03:20 wpa_supplicant[4555]: WEXT: if_removed already cleared - ignore event
Mar 17 19:03:20 wpa_supplicant[4555]: Wireless event: cmd=0x8b1a len=40
Mar 17 19:03:20 wpa_supplicant[4555]: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
Mar 17 19:03:20 wpa_supplicant[4555]: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
Mar 17 19:03:20 wpa_supplicant[4555]: WEXT: if_removed already cleared - ignore event
Mar 17 19:03:20 wpa_supplicant[4555]: EAPOL: EAP Session-Id not available
Mar 17 19:03:20 wpa_supplicant[4555]: eth0: State: DISCONNECTED -> SCANNING
Mar 17 19:03:20 wpa_supplicant[4555]: eth0: Starting AP scan for wildcard SSID
Mar 17 19:03:20 wpa_supplicant[4555]: eth0: Add radio work 'scan'@0xcbf60
Mar 17 19:03:20 wpa_supplicant[4555]: eth0: First radio work item in the queue - schedule start immediately
Mar 17 19:03:20 wpa_supplicant[4555]: eth0: Starting radio work 'scan'@0xcbf60 after 0.000052 second wait
Mar 17 19:03:20 wpa_supplicant[4555]: Scan requested (ret=0) - scan timeout 10 seconds
Mar 17 19:03:20 wpa_supplicant[4555]: EAPOL: EAP Session-Id not available
Mar 17 19:03:21 wpa_supplicant[4555]: EAPOL: EAP Session-Id not available
Mar 17 19:03:21 wpa_supplicant[4555]: EAPOL: EAP Session-Id not available
Mar 17 19:03:21 wpa_supplicant[4555]: EAPOL: disable timer tick
Mar 17 19:03:21 wpa_supplicant[4555]: EAPOL: EAP Session-Id not available
Mar 17 19:03:21 wpa_supplicant[4555]: EAPOL: EAP Session-Id not available
Mar 17 19:03:22 wpa_supplicant[4555]: EAPOL: EAP Session-Id not available
Mar 17 19:03:22 wpa_supplicant[4555]: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
Mar 17 19:03:22 wpa_supplicant[4555]: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
Mar 17 19:03:22 wpa_supplicant[4555]: WEXT: if_removed already cleared - ignore event
Mar 17 19:03:22 wpa_supplicant[4555]: Wireless event: cmd=0x8c02 len=29
Mar 17 19:03:22 wpa_supplicant[4555]: EAPOL: EAP Session-Id not available
Mar 17 19:03:22 wpa_supplicant[4555]: EAPOL: EAP Session-Id not available
Mar 17 19:03:23 wpa_supplicant[4555]: EAPOL: EAP Session-Id not available
Mar 17 19:03:23 wpa_supplicant[4555]: EAPOL: EAP Session-Id not available
Mar 17 19:03:23 wpa_supplicant[4555]: EAPOL: EAP Session-Id not available
Mar 17 19:03:23 wpa_supplicant[4555]: EAPOL: EAP Session-Id not available
Mar 17 19:03:24 wpa_supplicant[4555]: EAPOL: EAP Session-Id not available
Mar 17 19:03:24 wpa_supplicant[4555]: EAPOL: EAP Session-Id not available
Mar 17 19:03:24 wpa_supplicant[4555]: EAPOL: EAP Session-Id not available
Mar 17 19:03:24 wpa_supplicant[4555]: EAPOL: EAP Session-Id not available
Mar 17 19:03:25 wpa_supplicant[4555]: EAPOL: EAP Session-Id not available
Mar 17 19:03:25 wpa_supplicant[4555]: EAPOL: EAP Session-Id not available
Mar 17 19:03:25 wpa_supplicant[4555]: EAPOL: EAP Session-Id not available
Mar 17 19:03:26 wpa_supplicant[4555]: EAPOL: EAP Session-Id not available
Mar 17 19:03:26 UNCaGED: wpa_supplicant failed to connect
Mar 17 19:03:26 wpa_supplicant[4555]: eth0: Removing interface eth0
Mar 17 19:03:26 wpa_supplicant[4555]: eth0: Request to deauthenticate - bssid=00:00:00:00:00:00 pending_bssid=00:00:00:00:00:00 reason=3 state=SCANNING
Mar 17 19:03:26 wpa_supplicant[4555]: eth0: State: SCANNING -> DISCONNECTED
Mar 17 19:03:26 wpa_supplicant[4555]: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
Mar 17 19:03:26 wpa_supplicant[4555]: netlink: Operstate: ifindex=17 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
Mar 17 19:03:26 wpa_supplicant[4555]: EAPOL: External notification - portEnabled=0
Mar 17 19:03:26 wpa_supplicant[4555]: EAPOL: External notification - portValid=0
Mar 17 19:03:26 wpa_supplicant[4555]: wpa_driver_wext_set_countermeasures
Mar 17 19:03:26 wpa_supplicant[4555]: eth0: WPA: Clear old PMK and PTK
Mar 17 19:03:26 wpa_supplicant[4555]: eth0: Cancelling scan request
Mar 17 19:03:26 wpa_supplicant[4555]: eth0: Cancelling authentication timeout
Mar 17 19:03:26 wpa_supplicant[4555]: Remove interface eth0 from radio 
Mar 17 19:03:26 wpa_supplicant[4555]: eth0: Remove radio work 'scan'@0xcbf60 (started)
Mar 17 19:03:26 wpa_supplicant[4555]: eth0: radio_work_free('scan'@0xcbf60: num_active_works --> 0
Mar 17 19:03:26 wpa_supplicant[4555]: Remove radio 
Mar 17 19:03:26 wpa_supplicant[4555]: netlink: Operstate: ifindex=17 linkmode=0 (kernel-control), operstate=6 (IF_OPER_UP)
Mar 17 19:03:26 wpa_supplicant[4555]: eth0: CTRL-EVENT-TERMINATING 
Mar 17 19:03:26 UNCaGED: WiFi did not enable (1). Aborting!

@tmjwid
Copy link
Author

tmjwid commented Mar 17, 2020

Sorry, delete the comment as it had personally identifiable info in there.

@NiLuJe
Copy link
Contributor

NiLuJe commented Mar 17, 2020

Yeah, I knew that sounded familiar: koreader/koreader#4387

Might not be the exact same issue, but it sure sounds similar ;).

@shermp
Copy link
Owner

shermp commented Mar 17, 2020

If it's a wifi timeout, could always try changing

while ! wpa_cli status | tee -a "${MNT_ONBOARD_NEW}/wpacli_log.txt" | grep -q "wpa_state=COMPLETED"; do
        # If wpa_supplicant hasn't connected within 5 seconds, we couldn't connect to the Wifi network
        if [ ${WIFI_TIMEOUT} -ge 20 ]; then
            logmsg "E" "wpa_supplicant failed to connect"
            # Disable the Wifi stuff we have enabled before exiting...
            disable_wifi
            return 1
        fi
        usleep 250000
        WIFI_TIMEOUT=$(( WIFI_TIMEOUT + 1 ))
    done

by changing the if [ ${WIFI_TIMEOUT} -ge 20 ] to if [ ${WIFI_TIMEOUT} -ge 40 ], although I would have thought 5 seconds would have been enough,

@tmjwid
Copy link
Author

tmjwid commented Mar 17, 2020

40 didn't work, but 100 did.

@shermp
Copy link
Owner

shermp commented Mar 17, 2020

25 seconds!!!!! Really?

@tmjwid
Copy link
Author

tmjwid commented Mar 17, 2020

I just put a really high timeout to be 100% sure this was the issue, it was. Will test smaller values now.

@shermp
Copy link
Owner

shermp commented Mar 17, 2020

Something must be very weird with the Glo HD.

On my H2O, wpa_supplicant receives scan results in under a second:

Mar 18 08:59:39 wpa_supplicant[2424]: eth0: Event SCAN_RESULTS (3) received
Mar 18 08:59:39 wpa_supplicant[2424]: Received 1938 bytes of scan results (7 BSSes)
Mar 18 08:59:39 wpa_supplicant[2424]: eth0: BSS: Start scan result update 1

That's the main difference I saw in the wpa_supplicant log. At the same point, yours just started giving Mar 17 19:03:20 wpa_supplicant[4555]: EAPOL: EAP Session-Id not available

@tmjwid
Copy link
Author

tmjwid commented Mar 17, 2020

I modified the shell script to log on every count from the while loop, 49 times it took the first time, then 38 on the second attempt before it had the ip. I think anything over 50 will be fine, but it seems there is a weird issue with the Glo HD.

@shermp
Copy link
Owner

shermp commented Mar 17, 2020

Interesting, because the scan timeout is 10 seconds according to the wpa_supplicant logs.

Is your SSID hidden by any chance? If so, maybe it tries scanning, doesn't find anything, then attempts to connect to whatever is defined in the config file?

@pgaskin
Copy link
Contributor

pgaskin commented Mar 17, 2020

That's the main difference I saw in the wpa_supplicant log. At the same point, yours just started giving Mar 17 19:03:20 wpa_supplicant[4555]: EAPOL: EAP Session-Id not available

That error would be coming from wpa_supplicant_ctrl_iface_status or ieee802_1x_notify_create_actor, but since there's no IEEE 802.1X: Could not get EAP Session Id or IEEE 802.1X: Deriving CAK failed message after it, it must be coming from wpa_supplicant_ctrl_iface_status. That function gets called when the STATUS control interface is called, so I don't think it's relevant to this particular issue (other than that it got to a code path which checks the status).

@tmjwid
Copy link
Author

tmjwid commented Mar 17, 2020

Nope, SSID is visible. I do run on 2.4ghz with modified firmware (dd-wrt) but I also tired it on my works router which is just a stock linksys box and got the same results.

@shermp
Copy link
Owner

shermp commented Mar 17, 2020

If nothing else comes to mind, I can at least increase the timeout to give the Glo HD a chance.

@NiLuJe
Copy link
Contributor

NiLuJe commented Mar 17, 2020

Does a second connection attempt finishes the scan any faster?

IIRC, that's basically what we do in KOReader.

@shermp
Copy link
Owner

shermp commented Mar 17, 2020

Does a second connection attempt finishes the scan any faster?

IIRC, that's basically what we do in KOReader.

How do you implement that? Do you execute

pidof wpa_supplicant >/dev/null \
        || env -u LD_LIBRARY_PATH \
            wpa_supplicant -D wext -s -i "${INTERFACE}" -O /var/run/wpa_supplicant -c /etc/wpa_supplicant/wpa_supplicant.conf -B

a second time after a set timeout? Or some other method. Remember, a lot my wifi stuff is from koreader. The only thing I really added to the process was wpa_cli.

@NiLuJe
Copy link
Contributor

NiLuJe commented Mar 17, 2020

I'm not quite sure how that would translate here, as we do that with an actual wpa_supplicant frontend, not wpa_cli (https://github.com/koreader/koreader/blob/master/frontend/ui/network/wpa_supplicant.lua & https://github.com/koreader/lj-wpaclient).

@shermp
Copy link
Owner

shermp commented Mar 17, 2020

Doh, of course one would use wpa_cli to reconnect :p if I can figure it out of course...

@NiLuJe
Copy link
Contributor

NiLuJe commented Mar 17, 2020

Okay, the manpage is wonderfully unhelpful (Use the Source, Luke!), but wpa_cli -h does list the available commands ;).

@shermp
Copy link
Owner

shermp commented Mar 17, 2020

Oooh, wpa_cli can run a script which can respond to events. From the man page:

-a file
Run in daemon mode executing the action file based on events from wpa_supplicant. The specified file will be executed with the first argument set to interface name and second to "CONNECTED" or "DISCONNECTED" depending on the event. This can be used to execute networking tools required to configure the interface.
Additionally, three environmental variables are available to the file: WPA_CTRL_DIR, WPA_ID, and WPA_ID_STR. WPA_CTRL_DIR contains the absolute path to the ctrl_interface socket. WPA_ID contains the unique network_id identifier assigned to the active network, and WPA_ID_STR contains the content of the id_str option.

That might be a better way of achieving what I'm currently doing with grep.

Or maybe not, as it would be happening in a different shell?

I really need to investigate the wpa_cli man page some more.

@shermp
Copy link
Owner

shermp commented Mar 17, 2020

Okay, the manpage is wonderfully unhelpful (Use the Source, Luke!), but wpa_cli -h does list the available commands ;).

The online man pages for wpa_cli are most helpful. The contain a subset of the commands available compared to when I type wpa_cli -h on my kobo. They're not missing any commands, no sir!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants