Addition of %b/backend_type in log_line_prefix of TAP test logs

On Wed, May 21, 2025 at 8:51 AM Michael Paquier <michael@paquier.xyz> wrote:

Hi all,

While navigating through the logs in the CI, the buildfarm, or even my
own machine, I've found myself spending a lot of time looking at
very specific log entries to find out the PID of a specific process,
sometimes mistaking a normal backend vs a logical WAL sender while
looking for a PID, or just looking for an auxiliary process.

I'd like to suggest the following change in Cluster.pm:
-   print $conf "log_line_prefix = '%m [%p] %q%a '\n";
+   print $conf "log_line_prefix = '%m [%b,%p] %q%a '\n";

+1 to this change.

Since pg_regress uses log_line_prefix = '%m %b[%p] %q%a ',
isn't it better to use the same setting in TAP tests as well?

Regards,

--
Fujii Masao

On Wed, May 21, 2025 at 11:41:18AM +0900, Fujii Masao wrote:

Since pg_regress uses log_line_prefix = '%m %b[%p] %q%a ',
isn't it better to use the same setting in TAP tests as well?

Oh, right, good point. I've managed to miss this part in
pg_regress.c. Using the same value makes even more sense.
--
Michael

On 21 May 2025, at 04:48, Michael Paquier <michael@paquier.xyz> wrote:

On Wed, May 21, 2025 at 11:41:18AM +0900, Fujii Masao wrote:

Since pg_regress uses log_line_prefix = '%m %b[%p] %q%a ',
isn't it better to use the same setting in TAP tests as well?

Oh, right, good point. I've managed to miss this part in
pg_regress.c. Using the same value makes even more sense.

Agreed, and +1 on the change in general.

--
Daniel Gustafsson

On Wed, May 21, 2025 at 09:24:26AM +0200, Daniel Gustafsson wrote:

Agreed, and +1 on the change in general.

Another point perhaps worth considering after a second look: how about
pg_ci_base.conf? We have the following line there, exposing this
configuration with TEMP_CONFIG:
src/tools/ci/pg_ci_base.conf:log_line_prefix = '%m [%p][%b] %q[%a][%v:%x] '

The two other ones are:
src/test/perl/PostgreSQL/Test/Cluster.pm: '%m [%p] %q%a '
src/test/regress/pg_regress.c: '%m %b[%p] %q%a '

Perhaps it would be better to apply the same configuration as the CI
by default at the end? The difference is that the CI exposes
[virtual] XIDs. I've never used this information for debugging, but
that may be worth considering for consistency? This would make easier
checks across the buildfarm, the CI or local machines when looking for
differences in the logs with the same tests.

(I was incorrect previously about CI not using backend_type upthread.)
--
Michael

Michael Paquier <michael@paquier.xyz> writes:

On Wed, May 21, 2025 at 09:24:26AM +0200, Daniel Gustafsson wrote:

Agreed, and +1 on the change in general.

Another point perhaps worth considering after a second look: how about
pg_ci_base.conf? We have the following line there, exposing this
configuration with TEMP_CONFIG:
src/tools/ci/pg_ci_base.conf:log_line_prefix = '%m [%p][%b] %q[%a][%v:%x] '

The two other ones are:
src/test/perl/PostgreSQL/Test/Cluster.pm: '%m [%p] %q%a '
src/test/regress/pg_regress.c: '%m %b[%p] %q%a '

Perhaps it would be better to apply the same configuration as the CI
by default at the end?

I'd vote for standardizing on pg_regress.c's spelling, as that's got
the most usage history behind it. I'm unexcited about bloating the
logs with [%v:%x] --- that's data I've very seldom needed.

regards, tom lane

On 2025/05/22 8:58, Tom Lane wrote:

Michael Paquier <michael@paquier.xyz> writes:

On Wed, May 21, 2025 at 09:24:26AM +0200, Daniel Gustafsson wrote:

Agreed, and +1 on the change in general.

Another point perhaps worth considering after a second look: how about
pg_ci_base.conf? We have the following line there, exposing this
configuration with TEMP_CONFIG:
src/tools/ci/pg_ci_base.conf:log_line_prefix = '%m [%p][%b] %q[%a][%v:%x] '

The two other ones are:
src/test/perl/PostgreSQL/Test/Cluster.pm: '%m [%p] %q%a '
src/test/regress/pg_regress.c: '%m %b[%p] %q%a '

Perhaps it would be better to apply the same configuration as the CI
by default at the end?

I'd vote for standardizing on pg_regress.c's spelling, as that's got
the most usage history behind it. I'm unexcited about bloating the
logs with [%v:%x] --- that's data I've very seldom needed.

+1

Regards,

--
Fujii Masao
NTT DATA Japan Corporation

On Fri, May 23, 2025 at 11:56:59PM +0900, Fujii Masao wrote:

On 2025/05/22 8:58, Tom Lane wrote:

Michael Paquier <michael@paquier.xyz> writes:

Another point perhaps worth considering after a second look: how about
pg_ci_base.conf? We have the following line there, exposing this
configuration with TEMP_CONFIG:
src/tools/ci/pg_ci_base.conf:log_line_prefix = '%m [%p][%b] %q[%a][%v:%x] '

The two other ones are:
src/test/perl/PostgreSQL/Test/Cluster.pm: '%m [%p] %q%a '
src/test/regress/pg_regress.c: '%m %b[%p] %q%a '

Perhaps it would be better to apply the same configuration as the CI
by default at the end?

I'd vote for standardizing on pg_regress.c's spelling, as that's got
the most usage history behind it. I'm unexcited about bloating the
logs with [%v:%x] --- that's data I've very seldom needed.

+1

The %v:%x business in log_line_prefix has been introduced in
93d973494613 by Andres. Adding him in CC for comments about the CI
part.
--
Michael

On Sat, May 24, 2025 at 09:09:36AM +0900, Michael Paquier wrote:

On Fri, May 23, 2025 at 11:56:59PM +0900, Fujii Masao wrote:

On 2025/05/22 8:58, Tom Lane wrote:

I'd vote for standardizing on pg_regress.c's spelling, as that's got
the most usage history behind it. I'm unexcited about bloating the
logs with [%v:%x] --- that's data I've very seldom needed.

+1

Coming back to this thread as v19 is going to open up rather soon, the
suggestion from Tom seems to be the consensus reached, which is to use
the same value of log_line_prefix in the CI and the TAP as in
pg_regress.c. Attached is a patch to do so, that I'd like to apply on
HEAD once v19 opens up.

If anybody would prefer a backpatch or if anybody has any comments,
please feel free.
--
Michael

Hi,

On 2025-05-24 09:09:36 +0900, Michael Paquier wrote:

On Fri, May 23, 2025 at 11:56:59PM +0900, Fujii Masao wrote:

On 2025/05/22 8:58, Tom Lane wrote:

Michael Paquier <michael@paquier.xyz> writes:

Another point perhaps worth considering after a second look: how about
pg_ci_base.conf? We have the following line there, exposing this
configuration with TEMP_CONFIG:
src/tools/ci/pg_ci_base.conf:log_line_prefix = '%m [%p][%b] %q[%a][%v:%x] '

The two other ones are:
src/test/perl/PostgreSQL/Test/Cluster.pm: '%m [%p] %q%a '
src/test/regress/pg_regress.c: '%m %b[%p] %q%a '

Perhaps it would be better to apply the same configuration as the CI
by default at the end?

I'd vote for standardizing on pg_regress.c's spelling, as that's got
the most usage history behind it. I'm unexcited about bloating the
logs with [%v:%x] --- that's data I've very seldom needed.

+1

The %v:%x business in log_line_prefix has been introduced in
93d973494613 by Andres. Adding him in CC for comments about the CI
part.

I'm fine with that.

I'm not a huge fan of "%b" instead of "[%b]", but it doesn't matter much.

Greetings,

Andres Freund

On Fri, Jun 20, 2025 at 04:20:21PM +0900, Michael Paquier wrote:

Coming back to this thread as v19 is going to open up rather soon, the
suggestion from Tom seems to be the consensus reached, which is to use
the same value of log_line_prefix in the CI and the TAP as in
pg_regress.c. Attached is a patch to do so, that I'd like to apply on
HEAD once v19 opens up.

And done on HEAD, aka v19.
--
Michael