Some reload events missing after resume from hibernate (Windows, patterns.json)

[codecat555]

Talon v0.2.0-305-g968a (305)

I'm running events.tail() via a pipe to the repl in a wsl terminal window. Normally, when I save my parrot patterns.json file I see the following in the output:

2022-01-26 09:35:25.791869 user\parrot\parrot_integration.py | parrot loaded 26 patterns from C:\Users\xxxx\AppData\Roaming\talon\parrot\patterns.json
2022-01-26 09:35:25.792072 user\parrot\parrot_integration.py | parrot added: cluck
2022-01-26 09:35:25.792337 user\parrot\parrot_integration.py | parrot added: tut
2022-01-26 09:35:25.792602 user\parrot\parrot_integration.py | parrot added: pop
2022-01-26 09:35:25.792964 user\parrot\parrot_integration.py | parrot added: gluck
...

After resuming from hibernate today, I found that the above messages were no longer being printed although other events were appearing. The log did show the following messages each time:

2022-01-26 09:57:02 DEBUG [~] resource (patterns.json) -> user.parrot.parrot_integration

After several attempts, I interrupted events.tail() and restarted it. At that point, things started working again.

[lunixbochs]

Are you talking about the log viewer? events.tail() shouldn't have anything to do with the messages you're showing above

[codecat555]

One of the messages shown above - the last one, dated 2022-01-26 09:57:02 - is from talon.log

The other messages shown above are from the output of events.tail(), and those are the messages that were no longer being printed after resume.

I don't know if this exists in current versions, and I wouldn't say it's the most important issue in the queue. I think I filed it just because you said you wanted to hear about anomalies.

[lunixbochs]

Got it, thanks, I was confused because events.tail doesn't itself have timestamps, but I definitely read those wrong as those timestamps don't match talon's log timestamps either.

[codecat555]

I add timestamps to the events.tail() output so I can correlate them with log output. I see, however, you are right that the timestamps don't match in this case. I probably copy/pasted the wrong bit of log, but I think the behavior is described accurately.

Here are the commands that I used to capture that events.tail() output. I ran these under WSL.

First, I have a bash function defined -

teventsall() {$ (cd "/mnt/c/Program Files/Talon"; echo 'events.tail_all()' | ./python.exe -X utf8 repl.py)$ }$

Then, in a WSL terminal window, I invoked the following alias -

alias teventslog="teventsall | ts '%Y-%m-%d %.T'| tee /mnt/c/Users/XXX/AppData/Roaming/talon/logs/\$(date +'%Y%m%d%H%M%S')-events.log"$

[lunixbochs]

This is kind of complicated, are you sure there wasn't an issue with the overall pipeline rather than events.tail itself?

[codecat555]

Well, it would be nice if I didn't have to add my own timestamps. I'm not sure that pipeline is really all that complicated, although perhaps you're referring to the WSL part...

FWIW, I sometimes run 'tail -f' on a log file in this way and I've never noticed an issue with that, even across hibernate/resume.

Anyways, note that only some - not all - events were missing. I don't know how to explain that a pipeline glitch could reliably filter out just the parrot reload messages and not the others. This isn't something that just happened once, I saw it several times before deciding to document it here.

At the time, I recall thinking that this issue could be similar to the tobii problems seen after windows hibernate/resume. I think, at one point, we established that different events need to be handled for that case (as opposed to sleep/resume) - https://github.com/talonvoice/talon/issues/342.