save-entropy race in 10-STABLE (was: -CURRENT)?

[Ian Lepore]

On Fri, 2015-05-01 at 12:38 +0300, Lev Serebryakov wrote:
> On 01.05.2015 01:21, Dimitry Andric wrote:
> 
>  First of all, I should not write messages after 12 hours working day
> in the end of the week. Of course, I have 10-STABLE on this server.
> So, mailing list is not appropriate, sorry. But problem is true one.
> 
> >> % sudo grep -R save-entropy /etc /var/cron/tabs /etc/crontab:*/11
> >> *       *       *       *       operator 
> >> /usr/libexec/save-entropy %
> >> 
> >> Nothing wrong!
> > 
> > Ok, and what does /var/log/cron say about it?  Any chance there
> > might be two instances of the cron daemon running?
> % sudo ps -ax | grep cron
>  1457  -  Ss        0:02.46 /usr/sbin/cron -s
>  9980  0  S+        0:00.00 grep cron
> %
> 
> But in logs command is mentioned twice sometimes (note 03:03)!
> 
> May  1 02:00:00 onlyone /usr/sbin/cron[93867]: (operator) CMD
> (/usr/libexec/save-entropy)
> May  1 02:11:00 onlyone /usr/sbin/cron[94254]: (operator) CMD
> (/usr/libexec/save-entropy)
> May  1 02:22:00 onlyone /usr/sbin/cron[94289]: (operator) CMD
> (/usr/libexec/save-entropy)
> May  1 02:33:00 onlyone /usr/sbin/cron[94400]: (operator) CMD
> (/usr/libexec/save-entropy)
> May  1 02:44:00 onlyone /usr/sbin/cron[94512]: (operator) CMD
> (/usr/libexec/save-entropy)
> May  1 03:03:25 onlyone /usr/sbin/cron[94636]: (operator) CMD
> (/usr/libexec/save-entropy)
> May  1 03:03:25 onlyone /usr/sbin/cron[94632]: (operator) CMD
> (/usr/libexec/save-entropy)
> May  1 03:11:00 onlyone /usr/sbin/cron[95113]: (operator) CMD
> (/usr/libexec/save-entropy)
> May  1 03:22:00 onlyone /usr/sbin/cron[95146]: (operator) CMD
> (/usr/libexec/save-entropy)
> May  1 03:33:00 onlyone /usr/sbin/cron[95252]: (operator) CMD
> (/usr/libexec/save-entropy)
> May  1 03:44:00 onlyone /usr/sbin/cron[96168]: (operator) CMD
> (/usr/libexec/save-entropy)
> May  1 03:55:00 onlyone /usr/sbin/cron[96279]: (operator) CMD
> (/usr/libexec/save-entropy)
> 
> 
>  And with "cut | uniq -c" magic I found second command with same
> problem: /usr/libexec/atrun
> 
>  Again, about every second day it is executed twice at same time.
> 
>  Logs show, that it is NOT happen with every "save-entropy" or "atrun"
> execution, only as often as I get these "save-entropy" complains.

It looks like the events that should have run at 02:55:00 and 03:00:00
were both run at 03:03:25.  Does this same sort of pattern exist in
other instances of the error?

I don't have any theory about why the start of the jobs would get
delayed like that.

-- Ian