Cluster::restart dumping logs when stop fails

On 6 Apr 2024, at 23:44, Andres Freund <andres@anarazel.de> wrote:

It might be useful to print a few lines, but the whole log files can be
several megabytes worth of output.

The non-context aware fix would be to just print the last 1024 (or something)
bytes from the logfile:

diff --git a/src/test/perl/PostgreSQL/Test/Cluster.pm b/src/test/perl/PostgreSQL/Test/Cluster.pm
index 54e1008ae5..53d4751ffc 100644
--- a/src/test/perl/PostgreSQL/Test/Cluster.pm
+++ b/src/test/perl/PostgreSQL/Test/Cluster.pm
@@ -951,8 +951,8 @@ sub start

 	if ($ret != 0)
 	{
-		print "# pg_ctl start failed; logfile:\n";
-		print PostgreSQL::Test::Utils::slurp_file($self->logfile);
+		print "# pg_ctl start failed; logfile excerpt:\n";
+		print substr PostgreSQL::Test::Utils::slurp_file($self->logfile), -1024;

# pg_ctl could have timed out, so check to see if there's a pid file;
# otherwise our END block will fail to shut down the new postmaster.

Would that be a reasonable fix?

--
Daniel Gustafsson

Hi,

On 2024-04-07 00:19:35 +0200, Daniel Gustafsson wrote:

On 6 Apr 2024, at 23:44, Andres Freund <andres@anarazel.de> wrote:

It might be useful to print a few lines, but the whole log files can be
several megabytes worth of output.

The non-context aware fix would be to just print the last 1024 (or something)
bytes from the logfile:

That'd be better, yes. I'd mainly log the path to the logfile though, that's
probably at least as helpful for actually investigating the issue?

diff --git a/src/test/perl/PostgreSQL/Test/Cluster.pm b/src/test/perl/PostgreSQL/Test/Cluster.pm
index 54e1008ae5..53d4751ffc 100644
--- a/src/test/perl/PostgreSQL/Test/Cluster.pm
+++ b/src/test/perl/PostgreSQL/Test/Cluster.pm
@@ -951,8 +951,8 @@ sub start

if ($ret != 0)
{
-		print "# pg_ctl start failed; logfile:\n";
-		print PostgreSQL::Test::Utils::slurp_file($self->logfile);
+		print "# pg_ctl start failed; logfile excerpt:\n";
+		print substr PostgreSQL::Test::Utils::slurp_file($self->logfile), -1024;

# pg_ctl could have timed out, so check to see if there's a pid file;
# otherwise our END block will fail to shut down the new postmaster.

That's probably unnecessary optimization, but it seems a tad silly to read an
entire, potentially sizable, file to just use the last 1k. Not sure if the way
slurp_file() uses seek supports negative ofsets, the docs read to me like that
may only be supported with SEEK_END.

Greetings,

Andres Freund

On 7 Apr 2024, at 02:49, Andres Freund <andres@anarazel.de> wrote:
On 2024-04-07 00:19:35 +0200, Daniel Gustafsson wrote:

On 6 Apr 2024, at 23:44, Andres Freund <andres@anarazel.de> wrote:

The non-context aware fix would be to just print the last 1024 (or something)
bytes from the logfile:

That'd be better, yes. I'd mainly log the path to the logfile though, that's
probably at least as helpful for actually investigating the issue?

IIRC this was modelled around how it used to be earlier, in v14 in the
pre-refactored version we print the full logfile.

How about doing the below backpatched down to 15?

diff --git a/src/test/perl/PostgreSQL/Test/Cluster.pm b/src/test/perl/PostgreSQL/Test/Cluster.pm
index 54e1008ae5..a2f9409842 100644
--- a/src/test/perl/PostgreSQL/Test/Cluster.pm
+++ b/src/test/perl/PostgreSQL/Test/Cluster.pm
@@ -951,8 +951,7 @@ sub start

 	if ($ret != 0)
 	{
-		print "# pg_ctl start failed; logfile:\n";
-		print PostgreSQL::Test::Utils::slurp_file($self->logfile);
+		print "# pg_ctl start failed; see logfile for details: " . $self->logfile . "\n";

# pg_ctl could have timed out, so check to see if there's a pid file;
# otherwise our END block will fail to shut down the new postmaster.
@@ -1090,8 +1089,7 @@ sub restart

 	if ($ret != 0)
 	{
-		print "# pg_ctl restart failed; logfile:\n";
-		print PostgreSQL::Test::Utils::slurp_file($self->logfile);
+		print "# pg_ctl restart failed; see logfile for details: " . $self->logfile . "\n";

# pg_ctl could have timed out, so check to see if there's a pid file;
# otherwise our END block will fail to shut down the new postmaster.

--
Daniel Gustafsson

On 2024-04-06 Sa 20:49, Andres Freund wrote:

That's probably unnecessary optimization, but it seems a tad silly to read an
entire, potentially sizable, file to just use the last 1k. Not sure if the way
slurp_file() uses seek supports negative ofsets, the docs read to me like that
may only be supported with SEEK_END.

We should enhance slurp_file() so it uses SEEK_END if the offset is
negative. It would be a trivial patch:

diff --git a/src/test/perl/PostgreSQL/Test/Utils.pm b/src/test/perl/PostgreSQL/Test/Utils.pm
index 42d5a50dc8..8256573957 100644
--- a/src/test/perl/PostgreSQL/Test/Utils.pm
+++ b/src/test/perl/PostgreSQL/Test/Utils.pm
@@ -524,7 +524,7 @@ sub slurp_file

     if (defined($offset))
     {
-       seek($fh, $offset, SEEK_SET)
+       seek($fh, $offset, ($offset < 0 ? SEEK_END : SEEK_SET))
           or croak "could not seek \"$filename\": $!";
     }

cheers

andrew

cheers

andrew

--
Andrew Dunstan
EDB:https://www.enterprisedb.com

On 7 Apr 2024, at 14:51, Andrew Dunstan <andrew@dunslane.net> wrote:
On 2024-04-06 Sa 20:49, Andres Freund wrote:

That's probably unnecessary optimization, but it seems a tad silly to read an
entire, potentially sizable, file to just use the last 1k. Not sure if the way
slurp_file() uses seek supports negative ofsets, the docs read to me like that
may only be supported with SEEK_END.

We should enhance slurp_file() so it uses SEEK_END if the offset is negative.

Absolutely agree. Reading the thread I think Andres argues for not printing
anything at all in this case but we should support negative offsets anyways, it
will fort sure come in handy.

--
Daniel Gustafsson

On 2024-04-07 16:52:05 +0200, Daniel Gustafsson wrote:

On 7 Apr 2024, at 14:51, Andrew Dunstan <andrew@dunslane.net> wrote:
On 2024-04-06 Sa 20:49, Andres Freund wrote:

That's probably unnecessary optimization, but it seems a tad silly to read an
entire, potentially sizable, file to just use the last 1k. Not sure if the way
slurp_file() uses seek supports negative ofsets, the docs read to me like that
may only be supported with SEEK_END.

We should enhance slurp_file() so it uses SEEK_END if the offset is negative.

Absolutely agree. Reading the thread I think Andres argues for not printing
anything at all in this case but we should support negative offsets anyways, it
will fort sure come in handy.

I'm ok with printing path + some content or just the path.

- Andres

On 7 Apr 2024, at 18:28, Andres Freund <andres@anarazel.de> wrote:

On 2024-04-07 16:52:05 +0200, Daniel Gustafsson wrote:

On 7 Apr 2024, at 14:51, Andrew Dunstan <andrew@dunslane.net> wrote:
On 2024-04-06 Sa 20:49, Andres Freund wrote:

That's probably unnecessary optimization, but it seems a tad silly to read an
entire, potentially sizable, file to just use the last 1k. Not sure if the way
slurp_file() uses seek supports negative ofsets, the docs read to me like that
may only be supported with SEEK_END.

We should enhance slurp_file() so it uses SEEK_END if the offset is negative.

Absolutely agree. Reading the thread I think Andres argues for not printing
anything at all in this case but we should support negative offsets anyways, it
will fort sure come in handy.

I'm ok with printing path + some content or just the path.

I think printing the last 512 bytes or so would be a good approach, I'll take
care of it later tonight. That would be a backpatchable change IMHO.

--
Daniel Gustafsson

On 2024-04-07 18:51:40 +0200, Daniel Gustafsson wrote:

On 7 Apr 2024, at 18:28, Andres Freund <andres@anarazel.de> wrote:

On 2024-04-07 16:52:05 +0200, Daniel Gustafsson wrote:

On 7 Apr 2024, at 14:51, Andrew Dunstan <andrew@dunslane.net> wrote:
On 2024-04-06 Sa 20:49, Andres Freund wrote:

That's probably unnecessary optimization, but it seems a tad silly to read an
entire, potentially sizable, file to just use the last 1k. Not sure if the way
slurp_file() uses seek supports negative ofsets, the docs read to me like that
may only be supported with SEEK_END.

We should enhance slurp_file() so it uses SEEK_END if the offset is negative.

Absolutely agree. Reading the thread I think Andres argues for not printing
anything at all in this case but we should support negative offsets anyways, it
will fort sure come in handy.

I'm ok with printing path + some content or just the path.

I think printing the last 512 bytes or so would be a good approach, I'll take
care of it later tonight. That would be a backpatchable change IMHO.

+1 - thanks for quickly improving this.

On 7 Apr 2024, at 18:51, Daniel Gustafsson <daniel@yesql.se> wrote:

On 7 Apr 2024, at 18:28, Andres Freund <andres@anarazel.de> wrote:

I'm ok with printing path + some content or just the path.

I think printing the last 512 bytes or so would be a good approach, I'll take
care of it later tonight. That would be a backpatchable change IMHO.

In the end I opted for just printing the path to avoid introducing logic (at
this point in the cycle) for ensuring that a negative offset doesn't exceed the
filesize. Since it changes behavior I haven't backpatched it, but can do that
if we think it's more of a fix than a change (I think it can be argued either
way, I have no strong feelings).

--
Daniel Gustafsson