From owner-freebsd-ports@FreeBSD.ORG Thu Dec 8 16:29:14 2005 Return-Path: X-Original-To: ports@freebsd.org Delivered-To: freebsd-ports@FreeBSD.ORG Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 3386516A420 for ; Thu, 8 Dec 2005 16:29:14 +0000 (GMT) (envelope-from sven@dmv.com) Received: from smtp-gw-cl-d.dmv.com (smtp-gw-cl-d.dmv.com [216.240.97.42]) by mx1.FreeBSD.org (Postfix) with ESMTP id 6576143D69 for ; Thu, 8 Dec 2005 16:29:10 +0000 (GMT) (envelope-from sven@dmv.com) Received: from mail-gw-cl-a.dmv.com (mail-gw-cl-a.dmv.com [216.240.97.38]) by smtp-gw-cl-d.dmv.com (8.12.10/8.12.10) with ESMTP id jB8GT8ft018284 for ; Thu, 8 Dec 2005 11:29:08 -0500 (EST) (envelope-from sven@dmv.com) Received: from lanshark.dmv.com (lanshark.dmv.com [216.240.97.46]) by mail-gw-cl-a.dmv.com (8.12.9/8.12.9) with ESMTP id jB8GT8QU007457 for ; Thu, 8 Dec 2005 11:29:08 -0500 (EST) (envelope-from sven@dmv.com) From: Sven Willenberger To: ports@freebsd.org Content-Type: text/plain Date: Thu, 08 Dec 2005 11:31:01 -0500 Message-Id: <1134059461.6351.4.camel@lanshark.dmv.com> Mime-Version: 1.0 X-Mailer: Evolution 2.4.1 Content-Transfer-Encoding: 7bit X-Scanned-By: MIMEDefang 2.48 on 216.240.97.42 X-Scanned-By: MIMEDefang 2.48 on 216.240.97.38 Cc: Subject: (no subject) X-BeenThere: freebsd-ports@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Porting software to FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 08 Dec 2005 16:29:14 -0000 I originally posted this in the slony mailing list but since this may be a FreeBSD-specific error (and since I cannot get acknowledgement from anyone on the slony list that this may be a problem with slony) I am posting to this list as well. I have had an issue with logging slony for the last release or so. Currently I am using 1.1.2 built from ports on FreeBSD 6.0 and PostgreSQL 8.0.4. There are 2 different ways I can start up the slon daemon and get logging but what appears to be happening in the background is vastly different between the two. Method 1: The daemon gets started as follows: cd /usr/local/etc/slony /usr/local/bin/slon -p /var/run/slon/slon.pid -d 1 T1 'dbname=mydb user=myuser' | /usr/local/sbin/rotatelogs slony.%a.log 86400 & the logfile then reveals: 2005-11-29 16:27:03 EST CONFIG main: slon version 1.1.2 starting up 2005-11-29 16:27:03 EST CONFIG main: local node id = 3 2005-11-29 16:27:03 EST CONFIG main: launching sched_start_mainloop 2005-11-29 16:27:03 EST CONFIG main: loading current cluster configuration 2005-11-29 16:37:30 EST DEBUG1 cleanupThread: 0.040 seconds for cleanupEvent() 2005-11-29 16:37:31 EST DEBUG1 cleanupThread: 0.584 seconds for delete logs 2005-11-29 16:48:54 EST DEBUG1 cleanupThread: 0.013 seconds for cleanupEvent() 2005-11-29 16:48:54 EST DEBUG1 cleanupThread: 0.109 seconds for delete logs 2005-11-29 17:00:50 EST DEBUG1 cleanupThread: 0.042 seconds for cleanupEvent() 2005-11-29 17:00:50 EST DEBUG1 cleanupThread: 0.329 seconds for delete logs 2005-11-29 17:11:13 EST DEBUG1 cleanupThread: 0.014 seconds for cleanupEvent() 2005-11-29 17:11:13 EST DEBUG1 cleanupThread: 0.048 seconds for delete logs every 10 minutes or so a cleanupEvent() and delete logs occur. Method 2: using the FreeBSD rc system slon is started as /usr/local/bin/slon -f /usr/local/etc/slon.conf -p /var/run/slon.pid Where slon.conf contains: syslog 2 syslog_facility 'LOCAL1' log_level 1 log_timestamp 0 pid_file '/var/run/slon.pid' cluster_name T1 conn_info 'dbname=mydb user=myuser host=localhost port=5432' I have LOCAL1 set to log to /var/log/slony.log On startup I see: Nov 30 16:06:12 billact slon[702]: [35-1] CONFIG main: slon version 1.1.2 starting up Nov 30 16:06:12 billact slon[702]: [35-2] CONFIG main: local node id = 2 Nov 30 16:06:12 billact slon[702]: [35-3] CONFIG main: launching sched_start_mainloop Nov 30 16:06:12 billact slon[702]: [35-4] CONFIG main: loading current cluster configuration But now every 10 minutes I see: Nov 30 16:16:39 billact slon[702]: [38-1] CONFIG main: slon version 1.1.2 starting up Nov 30 16:16:39 billact slon[702]: [38-2] CONFIG main: local node id = 2 Nov 30 16:16:39 billact slon[702]: [38-3] CONFIG main: launching sched_start_mainloop Nov 30 16:16:39 billact slon[702]: [38-4] CONFIG main: loading current cluster configuration Nov 30 16:16:39 billact slon[702]: [39-41] DEBUG1 cleanupThread: 0.064 seconds for cleanupEvent() Nov 30 16:16:39 billact slon[702]: [39-42] DEBUG1 cleanupThread: 0.028 seconds for delete logs ** 10 Minutes later ** Nov 30 16:28:02 billact slon[702]: [40-1] CONFIG main: slon version 1.1.2 starting up Nov 30 16:28:02 billact slon[702]: [40-2] CONFIG main: local node id = 2 Nov 30 16:28:02 billact slon[702]: [40-3] CONFIG main: launching sched_start_mainloop Nov 30 16:28:02 billact slon[702]: [40-4] CONFIG main: loading current cluster configuration Nov 30 16:28:02 billact slon[702]: [41-41] DEBUG1 cleanupThread: 0.064 seconds for cleanupEvent() Nov 30 16:28:02 billact slon[702]: [41-42] DEBUG1 cleanupThread: 0.028 seconds for delete logs Nov 30 16:28:02 billact slon[702]: [41-43] DEBUG1 cleanupThread: 0.033 seconds for cleanupEvent() Nov 30 16:28:02 billact slon[702]: [41-44] DEBUG1 cleanupThread: 0.024 seconds for delete logs ** 10 Minutes later ** Nov 30 16:39:58 billact slon[702]: [43-1] CONFIG main: slon version 1.1.2 starting up Nov 30 16:39:58 billact slon[702]: [43-2] CONFIG main: local node id = 2 Nov 30 16:39:58 billact slon[702]: [43-3] CONFIG main: launching sched_start_mainloop Nov 30 16:39:58 billact slon[702]: [43-4] CONFIG main: loading current cluster configuration Nov 30 16:39:58 billact slon[702]: [43-41] DEBUG1 cleanupThread: 0.064 seconds for cleanupEvent() Nov 30 16:39:58 billact slon[702]: [43-42] DEBUG1 cleanupThread: 0.028 seconds for delete logs Nov 30 16:39:58 billact slon[702]: [43-43] DEBUG1 cleanupThread: 0.033 seconds for cleanupEvent() Nov 30 16:39:58 billact slon[702]: [43-44] DEBUG1 cleanupThread: 0.024 seconds for delete logs Nov 30 16:39:58 billact slon[702]: [43-45] DEBUG1 cleanupThread: 0.035 seconds for cleanupEvent() Nov 30 16:39:58 billact slon[702]: [43-46] DEBUG1 cleanupThread: 0.019 seconds for delete logs And so on, each 10 minute cycle it would appear another helper thread is created as evidenced by the ever growing pair of cleanupEvent() and delete logs with each cycle. Any ideas as to a) what may be causing this and b) how to troubleshoot what is going on here? Sven