(no subject)

[Sven Willenberger]

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
<snip>
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
<snip>
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
<snip>
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
<snip>
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