bug#23064: herd has incomplete status reporting, not so helpful

bug#23064: herd has incomplete status reporting, not so helpful

[Danny Milosavljevic]

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.

bug#23064: herd has incomplete status reporting, not so helpful

[Danny Milosavljevic]

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

bug#23064: herd has incomplete status reporting, not so helpful

[Ludovic Courtès]

Danny Milosavljevic <dannym@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’.

bug#23064: herd has incomplete status reporting, not so helpful

[Danny Milosavljevic]

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

bug#23064: herd has incomplete status reporting, not so helpful

[Ludovic Courtès]

[-- Attachment #1: Type: text/plain, Size: 1250 bytes --]

Danny Milosavljevic <dannym@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?


[-- Attachment #2: Type: text/x-patch, Size: 1266 bytes --]

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

[-- Attachment #3: Type: text/plain, Size: 232 bytes --]


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

bug#23064: herd has incomplete status reporting, not so helpful

[Danny Milosavljevic]

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

bug#23064: herd has incomplete status reporting, not so helpful

[Ludovic Courtès]

Danny Milosavljevic <dannym@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’.

bug#23064: herd has incomplete status reporting, not so helpful

[Ludovic Courtès]

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