Thread: Proposal: leave a hint when switching logging away from stderr
The attached patch is motivated by http://www.postgresql.org/message-id/CAJYQwwRYt9RMBzs-sH6uCr1OTG4joXqkDF-fkoYP6pv12t0dsQ@mail.gmail.com in which it appears that Oliver Elphick forgot to look in the configured log_directory directory for log output, and instead examined only the file that postmaster stderr was initially being sent to. He's far from the first to make such a mistake, and if a PG hacker of his standing can forget about this, I think we've got a usability issue we ought to do something about. This patch arranges to emit a hint message when/if we switch away from logging to the original postmaster stderr during startup. There are two cases to cover: we're still using LOG_DESTINATION_STDERR but redirecting stderr to a syslogger process, or we stop writing to stderr altogether, presumably in favor of going to syslog or something. I thought about trying to leave similar breadcrumbs if the logging parameters are changed while the postmaster is running, but it would add a fair amount of complication to the patch, and I'm not sure there's a lot of value in it. On-the-fly logging parameter changes don't happen without active DBA involvement, so it's a lot harder to credit that somebody would not be expecting the data to start going somewhere else. Thoughts? In particular, anyone want to bikeshed on the message wording? Does this rise to the level of a usability bug that ought to be back-patched? As I said, we've seen this type of thinko multiple times before. regards, tom lane diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c index e6d750d..dcb04cf 100644 *** a/src/backend/postmaster/postmaster.c --- b/src/backend/postmaster/postmaster.c *************** PostmasterMain(int argc, char *argv[]) *** 1164,1170 **** --- 1164,1180 ---- * Log_destination permits. We don't do this until the postmaster is * fully launched, since startup failures may as well be reported to * stderr. + * + * If we are in fact disabling logging to stderr, first emit a log message + * saying so, to provide a breadcrumb trail for users who may not remember + * that they configured logging to go somewhere else. */ + if (!(Log_destination & LOG_DESTINATION_STDERR)) + ereport(LOG, + (errmsg("ending log output to stderr"), + errhint("Future log output will go to log destination \"%s\".", + Log_destination_string))); + whereToSendOutput = DestNone; /* diff --git a/src/backend/postmaster/syslogger.c b/src/backend/postmaster/syslogger.c index e3b6102..957843f 100644 *** a/src/backend/postmaster/syslogger.c --- b/src/backend/postmaster/syslogger.c *************** SysLogger_Start(void) *** 634,639 **** --- 634,653 ---- /* now we redirect stderr, if not done already */ if (!redirection_done) { + #ifdef WIN32 + int fd; + #endif + + /* + * Leave a breadcrumb trail when redirecting, since many + * people have been misled by seeing some output to postmaster + * stderr and thinking that that's all there is. + */ + ereport(LOG, + (errmsg("redirecting log output to logging collector process"), + errhint("Look in directory \"%s\" for future log output.", + Log_directory))); + #ifndef WIN32 fflush(stdout); if (dup2(syslogPipe[1], fileno(stdout)) < 0) *************** SysLogger_Start(void) *** 649,656 **** close(syslogPipe[1]); syslogPipe[1] = -1; #else - int fd; - /* * open the pipe in binary mode and make sure stderr is binary * after it's been dup'ed into, to avoid disturbing the pipe --- 663,668 ---- diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c index a812ccd..a415b90 100644 *** a/src/backend/utils/error/elog.c --- b/src/backend/utils/error/elog.c *************** emit_log_hook_type emit_log_hook = NULL; *** 109,114 **** --- 109,115 ---- int Log_error_verbosity = PGERROR_VERBOSE; char *Log_line_prefix = NULL; /* format for extra log line info */ int Log_destination = LOG_DESTINATION_STDERR; + char *Log_destination_string = NULL; #ifdef HAVE_SYSLOG diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c index 2b753f8..8c9e9a9 100644 *** a/src/backend/utils/misc/guc.c --- b/src/backend/utils/misc/guc.c *************** int tcp_keepalives_count; *** 444,451 **** * cases provide the value for SHOW to display. The real state is elsewhere * and is kept in sync by assign_hooks. */ - static char *log_destination_string; - static char *syslog_ident_str; static bool phony_autocommit; static bool session_auth_is_superuser; --- 444,449 ---- *************** static struct config_string ConfigureNam *** 2871,2877 **** "depending on the platform."), GUC_LIST_INPUT }, ! &log_destination_string, "stderr", check_log_destination, assign_log_destination, NULL }, --- 2869,2875 ---- "depending on the platform."), GUC_LIST_INPUT }, ! &Log_destination_string, "stderr", check_log_destination, assign_log_destination, NULL }, diff --git a/src/include/utils/elog.h b/src/include/utils/elog.h index 6df0d37..59d6f5e 100644 *** a/src/include/utils/elog.h --- b/src/include/utils/elog.h *************** typedef enum *** 428,433 **** --- 428,434 ---- extern int Log_error_verbosity; extern char *Log_line_prefix; extern int Log_destination; + extern char *Log_destination_string; /* Log destination bitmap */ #define LOG_DESTINATION_STDERR 1
* Tom Lane (tgl@sss.pgh.pa.us) wrote:
> Thoughts? In particular, anyone want to bikeshed on the message wording?
Looks like a good idea to me and the wording looks fine to me.
> Does this rise to the level of a usability bug that ought to be
> back-patched? As I said, we've seen this type of thinko multiple
> times before.
For this, I'd say to not back-patch it; we seem to have had enough fun
with changing error messaging in back branches already lately (eg:
the recent autovacuum changes..).
Thanks,
Stephen
Stephen Frost <sfrost@snowman.net> writes:
> * Tom Lane (tgl@sss.pgh.pa.us) wrote:
>> Does this rise to the level of a usability bug that ought to be
>> back-patched? As I said, we've seen this type of thinko multiple
>> times before.
> For this, I'd say to not back-patch it; we seem to have had enough fun
> with changing error messaging in back branches already lately (eg:
> the recent autovacuum changes..).
Well, since these would be new messages, they'd just not get translated
(until the translators got around to them). Seems like the worst case
scenario is that someone who didn't understand the English version would
remain as clueless as before, which isn't much of a downside.
regards, tom lane
Tom, > I thought about trying to leave similar breadcrumbs if the logging > parameters are changed while the postmaster is running, but it would add a > fair amount of complication to the patch, and I'm not sure there's a lot > of value in it. On-the-fly logging parameter changes don't happen without > active DBA involvement, so it's a lot harder to credit thaat somebody would > not be expecting the data to start going somewhere else. Well, I think doing that ALSO would be worthwhile for the TODO list. I've often wished, for example, that if we switch log_directory the *last* message in the old log file be "reloading postgresql with new configuration" or something similar, so that I would know to look for a new log file somewhere else. If you are, for example, logging only errors, you wouldn't necessarily realize that logging on the file you're tailing/monitoring has stopped. The "active DBA involvement" argument doesn't hold much water given the many avenues for someone to accidentally introduce a configuration change they didn't intend. However, I also realize that the complexity of this feature's implementation would likely eclipse its usefulness. As such, I'd like to put it on the TODO list for some future occasion when we need to mess with log-switching code *anyway* and can include this. > > Thoughts? In particular, anyone want to bikeshed on the message wording? > > Does this rise to the level of a usability bug that ought to be > back-patched? As I said, we've seen this type of thinko multiple > times before. Hmmm. On the one hand, I can't see the harm in it. On the other hand, I'm reluctant to introduce non-critical behavior changes into backbranches no matter how minor. What if we just put this in 9.3 and up? -- Josh Berkus PostgreSQL Experts Inc. http://pgexperts.com
Josh, Tom,
* Josh Berkus (josh@agliodbs.com) wrote:
> > Does this rise to the level of a usability bug that ought to be
> > back-patched? As I said, we've seen this type of thinko multiple
> > times before.
>
> Hmmm. On the one hand, I can't see the harm in it. On the other hand,
> I'm reluctant to introduce non-critical behavior changes into
> backbranches no matter how minor. What if we just put this in 9.3 and up?
I'd be fine w/ this going into 9.3. What was perhaps not entirely clear
from my last mail is that I was complaining about the autovacuum changes
in 9.2.3 (iirc?) which caused it to be more "chatty" which likely
surprised some poor DBAs.
Thanks,
Stephen
On Thu, Aug 08, 2013 at 10:32:17PM -0400, Tom Lane wrote: > The attached patch is motivated by > http://www.postgresql.org/message-id/CAJYQwwRYt9RMBzs-sH6uCr1OTG4joXqkDF-fkoYP6pv12t0dsQ@mail.gmail.com > This patch arranges to emit a hint message when/if we switch away from > logging to the original postmaster stderr during startup. There are two > cases to cover: we're still using LOG_DESTINATION_STDERR but redirecting > stderr to a syslogger process, or we stop writing to stderr altogether, > presumably in favor of going to syslog or something. At LOG level, this feels a bit chatty: it's a 100% increase in startup-time messages if you count both the main message and the HINT. I can't think of another program with configuration-directed logging that does this on every startup. Makes perfect sense to me at DEBUG1, though, and that would have been enough for the situation you cite above. -- Noah Misch EnterpriseDB http://www.enterprisedb.com
Josh Berkus <josh@agliodbs.com> writes:
> Tom,
>> I thought about trying to leave similar breadcrumbs if the logging
>> parameters are changed while the postmaster is running, but it would add a
>> fair amount of complication to the patch, and I'm not sure there's a lot
>> of value in it. On-the-fly logging parameter changes don't happen without
>> active DBA involvement, so it's a lot harder to credit thaat somebody would
>> not be expecting the data to start going somewhere else.
> Well, I think doing that ALSO would be worthwhile for the TODO list.
> I've often wished, for example, that if we switch log_directory the
> *last* message in the old log file be "reloading postgresql with new
> configuration" or something similar, so that I would know to look for a
> new log file somewhere else. If you are, for example, logging only
> errors, you wouldn't necessarily realize that logging on the file you're
> tailing/monitoring has stopped.
In principle I see the risk, but I don't think I've ever seen an actual
report of someone getting confused this way by an on-the-fly logging
parameter change. Whereas there are numerous examples in the archives
of people not realizing that "pg_ctl -l foo" doesn't necessarily mean
that all the useful log output is in file foo. (Usually it's because
they're using a logging setup chosen by some packager, not by themselves.)
So I'm feeling that what you're suggesting is solving a different and
far less pressing problem than what I'm on about.
I did think a little bit about how to do it. For parameters that affect
where the logging collector writes data (probably only log_directory is
worth special handling), it would be quite easy to make the got_SIGHUP
code segment in syslogger.c emit a log message just before switching the
active value. However, if you want something similar for log_destination,
syslog_facility, syslog_ident, or event_source, it's far more problematic
because those settings affect the behavior of individual processes, and
so there's no unique point where we're switching from one log target to
another. We could have the postmaster report a value change but it's
likely that that message would not appear very close to the end of the
messages directed to the old target.
Another point here is that if you're tailing the current log file,
a plain old rotation (no parameter change anywhere) would also cut
you off without obvious notice. Maybe we shouldn't think about this
as a "change of parameter" problem, but just say it's worth emitting
an "end of log file" message anytime we're about to change to a new log
file, no matter the reason. But again, that's specific to the logging
collector case and doesn't help with any other log target. I also note
that I'm not familiar with any system logging tool that emits such
messages.
regards, tom lane
Noah Misch <noah@leadboat.com> writes:
> On Thu, Aug 08, 2013 at 10:32:17PM -0400, Tom Lane wrote:
>> This patch arranges to emit a hint message when/if we switch away from
>> logging to the original postmaster stderr during startup. There are two
>> cases to cover: we're still using LOG_DESTINATION_STDERR but redirecting
>> stderr to a syslogger process, or we stop writing to stderr altogether,
>> presumably in favor of going to syslog or something.
> At LOG level, this feels a bit chatty: it's a 100% increase in startup-time
> messages if you count both the main message and the HINT. I can't think of
> another program with configuration-directed logging that does this on every
> startup. Makes perfect sense to me at DEBUG1, though, and that would have
> been enough for the situation you cite above.
Hm. That would be enough for users who think to increase log_min_messages
while trying to resolve their problem. But what I'm mainly worried about
here is people who are relative novices, so I don't have a lot of
confidence that the patch would still help them if we made the message not
appear at default logging verbosity.
Also, I'm not sure that the chattiness argument is relevant, because no
message will be emitted at all unless you're switching to some log target
different from the postmaster's initial stderr. So the message won't show
up in the "official" log target files, only in an arguably vestigial
startup-time-messages-only file.
Does that ameliorate your concern, or do you still want it to be DEBUG1?
I'd be happier with DEBUG1 than with no message at all, but I don't think
it's going to help as many people at DEBUG1 as it would at LOG level.
regards, tom lane
On 08/09/2013 03:40 PM, Tom Lane wrote: > In principle I see the risk, but I don't think I've ever seen an actual > report of someone getting confused this way by an on-the-fly logging > parameter change. Whereas there are numerous examples in the archives > of people not realizing that "pg_ctl -l foo" doesn't necessarily mean > that all the useful log output is in file foo. (Usually it's because > they're using a logging setup chosen by some packager, not by themselves.) > So I'm feeling that what you're suggesting is solving a different and > far less pressing problem than what I'm on about. No question. That's why I suggested it as a TODO item instead of anyone working on it right now. The main benefit I see for this is security, especially with ALTER SYSTEM SET pending. Switching log destinations is a good way to cover your tracks if you have some kind of temporary superuser access (for example, by exploiting a SECURITY DEFINER function). If the switch were recorded somewhere other than the new log location, it would provide a little more sleuthing information for later auditors. > I did think a little bit about how to do it. For parameters that affect > where the logging collector writes data (probably only log_directory is > worth special handling), it would be quite easy to make the got_SIGHUP > code segment in syslogger.c emit a log message just before switching the > active value. However, if you want something similar for log_destination, > syslog_facility, syslog_ident, or event_source, it's far more problematic > because those settings affect the behavior of individual processes, and > so there's no unique point where we're switching from one log target to > another. We could have the postmaster report a value change but it's > likely that that message would not appear very close to the end of the > messages directed to the old target. But wait, there's more complications: what if you're switching log_directory because the disk on the old log location is full? Then we *can't* emit a log entry on switch, because we can't write it. Like I said, complicated out of proportion to be benefit, at least right now. > Another point here is that if you're tailing the current log file, > a plain old rotation (no parameter change anywhere) would also cut > you off without obvious notice. Yeah, I'm not concerned about that, since the location of the new log is predictable. > Maybe we shouldn't think about this > as a "change of parameter" problem, but just say it's worth emitting > an "end of log file" message anytime we're about to change to a new log > file, no matter the reason. But again, that's specific to the logging > collector case and doesn't help with any other log target. I also note > that I'm not familiar with any system logging tool that emits such > messages. I'm not familiar with other system logging tools. -- Josh Berkus PostgreSQL Experts Inc. http://pgexperts.com
On Fri, Aug 09, 2013 at 06:59:13PM -0400, Tom Lane wrote: > Noah Misch <noah@leadboat.com> writes: > > On Thu, Aug 08, 2013 at 10:32:17PM -0400, Tom Lane wrote: > >> This patch arranges to emit a hint message when/if we switch away from > >> logging to the original postmaster stderr during startup. There are two > >> cases to cover: we're still using LOG_DESTINATION_STDERR but redirecting > >> stderr to a syslogger process, or we stop writing to stderr altogether, > >> presumably in favor of going to syslog or something. > > > At LOG level, this feels a bit chatty: it's a 100% increase in startup-time > > messages if you count both the main message and the HINT. I can't think of > > another program with configuration-directed logging that does this on every > > startup. Makes perfect sense to me at DEBUG1, though, and that would have > > been enough for the situation you cite above. > > Hm. That would be enough for users who think to increase log_min_messages > while trying to resolve their problem. But what I'm mainly worried about > here is people who are relative novices, so I don't have a lot of > confidence that the patch would still help them if we made the message not > appear at default logging verbosity. > > Also, I'm not sure that the chattiness argument is relevant, because no > message will be emitted at all unless you're switching to some log target > different from the postmaster's initial stderr. So the message won't show > up in the "official" log target files, only in an arguably vestigial > startup-time-messages-only file. Perhaps the chatter would most affect use, typically casual, of pg_ctl without "-l" or similar. > Does that ameliorate your concern, or do you still want it to be DEBUG1? > I'd be happier with DEBUG1 than with no message at all, but I don't think > it's going to help as many people at DEBUG1 as it would at LOG level. I think of the "implicit sequence" messages we moved from NOTICE to DEBUG1 somewhat recently. No doubt those messages had helped at times, but they didn't quite carry their weight at NOTICE. My gut prediction is that this will fall in that same utility range. But you make a valid point about noise in the startup log being easier to discount. -- Noah Misch EnterpriseDB http://www.enterprisedb.com
Noah Misch <noah@leadboat.com> writes:
> On Fri, Aug 09, 2013 at 06:59:13PM -0400, Tom Lane wrote:
>> Also, I'm not sure that the chattiness argument is relevant, because no
>> message will be emitted at all unless you're switching to some log target
>> different from the postmaster's initial stderr. So the message won't show
>> up in the "official" log target files, only in an arguably vestigial
>> startup-time-messages-only file.
> Perhaps the chatter would most affect use, typically casual, of pg_ctl without
> "-l" or similar.
Well, use as casual as that would probably also involve default logging
parameters, so that no switch will occur and thus this patch would print
nothing new.
I think that the vast majority of users who have nondefault logging
parameters have them because they're using some packaged version of
Postgres, and most of those are probably not using pg_ctl directly
at all, but going through some initscript or equivalent to start PG.
(At least, that's the set of people that this patch is trying to
improve usability for.) Any initscript is going to be redirecting
initial stderr to someplace besides the terminal.
>> Does that ameliorate your concern, or do you still want it to be DEBUG1?
> I think of the "implicit sequence" messages we moved from NOTICE to DEBUG1
> somewhat recently. No doubt those messages had helped at times, but they
> didn't quite carry their weight at NOTICE. My gut prediction is that this
> will fall in that same utility range. But you make a valid point about noise
> in the startup log being easier to discount.
Well, we can certainly back off the messages' log level if we get
complaints. But I think the argument for this patch being useful
is a great deal stronger if it's allowed to operate by default.
regards, tom lane
On Sat, Aug 10, 2013 at 10:57:56AM -0400, Tom Lane wrote: > Noah Misch <noah@leadboat.com> writes: > > On Fri, Aug 09, 2013 at 06:59:13PM -0400, Tom Lane wrote: > >> Does that ameliorate your concern, or do you still want it to be DEBUG1? > > > I think of the "implicit sequence" messages we moved from NOTICE to DEBUG1 > > somewhat recently. No doubt those messages had helped at times, but they > > didn't quite carry their weight at NOTICE. My gut prediction is that this > > will fall in that same utility range. But you make a valid point about noise > > in the startup log being easier to discount. > > Well, we can certainly back off the messages' log level if we get > complaints. But I think the argument for this patch being useful > is a great deal stronger if it's allowed to operate by default. True enough. Your plan makes sense to me now; thanks. -- Noah Misch EnterpriseDB http://www.enterprisedb.com