Unable to Start USB Storage on Kobo Clara Colour

quanganhdo commented 3 weeks ago

KOReader version: Nightly (v2024.07-279-g06696ea91_2024-11-09)
Device: Kobo Clara Colour

Issue

When I try to Start USB Storage while a USB cable is plugged, it just opens/reopens the last viewed file. Same menu item works well with the setup and cable on my Kobo Libra Colour.

This has been happening across all KOReader versions that I tried on the Clara Colour.

Steps to reproduce

Start USB Storage > Nothing happens, except that the last viewed files are opened/reopened

`crash.log` (if applicable)

crash.log

crash.log is a file that is automatically created when KOReader crashes. It can normally be found in the KOReader directory:

/mnt/private/koreader for Cervantes
koreader/ directory for Kindle
.adds/koreader/ directory for Kobo
applications/koreader/ directory for Pocketbook

Android logs are kept in memory. Please go to [Menu] → Help → Bug Report to save these logs to a file.

Please try to include the relevant sections in your issue description. You can upload the whole crash.log file (zipped if necessary) on GitHub by dragging and dropping it onto this textbox.

If your issue doesn't directly concern a Lua crash, we'll quite likely need you to reproduce the issue with verbose debug logging enabled before providing the logs to us. To do so, go to Top menu → Hamburger menu → Help → Report a bug and tap Enable verbose logging. Restart as requested, then repeat the steps for your issue.

If you instead opt to inline it, please do so behind a spoiler tag:

crash.log

``` ```

NiLuJe commented 3 weeks ago

all KOReader versions

The range of which would be?

If you don't even see the tool popping up, that's... interesting.

In any case, I'm going to need verbose debug logs from KOReader, but more importantly, the output from logread (right after a failure) to see what the tool itself is saying.

If you do see the tool prop up, I'm also going to need the contents of the /usr/local/KoboUSBMS.log file.

NiLuJe commented 3 weeks ago

while a USB cable is plugged

And what happens if you start it before plugging a cable in? (It's available in the hamburger menu, near Exit)

quanganhdo commented 3 weeks ago

And what happens if you start it before plugging a cable in? (It's available in the hamburger menu, near Exit)

It pops up a notification that says Opening file "last viewed file" and does that instead of showing the expected full screen graphic for USB mode.

I installed the latest release on GitHub (the "outside" version) and upgraded to nightlies incrementally. All have the same behavior.

I'd grab more logs as soon as I get to my computer.

quanganhdo commented 3 weeks ago

There's no popup for the tool, that's for sure.

The output from logread doesn't seem to have anything to do with KoReader unless I overlooked something (I already enabled verbose logging and rebooted)

Nov 10 14:22:50 nickel: (     1.251 @ 0x1d07e30) loadPlugin: loaded plugin for QFontEngine
Nov 10 14:22:50 nickel: (     1.266 @ 0x1d07e30) loadPlugin: loaded plugin for QRawFont
Nov 10 14:22:50 nickel: (     1.269 @ 0x1d07e30) Loading iType.. true
Nov 10 14:22:53 nickel: (NickelMenu) (NickelHook) ... failsafe: info: renaming /usr/local/Kobo/imageformats/libnm.so.failsafe to /usr/local/Kobo/imageformats/libnm.so
Nov 10 14:22:53 nickel: (NickelMenu) (NickelHook) ... failsafe: info: freeing memory
Nov 10 14:22:58 nickel: (     9.021 @ 0x1d07e30) loadPlugin: loaded plugin for QRasterPaintEngine
Nov 10 14:22:58 nickel: (     9.068 @ 0x1d07e30 / ui.warning) "4.41.23145 (637199291b, 10/29/24)"
Nov 10 14:22:58 nickel: (     9.069 @ 0x1d07e30 / ui.debug) Periodic sync scheduled for "05:56:42"
Nov 10 14:22:58 nickel: (NickelMenu) MainNavView::MainNavView(0x1ed73a0, (nil)) (src/nickelmenu.cc:267)
Nov 10 14:22:58 nickel: (NickelMenu) Adding main menu button in tab bar for firmware 4.23.15505+. (src/nickelmenu.cc:270)
Nov 10 14:22:58 nickel: (NickelMenu) Added button. (src/nickelmenu.cc:408)
Nov 10 14:22:58 nickel: (     9.136 @ 0x1d07e30 / ui.warning) No controllers to pop
Nov 10 14:22:59 nickel: (    10.481 @ 0x2d4b940 / wifi.warning) void MTK::insertWifiModule() regulatory domain not set ""
Nov 10 14:23:02 wpa_supplicant[1183]: Successfully initialized wpa_supplicant
Nov 10 14:23:02 wpa_supplicant[1183]: rfkill: Cannot open RFKILL control device
Nov 10 14:23:02 dbus[369]: [system] Activating service name='name.marples.roy.dhcpcd' (using servicehelper)
Nov 10 14:23:02 dhcpcd[1186]: version 6.6.6 starting
Nov 10 14:23:02 dhcpcd[1186]: wlan0: using /sys hwaddr: a4:3c:d7:06:26:43
Nov 10 14:23:02 dhcpcd[1186]: wlan0: executing `/libexec/dhcpcd-run-hooks' PREINIT
Nov 10 14:23:02 dhcpcd-dbus: starting dhcpcd-dbus-0.6.0
Nov 10 14:23:02 dhcpcd[1186]: wlan0: executing `/libexec/dhcpcd-run-hooks' NOCARRIER
Nov 10 14:23:02 dhcpcd[1186]: no interfaces have a carrier
Nov 10 14:23:02 dhcpcd[1186]: forking to background
Nov 10 14:23:02 dhcpcd[1186]: forked to background, child pid 1198
Nov 10 14:23:02 dhcpcd[1198]: wlan0: waiting for carrier
Nov 10 14:23:02 dhcpcd-dbus: connected to dhcpcd-6.6.6
Nov 10 14:23:02 dhcpcd-dbus: retrieved interface wlan0 (NOCARRIER)
Nov 10 14:23:02 dhcpcd-dbus: status changed to disconnected
Nov 10 14:23:02 dhcpcd-dbus: no DBus connection to notify of status change
Nov 10 14:23:02 dhcpcd-dbus: connected to wpa_supplicant on interface wlan0
Nov 10 14:23:02 dhcpcd-dbus: scan results on interface wlan0
Nov 10 14:23:02 dhcpcd-dbus: no DBus connection to notify of status change
Nov 10 14:23:02 dbus[369]: [system] Successfully activated service 'name.marples.roy.dhcpcd'
Nov 10 14:23:02 dhcpcd-dbus: init completed, waiting for events
Nov 10 14:23:03 wpa_supplicant[1184]: wlan0: Trying to associate with SSID 'Bong'
Nov 10 14:23:03 dhcpcd-dbus: scan results on interface wlan0
Nov 10 14:23:03 wpa_supplicant[1184]: wlan0: Associated with d0:21:f9:f4:f0:46
Nov 10 14:23:03 wpa_supplicant[1184]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Nov 10 14:23:03 wpa_supplicant[1184]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=CA
Nov 10 14:23:03 wpa_supplicant[1184]: wlan0: WPA: Key negotiation completed with d0:21:f9:f4:f0:46 [PTK=CCMP GTK=CCMP]
Nov 10 14:23:03 wpa_supplicant[1184]: wlan0: CTRL-EVENT-CONNECTED - Connection tod0:21:f9:f4:f0:46 completed [id=0 id_str=]
Nov 10 14:23:03 dhcpcd[1198]: wlan0: carrier acquired
Nov 10 14:23:03 dhcpcd[1198]: wlan0: executing `/libexec/dhcpcd-run-hooks' CARRIER
Nov 10 14:23:03 dhcpcd[1198]: wlan0: delaying IPv4 for 0.2 seconds
Nov 10 14:23:03 dhcpcd-dbus: event on interface wlan0 (CARRIER)
Nov 10 14:23:04 dhcpcd[1198]: wlan0: using ClientID 01:a4:3c:d7:06:26:43
Nov 10 14:23:04 dhcpcd[1198]: wlan0: reading lease `/var/db/dhcpcd-wlan0-Bong.lease'
Nov 10 14:23:04 dhcpcd[1198]: wlan0: rebinding lease of 192.168.1.151
Nov 10 14:23:04 dhcpcd[1198]: wlan0: sending REQUEST (xid 0xb4667da0), next in 3.7 seconds
Nov 10 14:23:04 dhcpcd[1198]: wlan0: acknowledged 192.168.1.151 from 192.168.1.1
Nov 10 14:23:04 dhcpcd[1198]: wlan0: leased 192.168.1.151 for 86400 seconds
Nov 10 14:23:04 dhcpcd[1198]: wlan0: renew in 43200 seconds, rebind in 75600 seconds
Nov 10 14:23:04 dhcpcd[1198]: wlan0: writing lease `/var/db/dhcpcd-wlan0-Bong.lease'
Nov 10 14:23:04 dhcpcd[1198]: wlan0: adding IP address 192.168.1.151/24
Nov 10 14:23:04 dhcpcd[1198]: wlan0: adding route to 192.168.1.0/24
Nov 10 14:23:04 dhcpcd[1198]: wlan0: adding default route via 192.168.1.1
Nov 10 14:23:04 dhcpcd[1198]: wlan0: executing `/libexec/dhcpcd-run-hooks' REBOOT
Nov 10 14:23:04 dhcpcd-dbus: event on interface wlan0 (REBOOT)
Nov 10 14:23:04 dhcpcd-dbus: status changed to connected
Nov 10 14:23:04 nickel: (NickelMenu) checking for config updates (src/nickelmenu.cc:319)
Nov 10 14:23:04 nickel: (NickelMenu) global: scanning for config files (src/config.c:915)
Nov 10 14:23:04 nickel: (NickelMenu) config: skipping /mnt/onboard/.adds/nm/. because it's a special file (src/config.c:43)
Nov 10 14:23:04 nickel: (NickelMenu) config: skipping /mnt/onboard/.adds/nm/.. because it's a special file (src/config.c:43)
Nov 10 14:23:04 nickel: (NickelMenu) global: no changes detected (src/config.c:925)
Nov 10 14:23:04 nickel: (NickelMenu) global: running generators (src/config.c:945)
Nov 10 14:23:04 nickel: (NickelMenu) config: running generators (src/config.c:713)
Nov 10 14:23:04 nickel: (NickelMenu) config: generated items (src/config.c:755)
Nov 10 14:23:04 nickel: (NickelMenu) global: no generators updated (src/config.c:947)
Nov 10 14:23:04 nickel: (NickelMenu) revision = 0 (src/nickelmenu.cc:321)
Nov 10 14:23:04 nickel: (NickelMenu) building menu (src/nickelmenu.cc:323)
Nov 10 14:23:04 nickel: (NickelMenu) adding item 'Series'... (src/nickelmenu.cc:348)
Nov 10 14:23:04 nickel: (NickelMenu) adding item 'Reading Stats'... (src/nickelmenu.cc:348)
Nov 10 14:23:04 nickel: (NickelMenu) adding item 'My Words'... (src/nickelmenu.cc:348)
Nov 10 14:23:04 nickel: (NickelMenu) adding item 'Send to Kobo'... (src/nickelmenu.cc:348)
Nov 10 14:23:04 nickel: (NickelMenu) adding item 'Toggle Screenshots'... (src/nickelmenu.cc:348)
Nov 10 14:23:04 nickel: (NickelMenu) adding item 'Connect to USB'... (src/nickelmenu.cc:348)
Nov 10 14:23:04 nickel: (NickelMenu) adding item 'KOReader'... (src/nickelmenu.cc:348)
Nov 10 14:23:04 nickel: (NickelMenu) showing menu (src/nickelmenu.cc:397)
Nov 10 14:23:05 nickel: (NickelMenu) item 'KOReader' pressed... (src/nickelmenu.cc:391)
Nov 10 14:23:05 nickel: (NickelMenu) action 0xaf709565 with argument quiet:exec /mnt/onboard/.adds/koreader/koreader.sh :  (src/nickelmenu.cc:666)
Nov 10 14:23:05 nickel: (NickelMenu) ...success=1 ; on_success=1 on_failure=1 skip=0 (src/nickelmenu.cc:667)
Nov 10 14:23:05 nickel: (NickelMenu) ...result: type=0 msg='(null)', handling... (src/nickelmenu.cc:703)
Nov 10 14:23:05 nickel: (NickelMenu) done (src/nickelmenu.cc:393)
Nov 10 14:23:05 dhcpcd-dbus: Got signal 15, exiting
Nov 10 14:23:05 dhcpcd[1198]: received signal TERM from PID 1231, stopping
Nov 10 14:23:05 dhcpcd[1198]: wlan0: removing interface
Nov 10 14:23:05 dhcpcd[1198]: wlan0: executing `/libexec/dhcpcd-run-hooks' STOPPED
Nov 10 14:23:05 dhcpcd[1198]: exited

crash.log is attached in my first post, and there's no /usr/local/KoboUSBMS.log file on disk.

NiLuJe commented 3 weeks ago

crash.log is attached in my first post

Oh, my bad, I keep skipping over these when it's a link in the template -_-".

Which gives us a nice:

Couldn't unpack KoboUSBMS, restarting KOReader . . .

Which is... interesting ^^.

@benoit-pierre: it looks like data/KoboUSBMS.tar.gz is missing from the OTA packages (it's also missing from ota/package.index, which is also a problem, and potentially the root of the issue ^^).

For reference, which initial version did you install exactly (and what do you mean by "outside"? o_O)?

Frenzie commented 3 weeks ago

Alright, I'll wait.

quanganhdo commented 3 weeks ago

For reference, which initial version did you install exactly (and what do you mean by "outside"? o_O)?

https://github.com/koreader/koreader/releases/tag/v2024.07 is named "Outside", haha.

benoit-pierre commented 3 weeks ago

I just built master locally, and KoboUSBMS.tar.gz is included in both zip and targz, as well as listed in ota/package.index.

quanganhdo commented 3 weeks ago

it looks like data/KoboUSBMS.tar.gz is missing from the OTA packages

Somehow it's missing indeed. Copying it over from the latest release fixed my problem. Thanks for looking into this, @NiLuJe.

benoit-pierre commented 3 weeks ago

How can I get a un-truncated log from a job on https://gitlab.com/koreader/nightly-builds?

benoit-pierre commented 3 weeks ago

BTW, it looks like https://gitlab.com/gitlab-org/gitlab-runner/-/issues/4490 / https://gitlab.com/gitlab-org/gitlab-runner/-/issues/27896 are closed, so maybe the build log workaround can be removed.

Frenzie commented 3 weeks ago

I removed it. Hopefully it'll succeed. https://gitlab.com/koreader/nightly-builds/-/jobs/8319118840

benoit-pierre commented 3 weeks ago

I can reproduce in docker… Some make bug I think.

diff --git a/Makefile b/Makefile
index 74a125d91..f350f7983 100644
--- a/Makefile
+++ b/Makefile
@@ -62,6 +62,9 @@ define DATADIR_FILES
 $(CR3GUI_DATADIR_FILES)
 $(OUTPUT_DIR_DATAFILES)
 $(THIRDPARTY_DIR)/kpvcrlib/cr3.css
+$(warning $$(wildcard $(OUTPUT_DIR)/data/*))
+$(warning $(wildcard $(OUTPUT_DIR)/data/*))
+$(warning $(shell set -x; ls $(OUTPUT_DIR)/data/))
 endef

 # files to link from main directory

Docker:

 100% | Installing 'openssh'
Makefile:97: $(wildcard base/build/arm-kobo-linux-gnueabihf/data/*)
Makefile:97: 
+ ls base/build/arm-kobo-linux-gnueabihf/data/
Makefile:97: KoboUSBMS.tar.gz ca-bundle.crt dict tessdata
[*] Install update once marker
[*] Install C++ runtime...
[*] Install plugins
[*] Install resources
[*] Install data files

vs non-Docker:

 100% | Installing 'zsync2'
Makefile:97: $(wildcard base/build/arm-kobo-linux-gnueabihf/data/*)
Makefile:97: base/build/arm-kobo-linux-gnueabihf/data/ca-bundle.crt base/build/arm-kobo-linux-gnueabihf/data/dict base/build/arm-kobo-linux-gnueabihf/data/KoboUSBMS.tar.gz base/build/arm-kobo-linux-gnueabihf/data/tessdata
+ ls base/build/arm-kobo-linux-gnueabihf/data/
Makefile:97: ca-bundle.crt dict KoboUSBMS.tar.gz tessdata
[*] Install update once marker
[*] Install C++ runtime...
[*] Install plugins
[*] Install resources
[*] Install data files

benoit-pierre commented 3 weeks ago

This one I think…

benoit-pierre commented 3 weeks ago

@Frenzie: do you plan a new release soon?

NiLuJe commented 3 weeks ago

BTW, it looks like https://gitlab.com/gitlab-org/gitlab-runner/-/issues/4490 / https://gitlab.com/gitlab-org/gitlab-runner/-/issues/27896 are closed, so maybe the build log workaround can be removed.

Worth a try anyway ;).

Frenzie commented 3 weeks ago

I am, yes.

Commodore64user commented 3 weeks ago

I am, yes.

Today, tomorrow?

Frenzie commented 3 weeks ago

Not today, some last minute code was just merged.

Commodore64user commented 3 weeks ago

Not today, some last minute code was just merged.

mate we are sick of being "outside", let us back in... ;)

edit: 🎼 knock knock knocking on Frenzie’s door 🎶… we still outside ;)

koreader / koreader