bug#39824: 26.2; timers sometimes stop working when coming back from sleep

[Eli Zaretskii <eliz@gnu.org>]

> From: Gijs Hillenius <gijs@hillenius.net>
> Cc: 39824@debbugs.gnu.org
> Date: Wed, 01 Apr 2020 09:09:35 +0200
> 
> I need a bit of help with instrumenting this correctly:

See below for some ideas.

> I've instrumented (run-at-time "10:35" 21600 'org-mobile-push)
> 
> using (evel-defun) C-M-x
> 
> This shows org-mobile-push runs without errors. In *Messages*:
> 
> (snip)
> Edebug: edebug-anon11
> Tracing...
> Result: [nil 24189 51396 0 21600 org-mobile-push nil nil 0]

This time corresponds to 2020-03-27 10:35:00.  Did you show the timer
before or after the call to timer-inc-time in timer-event-handler,
which calls your timer function?  If this is after timer-inc-time was
called, then the above is the time of the _next_ timer invocation.  I
think it would be useful to log in *Messages* also the value of
current-time when the timer runs.

> Creating agendas...
> Preparing diary...done
> 
> [...] ten lines equal to this ^ one
> 
> Preparing diary...done
> Agenda written to Org file /home/gijs/d/MobileOrg/agendas.org
> Creating agendas...done
> Saving all Org buffers... done
> Copying files...
> Writing index file...
> Writing checksums...
> Files for mobile viewer staged
> [nil 24190 7460 0 21600 org-mobile-push nil nil 0]

This time corresponds to 2020-03-27 16:35:00, the next time your timer
should fire.

> M-x list-timers tells me:
> 
>       -71245.81   360.00 org-mobile-push
> 
> and eh, a little later, the variable value of list-timers shows:
> 
> ([t 24188 52132 0 21600 org-mobile-push nil nil 0]

But this time corresponds to 2020-03-26 16:35:00, i.e. the _previous_
day.  How could this have happened?

> But then...  I guess (eval-defun) has run. I was expecting it to run
> again in six hours?  I can wait all day, put the laptop to sleep, but
> the timer won't repeat. The next day the list-timer will show a minus
> sign for org-mobile-push, for example
> 
> -54728.53   360.00 org-mobile-push
> 
> and looking at /home/gijs/d/MobileOrg/agendas.org will show me the files
> were updated only when I eval-defun'ed (run-at-time "10:35" 21600
> 'org-mobile-push) the day before. Not at 10:35, not "six hours" later,
> not the next morning.

So you are saying that the messages in *Messages* that report the
update of /home/gijs/d/MobileOrg/agendas.org on 2020-03-27 10:35:00
are a lie, and no update actually happened at that time?  That would
be surprising, since Emacs says it wrote the file.  Or am I missing
something?  Maybe the time value shown there is the time of the _next_
timer trigger?

> Did I evel-defun'ed org-mobile-push, instead of run-at-time?

I cannot know that.  But what I had in mind was to add 'message' calls
in timer-event-handler, where it calls the timer function, increments
the time to calculate the next time the timer should run, and sets the
first element of the timer vector to nil.  Then we might have a better
idea what happens there when this strange problem occurs.  In
particular, I now wonder how come timer-inc-time returned the time for
the _previous_ day (assuming it was that function which did it).

Thanks.