EnterpriseDB / barman

Barman - Backup and Recovery Manager for PostgreSQL
https://www.pgbarman.org/
GNU General Public License v3.0
2.13k stars 193 forks source link

stderr logging does not work for `barman cron` subprocesses #243

Closed SpComb closed 5 years ago

SpComb commented 5 years ago

I would like to run barman inside a Docker container, with all barman logs going to the normal Docker console logs rather than a logfile. This is mostly easy enough by just leaving the log_file = ... unconfigured so that barman defaults to stderr logging.

However, the barman commands launched by barman cron will never write their logs anywhere in this configuration, because the cron command BarmanSubProcess redirects stderr to /dev/null.

Ideally, the subprocesses launched by barman cron in this configuration would keep their stderr open for logging purposes.

SpComb commented 5 years ago

Testing with the following hacky patch results in the desired behavior when running barman cron under supercronic:

diff --git a/barman/command_wrappers.py b/barman/command_wrappers.py
index f401c6f..3aa6b11 100644
--- a/barman/command_wrappers.py
+++ b/barman/command_wrappers.py
@@ -1013,7 +1013,7 @@ class BarmanSubProcess(object):
         proc = subprocess.Popen(
             self.command,
             preexec_fn=os.setsid, close_fds=True,
-            stdin=devnull, stdout=devnull, stderr=devnull)
+            stdin=devnull, stdout=devnull)
         _logger.debug("BarmanSubProcess: subprocess started. pid: %s",
                       proc.pid)

Output

[terom@xxx-backup-dev1 ~]$ docker logs -f barman
time="2019-10-09T14:08:32Z" level=info msg="read crontab: /etc/supercronic/crontab"
time="2019-10-09T14:09:00Z" level=info msg=starting iteration=0 job.command="/usr/bin/barman cron" job.position=0 job.schedule="* *  * * *"
time="2019-10-09T14:09:00Z" level=info msg="Starting WAL archiving for server xxx-postgres-dev1@11" channel=stdout iteration=0 job.command="/usr/bin/barman cron" job.position=0 job.schedule="* *  * * *"
time="2019-10-09T14:09:01Z" level=info msg="Starting streaming archiver for server xxx-postgres-dev1@11" channel=stdout iteration=0 job.command="/usr/bin/barman cron" job.position=0 job.schedule="* *  * * *"
time="2019-10-09T14:09:01Z" level=info msg="2019-10-09 14:09:01,952 [27] barman.wal_archiver INFO: No xlog segments found from streaming for xxx-postgres-dev1@11." channel=stderr iteration=0 job.command="/usr/bin/barman cron" job.position=0 job.schedule="* *  * * *"
time="2019-10-09T14:09:03Z" level=info msg="2019-10-09 14:09:03,023 [28] barman.server INFO: Starting receive-wal for server xxx-postgres-dev1@11" channel=stderr iteration=0 job.command="/usr/bin/barman cron" job.position=0 job.schedule="* *  * * *"
time="2019-10-09T14:09:04Z" level=info msg="2019-10-09 14:09:04,712 [28] barman.wal_archiver INFO: Activating WAL archiving through streaming protocol" channel=stderr iteration=0 job.command="/usr/bin/barman cron" job.position=0 job.schedule="* *  * * *"
time="2019-10-09T14:09:06Z" level=info msg="2019-10-09 14:09:06,283 [28] barman.command_wrappers INFO: xxx-postgres-dev1@11: pg_receivewal: starting log streaming at 2/2B000000 (timeline 1)" channel=stderr iteration=0 job.command="/usr/bin/barman cron" job.position=0 job.schedule="* *  * * *"