PostgreSQL logs to stdout/stderrr, which is lost

  • Done
  • quality assurance status badge
Details
2 participants
  • Danny Milosavljevic
  • Ludovic Courtès
Owner
unassigned
Submitted by
Danny Milosavljevic
Severity
normal

Debbugs page

Danny Milosavljevic wrote 9 years ago
herd has incomplete status reporting, not so helpful
(address . bug-guix@gnu.org)
20160319161337.609ada55@scratchpost.org
So there was a postgresql update where the data format was incompatible.

That happens regularily and is ... acceptable, I guess (even more acceptable in guix because I can easily switch back to the old release).

However, in order to find that out, I had to:

$ psql
... something about a socket not being reachable

$ sudo herd status postgres
Status of postgres:
It is started.
Running value is 18438.
It is enabled.
Provides (postgres).
Requires (user-processes loopback).
Conflicts with ().
Will be respawned.

So it claimed that everything was just peachy.

$ sudo herd stop postgres
$ sudo herd start postgres

... which reported nothing out of the ordinary either.

$ ps -ef |grep postgres
[xxxx] <defunct>

Aha! finally an indication that something is amiss.

So I tried to find the log entries, to no avail so far.
(I found: /gnu/store/b073csgl56g2wnq7azj4wrswb6azsvc0-postgresql-9.5.1/bin/pg_ctl -D /var/lib/postgresql/data -l logfile start, not sure how that helps)
$ man pg_ctl
No manual entry for pg_ctl

In the mean time, I decided I can just start up the postgres server process manually and it will tell me.

$ postgres --config-file=/etc/postgresql.conf -D /var/lib/postgresql/data
FATAL: data directory "/var/lib/postgresql/data" has wrong ownership
HINT: The server must be started by the user that owns the data directory.

$ sudo -i
# su - postgres
Password:

errr... what password?

# passwd postgres
...
# su - postgres
Password:
su: Authentication failure

# passwd -u postgres
# su - postgres
Password:
This account is currently not available.

Hmmm...

$ sudo -u postgres postgres --config-file=/etc/postgresql.conf -D /var/lib/postgresql/data
FATAL: database files are incompatible with server
DETAIL: The data directory was initialized by PostgreSQL version 9.3, which is not compatible with this version 9.5.1.
$

Aha! It says so right there in the standard output (or error?). Where did that message go in the shepherd case?

$ cd /var/log
$ grep -r incompatible .
$

???

Anyway, it works again now but we shouldn't have to do this kind of digging.
Danny Milosavljevic wrote 9 years ago
(address . 23064@debbugs.gnu.org)
20160319162529.5bfd95ca@scratchpost.org
Toggle quote (2 lines)
> Aha! It says so right there in the standard output (or error?). Where did that message go in the shepherd case?

It's on standard error. The exit code is 1.
Ludovic Courtès wrote 9 years ago
(name . Danny Milosavljevic)(address . dannym@scratchpost.org)(address . 23064@debbugs.gnu.org)
87lh5ef9uy.fsf@gnu.org
Danny Milosavljevic <dannym@scratchpost.org> skribis:

Toggle quote (20 lines)
> $ sudo herd status postgres
> Status of postgres:
> It is started.
> Running value is 18438.
> It is enabled.
> Provides (postgres).
> Requires (user-processes loopback).
> Conflicts with ().
> Will be respawned.
>
> So it claimed that everything was just peachy.
>
> $ sudo herd stop postgres
> $ sudo herd start postgres
>
> ... which reported nothing out of the ordinary either.
>
> $ ps -ef |grep postgres
> [xxxx] <defunct>

Sounds like postgresql died and shepherd did not notice? Or maybe it
keeps trying to respawn it? What did /var/log/shepherd.log say?

Toggle quote (11 lines)
> $ sudo -u postgres postgres --config-file=/etc/postgresql.conf -D /var/lib/postgresql/data
> FATAL: database files are incompatible with server
> DETAIL: The data directory was initialized by PostgreSQL version 9.3, which is not compatible with this version 9.5.1.
> $
>
> Aha! It says so right there in the standard output (or error?). Where did that message go in the shepherd case?
>
> $ cd /var/log
> $ grep -r incompatible .
> $

Currently the Shepherd does not do log stdout/stderr of its child
processes, which sucks somewhat.

However, daemons can usually be told to write to syslog, which is more
appropriate than writing things to stdout/stderr anyway. What’s the
right command-line/configuration option to have postgresql use syslog?

Thanks,
Ludo’.
Danny Milosavljevic wrote 9 years ago
(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 23064@debbugs.gnu.org)
20160319223921.107f27bc@scratchpost.org
Toggle quote (3 lines)
> Sounds like postgresql died and shepherd did not notice? Or maybe it
> keeps trying to respawn it? What did /var/log/shepherd.log say?

2016-03-19 10:34:48 Service postgres has been started.
2016-03-19 10:34:49 Respawning postgres.
2016-03-19 10:34:49 Service postgres has been started.
2016-03-19 10:34:50 Respawning postgres.
2016-03-19 10:34:50 Service postgres has been started.
2016-03-19 10:34:51 Respawning postgres.
2016-03-19 10:34:51 Service postgres has been started.
2016-03-19 10:34:52 Respawning postgres.
2016-03-19 10:34:52 Service postgres has been started.
2016-03-19 10:34:53 Respawning postgres.
2016-03-19 10:34:53 Service postgres has been started.
2016-03-19 10:34:54 Respawning postgres.
2016-03-19 10:34:54 Service postgres has been started.

Toggle quote (3 lines)
> Currently the Shepherd does not do log stdout/stderr of its child
> processes, which sucks somewhat.

Yeah, that's not good.

Toggle quote (3 lines)
> However, daemons can usually be told to write to syslog, which is more
> appropriate than writing things to stdout/stderr anyway.

It can always be unable to open syslog for some reason.

If shepherd can't/doesn't redirect stderr on its own, it would be nice to have init write it somewhere and everyone else inherit it as default. Just throwing it away is not nice.

But I agree, the chance of being able to write it to syslog is high. Btw: How does guixsd know to start the syslog service before the postgres service?

Toggle quote (2 lines)
>What’s the right command-line/configuration option to have postgresql use syslog?

The option is

log_destination = 'syslog'

in postgresql.conf

which is generated in gnu/services/databases.scm (%default-postgres-config).

Does shepherd back off from respawing it eventually (if it respawns too fast) or will it log the same messages into syslog once every 0.1 s until my disk is full? :->
Ludovic Courtès wrote 9 years ago
(name . Danny Milosavljevic)(address . dannym@scratchpost.org)(address . 23064@debbugs.gnu.org)
87shzkcjoi.fsf@gnu.org
Danny Milosavljevic <dannym@scratchpost.org> skribis:

Toggle quote (6 lines)
>> Sounds like postgresql died and shepherd did not notice? Or maybe it
>> keeps trying to respawn it? What did /var/log/shepherd.log say?
>
> 2016-03-19 10:34:48 Service postgres has been started.
> 2016-03-19 10:34:49 Respawning postgres.

OK.

Toggle quote (7 lines)
>> However, daemons can usually be told to write to syslog, which is more
>> appropriate than writing things to stdout/stderr anyway.
>
> It can always be unable to open syslog for some reason.
>
> If shepherd can't/doesn't redirect stderr on its own, it would be nice to have init write it somewhere and everyone else inherit it as default. Just throwing it away is not nice.

Agreed.

Toggle quote (2 lines)
> But I agree, the chance of being able to write it to syslog is high. Btw: How does guixsd know to start the syslog service before the postgres service?

Syslogd is another Shepherd service, so all we need is to express this
dependency.

Toggle quote (10 lines)
>>What’s the right command-line/configuration option to have postgresql use syslog?
>
> The option is
>
> log_destination = 'syslog'
>
> in postgresql.conf
>
> which is generated in gnu/services/databases.scm (%default-postgres-config).

Could you try this and report back?
Toggle diff (28 lines)
diff --git a/gnu/services/databases.scm b/gnu/services/databases.scm
index 6c3b829..690375e 100644
--- a/gnu/services/databases.scm
+++ b/gnu/services/databases.scm
@@ -1,6 +1,6 @@
;;; GNU Guix --- Functional package management for GNU
;;; Copyright © 2015 David Thompson <davet@gnu.org>
-;;; Copyright © 2015 Ludovic Courtès <ludo@gnu.org>
+;;; Copyright © 2015, 2016 Ludovic Courtès <ludo@gnu.org>
;;; Copyright © 2016 Leo Famulari <leo@famulari.name>
;;;
;;; This file is part of GNU Guix.
@@ -56,6 +56,7 @@ host all all ::1/128 trust"))
(define %default-postgres-config
(mixed-text-file "postgresql.conf"
+ "log_destination = 'syslog'\n"
"hba_file = '" %default-postgres-hba "'\n"
"ident_file = '" %default-postgres-ident "'\n"))
@@ -116,7 +117,7 @@ host all all ::1/128 trust"))
(list (shepherd-service
(provision '(postgres))
(documentation "Run the PostgreSQL daemon.")
- (requirement '(user-processes loopback))
+ (requirement '(user-processes loopback syslogd))
(start #~(make-forkexec-constructor #$start-script))
(stop #~(make-kill-destructor))))))))
Toggle quote (2 lines)
> Does shepherd back off from respawing it eventually (if it respawns too fast) or will it log the same messages into syslog once every 0.1 s until my disk is full? :->

Yes, it avoids respawning too fast.

Thanks,
Ludo’.
Ludovic Courtès wrote 9 years ago
retitle
(address . request@debbugs.gnu.org)
87zits9op2.fsf@gnu.org
retitle 23064 PostgreSQL logs to stdout/stderrr, which is lost
thanks
Danny Milosavljevic wrote 9 years ago
Re: bug#23064: herd has incomplete status reporting, not so helpful
(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 23064@debbugs.gnu.org)
20160322202916.53b89904@scratchpost.org
Hi Ludo,

Toggle quote (2 lines)
> Could you try this and report back?

$ patch -p1 < ...
$ sudo ./pre-inst-env guix system reconfigure /etc/config.scm
$ sudo herd stop postgres
$ sudo herd start postgres
Service postgres has been started.
$ tail -f /var/log/messages
Mar 22 20:15:51 localhost nscd: 213 monitored file `/etc/services` was created, adding watch
Mar 22 20:15:51 localhost nscd: 213 monitored file `/etc/services` was written to
Mar 22 20:20:40 localhost postgres[2115]: [1-1] FATAL: database files are incompatible with server
Mar 22 20:20:40 localhost postgres[2115]: [1-2] DETAIL: The data directory was initialized by PostgreSQL version 9.3, which is not compatible with this version 9.5.1.
...

Nice :-)

Thanks!

Although it would be nice to have shepherd have a field in "herd status" which tells you when it respawned the service in < 1 s intervals (or maybe if it respawned it < 1 s after the initial start) - or maybe just how long ago it was (last) started and when the actual herd start command was :-)
Ludovic Courtès wrote 9 years ago
(name . Danny Milosavljevic)(address . dannym@scratchpost.org)(address . 23064-done@debbugs.gnu.org)
87poumxfjo.fsf@gnu.org
Danny Milosavljevic <dannym@scratchpost.org> skribis:

Toggle quote (13 lines)
>> Could you try this and report back?
>
> $ patch -p1 < ...
> $ sudo ./pre-inst-env guix system reconfigure /etc/config.scm
> $ sudo herd stop postgres
> $ sudo herd start postgres
> Service postgres has been started.
> $ tail -f /var/log/messages
> Mar 22 20:15:51 localhost nscd: 213 monitored file `/etc/services` was created, adding watch
> Mar 22 20:15:51 localhost nscd: 213 monitored file `/etc/services` was written to
> Mar 22 20:20:40 localhost postgres[2115]: [1-1] FATAL: database files are incompatible with server
> Mar 22 20:20:40 localhost postgres[2115]: [1-2] DETAIL: The data directory was initialized by PostgreSQL version 9.3, which is not compatible with this version 9.5.1.

Great, thanks for testing! Pushed as
9b1cee97a5a75766cb52553111794c758c4f1651.

Toggle quote (2 lines)
> Although it would be nice to have shepherd have a field in "herd status" which tells you when it respawned the service in < 1 s intervals (or maybe if it respawned it < 1 s after the initial start) - or maybe just how long ago it was (last) started and when the actual herd start command was :-)

In trying to implement that, I realized there’s a bug in respawn delay
handling. More on that later.

Ludo’.
Closed
Ludovic Courtès wrote 9 years ago
(name . Danny Milosavljevic)(address . dannym@scratchpost.org)(address . 23064@debbugs.gnu.org)
87vb4cuaxr.fsf@gnu.org
Hi again,

There was indeed a respawn bug fixed by Shepherd commit
8c8a010b425e56461289bae62a94ee401e5dad41.

I also changed ‘herd’ so that ’herd status foo’ shows the last respawn
time, as you suggested.

I’ll cut a 0.3.1 release soon.

Thanks!

Ludo’.
?
Your comment

This issue is archived.

To comment on this conversation send an email to 23064@debbugs.gnu.org

To respond to this issue using the mumi CLI, first switch to it
mumi current 23064
Then, you may apply the latest patchset in this issue (with sign off)
mumi am -- -s
Or, compose a reply to this issue
mumi compose
Or, send patches to this issue
mumi send-email *.patch
You may also tag this issue. See list of standard tags. For example, to set the confirmed and easy tags
mumi command -t +confirmed -t +easy
Or, remove the moreinfo tag and set the help tag
mumi command -t -moreinfo -t +help