From owner-freebsd-current@FreeBSD.ORG Fri May 1 12:01:36 2015 Return-Path: Delivered-To: freebsd-current@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by hub.freebsd.org (Postfix) with ESMTPS id 83923570; Fri, 1 May 2015 12:01:36 +0000 (UTC) Received: from relay.mailchannels.net (nov-007-i535.relay.mailchannels.net [46.232.183.89]) by mx1.freebsd.org (Postfix) with ESMTP id 1A4131EF8; Fri, 1 May 2015 12:01:32 +0000 (UTC) X-Sender-Id: duocircle|x-authuser|hippie Received: from smtp5.ore.mailhop.org (ip-10-237-13-110.us-west-2.compute.internal [10.237.13.110]) by relay.mailchannels.net (Postfix) with ESMTPA id D27D25138; Fri, 1 May 2015 12:01:17 +0000 (UTC) X-Sender-Id: duocircle|x-authuser|hippie Received: from smtp5.ore.mailhop.org (smtp5.ore.mailhop.org [10.83.15.107]) (using TLSv1 with cipher DHE-RSA-AES256-SHA) by 0.0.0.0:2500 (trex/5.4.8); Fri, 01 May 2015 12:01:19 +0000 X-MC-Relay: Neutral X-MailChannels-SenderId: duocircle|x-authuser|hippie X-MailChannels-Auth-Id: duocircle X-MC-Loop-Signature: 1430481678684:3311123954 X-MC-Ingress-Time: 1430481678684 Received: from c-73-34-117-227.hsd1.co.comcast.net ([73.34.117.227] helo=ilsoft.org) by smtp5.ore.mailhop.org with esmtpsa (TLSv1.2:DHE-RSA-AES256-GCM-SHA384:256) (Exim 4.82) (envelope-from ) id 1Yo9cz-00064x-5p; Fri, 01 May 2015 12:01:09 +0000 Received: from revolution.hippie.lan (revolution.hippie.lan [172.22.42.240]) by ilsoft.org (8.14.9/8.14.9) with ESMTP id t41C17Q0053866; Fri, 1 May 2015 06:01:07 -0600 (MDT) (envelope-from ian@freebsd.org) X-Mail-Handler: DuoCircle Outbound SMTP X-Originating-IP: 73.34.117.227 X-Report-Abuse-To: abuse@duocircle.com (see https://support.duocircle.com/support/solutions/articles/5000540958-duocircle-standard-smtp-abuse-information for abuse reporting information) X-MHO-User: U2FsdGVkX1+Bu+3rthTNN3C3G73BNmGJ Message-ID: <1430481667.6170.2.camel@freebsd.org> Subject: Re: save-entropy race in 10-STABLE (was: -CURRENT)? From: Ian Lepore To: lev@FreeBSD.org Cc: Dimitry Andric , freebsd-current@freebsd.org Date: Fri, 01 May 2015 06:01:07 -0600 In-Reply-To: <554349AA.9080004@FreeBSD.org> References: <55429C8B.4000904@FreeBSD.org> <5542A700.4020708@FreeBSD.org> <554349AA.9080004@FreeBSD.org> Content-Type: text/plain; charset="us-ascii" X-Mailer: Evolution 3.12.10 FreeBSD GNOME Team Port Mime-Version: 1.0 Content-Transfer-Encoding: 7bit X-AuthUser: hippie X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.20 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 01 May 2015 12:01:36 -0000 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