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

Autoshutdown not initiating when already in sleep mode on Kobo Glo #7994

Closed
Bartvelp opened this issue Jul 19, 2021 · 24 comments
Closed

Autoshutdown not initiating when already in sleep mode on Kobo Glo #7994

Bartvelp opened this issue Jul 19, 2021 · 24 comments

Comments

@Bartvelp
Copy link

  • KOReader version: v2021.06
  • Device: Kobo Glo

Issue

Auto-shutdown does not work when the device already is in sleep mode. It does not matter if the sleepmode was initiated by the user or by auto-sleepmode. My battery sucks so that's one reason I would like this to work.

Steps to reproduce

Set auto-sleepmode to 5 minutes, and auto-shutdown to a higher value (I use 0.1 hours == 6 minutes for testing)
The device will now never exit the sleep mode to go to a full shutdown, thus using a higher sleep current and draining the battery.

crash.log (with dev mode and verbose logging on)

My device is set to auto-sleep after 5 minutes, and to auto shutdown after 0.1 hours. I stopped touching the device at 21:22, the device correctly went to sleep at 21:27, but never woke up at 21;28 to shutdown completely. I woke up the device at 22:15 to get this log contents.

crash.log (snipped, full log down below )
07/19/21-21:27:08 DEBUG AutoSuspend: onSuspend
07/19/21-21:27:08 DEBUG AutoSuspend: unschedule
07/19/21-21:27:08 INFO  WakeupMgr: scheduling wakeup in 360
07/19/21-21:27:08 DEBUG AutoTurn: onSuspend
07/19/21-21:27:08 DEBUG AutoTurn: unschedule
07/19/21-21:27:08 DEBUG BackgroundRunnerWidget:onSuspend() @  1626722828
07/19/21-21:27:08 DEBUG NetworkListener: unschedule network activity check
07/19/21-21:27:08 DEBUG Suspending...
07/19/21-21:27:08 DEBUG Sleep cover is open
-- snip --
07/19/21-21:27:24 INFO  Kobo suspend: going to sleep . . .
07/19/21-21:27:24 INFO  Kobo suspend: asked the kernel to put subsystems to sleep, ret: true
07/19/21-21:27:26 INFO  Kobo suspend: waited for 2s because of reasons...
07/19/21-21:27:26 INFO  Kobo suspend: synced FS
07/19/21-21:27:26 INFO  Kobo suspend: asking for a suspend to RAM . . .
07/19/21-21:27:26 INFO  Kobo suspend: ZzZ ZzZ ZzZ? Write syscall returned:  true
07/19/21-22:15:10 INFO  Kobo suspend: woke up!
07/19/21-22:15:10 DEBUG Kobo suspend: scheduling unexpected wakeup guard

Please let me know if any more details are necessary, I have the emulator running and am able to trying to debug. But this project is a bit too big to wrap my head around to do it myself.

full crash.log

@NiLuJe
Copy link
Member

NiLuJe commented Jul 19, 2021

The wakeup appears to get scheduled properly for 6 minutes after suspension, but it apparently never fired.

I can confirm that this works properly on an H2O and a Forma, FWIW.

If you have shell access to the device, what does cat /proc/driver/rtc say?

@NiLuJe
Copy link
Member

NiLuJe commented Jul 19, 2021

Also, we need over 15s of logs after the wakeup to see the results of the wakeup guard checks ;).

@Frenzie
Copy link
Member

Frenzie commented Jul 20, 2021

I can confirm that this works properly on an H2O and a Forma, FWIW.

I haven't verified that it's still working and I probably won't do so today, but it's been a couple of months since anything changed in that direction and I verified after #7624.

@Bartvelp
Copy link
Author

The wakeup appears to get scheduled properly for 6 minutes after suspension, but it apparently never fired.

I can confirm that this works properly on an H2O and a Forma, FWIW.

If you have shell access to the device, what does cat /proc/driver/rtc say?

I checked when the device is awake (so I have wifi access and can ssh into it). Do I need to check /proc/driver/rtc when it is asleep using the serial connection, if that is even possible?

[root@kobo koreader]# cat /proc/driver/rtc
rtc_time	: 10:34:09
rtc_date	: 2021-07-20
alrm_time	: 00:00:01
alrm_date	: 1970-01-01
alarm_IRQ	: yes
alrm_pending	: no
24hr		: yes

Was the full error.log sufficient? here is a new one from this morning without any removing
crash_full.log

Nickel can shutdown while sleeping just fine btw, so it isn't a hardware limitation.

@Frenzie
Copy link
Member

Frenzie commented Jul 20, 2021

Do I need to check /proc/driver/rtc when it is asleep using the serial connection, if that is even possible?

It wouldn't be sleeping, now would it? ;-)

Just have some script write a timestamp every (x) second(s) and you'll see well enough whether it's actually sleeping or not.

@Bartvelp
Copy link
Author

Do I need to check /proc/driver/rtc when it is asleep using the serial connection, if that is even possible?

It wouldn't be sleeping, now would it? ;-)

Just have some script write a timestamp every (x) second(s) and you'll see well enough whether it's actually sleeping or not.

watch "date >> date.log && cat date.log"
gives

Tue Jul 20 20:48:47 CEST 2021
Tue Jul 20 20:48:49 CEST 2021
Tue Jul 20 20:48:51 CEST 2021 # Kobo goes to sleep here due to 5 minutes of inactivity, and wifi is lost
Tue Jul 20 20:48:53 CEST 2021
Tue Jul 20 20:48:55 CEST 2021
Tue Jul 20 20:48:57 CEST 2021
Tue Jul 20 20:48:59 CEST 2021
Tue Jul 20 20:49:01 CEST 2021
Tue Jul 20 20:49:03 CEST 2021
Tue Jul 20 20:49:05 CEST 2021
Tue Jul 20 20:49:07 CEST 2021
Tue Jul 20 20:49:09 CEST 2021
Tue Jul 20 20:49:11 CEST 2021
Tue Jul 20 20:52:28 CEST 2021 # Kobo wakes up again from sleep because I use the power slider
Tue Jul 20 20:52:30 CEST 2021
Tue Jul 20 20:52:32 CEST 2021

Kinda weird behaviour if you ask me, I don't know what the sleep modes exactly do, but it keeps running the script for 20 seconds after going to sleep and then stops.

I also logged /proc/driver/rtc while autosuspend kicks in

[root@kobo koreader]# watch "date >> rtc.log && cat /proc/driver/rtc >> rtc.log && cat rtc.log"

rtc.log
Tue Jul 20 21:03:17 CEST 2021
rtc_time	: 19:03:17
rtc_date	: 2021-07-20
alrm_time	: 00:00:01
alrm_date	: 1970-01-01
alarm_IRQ	: yes
alrm_pending	: no
24hr		: yes
Tue Jul 20 21:03:19 CEST 2021
rtc_time	: 19:03:19
rtc_date	: 2021-07-20
alrm_time	: 00:00:01
alrm_date	: 1970-01-01
alarm_IRQ	: yes
alrm_pending	: no
24hr		: yes
Tue Jul 20 21:03:21 CEST 2021 # Kobo goes to sleep again
rtc_time	: 19:03:21
rtc_date	: 2021-07-20
alrm_time	: 00:00:01
alrm_date	: 1970-01-01
alarm_IRQ	: yes
alrm_pending	: no
24hr		: yes
Tue Jul 20 21:03:23 CEST 2021
rtc_time	: 19:03:23
rtc_date	: 2021-07-20
alrm_time	: 00:00:01
alrm_date	: 1970-01-01
alarm_IRQ	: yes
alrm_pending	: no
24hr		: yes
Tue Jul 20 21:03:25 CEST 2021
rtc_time	: 19:03:25
rtc_date	: 2021-07-20
alrm_time	: 00:00:01
alrm_date	: 1970-01-01
alarm_IRQ	: yes
alrm_pending	: no
24hr		: yes
Tue Jul 20 21:03:27 CEST 2021
rtc_time	: 19:03:27
rtc_date	: 2021-07-20
alrm_time	: 00:00:01
alrm_date	: 1970-01-01
alarm_IRQ	: yes
alrm_pending	: no
24hr		: yes
Tue Jul 20 21:03:29 CEST 2021
rtc_time	: 19:03:30
rtc_date	: 2021-07-20
alrm_time	: 00:00:01
alrm_date	: 1970-01-01
alarm_IRQ	: yes
alrm_pending	: no
24hr		: yes
Tue Jul 20 21:03:31 CEST 2021
rtc_time	: 19:03:32
rtc_date	: 2021-07-20
alrm_time	: 00:00:01
alrm_date	: 1970-01-01
alarm_IRQ	: yes
alrm_pending	: no
24hr		: yes
Tue Jul 20 21:06:19 CEST 2021 # I wake the kobo up again
rtc_time	: 19:06:18
rtc_date	: 2021-07-20
alrm_time	: 00:00:01
alrm_date	: 1970-01-01
alarm_IRQ	: yes
alrm_pending	: no
24hr		: yes
Tue Jul 20 21:06:21 CEST 2021
rtc_time	: 19:06:20
rtc_date	: 2021-07-20
alrm_time	: 00:00:01
alrm_date	: 1970-01-01
alarm_IRQ	: yes
alrm_pending	: no
24hr		: yes

Again the kobo is running the script 10 more seconds after losing wifi, but no alrm_time is set and it never wakes up again until I wake it up again.

@Frenzie
Copy link
Member

Frenzie commented Jul 20, 2021

Kinda weird behaviour if you ask me, I don't know what the sleep modes exactly do, but it keeps running the script for 20 seconds after going to sleep and then stops.

That's intentional. The modules need time to unload properly etc. or suspend will fail. (At least on some Kobos.)

@NiLuJe
Copy link
Member

NiLuJe commented Jul 20, 2021

Well, the alarm being stuck @ epoch is a strong hint that something is indeed failing to even set the alarm. (nickel itself should have set it a bunch of times before we even start. Which reminds me: how are you booting KOReader?).

I suppose it could be a strange Glo-specific quirk (ping @poire-z ;)), or faulty hardware?

Does the rtcwake shell utility succeed in setting one? (say, something like rtcwake -u -s 60)

@poire-z
Copy link
Contributor

poire-z commented Jul 20, 2021

(I have a Glo "HD" - and even if I don't use KOReader's own alarm stuff, I have some private hacks that use it - writing into /sys/class/rtc/rtc0/wakealarm - without issues.)

@NiLuJe
Copy link
Member

NiLuJe commented Jul 20, 2021

Oops, forgot that there was a non-HD Glo ^^. It's Mk. 4, so I'm pretty sure we'd have heard about it before if it were a generic issue on that generation ;).

@Bartvelp
Copy link
Author

[root@kobo bin]# rtcwake -s 60
rtcwake: /dev/rtc0 not enabled for wakeup events

which apperently is due to /sys/class/rtc/rtc0/device/power/wakeup not containing "enabled"

[root@kobo bin]# echo "enabled" > /sys/class/rtc/rtc0/device/power/wakeup
sh: write error: Invalid argument

but I cannot write to it.

[root@kobo bin]# echo "enabled" > /sys/class/rtc/rtc0/wakealarm
-sh: can't create /sys/class/rtc/rtc0/wakealarm: nonexistent directory

seems to be due to a faulty check here https://github.com/kobolabs/busybox/blob/kobo/util-linux/rtcwake.c#L69
one guy got it working by commenting out the faulty check and recompiling https://www.mobileread.com/forums/showthread.php?t=212145&page=4

so it appears to be due to a faulty busybox, but I am not sure how Nickel does it then. I am no C expert and I don't know how to recompile the busybox for the Kobo and the original link on mobilereads is dead. Maybe I can open it up in a hex editor and change the location of the checked file.

And yes, I have a non HD hand me down Kobo Glo ;)

@NiLuJe
Copy link
Member

NiLuJe commented Jul 20, 2021

Neither we nor nickel use the busybox applet to do it, it was just supposed to be another way to do it to triple-check, but, alas, it indeed doesn't work without patching.

@Bartvelp
Copy link
Author

Ah okay thanks, so I patched the binary, and it successfully goes to sleep with:

[root@kobo bin]# busybox_new rtcwake -s 1
wakeup from "standby" at Tue Jul 20 21:55:05 2021

But then it freezes? the frontlight stays on but the device is not responsive. When I turn it off using the slider for 10 seconds I can boot again. Maybe this is all just a bit too much to ask from such an old device...

@NiLuJe
Copy link
Member

NiLuJe commented Jul 21, 2021

Not quite sure why we can't wakeup from that, but I can confirm that ;p.

Unless you break suspend by keeping the USB host controller busy (i.e., I was in USBNet mode at the time):

┌─(ROOT@dahlia:pts/0)──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────(~)─┐
└─(0.91:22%:15:04:96%:#)── cat /proc/driver/rtc                                                                                                                                                                                                                                                                                                        ──(Wed, Jul 21)─┘
rtc_time        : 13:04:57
rtc_date        : 2021-07-21
alrm_time       : 00:00:00
alrm_date       : 1970-01-01
alarm_IRQ       : no
alrm_pending    : no
24hr            : yes
┌─(ROOT@dahlia:pts/0)──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────(~)─┐
└─(0.77:13%:15:04:96%:#)── ./busybox rtcwake -u -s 60                                                                                                                                                                                                                                                                                                  ──(Wed, Jul 21)─┘
wakeup from "mem" at Wed Jul 21 15:06:22 2021
rtcwake: write error: Device or resource busy
- [15:04] root has logged on pts/1 from 192.168.2.1 -                                                                                                                                                                                                                                                                                                                    
┌─(ROOT@dahlia:pts/0)──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────(~)─┐
└─(1:0.57:13%:15:05:96%:#)── cat /proc/driver/rtc                                                                                                                                                                                                                                                                                                      ──(Wed, Jul 21)─┘
rtc_time        : 13:05:25
rtc_date        : 2021-07-21
alrm_time       : 15:06:22
alrm_date       : 2021-07-21
alarm_IRQ       : yes
alrm_pending    : no
24hr            : yes

EDIT: Also, the -u flag is borked? Oh, well.

@Bartvelp
Copy link
Author

Just checked the all the available modes of rtcwake,
only mem and stanby seem to be "supported". Unfortunately both suspend the kobo to an unrecoverable state and they never seem to wake up. It's a shame since it sips my poor battery, I wish there was a way of just displaying the "sleep" screen when it's actually still awake, so it can then go to full sleep after x minutes.

A well, I'll guess I will resort to Nickel on vacations.
Thanks for your work on KoReader and your troubleshooting.

@Bartvelp
Copy link
Author

Bartvelp commented Jul 24, 2021

I figures out why it was freezing, apparently you cannot go to sleep when WiFi is enabled (which it was due to my SSH session).

The following script works:

echo 1 > /sys/power/state-extended
echo start > /mnt/onboard/.adds/status
date >> /mnt/onboard/.adds/status

rmmod dhd
rmmod sdio_wifi_pwr
sync

echo going_to_sleep > /mnt/onboard/.adds/status
date >> /mnt/onboard/.adds/status

/mnt/onboard/.adds/busybox_new rtcwake -m mem -s 30 2>&1 >> /mnt/onboard/.adds/status
echo awake >> /mnt/onboard/.adds/status
date >> /mnt/onboard/.adds/status

sleep 5
echo still_awake >> /mnt/onboard/.adds/status
date >> /mnt/onboard/.adds/status

insmod /drivers/ntx508/wifi/sdio_wifi_pwr.ko
insmod /drivers/ntx508/wifi/dhd.ko
sleep 2

it produces:

going_to_sleep
Sat Jul 24 14:01:29 CEST 2021
wakeup from "mem" at Sat Jul 24 12:02:01 2021
awake
Sat Jul 24 14:02:00 CEST 2021
still_awake
Sat Jul 24 14:02:05 CEST 2021

This suggests the bug is in KoReader after all, I almost never have Wi-Fi enabled so I guess it can't be that. dhd and sdio_wifi_pwr are not loaded when Wi-Fi is disabled in KoReader so I can't figure where KoReader schedules it's wakeup but it should work.

Edit: Apparently it is done in koreader-base and the comments say it is done the same way as rtcwake, which is odd

@Bartvelp Bartvelp reopened this Jul 24, 2021
@NiLuJe
Copy link
Member

NiLuJe commented Jul 24, 2021

Oh, right, the good old "kernel implodes if you suspend with wi-fi on", good catch ;).

You still haven't posted the before/after status of /proc/driver/rtc, so I still have no idea how the alarm looked once set, although the script does appear to confirm that it can be set & fire properly ;).

And it's indeed irrelevant as far as KOReader itself is concerned, as we kill Wi-Fi much earlier than we try to actually suspend ;).

(And a hang on suspend wasn't your original issue: no alarm being set is ;)).

@Frenzie
Copy link
Member

Frenzie commented Jul 24, 2021

This suggests the bug is in KoReader after all, I almost never have Wi-Fi enabled so I guess it can't be that. dhd and sdio_wifi_pwr are not loaded when Wi-Fi is disabled in KoReader so I can't figure where KoReader schedules it's wakeup but it should work.

See #7994 (comment)

@Bartvelp
Copy link
Author

Oh, right, the good old "kernel implodes if you suspend with wi-fi on", good catch ;).

You still haven't posted the before/after status of /proc/driver/rtc, so I still have no idea how the alarm looked once set, although the script does appear to confirm that it can be set & fire properly ;).

And it's indeed irrelevant as far as KOReader itself is concerned, as we kill Wi-Fi much earlier than we try to actually suspend ;).

(And a hang on suspend wasn't your original issue: no alarm being set is ;)).

Not sure when /proc/driver/rtc should report something different, since I assume the alarm is reset when it wakes up again.
Since rtcwake immediately sleeps when invoked I can never see the alarm being set right? (but it must be set, how would it otherwise wakup?)

# before rtcwake
rtc_time	: 12:53:05
rtc_date	: 2021-07-24
alrm_time	: 00:00:01
alrm_date	: 1970-01-01
alarm_IRQ	: yes
alrm_pending	: no
24hr		: yes
# schedule with  rtcwake -m mem -s 30
wakeup from "mem" at Sat Jul 24 12:53:36 2021
# after wakeup
rtc_time	: 12:53:36
rtc_date	: 2021-07-24
alrm_time	: 00:00:01
alrm_date	: 1970-01-01
alarm_IRQ	: yes
alrm_pending	: no
24hr		: yes

@NiLuJe
Copy link
Member

NiLuJe commented Jul 24, 2021

AFAIK, the alarm should stick, even if fired (e.g., it should be visible there).

Let me double-check on an H2O.

@NiLuJe
Copy link
Member

NiLuJe commented Jul 24, 2021

Yup:

going_to_sleep
Sat Jul 24 15:14:14 CEST 2021
rtc_time        : 13:14:14
rtc_date        : 2021-07-24
alrm_time       : 16:17:28
alrm_date       : 2021-07-24
alarm_IRQ       : yes
alrm_pending    : no
24hr            : yes
wakeup from "mem" at Sat Jul 24 13:14:45 2021
awake
Sat Jul 24 15:14:45 CEST 2021
rtc_time        : 13:14:45
rtc_date        : 2021-07-24
alrm_time       : 13:14:45
alrm_date       : 2021-07-24
alarm_IRQ       : yes
alrm_pending    : no
24hr            : yes
still_awake
Sat Jul 24 15:14:50 CEST 2021

Shot in the dark: it's possible the battery is dying, making reading the rtc unreliable, while still allowing it to be set & fire (mostly okay).

Unfortunately, we rely on a sane RTC, and being able to read it in order to validate the alarm.

@Bartvelp
Copy link
Author

My battery is less than a year old but not stock (I put a 700mah in) so I don't think it's dying. Thanks for your help, a pity the RTC date not being set messes things up. I'll maybe try to hack koreader to do what I want.

@NiLuJe
Copy link
Member

NiLuJe commented Jul 24, 2021

Nickel does an extra ioctl specifically aimed at checking the RTC voltage (RTC_VL_READ) to possibly deal with similar issues? Unfortunately, what the rtc driver answers to that ioctl is often buggy at specific points in time (e.g., right after resume... -_-"), which kind of defeats the purpose without massive over-engineering.

@Bartvelp
Copy link
Author

I injected the following code into koreader/frontend/device/kobo/device.lua here which uses my modified rtc awake to sleep the kobo for 30 minutes, and shut it down after 30 minutes of sleeping. Still need to test some more, but solves my problem. Thanks once again for the amazing work on koreader, so hackable! It's a shame Kobo/pocketbook/amazon does not invest a few bucks into this project.

        logger.info("Kobo suspend: Bart edit")
        epoch_before_sleep = os.time(os.date("!*t"))
        seconds_sleep = 60 * 30 -- 30 minutes of sleep
        logger.info("Kobo suspend: suspending, epoch " .. epoch_before_sleep .. " awaking in s: " .. seconds_sleep)
        os.execute("/mnt/onboard/.adds/busybox_new rtcwake -m mem -s " .. seconds_sleep)
        -- When we resume here, we either used the slider or the rtcwake fired
        epoch_after_sleep = os.time(os.date("!*t"))
        sec_asleep = epoch_after_sleep - epoch_before_sleep
        if sec_asleep > seconds_sleep - 30 then -- we slept so long, we awoke due to rtcwake, 30 seconds of leeway
            logger.info("Kobo suspend: Shutting down, sec asleep: " .. sec_asleep)
            os.execute("/usr/local/kfmon/bin/fbink -S 4 -m -M shutdown")
            os.execute("/bin/sleep 5 && poweroff -f")
        else
            logger.info("Kobo suspend: woke up due to slider, sec asleep: " .. sec_asleep)
        end

NiLuJe added a commit to koreader/koreader-base that referenced this issue Oct 16, 2023
We've had a couple reports over the years of broken alarm reads on old NTX boards (in... every sense of the word; this only seems to affect old i.MX RTCs, true, but more specifically really old devices, with possibly dying batteries).

e.g., koreader/koreader#7994 & koreader/koreader#10996

While there *is* an ioctl that is supposed to help with this sort of stuff by reporting on the state of RTC's battery voltage, in my own testing on much less broken RTCs, it was extremely unreliable (especially when it matters most, i.e., right after a wakeup), so, that's kind of a no-go.

Thankfully, when this occurs, the returned alarm is *extremely* obviously bogus: `1`, as in, Epoch.

TL;DR: Just ignore such return values and assume the alarm did indeed fire properly, we already validate against both the task and the current time, double-checking the actual alarm is just a defensive and pedantic guard against... something... setting alarms behind our back, which should never really happen in the first place, least of all on the affected platform (Kobo) ;).

Also actually implement honoring WakeupMgr's character device selection, in case we ever need to actually use something other than rtc0 ;).
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

4 participants