Debian Default Logging Explained

April 4, 2020
Hacking PostgreSQL Debian

I love what Debian did to make Postgres administration tasks easier. However, when I was writing the article “What’s wrong with Postgres?", I found something unexpected in my Ubuntu server.

I was trying to find Postgres log file, so I tried

postgres=# select pg_current_logfile();
 pg_current_logfile
--------------------

(1 row)

But, I know that, by default, I’ll find my logs under /var/log/postgresql, and sure enough:

[root@elinor] ll /var/log/postgresql/
drwxrwxr-t  2 root     postgres   4096 Apr  4 13:08 ./
drwxrwxr-x 10 root     syslog     4096 Apr  4 12:45 ../
-rw-r-----  1 postgres adm         563 Apr  4 13:08 postgresql-12-elinor.log

So, how did my wrapper make Postgres log without Postgres knowing it was logging?

Postgres settings

So I quickly checked the logging settings in postgresql.conf:

So, for Postgres, there was no logging to /var/log/postgresql.

pg_ctlcluster ?

I guessed that there was something in pg_ctlcluster that redirected the logs to /var/log/postgresql, so I had to dig into the Perl wrapper to find where this was instructed.

First, let’s find it:

[root@elinor] which pg_ctlcluster
/usr/bin/pg_ctlcluster

When you invoke pg_ctlcluster as root without any switch, it uses systemd to launch Postgres service:

# if we are root, redirect to systemctl unless stopping a cluster running outside systemd
} elsif ($> == 0) {
    if ($action eq 'stop' and not $unit_active) {
        # proceed with pg_ctlcluster
    } else {
        #print "Redirecting $action request to systemctl\n" if (-t 1);
        system 'systemctl', $action, "postgresql\@$version-$cluster";
        exit $? >> 8;
        # program end
    }

Systemd

So now, I needed to look at the Systemd Unit file for service postgresql@12-elinor, but I found better: I found the template unit file for Postgres services!

[...]
[Service]
Type=forking
# -: ignore startup failure (recovery might take arbitrarily long)
# the actual pg_ctl timeout is configured in pg_ctl.conf
ExecStart=-/usr/bin/pg_ctlcluster --skip-systemctl-redirect %i start
# 0 is the same as infinity, but "infinity" needs systemd 229
TimeoutStartSec=0
ExecStop=/usr/bin/pg_ctlcluster --skip-systemctl-redirect -m fast %i stop
TimeoutStopSec=1h
ExecReload=/usr/bin/pg_ctlcluster --skip-systemctl-redirect %i reload
PIDFile=/run/postgresql/%i.pid
SyslogIdentifier=postgresql@%i
# prevent OOM killer from choosing the postmaster (individual backends will
# reset the score to 0)
OOMScoreAdjust=-900
# restarting automatically will prevent "pg_ctlcluster ... stop" from working,
# so we disable it here. Also, the postmaster will restart by itself on most
# problems anyway, so it is questionable if one wants to enable external
# automatic restarts.
#Restart=on-failure
# (This should make pg_ctlcluster stop work, but doesn't:)
#RestartPreventExitStatus=SIGINT SIGTERM
[...]

And that’s where I found out that the Postgres service unit file was indeed re-entering pg_ctlcluster but this time with a switch called --skip-systemctl-redirect.

pg_ctlcluster again

So, if you’re using the switch --skip-systemctl-redirect, you’ll find out, that you’ll reach this code line:

exit &$action;

In my case, the action variable contains start, so it will execute the subroutine start which is luckily defined in the same file from line 106 to line 254.

What’s interesting is the default logfile and how it is given to Postgres:

my @options = ($pg_ctl, 'start', '-D', $info{'pgdata'}); 
my $logsize = 0;
[...]
    push @options, ('-l', $info{'logfile'}); 
[...]
    exec $pg_ctl @options or error "could not exec $pg_ctl @options: $!";

So, it means that this log file is generated using the -l (meaning --log) switch of pg_ctl.

Today, I learned that if you used the -l switch of pg_ctl logfile, the pg_current_logfile() function won’t be able to help you to find where is your log file, that’s why I recommend using Postgres settings in postgresql.conf instead of the -l switch of pg_ctl.

PGSQL Phriday #015: Primary keys: UUID, CUID, or TSID?

February 3, 2024
PGSQL Phriday PostgreSQL

PGSQL Phriday #015: UUID: let's fight!

January 27, 2024
PGSQL Phriday PostgreSQL

PGSQL Phriday #010: Log analysis

July 7, 2023
PGSQL Phriday PostgreSQL