Current log files when rotating?

Let's say you're using logging_collector and you've put some %-escapes
into log_filename for daily log rotation. Perhaps it's daily rotation
with this pattern:

log_filename = 'postgresql-%Y-%m-%d.log'

Is there any good way to ask the server what log file name it's currently
writing to? I was trying to write something that does a "tail" on the
current log, and was hoping there was a simple way to figure out which
file that goes against. Looking for the latest timestamp or running
strftime would both work I guess, those just seemed a little heavy (was
hoping for an "alias"-sized answer) to figure out something that the
server certainly knows.

--
* Greg Smith gsmith(at)gregsmith(dot)com http://www.gregsmith.com Baltimore, MD

Greg Smith wrote:
> Let's say you're using logging_collector and you've put some %-escapes
> into log_filename for daily log rotation. Perhaps it's daily rotation
> with this pattern:
>
> log_filename = 'postgresql-%Y-%m-%d.log'
>
> Is there any good way to ask the server what log file name it's
> currently writing to? I was trying to write something that does a
> "tail" on the current log, and was hoping there was a simple way to
> figure out which file that goes against. Looking for the latest
> timestamp or running strftime would both work I guess, those just seemed
> a little heavy (was hoping for an "alias"-sized answer) to figure out
> something that the server certainly knows.
>

As long as you're using a reasonable[1] format for the date, you could
simply list postgresql-*.log and grab the last filename.

[1] eg. Year-Month-day, which will always be ordered properly.

Greg Smith <gsmith(at)gregsmith(dot)com> writes:
> Is there any good way to ask the server what log file name it's currently
> writing to? I was trying to write something that does a "tail" on the
> current log, and was hoping there was a simple way to figure out which
> file that goes against. Looking for the latest timestamp or running
> strftime would both work I guess, those just seemed a little heavy (was
> hoping for an "alias"-sized answer) to figure out something that the
> server certainly knows.

Well, the log collector subprocess knows it, but nothing else does.

regards, tom lane

On Mon, 2008-11-10 at 13:46 -0500, Greg Smith wrote:
> Let's say you're using logging_collector and you've put some %-escapes
> into log_filename for daily log rotation. Perhaps it's daily rotation
> with this pattern:
>
> log_filename = 'postgresql-%Y-%m-%d.log'
>
> Is there any good way to ask the server what log file name it's currently
> writing to? I was trying to write something that does a "tail" on the
> current log, and was hoping there was a simple way to figure out which
> file that goes against. Looking for the latest timestamp or running
> strftime would both work I guess, those just seemed a little heavy (was
> hoping for an "alias"-sized answer) to figure out something that the
> server certainly knows.
>

show log_filename;

?

Then just grab the strftime string?

Joshua D. Drake

> --
> * Greg Smith gsmith(at)gregsmith(dot)com http://www.gregsmith.com Baltimore, MD
>
--

On Mon, 2008-11-10 at 13:46 -0500, Greg Smith wrote:
> Let's say you're using logging_collector and you've put some %-escapes
> into log_filename for daily log rotation. Perhaps it's daily rotation
> with this pattern:
>
> log_filename = 'postgresql-%Y-%m-%d.log'
>
> Is there any good way to ask the server what log file name it's currently
> writing to? I was trying to write something that does a "tail" on the
> current log, and was hoping there was a simple way to figure out which
> file that goes against. Looking for the latest timestamp or running
> strftime would both work I guess, those just seemed a little heavy (was
> hoping for an "alias"-sized answer) to figure out something that the
> server certainly knows.
>

Sorry my response was dumb. That would be a pain. I checked the admin
functions and there is currently no easy way to do it. Sounds like an
easy thing to add though.

Joshua D. Drake

> --
> * Greg Smith gsmith(at)gregsmith(dot)com http://www.gregsmith.com Baltimore, MD
>
--

On Mon, Nov 10, 2008 at 01:46:14PM -0500, Greg Smith wrote:
> strftime would both work I guess, those just seemed a little heavy (was
> hoping for an "alias"-sized answer) to figure out something that the
> server certainly knows.

it's not nice, but it works:
alias pgtail='/bin/ls -1 /var/log/postgresql/postgresql*log | tail -n 1 | xargs tail -f'

of course it has some assumptions:
1. your logs are in /var/log/postgresql/ directory (easy to change)
2. your logs are named in such way that sorting them alphabetically will
sort them chronologically (i.e. %Y-%m-%d or something similar) (not easy
to change)

depesz

--
Linkedin: http://www.linkedin.com/in/depesz / blog: http://www.depesz.com/
jid/gtalk: depesz(at)depesz(dot)com / aim:depeszhdl / skype:depesz_hdl / gg:6749007

$ cat dbscripts/logtail.py
#!/usr/bin/env python

"""
usage: logtail [-d pathname][-n]
-d pathname Use pathname instead of /var/lib/postgresql/8.2/main/pg_log
-n Just print the current log file name and exit
-l List the log file names
-p [files] Run the files through pager
"""

import os, time, sys, getopt, signal

class LogTail:

"""Logfile tailer for rotated log files.

Initially purpouse was to keep tail on PostgreSQL logs, but can be used
with any application that satisfies these assumptions:

* All log files reside in the same directory.
* We can find last log file by sorting the file list alphabetically.
* When log is switched, we start tailing from the last file - assume
that
there will be no gaps (sufficiently large files).
"""

def __init__(self,logpath):
"""Initialize the logtailer, open the initial log file."""
self.logpath = logpath
self.logfile = None
self.logf = None
self.probesleft = 2
self.first = True

def getfilenames(self):
"""Return the sorted list of log file names"""
files = []
for f in os.listdir(self.logpath):
if f.startswith("postgresql-20"):
files.append(os.path.join(self.logpath, f))
files.sort()
return files

def getlogname(self):
"""Return the name of current logfile."""
files = self.getfilenames()
if files:
return files[-1]
return None

def readline(self):
"""Read single line from logfile, switch to next file if current
file is exhausted."""
while True:
# If not already open, keep trying until it becomes available
while not self.logf:
self.logfile = self.getlogname()
if not self.logfile:
# initial log file not found
time.sleep(1)
continue

try:
self.logf = open(self.logfile)
self.probesleft = 2
except IOError, msg:
time.sleep(1)

if self.first:
# seek to EOF of first file
self.first = False
self.logf.seek(0, 2)

line = self.logf.readline()
if line:
return line
self.logf.seek(0, 1) # reset EOF condition for next attempt

if self.logfile != self.getlogname():
self.probesleft -= 1
if not self.probesleft:
self.logf = None
else:
time.sleep(0.2)

def __iter__(self):
"""Initialize iterator"""
return self

def next(self):
"""Iterator wrapper for readline()"""
return self.readline()

def view_file(logpath, args):
"""Run the specified files through pager"""
lt = LogTail(logpath)
if not args:
args = [ lt.getlogname() ]
logfiles = lt.getfilenames()
for f in args:
if not f in logfiles or not os.path.exists(f):
print f, "is not a postgres log file."
sys.exit(1)

signal.signal(signal.SIGINT, signal.SIG_IGN)
os.environ["LESSSECURE"] = "1"
os.spawnv(os.P_WAIT, "/usr/bin/less", [ "less", "-n" ] + args)

def usage():
print __doc__
sys.exit(1)

def main():
logpath = "/var/lib/postgresql/8.2/main/pg_log"

try:
opts, args = getopt.getopt(sys.argv[1:], "nlpd:h")
except getopt.error, msg:
print msg
usage()

for opt,arg in opts:
if opt == "-n":
# list current file
print LogTail(logpath).getlogname()
sys.exit(0)
elif opt == "-l":
# list the log files
for f in LogTail(logpath).getfilenames():
print f
sys.exit(0)
elif opt == "-p":
# run the file through pager
view_file(logpath, args)
sys.exit(0)
elif opt == "-d":
logpath = arg;
elif opt == "-h":
usage()

try:
for line in LogTail(logpath):
sys.stdout.write(line)
sys.stdout.flush()
except KeyboardInterrupt:
pass

if __name__ == "__main__":
main()

On Mon, Nov 10, 2008 at 8:46 PM, Greg Smith <gsmith(at)gregsmith(dot)com> wrote:

> Let's say you're using logging_collector and you've put some %-escapes into
> log_filename for daily log rotation. Perhaps it's daily rotation with this
> pattern:
>
> log_filename = 'postgresql-%Y-%m-%d.log'
>
> Is there any good way to ask the server what log file name it's currently
> writing to? I was trying to write something that does a "tail" on the
> current log, and was hoping there was a simple way to figure out which file
> that goes against. Looking for the latest timestamp or running strftime
> would both work I guess, those just seemed a little heavy (was hoping for an
> "alias"-sized answer) to figure out something that the server certainly
> knows.
>
> --
> * Greg Smith gsmith(at)gregsmith(dot)com http://www.gregsmith.com Baltimore, MD
>
> --
> Sent via pgsql-general mailing list (pgsql-general(at)postgresql(dot)org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-general
>

On Mon, 2008-11-10 at 20:12 +0100, hubert depesz lubaczewski wrote:
> On Mon, Nov 10, 2008 at 01:46:14PM -0500, Greg Smith wrote:
> > strftime would both work I guess, those just seemed a little heavy (was
> > hoping for an "alias"-sized answer) to figure out something that the
> > server certainly knows.
>
> it's not nice, but it works:
> alias pgtail='/bin/ls -1 /var/log/postgresql/postgresql*log | tail -n 1 | xargs tail -f'
>
> of course it has some assumptions:
> 1. your logs are in /var/log/postgresql/ directory (easy to change)
> 2. your logs are named in such way that sorting them alphabetically will
> sort them chronologically (i.e. %Y-%m-%d or something similar) (not easy
> to change)

Hmm what about just "ls -tu"

Which if I am reading the man page correctly sorts by last access time.

Joshua D. Drake

>
> depesz
>
> --
> Linkedin: http://www.linkedin.com/in/depesz / blog: http://www.depesz.com/
> jid/gtalk: depesz(at)depesz(dot)com / aim:depeszhdl / skype:depesz_hdl / gg:6749007
>
--

On Mon, Nov 10, 2008 at 12:44 PM, Joshua D. Drake <jd(at)commandprompt(dot)com> wrote:
> On Mon, 2008-11-10 at 20:12 +0100, hubert depesz lubaczewski wrote:
>> On Mon, Nov 10, 2008 at 01:46:14PM -0500, Greg Smith wrote:
>> > strftime would both work I guess, those just seemed a little heavy (was
>> > hoping for an "alias"-sized answer) to figure out something that the
>> > server certainly knows.
>>
>> it's not nice, but it works:
>> alias pgtail='/bin/ls -1 /var/log/postgresql/postgresql*log | tail -n 1 | xargs tail -f'
>>
>> of course it has some assumptions:
>> 1. your logs are in /var/log/postgresql/ directory (easy to change)
>> 2. your logs are named in such way that sorting them alphabetically will
>> sort them chronologically (i.e. %Y-%m-%d or something similar) (not easy
>> to change)
>
> Hmm what about just "ls -tu"
>
> Which if I am reading the man page correctly sorts by last access time.

ls -tr1 filename*|tail -n 1 will give you the most recently modified
file. -tu will give you the file last accessed which may or may not
be the file you want.

On Mon, Nov 10, 2008 at 11:44:31AM -0800, Joshua D. Drake wrote:
> Hmm what about just "ls -tu"
> Which if I am reading the man page correctly sorts by last access time.

which might not be what you need. the problem is that there is no
guarantee that the last "accessed" file is the current one.

on the other hand - there is also no such guarantee for current being
"last after sorting", so there is a room for failure here anyway.

the only way to do it without having problems with "strange" names or
dates of access:

ps uw -C postgres | grep logger | awk '{print "/proc/"$2"/fd"}' | xargs ls -l | grep /var/log/postgresql | awk '{print $NF}' | xargs tail -f

but it has its own set of problems ranging from "being totally
unreadable" to "requires running on postgres user or as root".

Best regards,

depesz

--
Linkedin: http://www.linkedin.com/in/depesz / blog: http://www.depesz.com/
jid/gtalk: depesz(at)depesz(dot)com / aim:depeszhdel / skype:depesz_hdl / gg:6749007

On Mon, 2008-11-10 at 20:55 +0100, hubert depesz lubaczewski wrote:
> On Mon, Nov 10, 2008 at 11:44:31AM -0800, Joshua D. Drake wrote:
> > Hmm what about just "ls -tu"
> > Which if I am reading the man page correctly sorts by last access time.
>
> which might not be what you need. the problem is that there is no
> guarantee that the last "accessed" file is the current one.
>
> on the other hand - there is also no such guarantee for current being
> "last after sorting", so there is a room for failure here anyway.
>
> the only way to do it without having problems with "strange" names or
> dates of access:
>
> ps uw -C postgres | grep logger | awk '{print "/proc/"$2"/fd"}' | xargs ls -l | grep /var/log/postgresql | awk '{print $NF}' | xargs tail -f
>
> but it has its own set of problems ranging from "being totally
> unreadable" to "requires running on postgres user or as root".

O.k. so I think this whole thread screams TODO...

A function that allows a postgresql user to know which log file is
currently being written to.

Joshua D. Drake

>
> Best regards,
>
> depesz
>
> --
> Linkedin: http://www.linkedin.com/in/depesz / blog: http://www.depesz.com/
> jid/gtalk: depesz(at)depesz(dot)com / aim:depeszhdel / skype:depesz_hdl / gg:6749007
>
--

Greg Smith wrote:
> Let's say you're using logging_collector and you've put some %-escapes
> into log_filename for daily log rotation. Perhaps it's daily rotation
> with this pattern:
>
> log_filename = 'postgresql-%Y-%m-%d.log'
>
> Is there any good way to ask the server what log file name it's currently
> writing to? I was trying to write something that does a "tail" on the
> current log, and was hoping there was a simple way to figure out which
> file that goes against. Looking for the latest timestamp or running
> strftime would both work I guess, those just seemed a little heavy (was
> hoping for an "alias"-sized answer) to figure out something that the
> server certainly knows.

It seems that there is enough need for this feature, that it has been
implemented multiple times -- but most of them will fail in corner
cases. Seems an obvious candidate for an in-core function ...

--
Alvaro Herrera http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

On Mon, 10 Nov 2008, Joshua D. Drake wrote:

> O.k. so I think this whole thread screams TODO...

Me too; added to the TODO list on the wiki. I presumed there had to be a
simple way to handle this as the need for it seemed pretty obvious. All
of the sample scripts and shell tricks are appreciated, I'll hack together
something that works. And now that I know it's not just me I'll see if I
can expose this in a future patch.

--
* Greg Smith gsmith(at)gregsmith(dot)com http://www.gregsmith.com Baltimore, MD

Alvaro Herrera <alvherre(at)commandprompt(dot)com> writes:
> It seems that there is enough need for this feature, that it has been
> implemented multiple times -- but most of them will fail in corner
> cases. Seems an obvious candidate for an in-core function ...

... which will still fail in corner cases. Not to mention the race
condition when the logger has just/is about to switch.

regards, tom lane

On Mon, 2008-11-10 at 16:35 -0500, Tom Lane wrote:
> Alvaro Herrera <alvherre(at)commandprompt(dot)com> writes:
> > It seems that there is enough need for this feature, that it has been
> > implemented multiple times -- but most of them will fail in corner
> > cases. Seems an obvious candidate for an in-core function ...
>
> ... which will still fail in corner cases. Not to mention the race
> condition when the logger has just/is about to switch.

Which is still 99% better than the alternative.

>
> regards, tom lane
>
--

On Nov 10, 2008, at 1:35 PM, Tom Lane wrote:

> Alvaro Herrera <alvherre(at)commandprompt(dot)com> writes:
>> It seems that there is enough need for this feature, that it has been
>> implemented multiple times -- but most of them will fail in corner
>> cases. Seems an obvious candidate for an in-core function ...
>
> ... which will still fail in corner cases. Not to mention the race
> condition when the logger has just/is about to switch.

Also, it's going to be a fairly rare app that will need to both
look at the current logfile and access the database, so providing
visibility via a sql function seem clunky.

Maybe just have the logger maintain a symlink to the current
logfile, or log to a static filename and only use a dynamically
generated filename when renaming the log file during rotation?

Cheers,
Steve

On Mon, 10 Nov 2008, Tom Lane wrote:

> Alvaro Herrera <alvherre(at)commandprompt(dot)com> writes:
>> It seems that there is enough need for this feature, that it has been
>> implemented multiple times -- but most of them will fail in corner
>> cases. Seems an obvious candidate for an in-core function ...
>
> ... which will still fail in corner cases. Not to mention the race
> condition when the logger has just/is about to switch.

As you can see from the responses here, barring an official way people are
just going to hack up their own solutions that are even more error-prone
than that. A core implementation that has a documented potential for a
race condition would still be a large improvement over nothing at all
here. As long as it's atomic enough to give you either the old name or
the new one, that's good enough.

In a typical log-reading application, you're going to poll the server to
check the file name more regularly than it can possibly change. The fact
that you might get a file name that will go stale almost immediately
afterwards isn't a problem. You'll keep reading from the old file, it
won't have anything new in it for some number of minutes or hours. When
you next check the server, you'll see a new file listed, then start fresh
on that one until you catch up. In some cases, the fact that the file
name changed and the server is working on a new one is actually the
trigger you're looking for--at that point you know it's safe to run
analysis on the old file because it's complete.

I can think of some better ways to slice that switching time downward
(NOTIFY comes to mind), but I'd bet most admins wouldn't use a more
sophisticated one even if it were available--too much work compared to
something that just polls and looks for changes.

--
* Greg Smith gsmith(at)gregsmith(dot)com http://www.gregsmith.com Baltimore, MD

>> It seems that there is enough need for this feature, that it has been
>> implemented multiple times -- but most of them will fail in corner
>> cases. Seems an obvious candidate for an in-core function ...
>
> ... which will still fail in corner cases. Not to mention the race
> condition when the logger has just/is about to switch.

Best way is to integrate log retrieval into language:

select *
from pg_log_current ;
order by logtime desc
limit 1000

or

select *
from pg_log_current(1000)

Andrus.

On Mon, Nov 10, 2008 at 02:30:41PM -0800, Steve Atkins wrote:
> On Nov 10, 2008, at 1:35 PM, Tom Lane wrote:
> >Alvaro Herrera <alvherre(at)commandprompt(dot)com> writes:
> >>It seems that there is enough need for this feature, that it has been
> >>implemented multiple times -- but most of them will fail in corner
> >>cases. Seems an obvious candidate for an in-core function ...
> >
> >... which will still fail in corner cases. Not to mention the race
> >condition when the logger has just/is about to switch.
>
> Also, it's going to be a fairly rare app that will need to both
> look at the current logfile and access the database, so providing
> visibility via a sql function seem clunky.

Indeed, logfiles seem to be in a different world than from inside the
database. It seems there are a couple of options; go and ask PG when
you want to know (pg_ctl seems like a reasonable place IMHO) or have
PG tell you when it's rotating logs, ala the current archiving of WAL
files.

> Maybe just have the logger maintain a symlink to the current
> logfile,

If used; a log archival program could do this.

> or log to a static filename and only use a dynamically
> generated filename when renaming the log file during rotation?

However, this seems like a simpler solution altogether---no need to even
ask as you know the answer already!

This does still leave the question of whether there should be a log
archival program around to tell you when they actually rotate. Going
by the fact that people appear to cope with the current behavior, this
just seems unnecessarily complicated and can reasonably be delayed for a
while.

Sam

Sam Mason <sam(at)samason(dot)me(dot)uk> writes:

> On Mon, Nov 10, 2008 at 02:30:41PM -0800, Steve Atkins wrote:
>> On Nov 10, 2008, at 1:35 PM, Tom Lane wrote:
>> >Alvaro Herrera <alvherre(at)commandprompt(dot)com> writes:
>> >>It seems that there is enough need for this feature, that it has been
>> >>implemented multiple times -- but most of them will fail in corner
>> >>cases. Seems an obvious candidate for an in-core function ...
>> >
>> >... which will still fail in corner cases. Not to mention the race
>> >condition when the logger has just/is about to switch.
>>
>> Also, it's going to be a fairly rare app that will need to both
>> look at the current logfile and access the database, so providing
>> visibility via a sql function seem clunky.
>
> Indeed, logfiles seem to be in a different world than from inside the
> database. It seems there are a couple of options; go and ask PG when
> you want to know (pg_ctl seems like a reasonable place IMHO) or have
> PG tell you when it's rotating logs, ala the current archiving of WAL
> files.
>
>> Maybe just have the logger maintain a symlink to the current
>> logfile,
>
> If used; a log archival program could do this.
>
>> or log to a static filename and only use a dynamically
>> generated filename when renaming the log file during rotation?
>
> However, this seems like a simpler solution altogether---no need to even
> ask as you know the answer already!
>
> This does still leave the question of whether there should be a log
> archival program around to tell you when they actually rotate. Going
> by the fact that people appear to cope with the current behavior, this
> just seems unnecessarily complicated and can reasonably be delayed for a
> while.

If I may revive this thread...

While generally sane and lightweight, the symlink approach still leaves
the chance for a race condition at the time of the switch.

What if we add an option for logging collector to duplicate every write
to the current file to a non-blocking fifo or something like that? This
seems to solve the problem of running "tail -f" against the current log
stream, which was the original request:

http://www.postgresql.org/message-id/Pine.GSO.4.64.0811101325260.9276@westnet.com

The fifo, however only allows for only one reader connection if I'm not
missing something.

--
Alex