Kobo Aura H2O: no input other than off/standby button registered after resume

[Frenzie]

Quoting jlynton:

I just tried the latest koreader nightly 841 which includes Frenzie's changes (thanks frenzie!), starting from KSM. It works fine, until I sleep it from the power button - when I wake it the screen does not respond to any taps, all I can do is sleep/wake it again with the power button, a long press of which does not turn it off.

I'd noticed the problem, but I had more pressing matters to deal with. After suspending the error log reads sh: write error: Operation not permitted (cf. #301 ?). However, I don't think it's related to the observed behavior. Adding sleep 2 to the suspend.sh script gets rid of the error, but nothing more.

I was trying to investigate whether it's related to screen_saver_mode, but disabling the if Device.screen_saver_mode check in frontend/ui/uimanager.lua has no effect.

I'm stuck at this point because of debug output issues. I start the program with ./reader.lua -d /mnt/onboard 1>koreader.log 2>crash.log, but my koreader.log always ends up empty after a forced shutdown or reset, no matter how long I wait before doing so. So I suppose it must be something other than changes not being written to the filesystem yet.

[houqp]

Are you using KSM, if so, does its sleep feature work for you? Is it reproducible when you run the reader in a SSH shell?

[Frenzie]

Affirmative, I'm using KSM as per the installation instructions, except I added the debug flag. The KSM sleep feature doesn't seem to work at all. It's more of a full screen refresh after which it's business as usual. I imagine the full screen refresh is supposed to happen when coming out of sleep.

The sleep feature in vlasovsoftlauncher seems to work perfectly. I put it to sleep in vlasovsoftlauncher overnight and the device claims the battery is still 100%.

Is it reproducible when you run the reader in a SSH shell?

I'm afraid you'll have to explain what you want me to do. Run the program from within a screen or tmux session to which I can reattach after coming out of sleep or something?

[Frenzie]

Okay, after fixing the debug output (3334903), redirecting stderr to stdout for clarity (./reader.lua -d /mnt/onboard 1>koreader.log 2>&1), and adding a couple of date statements in suspend.sh I'm none the wiser, except that the write error definitely refers to /sys/power/state and not /sys/power/state-extended.

#!/bin/sh
export PATH=$PATH:/sbin:/usr/sbin

#disable wifi
if lsmod | grep -q sdio_wifi_pwr ; then
    wlarm_le -i eth0 down
    ifconfig eth0 down
    rmmod -r dhd
    rmmod -r sdio_wifi_pwr
fi

#go to sleep

date
echo "writing /sys/power/state-extended & /sys/power/state"
sync

echo 1 > /sys/power/state-extended
echo mem > /sys/power/state

date
echo "/sys/power/state: " && cat /sys/power/state

# Suspending...
# show screensaver
Sat Oct 18 16:47:29 CEST 2014
writing /sys/power/state-extended & /sys/power/state
sh: write error: Operation not permitted
Sat Oct 18 16:47:29 CEST 2014
/sys/power/state: 
standby mem
# waiting endlessly
# waiting endlessly
# key ev {
    ["type"] = 1,
    ["time"] = {
        ["usec"] = 994334,
        ["sec"] = 1413643654
    },
    ["code"] = 116,
    ["value"] = 1
}
# waiting endlessly
# key ev {
    ["type"] = 1,
    ["time"] = {
        ["usec"] = 184328,
        ["sec"] = 1413643655
    },
    ["code"] = 116,
    ["value"] = 0
}
# Resuming...
1
# echoed state-extended
0
# close screensaver
# painting {
    ["y"] = 0,
    ["x"] = 0,
    ["h"] = 1430,
    ["w"] = 1080
} to 0 10
# waiting endlessly
# key ev {
    ["type"] = 1,
    ["time"] = {
        ["usec"] = 734331,
        ["sec"] = 1413643662
    },
    ["code"] = 116,
    ["value"] = 1
}
# waiting endlessly
# key ev {
    ["type"] = 1,
    ["time"] = {
        ["usec"] = 954331,
        ["sec"] = 1413643662
    },
    ["code"] = 116,
    ["value"] = 0
}
# Suspending...
# show screensaver
Sat Oct 18 16:47:44 CEST 2014
writing /sys/power/state-extended & /sys/power/state

I tried adding some sleep statements as follows, but contrary to my earlier suggestion that seems to have no effect.

#go to sleep

date
echo "writing /sys/power/state-extended & /sys/power/state"
sync

sleep 1

echo 1 > /sys/power/state-extended

sleep 2

echo mem > /sys/power/state

date
echo "/sys/power/state: " && cat /sys/power/state

[houqp]

Where did you put the # waiting endlessly print?

I'm afraid you'll have to explain what you want me to do. Run the program from within a screen or tmux session to which I can reattach after coming out of sleep or something?

Oh, I mean just run koreader in a persistent ssh connection and try to suspend with ssh running.

BTW, where can get the source code for vlasovsoftlauncher? If suspend/resume works for vlasovsoftlauncher, we might be able to steal some ideas from it ;)

[Frenzie]

In ui/uimanager.lua where the comment says "wait endlessly". It wasn't helpful. Btw, many debug calls in ui/input.lua don't seem to print anything (like everything in Input:init(), such as "Auto-detected Kobo"), while using print() does work. I'm not sure what's up there because everything looks like it should be in order.

Oh, I mean just run koreader in a persistent ssh connection and try to suspend with ssh running.

I expect that might block suspending? Then again, I suppose it wouldn't really matter in this case.

BTW, where can get the source code for vlasovsoftlauncher? If suspend/resume works for vlasovsoftlauncher, we might be able to steal some ideas from it ;)

You can't get the source as such, but you seem to be able to get partials here. Specifically, there is the Kobo-specific Qt code.

On line 18 of QtKoboPlugins/KoboTS/kobots.cpp, it reads:

_fd = open("/dev/input/event1", O_RDONLY);

Which makes me wonder, is the SDL-based input.open("/dev/input/event1") also opening it as O_RDONLY or is it using e.g. O_RDWR? And how the heck could one find out, change it, etc.? :P

For the suspend.sh script you need the main download, but it's functionally no different than the one in KOReader.

I slightly modified it to make sure it's actually working and not just pretending to by merely displaying the suspend image:

#!/bin/sh

logfile=$$.log
exec > $logfile 2>&1

export PATH=$PATH:/sbin:/usr/sbin

date
echo "suspend.sh: enter"

handler()
{
    kill -15 $pid
    echo 0 > /sys/power/state-extended
    echo "suspend.sh: killed"
    exit 1
}

trap handler SIGTERM

sleep 10 &
pid=$!
wait $pid

# disable wifi
if lsmod | grep -q sdio_wifi_pwr ; then
    wlarm_le -i eth0 down
    ifconfig eth0 down
    /sbin/rmmod -r dhd
    /sbin/rmmod -r sdio_wifi_pwr
fi

echo 1 > /sys/power/state-extended

date
echo "sleeping... zzz-zzz-zzz-zzz :)"

sync
echo mem > /sys/power/state
echo 0 > /sys/power/state-extended

date
echo "suspend.sh: normal exit"

Behold, no error messages and the wake-up date isn't printed until I actually resume the device.

Mon Oct 20 10:40:05 CEST 2014
suspend.sh: enter
Mon Oct 20 10:40:15 CEST 2014
sleeping... zzz-zzz-zzz-zzz :)
Mon Oct 20 10:41:14 CEST 2014
suspend.sh: normal exit

I don't understand why it starts sleep 10 as a background process and subsequently waits for all background processes to finish. It seems to me that either the sleep is redundant or the waiting for background processes is redundant. The SIGTERM handler is there in case you interrupt the 10s waiting period.

[hwhw]

I think what you are seeing w/ regard to the suspend script is a historically grown mess.

Kobo input interfacing does not use SDL. It uses the (old, thus implemented a bit crude) input.c/input.h interface in base. SDL follows its API. There is no opening of any device with SDL, as SDL provides the input events. That part of the input API is a NOP for SDL.

The debug statements will produce output only when debugging is enabled - i.e. you start koreader with the "-d" flag.

That "wait endlessly" should be read in context of the "wait 100msecs" above it. In any case the waiting ends by an event... But you're right, that's the place where an event should be detected. As for debugging missing events after wake-up from suspend, I think input.c is the place to start looking. BTW: we open with (O_RDONLY | O_NONBLOCK).

[hwhw]

By the way: I've long since wanted to clean up input.c/input.h. It should be an FFI-based interface rather than being Lua/C API. Also, there's still some "emulation" code in there, i.e. SDL-interfacing. That isn't actually used anymore - there is an FFI-based interface for SDL, including input, in the "ffi" subfolder now.

[Frenzie]

The debug statements will produce output only when debugging is enabled - i.e. you start koreader with the "-d" flag.

That's what I was trying to convey: most of the debug stuff works but not all of it. Without -d you don't get any. The stable build from back in April does manage to output that stuff about auto-detecting Kobo, firmware version and resolution.

As for debugging missing events after wake-up from suspend, I think input.c is the place to start looking.

Well, technically it doesn't suspend at all. I didn't realize that initially. Although I don't think it should make a difference.

BTW: we open with (O_RDONLY | O_NONBLOCK).

Just a thought. So that's not it, then. :)

[Frenzie]

I finally got around to checking on dmesg, although only the annoying BusyBox version yet.

PM: Preparing system for mem sleep
Freezing user space processes ... freeze 1!!!!!!!!!!!!!!!!!!!!
(elapsed 0.01 seconds) done.
Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
PM: Entering mem sleep
Suspending console(s) (use no_console_suspend to debug)
[zForce_ir_touch_recv_data-221] command Deactivate ...
USB Host suspend begins
ehci_fsl_drv_suspend, pm event 
waiting for VEE stable ,please retry suspend later !!!
pm_op(): platform_pm_suspend+0x0/0x54 returns -1
PM: Device mxc_epdc_fb failed to suspend: error -1
PM: Some devices failed to suspend
ehci fsl drv resume begins: Host 1
ehci_fsl_drv_resume,pm event, wait for wakeup irq if needed
ehci_fsl_bus_resume, Host 1
PM: resume of devices complete after 41.818 msecs
PM: Finishing wakeup.
Restarting tasks ... done.

So it looks like it's the framebuffer that's be blocking standby, but it's unclear to me why that should be the case. The "waiting for VEE stable ,please retry suspend later" line comes from drivers/video/mxc/lk_tps65185.c in the kernel sources.

That's followed by this strange-looking stuff:

[drivers/input/touchscreen/zforce_i2c.c-685] zforce_i2c_close()
[zForce_ir_touch_recv_data-221] command Deactivate ...
[drivers/input/touchscreen/zforce_i2c.c-669] zforce_i2c_open()
[zForce_ir_touch_recv_data-224] command Activate (0) ...
[zForce_ir_touch_recv_data-233] command Resolution (0) ...
[zForce_ir_touch_recv_data-267] command Frequency (0) ...
[zForce_ir_touch_recv_data-242] command Configuration ...
[drivers/input/touchscreen/zforce_i2c.c-685] zforce_i2c_close()
[zForce_ir_touch_recv_data-221] command Deactivate ...
epdc_intr_work_func(4799):some thread is waiting for update !but we won't want to wake it up !
    upd_pending_list empty=1,upd_buf_free_list full=0,cur_update@9e1dcfa0,epdc_luts_active=0x1
[drivers/input/touchscreen/zforce_i2c.c-669] zforce_i2c_open()
[zForce_ir_touch_recv_data-224] command Activate (0) ...
[zForce_ir_touch_recv_data-233] command Resolution (0) ...
[zForce_ir_touch_recv_data-267] command Frequency (0) ...
[zForce_ir_touch_recv_data-242] command Configuration ...
[drivers/input/touchscreen/zforce_i2c.c-685] zforce_i2c_close()
[zForce_ir_touch_recv_data-221] command Deactivate ...
epdc_intr_work_func(4799):some thread is waiting for update !but we won't want to wake it up !

[Frenzie]

I come bearing hopeful news. I obtained what seems to be a proper sleep by executing suspend.sh from an SSH session while KOReader was running.

TPS65185 temprature data = 0x19,25
[ntx_get_battery_vol-1890] 96,bat=1010
Wifi / BT power control 0 rst 142
cd_status=1 removed
cd_status=1 removed
mmc1: Card removed and resetting controller.
mmc1: card 0001 removed
PM: Preparing system for mem sleep
Freezing user space processes ... freeze 1!!!!!!!!!!!!!!!!!!!!
(elapsed 0.01 seconds) done.
Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
PM: Entering mem sleep
Suspending console(s) (use no_console_suspend to debug)
[zForce_ir_touch_recv_data-221] command Deactivate ...
USB Host suspend begins
ehci_fsl_drv_suspend, pm event 
[sdhci_suspend-1838] skip suspend for ESD (mmc0)
PM: suspend of devices complete after 210.704 msecs
suspend wp cpu=1000000000
PM: late suspend of devices complete after 0.171 msecs
PM: early resume of devices complete after 0.101 msecs
[zForce_ir_touch_recv_data-256] command BootComplete (0)...
[zForce_ir_touch_recv_data-224] command Activate (0) ...
[zForce_ir_touch_recv_data-233] command Resolution (0) ...
[zForce_ir_touch_recv_data-267] command Frequency (0) ...
[zForce_ir_touch_recv_data-242] command Configuration ...
[sdhci_resume-1901] skip resume for ESD (mmc0)
ehci fsl drv resume begins: Host 1
ehci_fsl_drv_resume,pm event, wait for wakeup irq if needed
ehci_fsl_bus_resume, Host 1
PM: resume of devices complete after 300.483 msecs
PM: Finishing wakeup.
Restarting tasks ... done.
TPS65185 temprature data = 0x1a,26
restore vcom from -1390mV to -1390mV

This would suggest that something KOReader does while preparing for suspend is in fact blocking the device's ability to suspend. I'll have to perform some further tests on this tomorrow or in the weekend to double check. Also I will have to disable all of KOReader's power button handling to see if input might be working correctly after resuming.

[houqp]

nice, so you are able to freeze the screen and wake up afterwards with this method? could you point me to the download link for the latest kobo kernel source code?

[hwhw]

Just FYI, in a few hours (I hope), I'll be done with a large reorganisation of our device/input/screen handling code.

[Frenzie]

@houqp

nice, so you are able to freeze the screen and wake up afterwards with this method?

Yes, the screen stops responding until I press the power button to resume. It's now also confirmed by the suspend log: the double checking I referred to previously (OTA updates overwrote my debugging aids):

Fri Oct 31 09:40:34 CET 2014
suspend.sh: enter
Fri Oct 31 09:42:07 CET 2014
suspend.sh: normal exit

could you point me to the download link for the latest kobo kernel source code?

The kernel source is available here.

Commenting out the power button's definition in input.lua suffices so that I'm now able to confirm that input is still working after resume.

Once the reorganization is done, I figure the best way to debug this is by disabling all suspend/resume actions except calling suspend.sh and working up from there by re-enabling it one by one. Unfortunately because it has to be tested on the device that might take a while.

Btw, I just realized that /sys/power/state-extended was never changed back to 0, at least not by suspend.sh or KOReader. I'm not entirely sure what this means, because I seem to recall the device refusing to sleep if it wasn't 1. This is mostly a note to self to run some future tests on that, but it's probably not terribly important for the moment.

[hwhw]

It is changed back:

koreader/frontend/ui/device.lua

Line 241 in b0682b0

os.execute("echo 0 > /sys/power/state-extended")

- yes, that file is quite a mess.

[Frenzie]

Right, but by disabling KOReader's power button handling that was never called. :)

[Frenzie]

Success! I managed to track down the problem to the following lines: 210, 218, 228 and 251. With these lines commented out I get a clean suspend/resume with working input.

[hwhw]

OK, so the H2O doesn't want us to show the screensaver. Maybe, there's a bug lurking in the screensaver code, maybe it's the order of things we do - we'll see. Thank you so much for debugging!

[houqp]

Interesting, looking at the driver code, we will only run into the "waiting for VEE stable" error code path when current jiffies is less than a global value gdwSafeTick_To_TurnOFF_EP3V3. And part of the eink screen update handler does update this value to jiffies+TPS65185_EP3V3_OFFTICKS. But I don't have enough information to be sure the self.screen:refresh(0) in prepareSuspend() actually went through that code path. @Frenzie , have you tried to simply comment out that screen:refresh(0) call to get rid of the waiting for VEE stable error log?

[Frenzie]

@houqp
Yes, I did. It does seem to get rid of that particular error:

PM: Preparing system for mem sleep
Freezing user space processes ... freeze 1!!!!!!!!!!!!!!!!!!!!
(elapsed 0.01 seconds) done.
Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
PM: Entering mem sleep
Suspending console(s) (use no_console_suspend to debug)
[zForce_ir_touch_recv_data-221] command Deactivate ...
USB Host suspend begins
ehci_fsl_drv_suspend, pm event 
pmic pwrdwn delay work pending !!
pm_op(): platform_pm_suspend+0x0/0x54 returns -1
PM: Device mxc_epdc_fb failed to suspend: error -1
PM: Some devices failed to suspend
ehci fsl drv resume begins: Host 1
ehci_fsl_drv_resume,pm event, wait for wakeup irq if needed
ehci_fsl_bus_resume, Host 1
PM: resume of devices complete after 42.120 msecs
PM: Finishing wakeup.
Restarting tasks ... done.

Unfortunately, however, it also results in a lack of any log files being written after resuming. The KOReader log ends here:

# Suspending...
# show screensaver
# show widget

But the problem isn't limited to KOReader. My dmesg > dmesg_after line in suspend.sh isn't being written either, nor is my echo "exit suspend.sh". Apparently suspending a second time does result in a clean suspend/resume judging by dmesg, which finally writes something after a third failed suspend/resume. That third suspend/resume cycle is what allowed me to post that output above. Unfortunately the input issue drowns out older messages, so I'm not sure what happened. In any case, as you can see there's no waiting for VEE stable.

[houqp]

Hm... it's weird that we get another pmic pwrdwn delay work pending error though. Does it help to simply increase the reschedule time for suspend call? Say just for testing purpose, set the 2 in UIManager:scheduleIn(2, function() self:Suspend() end) to 5 or something.

[Frenzie]

No, I already tried that, although not extensively. I'll check what it does in that particular case later.

[Frenzie]

Although I could swear I tried setting UIManager:scheduleIn(2, function() self:Suspend() end) to a value as high as 20 or 30 during my very first tests, some testing on the current codebase suggests that everything proceeds smoothly with screensaver and all as long as it's set to at least 9.

I was under the impression that the Screensaver:show() line is blocking the scheduling of the suspend until it's done. Am I wrong? In any case, only in certain circumstances does it take a few seconds for the screensaver to show up, whereas the same problems occur on e.g. an ePub without a cover image where the drawing is instantaneous. I'm not sure if this points to any deeper code issues, but an obvious workaround presents itself: Frenzie@8cd8028

Something like that is probably a good idea regardless in case someone presses the power button twice within a really short time period. But with the 10 second delay it pretty much becomes a necessity.