PostgreSQL logging, strftime, and you

Reading time ~5 minutes

PostgreSQL has a pretty extensive logging facility. I’ve talked briefly about configuring it to get the most out of pgBadger before, but today I’m gonna talk a bit about the naming of the log file itself. The chosen filename doesn’t have to be static. You can, in fact, have the name dynamically created by using strftime() escapes. But what exactly are those?

    The strftime() function formats the information from timeptr into the buffer s,
    according to the string pointed to by format.

    The format string consists of zero or more conversion specifications and ordi-
    nary characters.  All ordinary characters are copied directly into the buffer.
    A conversion specification consists of a percent sign ```%''' and one other
    character.

Say what? Essentially, given a timestamp and a format specification, you’ll get the timestamp back in a different formatted output. So what are these format specifications? Well, they are defined by your systems libc implementation. On Linux, this is (typically) glibc, whereas on OSX and the BSDs, it’s BSD libc. You really shouldn’t see a difference between these two, but it could happen. On macOS Sierra, they are (for the examples below, we’ll use today’s date of Monday, November 21, 2016 with a timestamp of 1pm EST):

    %A    is replaced by national representation of the full weekday name ("Monday")
    %a    is replaced by national representation of the abbreviated weekday name ("Mon")
    %B    is replaced by national representation of the full month name ("November")
    %b    is replaced by national representation of the abbreviated month name ("Nov")
    %C    is replaced by (year / 100) as decimal number; single digits are preceded by a zero ("20")
    %c    is replaced by national representation of time and date ("Mon Nov 21 13:00:00 2016")
    %D    is equivalent to ``%m/%d/%y'' ("11/21/16")
    %d    is replaced by the day of the month as a decimal number (01-31) ("21")
    %e    is replaced by the day of the month as a decimal number (1-31); single digits are preceded by a blank ("21")
    %F    is equivalent to ``%Y-%m-%d'' ("2016-11-21")
    %G    is replaced by a year as a decimal number with century.  This year is the one that contains the greater part of the week (Monday as the first day of the week) ("2016")
    %g    is replaced by the same year as in ``%G'', but as a decimal number without century (00-99) ("16")
    %H    is replaced by the hour (24-hour clock) as a decimal number (00-23) ("12")
    %h    the same as %b ("Nov")
    %I    is replaced by the hour (12-hour clock) as a decimal number (01-12) ("12")
    %j    is replaced by the day of the year as a decimal number (001-366) ("326")
    %k    is replaced by the hour (24-hour clock) as a decimal number (0-23); single digits are preceded by a blank ("13")
    %l    is replaced by the hour (12-hour clock) as a decimal number (1-12); single digits are preceded by a blank (" 1")
    %M    is replaced by the minute as a decimal number (00-59) ("00")
    %m    is replaced by the month as a decimal number (01-12) ("11")
    %n    is replaced by a newline
    %p    is replaced by national representation of either "ante meridiem" (a.m.) or "post meridiem" (p.m.)  as appropriate ("PM")
    %R    is equivalent to ``%H:%M'' ("13:00")
    %r    is equivalent to ``%I:%M:%S %p'' ("01:00:00 PM")
    %S    is replaced by the second as a decimal number (00-60) ("00")
    %s    is replaced by the number of seconds since the Epoch, UTC ("1479751200")
    %T    is equivalent to ``%H:%M:%S'' ("13:00:00")
    %t    is replaced by a tab
    %U    is replaced by the week number of the year (Sunday as the first day of the week) as a decimal number (00-53) ("47")
    %u    is replaced by the weekday (Monday as the first day of the week) as a decimal number (1-7) ("1")
    %V    is replaced by the week number of the year (Monday as the first day of the week) as a decimal number (01-53).  If the week containing January 1 has four or more days in the new year, then it is week 1; otherwise it is the last week of the previous year, and the next week is week 1 ("47")
    %v    is equivalent to ``%e-%b-%Y'' ("21-Nov-2016")
    %W    is replaced by the week number of the year (Monday as the first day of the week) as a decimal number (00-53) ("47")
    %w    is replaced by the weekday (Sunday as the first day of the week) as a decimal number (0-6) ("1")
    %X    is replaced by national representation of the time ("13:00:00")
    %x    is replaced by national representation of the date ("11/21/2016")
    %Y    is replaced by the year with century as a decimal number ("2016")
    %y    is replaced by the year without century as a decimal number (00-99) ("16")
    %Z    is replaced by the time zone name ("EST")
    %z    is replaced by the time zone offset from UTC; a leading plus sign stands for east of UTC, a minus sign for west of UTC, hours and minutes follow with two digits each and no delimiter between them ("-0500")
    %%    is replaced by `%'

Phew! That was a lot wasn’t it? And where exactly does this come into play? As the postgresql.conf says:

log_filename = 'postgresql-%a.log'      # log file name pattern,
                                        # can include strftime() escapes

So, you can use any of the escapes above to craft a filename that automagically gets updated according to the current timestamp. In my example above, I’m getting PostgreSQL to create a new logfile with the local weekday abbreviation. So my $PGDATA/pg_log directory will only ever contain:

postgresql-Sun.log postgresql-Mon.log postgresql-Tue.log
postgresql-Wed.log postgresql-Thu.log postgresql-Fri.log
postgresql-Sat.log

But wait! The key to all this is that PostgreSQL only evaluates the filename when it first opens/creates the logfile. So, if you start your cluster on Mon and do not restart it and don’t have it configured to log rotate, you’ll still be writing to postgresql-Mon.log forever. Fortunately, PostgreSQL has you covered here too:

log_rotation_age = 1d      # Automatic rotation of logfiles will
                           # happen after that time.  0 disables.
log_rotation_size = 10MB   # Automatic rotation of logfiles will
                           # happen after that much log output.
                           # 0 disables.

So, using my log_filename from above, I enable log_rotation_age (set to 1 day) and disable log_rotation_size and I automatically get a new log every day. If I wanted hourly logs, I could do something like:

log_filename = 'postgresql-%a-%H'
log_rotation_age = 1h

which would give me logs of postgresql-Mon-00, postgresql-Mon-01, etc. You should be able to see how combining these three postgresql.conf parameters and some crafty strftime() escapes gives you a ton of flexibility in your logging. So go forth and tweak those logs!

updated PostgreSQL homebrew script

With the release of PostgreSQL 10, I've updated my `pg` script. You might recall from previous posts that this script is for Homebrew use...… Continue reading

When you cannot get there from here

Published on July 25, 2017

Installing pgBackRest on OSX

Published on June 14, 2017