search

shermp / Kobo-UNCaGED

UNCaGED, for Kobo devices
GNU Affero General Public License v3.0
101 stars 7 forks source link

wpa_supplicant error on wifi enable. #29

Open tmjwid opened 4 years ago

tmjwid commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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

NiLuJe commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

@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 commented 4 years ago

@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 commented 4 years ago

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 commented 4 years ago

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 https://github.com/NiLuJe/kfmon/commit/11b6641ab48e10e34d723d4b320fa2646ccfffaa

**** 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 commented 4 years ago

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

shermp commented 4 years ago

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

NiLuJe commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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

shermp commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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

shermp commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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

shermp commented 4 years ago

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

shermp commented 4 years ago

Can you check you've got a valid wifi config in /etc/wpa_supplicant/wpa_supplicant.conf?

tmjwid commented 4 years ago

I have two network objects. My current network is there and another which I do not remember setting up (the kobo is second hand). I'll remove the other network and try again.

tmjwid commented 4 years ago

image Here's my wpa_supplicant.conf. I know blocking out the psk isn't needed but habit again.

Thank you for looking into this btw

shermp commented 4 years ago

Yep, the config looks ok.

@NiLuJe I'm really scratching my head over this one! Do you have any ideas on ways to get more info out of wpa_supplicant? Or more diagnostics that could be added to the shell script?

NiLuJe commented 4 years ago

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 ;).

That's from a quick glance at the manpage, I have no real experience with wpa_cli ;).

@tmjwid: If you still have KOReader/Plato installed, does WiFi behave there?

pgaskin commented 4 years ago

A strace of wpa_supplicant might be helpful.

tmjwid commented 4 years ago

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 ;).

That's from a quick glance at the manpage, I have no real experience with wpa_cli ;).

@tmjwid: If you still have KOReader/Plato installed, does WiFi behave there?

I will install them and see how they fair.

A strace of wpa_supplicant might be helpful.

Will do, I'll install @NiLuJe's telnet tools tonight and get you a strace.

Is there anything else I can do in the meantime? If not, I'll get you the information tonight.

tmjwid commented 4 years ago

@geek1011

Here's the strace command I'll use strace wpa_cli -i eth0. I am not accustom to the program, so any other args you want to me provide please let me know.

shermp commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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

tmjwid commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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

NiLuJe commented 4 years ago

Yeah, I knew that sounded familiar: https://github.com/koreader/koreader/issues/4387

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