GNU bug report logs - #23064
PostgreSQL logs to stdout/stderrr, which is lost

Previous Next

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 23064 in the body.
You can then email your comments to 23064 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):

From: Danny Milosavljevic <dannym <at> scratchpost.org>
To: bug-guix <at> gnu.org
Subject: herd has incomplete status reporting, not so helpful
Date: Sat, 19 Mar 2016 16:13:37 +0100

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.

Message #8 received at 23064 <at> debbugs.gnu.org (full text, mbox):

From: Danny Milosavljevic <dannym <at> scratchpost.org>
To: 23064 <at> debbugs.gnu.org
Subject: Re: bug#23064: herd has incomplete status reporting, not so helpful
Date: Sat, 19 Mar 2016 16:25:29 +0100

> 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.

Message #11 received at 23064 <at> debbugs.gnu.org (full text, mbox):

From: ludo <at> gnu.org (Ludovic Courtès)
To: Danny Milosavljevic <dannym <at> scratchpost.org>
Cc: 23064 <at> debbugs.gnu.org
Subject: Re: bug#23064: herd has incomplete status reporting, not so helpful
Date: Sat, 19 Mar 2016 22:15:01 +0100

Danny Milosavljevic <dannym <at> scratchpost.org> skribis:

> $ 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?

> $ 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’.

Message #14 received at 23064 <at> debbugs.gnu.org (full text, mbox):

From: Danny Milosavljevic <dannym <at> scratchpost.org>
To: ludo <at> gnu.org (Ludovic Courtès)
Cc: 23064 <at> debbugs.gnu.org
Subject: Re: bug#23064: herd has incomplete status reporting, not so helpful
Date: Sat, 19 Mar 2016 22:39:21 +0100

> 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.

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

Yeah, that's not good.

> 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?

>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? :->

Message #17 received at 23064 <at> debbugs.gnu.org (full text, mbox):

From: ludo <at> gnu.org (Ludovic Courtès)
To: Danny Milosavljevic <dannym <at> scratchpost.org>
Cc: 23064 <at> debbugs.gnu.org
Subject: Re: bug#23064: herd has incomplete status reporting, not so helpful
Date: Mon, 21 Mar 2016 09:35:41 +0100

[Message part 1 (text/plain, inline)]

Danny Milosavljevic <dannym <at> scratchpost.org> skribis:

>> 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.

>> 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.

> 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.

>>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?

[Message part 2 (text/x-patch, inline)]

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 <at> gnu.org>
-;;; Copyright © 2015 Ludovic Courtès <ludo <at> gnu.org>
+;;; Copyright © 2015, 2016 Ludovic Courtès <ludo <at> gnu.org>
 ;;; Copyright © 2016 Leo Famulari <leo <at> 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))))))))
 

[Message part 3 (text/plain, inline)]

> 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’.

Message #22 received at 23064 <at> debbugs.gnu.org (full text, mbox):

From: Danny Milosavljevic <dannym <at> scratchpost.org>
To: ludo <at> gnu.org (Ludovic Courtès)
Cc: 23064 <at> debbugs.gnu.org
Subject: Re: bug#23064: herd has incomplete status reporting, not so helpful
Date: Tue, 22 Mar 2016 20:29:16 +0100

Hi Ludo,

> 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 :-)

Message #27 received at 23064-done <at> debbugs.gnu.org (full text, mbox):

From: ludo <at> gnu.org (Ludovic Courtès)
To: Danny Milosavljevic <dannym <at> scratchpost.org>
Cc: 23064-done <at> debbugs.gnu.org
Subject: Re: bug#23064: herd has incomplete status reporting, not so helpful
Date: Wed, 23 Mar 2016 00:23:55 +0100

Danny Milosavljevic <dannym <at> scratchpost.org> skribis:

>> 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.

> 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’.

Message #30 received at 23064 <at> debbugs.gnu.org (full text, mbox):

From: ludo <at> gnu.org (Ludovic Courtès)
To: Danny Milosavljevic <dannym <at> scratchpost.org>
Cc: 23064 <at> debbugs.gnu.org
Subject: Re: bug#23064: herd has incomplete status reporting, not so helpful
Date: Wed, 23 Mar 2016 22:44:00 +0100

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’.

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.