axkibe/lsyncd — Issue #80: lsyncd spinning 100% CPU, writing "Normal: waiting for 1 more child processes" indefinitely to the log
Author: axkibe
Created: 2011-11-16 15:09:47+00:00
State: open

Originally filed by ari...@gmail.com on 2011-08-26T19:25:04

What steps will reproduce the problem?
1. Some event over long periods of runtime triggers this. It is often accompanied by a defunct rsync process, so that seems like the likely problem. It appears lsyncd is busy waiting for a process that doesn't exist any longer or is defunct.

What is the expected behavior? What does Lsyncd do instead?

lsyncd should not be spinning waiting on a non-existent or defunct rsync process. Instead, the spinning consumes lots of CPU and this never resolves itself leaving the logs to fill up the filesystem. Paste of the output of an strace on the process when it is spinning:

...
times(NULL) = 678493293
open("/var/log/lsyncd/lsyncd.log", O_WRONLY|O_CREAT|O_APPEND, 0666) = 4
fstat(4, {st_mode=S_IFREG|0644, st_size=6052297879, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2b1498d46000
fstat(4, {st_mode=S_IFREG|0644, st_size=6052297879, ...}) = 0
lseek(4, 6052297879, SEEK_SET) = 6052297879
write(4, "Thu Aug 25 15:03:39 2011 Normal: waiting for 1 more child processes.\n", 69) = 69
close(4) = 0
munmap(0x2b1498d46000, 4096) = 0
times(NULL) = 678493294
wait4(0, 0x7fff629f1168, WNOHANG, NULL) = 0
times(NULL) = 678493294
open("/var/log/lsyncd/lsyncd.log", O_WRONLY|O_CREAT|O_APPEND, 0666) = 4
fstat(4, {st_mode=S_IFREG|0644, st_size=6052297948, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2b1498d46000
fstat(4, {st_mode=S_IFREG|0644, st_size=6052297948, ...}) = 0
lseek(4, 6052297948, SEEK_SET) = 6052297948
write(4, "Thu Aug 25 15:03:39 2011 Normal: waiting for 1 more child processes.\n", 69) = 69
close(4) = 0
munmap(0x2b1498d46000, 4096) = 0
times(NULL) = 678493294
wait4(0, 0x7fff629f1168, WNOHANG, NULL) = 0
times(NULL) = 678493294
open("/var/log/lsyncd/lsyncd.log", O_WRONLY|O_CREAT|O_APPEND, 0666) = 4
fstat(4, {st_mode=S_IFREG|0644, st_size=6052298017, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2b1498d46000
fstat(4, {st_mode=S_IFREG|0644, st_size=6052298017, ...}) = 0
lseek(4, 6052298017, SEEK_SET) = 6052298017
write(4, "Thu Aug 25 15:03:39 2011 Normal: waiting for 1 more child processes.\n", 69) = 69
close(4) = 0
munmap(0x2b1498d46000, 4096) = 0
times(NULL) = 678493294
wait4(0, 0x7fff629f1168, WNOHANG, NULL) = 0
times(NULL) = 678493294
open("/var/log/lsyncd/lsyncd.log", O_WRONLY|O_CREAT|O_APPEND, 0666) = 4
fstat(4, {st_mode=S_IFREG|0644, st_size=6052298086, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2b1498d46000
fstat(4, {st_mode=S_IFREG|0644, st_size=6052298086, ...}) = 0
lseek(4, 6052298086, SEEK_SET) = 6052298086
write(4, "Thu Aug 25 15:03:39 2011 Normal: waiting for 1 more child processes.\n", 69) = 69
close(4) = 0
munmap(0x2b1498d46000, 4096) = 0
times(NULL) = 678493294
...

What version of Lsyncd are you using? On what operating system (host and
target(s)?

2.0.4 Centos 5.6, with a single custom patch to specify the rsync bin path and fix an issue where a spin occurs when rsync binary isn't available or dest hostname is invalid. Relevant portion of the patch:

@@ -3069,7 +3075,7 @@
[ 25] = "die",
[ 30] = "again",
[ 35] = "again",
-	[255] = "again",
+--	[255] = "again", -- dont, consisten failure, if e.g. rsync binary not available or dest hostname invalid
}

Full patch attached

If applicable please copy/paste your Lsyncd configuration file.

--- This file is generated by puppet
settings = {
logfile = "/var/log/lsyncd/lsyncd.log",
statusFile = "/var/run/lsyncd/lsyncd.status",
nodaemon = false,
}
sync{default.rsyncssh, source="/home", host="user@server", targetdir="/home", rsyncOps={"-au", "--exclude", "*.lock", "--exclude", "*.newlock"}, exclude={"dovecot-uidlist.lock", "dovecot.index.log.newlock", "dovecot.index.cache.lock", "subscriptions.lock", "dovecot-keywords.lock"}, init=false}

If applicable please copy/paste a logfile generated with '-log all' of a
minimal testcase that raises this problem.

Please provide any additional information below.

Everything runs fine for tens of thousands of updates until it gets to this point. It's intermittent when the failure occurs, but it seems reasonable a fix can be made to not indefinitely wait on something that will never return...at least not busy wait indefinitely and eat up CPU.