Re: A single escape required for log_filename

Hello,

O.k. so I admit I probably should have known this already but I didn't.
Normally I setup logging to use -%a.log. However I had a requirement
today that is having me setup a flat filename... as in postgresql.log.

When I set it up, it automatically appended the time so I got:

postgresql.log.1231878270

That seems a bit, well wrong. If I say I want postgresql.log I should
get postgresql.log.

Or am I completely cranked?

Joshua D. Drake

--
PostgreSQL
Consulting, Development, Support, Training
503-667-4564 - http://www.commandprompt.com/
The PostgreSQL Company, serving since 1997

"Joshua D. Drake" <jd(at)commandprompt(dot)com> writes:
> When I set it up, it automatically appended the time so I got:
> postgresql.log.1231878270
> That seems a bit, well wrong. If I say I want postgresql.log I should
> get postgresql.log.

You'd probably reconsider around the time the log file filled your disk.
You really *don't* want a single fixed filename, you want some kind of
rotation series.

regards, tom lane

On Tue, Jan 13, 2009 at 4:20 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> "Joshua D. Drake" <jd(at)commandprompt(dot)com> writes:
>> When I set it up, it automatically appended the time so I got:
>> postgresql.log.1231878270
>> That seems a bit, well wrong. If I say I want postgresql.log I should
>> get postgresql.log.
>
> You'd probably reconsider around the time the log file filled your disk.
> You really *don't* want a single fixed filename, you want some kind of
> rotation series.

Clearly so, but it does seem a bit odd if there's really NO way to
insist on a particular fixed filename.

...Robert

Robert Haas wrote:

> > "Joshua D. Drake" <jd(at)commandprompt(dot)com> writes:
> >> When I set it up, it automatically appended the time so I got:
> >> postgresql.log.1231878270
> >> That seems a bit, well wrong. If I say I want postgresql.log I should
> >> get postgresql.log.
> >
> > You'd probably reconsider around the time the log file filled your disk.
> > You really *don't* want a single fixed filename, you want some kind of
> > rotation series.
>
> Clearly so, but it does seem a bit odd if there's really NO way to
> insist on a particular fixed filename.

Indeed ... some of us have scripts that count on a given name. Fiddling them to look for the most recent seems like an unwarranted bit of busy work. Or am I missing something ? If I _want_ a foot-deringer, isn't that my business ?

My $0.02 worth (less and less, every day)

Greg Williamson
Senior DBA
DigitalGlobe

Confidentiality Notice: This e-mail message, including any attachments, is for the sole use of the intended recipient(s) and may contain confidential and privileged information and must be protected in accordance with those provisions. Any unauthorized review, use, disclosure or distribution is prohibited. If you are not the intended recipient, please contact the sender by reply e-mail and destroy all copies of the original message.

(My corporate masters made me say this.)

On Tue, 2009-01-13 at 16:20 -0500, Tom Lane wrote:
> "Joshua D. Drake" <jd(at)commandprompt(dot)com> writes:
> > When I set it up, it automatically appended the time so I got:
> > postgresql.log.1231878270
> > That seems a bit, well wrong. If I say I want postgresql.log I should
> > get postgresql.log.
>
> You'd probably reconsider around the time the log file filled your disk.
> You really *don't* want a single fixed filename, you want some kind of
> rotation series.

I have perfectly good log rotation utility that exists on my OS. (yes I
am aware of the possibility of losing a log entry when using logrotate).
The behavior is counter-intuitive. I can either ask for a fixed filename
or I can't. PostgreSQL shouldn't say, "I know what you meant, you meant
to put a timestamp on the end".

The behavior does not appear to be documented in the code or in the
docs. (I can submit a patch for that of course)

Sincerely,

Joshua D. Drake

>
> regards, tom lane
>
--
PostgreSQL
Consulting, Development, Support, Training
503-667-4564 - http://www.commandprompt.com/
The PostgreSQL Company, serving since 1997

"Joshua D. Drake" <jd(at)commandprompt(dot)com> writes:
> I have perfectly good log rotation utility that exists on my OS. (yes I
> am aware of the possibility of losing a log entry when using logrotate).

You might think you do, but it won't work with PG; external rotators
only work with programs that respond to SIGHUP by re-opening their log
files.

> The behavior does not appear to be documented in the code or in the
> docs.

Don't know where you looked ...

log_filename (string)

When logging_collector is enabled, this parameter sets the file names of
the created log files. The value is treated as a strftime pattern, so
%-escapes can be used to specify time-varying file names. (Note that if
there are any time-zone-dependent %-escapes, the computation is done in
the zone specified by log_timezone.) If no %-escapes are present,
PostgreSQL will append the epoch of the new log file's creation
time. For example, if log_filename were server_log, then the chosen file
name would be server_log.1093827753 for a log starting at Sun Aug 29
19:02:33 2004 MST. This parameter can only be set in the postgresql.conf
file or on the server command line.

regards, tom lane

On Tue, 2009-01-13 at 16:58 -0500, Tom Lane wrote:
> "Joshua D. Drake" <jd(at)commandprompt(dot)com> writes:
> > I have perfectly good log rotation utility that exists on my OS. (yes I
> > am aware of the possibility of losing a log entry when using logrotate).
>
> You might think you do, but it won't work with PG; external rotators
> only work with programs that respond to SIGHUP by re-opening their log
> files.

copytruncate resolves this issue does it not? On that note it seems
maybe that is a smart idea (to reopen the log). PostgreSQL will already
allow you to arbitrarily change the log_filename with a HUP.

> PostgreSQL will append the epoch of the new log file's creation
> time. For example, if log_filename were server_log, then the chosen file
> name would be server_log.1093827753 for a log starting at Sun Aug 29
> 19:02:33 2004 MST. This parameter can only be set in the postgresql.conf
> file or on the server command line.

O.k. at least its documented (will go peek at my info).

Joshua D. Drake

--
PostgreSQL
Consulting, Development, Support, Training
503-667-4564 - http://www.commandprompt.com/
The PostgreSQL Company, serving since 1997

Joshua,

* Joshua D. Drake (jd(at)commandprompt(dot)com) wrote:
> When I set it up, it automatically appended the time so I got:
>
> postgresql.log.1231878270
>
> That seems a bit, well wrong. If I say I want postgresql.log I should
> get postgresql.log.
>
> Or am I completely cranked?

No. I agree with you completely. I'm also well versed in the
requirements of log handling and log rotation. Debian handles this by
passing a '-l' to pg_ctl (usually
/var/log/postgresql/postgresql-X.Y-CLUSTER.log), rotation is handled
by logrotate.

Thanks,

Stephen

* Tom Lane (tgl(at)sss(dot)pgh(dot)pa(dot)us) wrote:
> "Joshua D. Drake" <jd(at)commandprompt(dot)com> writes:
> > I have perfectly good log rotation utility that exists on my OS. (yes I
> > am aware of the possibility of losing a log entry when using logrotate).
>
> You might think you do, but it won't work with PG; external rotators
> only work with programs that respond to SIGHUP by re-opening their log
> files.

logrotate will work well enough using copytruncate. It's certainly
unfortunate that PostgreSQL doesn't provide a better mechanism.

Thanks,

Stephen

* Joshua D. Drake (jd(at)commandprompt(dot)com) wrote:
> On Tue, 2009-01-13 at 16:58 -0500, Tom Lane wrote:
> > You might think you do, but it won't work with PG; external rotators
> > only work with programs that respond to SIGHUP by re-opening their log
> > files.
>
> copytruncate resolves this issue does it not? On that note it seems
> maybe that is a smart idea (to reopen the log). PostgreSQL will already
> allow you to arbitrarily change the log_filename with a HUP.

It would certainly be nice to have a way to cause PostgreSQL to reopen
it's log file without disrupting operation. That's a much better option
than using copytruncate.

Thanks,

Stephen

Stephen Frost wrote:
> Joshua,
>
> * Joshua D. Drake (jd(at)commandprompt(dot)com) wrote:
>
>> When I set it up, it automatically appended the time so I got:
>>
>> postgresql.log.1231878270
>>
>> That seems a bit, well wrong. If I say I want postgresql.log I should
>> get postgresql.log.
>>
>> Or am I completely cranked?
>>
>
> No. I agree with you completely. I'm also well versed in the
> requirements of log handling and log rotation. Debian handles this by
> passing a '-l' to pg_ctl (usually
> /var/log/postgresql/postgresql-X.Y-CLUSTER.log), rotation is handled
> by logrotate.
>
>

Then Debian is (surprise!) not doing the smartest thing. Not using the
logging collector means you miss several possible advantages, including
CSV logs and protection against multiplexed log lines.

Surely a good log rotator allows a custom rotation action (in this case,
connecting to postgres and calling 'select pg_rotate_logfile()' )

cheers

andrew

Andrew Dunstan <andrew(at)dunslane(dot)net> writes:

> Then Debian is (surprise!) not doing the smartest thing. Not using the logging
> collector means you miss several possible advantages, including CSV logs and
> protection against multiplexed log lines.

Well it's not the smartest thing by your set of priorities. Debian's
priorities are generally to have all packages behave in consistent ways. In
particular it's very useful to be able to guarantee that all log files will go
to the same place and be governed by a single set of policies defined in a
single place.

--
Gregory Stark
EnterpriseDB http://www.enterprisedb.com
Ask me about EnterpriseDB's PostGIS support!

On Tue, Jan 13, 2009 at 4:58 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> "Joshua D. Drake" <jd(at)commandprompt(dot)com> writes:
>> I have perfectly good log rotation utility that exists on my OS. (yes I
>> am aware of the possibility of losing a log entry when using logrotate).
>
> You might think you do, but it won't work with PG; external rotators
> only work with programs that respond to SIGHUP by re-opening their log
> files.

If that were true, then we would surely want to change it so that it
always re-opens the log file in response to SIGHUP. But I don't think
it is - it seems we have pg_rotate_logfile() for that purpose.
Standard utilities like the logrotate that ships with Fedora can run
an external command after rotating the log file, and that external
command can arrange to invoke pg_rotate_logfile(). Admittedly, this
may be a little bit clunky: maybe we should always reopen the logfiles
on receipt of a SIGHUP, since there doesn't seem to be much of a
downside.

(It's true that if we go that route more people will set up external
log rotators to SIGHUP PostgreSQL, and that could increase the chance
of SIGHUP causing the postgresql.conf file to be reloaded when the
user wasn't quite ready, but that doesn't seem to be much of an
argument for not doing it. Apache does the same thing, and on one
occasion it took down my entire web server, but I don't blame the
Apache project for the fact that I left my configuration in a
screwed-up state before taking off for the weekend.)

Automatically adding the date is a much bigger problem for an external
rotator. It means that there is no way to get a constant filename. I
don't think there's a clean way to handle that situation using Red
Hat's logrotate, which may be why Red Hat's out-of-the-box PG
configuration doesn't handle PG logfiles the way it handles all of its
other log files, which may be why I wasn't really aware that PG even
HAD a log file until about six months ago.

Suggested patch attached.

...Robert

Andrew,

* Andrew Dunstan (andrew(at)dunslane(dot)net) wrote:
> Then Debian is (surprise!) not doing the smartest thing.

As Gregory pointed out, Debian is doing it for some very good reasons,
and is doing it the best it can. Also, I have a huge amount of respect
for Martin Pitt (the Debian maintainer), and if there's a better
approach or a better option, which keeps the promises we've made to our
users and works with Debian policy, I'm confident that Martin would be
more than happy to implement it. He's done some amazingly excellent
work on supporting multiple concurrent major PostgreSQL versions which
has been invaluable to us.

> Not using the logging collector means you miss several possible
> advantages, including CSV logs and protection against multiplexed
> log lines.

Users, of course, can always change it. If a user configures PG to log
in a different way, then Debian will respect that. I'd be happy to help
you find the appropriate places in the code to look (as I did) at how
it's handled.

> Surely a good log rotator allows a custom rotation action (in this case,
> connecting to postgres and calling 'select pg_rotate_logfile()' )

Yes, logrotate will happily call external applications. Maybe I'm
missing something, but obviously if PG can't be configured with a fixed
filename, pg_rotate_logfile() doesn't help the situation.

Thanks,

Stephen

Stephen Frost wrote:
>> Surely a good log rotator allows a custom rotation action (in this case,
>> connecting to postgres and calling 'select pg_rotate_logfile()' )
>>
>
> Yes, logrotate will happily call external applications. Maybe I'm
> missing something, but obviously if PG can't be configured with a fixed
> filename, pg_rotate_logfile() doesn't help the situation.
>
>
>

I should think a good rotator tool didn't need a fixed filename either.

I'm not sure what postgres does if the filename contains %% as the only
escape, although that's would be a fairly ugly hack.

cheers

andrew

Andrew Dunstan <andrew(at)dunslane(dot)net> writes:
> I'm not sure what postgres does if the filename contains %% as the only
> escape, although that's would be a fairly ugly hack.

Yes, any %-escape is enough to disable the addition of the timestamp.

Looking back at the archives, I believe the real reason it's like this
is that the original patch supported *only* a fixed filename followed by
numeric timestamp, and that the reason it was that way was that the
patch also included an early version of pg_logdir_ls() that expected the
filenames to be formatted that way. The current version of pg_logdir_ls
(see contrib/adminpack) has been adjusted to expect filenames built
according to "postgresql-%Y-%m-%d_%H%M%S.log" instead, so maybe the
original rationale is dead.

However, since there's no standard strftime escape for epoch,
Robert's proposal to rip out the functionality would break any existing
code that still depends on this formatting option. I can't say that
there is any, but by the same token he can't say there isn't.

regards, tom lane

Andrew,

* Andrew Dunstan (andrew(at)dunslane(dot)net) wrote:
> Stephen Frost wrote:
>> Yes, logrotate will happily call external applications. Maybe I'm
>> missing something, but obviously if PG can't be configured with a fixed
>> filename, pg_rotate_logfile() doesn't help the situation.
>
> I should think a good rotator tool didn't need a fixed filename either.

Sure, you could hack up something to deal with the name changing
constantly, and also hack up a script to call pg_rotate_logfile() when
necessary, and move the file to the name you want, but all in all,
that's a terrible solution, rather fragile, and worse than just using
copytruncate.

> I'm not sure what postgres does if the filename contains %% as the only
> escape, although that's would be a fairly ugly hack.

Based on my read of logfile_getname and pg_strftime/_fmt, it would
produce a '%' in the filename, but not add a timestamp. That's good,
but still kind of awkward and counter-intuitive. I'd also be a bit
concerned that the "doesn't-add-timestamp" behavior might change, and
that if we made the default configuration use that behavior we'd have to
add a huge comment above it explaining all of this so that an end-user
doesn't remove it from logfile name and break things unintentionally.

Honestly, I feel it's terrible to blatently ignore what the
administrator asked for and to not provide any mechanism for the user to
get what they want. If an administrator isn't aware or doesn't
understand log rotation issues they're going to have alot larger
problems than the PostgreSQL log.

In terms of a solution, I realize we have some backwards-compatibility
issues to deal with, but in general I think we should allow the
administrator to pick whatever filename they want. We could add another
option of 'log_add_timestamp' and default to true, though I suspect some
will be unhappy with that approach. We could change it and mention it
very clearly in the release notes as an alternative. Using
pg_rotate_log() as a way to force a log re-opening is alright, but I'd
prefer we do it on SIGHUP regardless, that's an extremely common
approach and quite reasonably, imv.

Thanks,

Stephen

> However, since there's no standard strftime escape for epoch,
> Robert's proposal to rip out the functionality would break any existing
> code that still depends on this formatting option. I can't say that
> there is any, but by the same token he can't say there isn't.

Absolutely - so the question is, is it worth the possibility of
breaking backward compatibility to get the benefit of being able to
work with an external log rotator?

I think it is.

It's hard for me to believe that the base of people who want to have
the epoch automatically appended to their log file name is very large.
The only use-case I can see for this behavior is if you wanted to
make sure that every postmaster start got its own logfile but you
didn't really care what those logfiles were called. But even if
that's your situation, why wouldn't you just use the default value in
postgresql.conf, which will also generate a new filename each time?

On the other hand, it's easy for me to believe that a lot of people
want to use external log rotators.

I think it certainly merits some mention in the release notes. But I
can't believe you'll get too many complaints. Even if people do have
to change a script or something, that's a pretty easy recovery
compared to what they'll have to do when they issue one of those fancy
new TRUNCATE commands that are now recursive. (Oh, yeah, at the end
of every month I run this script - it creates a new inherited table,
moves all of the data from the parent table to the new inherited
table, and then truncates the parent....)

...Robert

On Wednesday 14 January 2009 05:23:53 Tom Lane wrote:
> However, since there's no standard strftime escape for epoch,
> Robert's proposal to rip out the functionality would break any existing
> code that still depends on this formatting option.

If it came down to this, then I'd say rip it out. Naming log files by epoch
isn't exactly a user-friendly practice anyway, and there are equivalent but
more readable formatting options available.

On Wed, 2009-01-14 at 18:37 +0200, Peter Eisentraut wrote:
> On Wednesday 14 January 2009 05:23:53 Tom Lane wrote:
> > However, since there's no standard strftime escape for epoch,
> > Robert's proposal to rip out the functionality would break any existing
> > code that still depends on this formatting option.
>
> If it came down to this, then I'd say rip it out. Naming log files by epoch
> isn't exactly a user-friendly practice anyway, and there are equivalent but
> more readable formatting options available.

+1

Joshua D. Drake

>
--
PostgreSQL - XMPP: jdrake(at)jabber(dot)postgresql(dot)org
Consulting, Development, Support, Training
503-667-4564 - http://www.commandprompt.com/
The PostgreSQL Company, serving since 1997

> If it came down to this, then I'd say rip it out. Naming log files by epoch
> isn't exactly a user-friendly practice anyway, and there are equivalent but
> more readable formatting options available.

There are other alternatives but they're all ugly. For example, we
could make %0 (or some sequence that isn't taken) evaluate to the
empty string, or we could add another GUC to control the
interpretation of this GUC. But I don't think the ugliness is
justified in this instance.

...Robert

Peter Eisentraut wrote:
> On Wednesday 14 January 2009 05:23:53 Tom Lane wrote:
> > However, since there's no standard strftime escape for epoch,
> > Robert's proposal to rip out the functionality would break any existing
> > code that still depends on this formatting option.
>
> If it came down to this, then I'd say rip it out. Naming log files by epoch
> isn't exactly a user-friendly practice anyway, and there are equivalent but
> more readable formatting options available.

Are we doing anything about this for 8.4?

--
Bruce Momjian <bruce(at)momjian(dot)us> http://momjian.us
EnterpriseDB http://enterprisedb.com

+ If your life is a hard drive, Christ can be your backup. +

On Fri, Feb 6, 2009 at 12:44 PM, Bruce Momjian <bruce(at)momjian(dot)us> wrote:
> Peter Eisentraut wrote:
>> On Wednesday 14 January 2009 05:23:53 Tom Lane wrote:
>> > However, since there's no standard strftime escape for epoch,
>> > Robert's proposal to rip out the functionality would break any existing
>> > code that still depends on this formatting option.
>>
>> If it came down to this, then I'd say rip it out. Naming log files by epoch
>> isn't exactly a user-friendly practice anyway, and there are equivalent but
>> more readable formatting options available.
>
> Are we doing anything about this for 8.4?

The patch is trivial and unlikely to break anything, but Tom wasn't
sure it made sense to change the behavior. I believe he's in the
minority, though.

...Robert

Robert Haas wrote:
> Suggested patch attached.

I have committed your patch.