Обсуждение: psql tests hangs

> On 9 May 2023, at 08:52, Pavel Stehule <pavel.stehule@gmail.com> wrote:
>
> Hi
>
> I try run make check-world. Now I have problems with tests of psql
>
> I had to cancel tests
>
> log:
>
> [08:46:49.828](0.038s) ok 63 - no ON_ERROR_STOP, --single-transaction and multiple -c switches
> [08:46:49.860](0.033s) ok 64 - client-side error commits transaction, no ON_ERROR_STOP and multiple -c switches
> [08:46:49.928](0.067s) ok 65 - \copy from with DEFAULT: exit code 0
> [08:46:49.929](0.001s) ok 66 - \copy from with DEFAULT: no stderr
> [08:46:49.930](0.001s) ok 67 - \copy from with DEFAULT: matches
> death by signal at /home/pavel/src/postgresql.master/src/bin/psql/../../../src/test/perl/PostgreSQL/Test/Cluster.pm line 3042.
> # Postmaster PID for node "main" is 157863
> ### Stopping node "main" using mode immediate
> # Running: pg_ctl -D /home/pavel/src/postgresql.master/src/bin/psql/tmp_check/t_001_basic_main_data/pgdata -m immediate stop
> waiting for server to shut down.... done
> server stopped
> # No postmaster PID for node "main"
> [08:47:30.361](40.431s) # Tests were run but no plan was declared and done_testing() was not seen.
> [08:47:30.362](0.001s) # Looks like your test exited with 4 just after 67.
> Warning: unable to close filehandle $orig_stderr properly: Broken pipe during global destruction.

I'm unable to reproduce, and this clearly works in the buildfarm and CI.  Did
you run out of disk on the volume during the test or something similar?
Anything interesting in the serverlogs from the tmp_check install?

--
Daniel Gustafsson

út 9. 5. 2023 v 10:48 odesílatel Daniel Gustafsson <daniel@yesql.se> napsal:

> On 9 May 2023, at 08:52, Pavel Stehule <pavel.stehule@gmail.com> wrote:
>
> Hi
>
> I try run make check-world. Now I have problems with tests of psql
>
> I had to cancel tests
>
> log:
>
> [08:46:49.828](0.038s) ok 63 - no ON_ERROR_STOP, --single-transaction and multiple -c switches
> [08:46:49.860](0.033s) ok 64 - client-side error commits transaction, no ON_ERROR_STOP and multiple -c switches
> [08:46:49.928](0.067s) ok 65 - \copy from with DEFAULT: exit code 0
> [08:46:49.929](0.001s) ok 66 - \copy from with DEFAULT: no stderr
> [08:46:49.930](0.001s) ok 67 - \copy from with DEFAULT: matches
> death by signal at /home/pavel/src/postgresql.master/src/bin/psql/../../../src/test/perl/PostgreSQL/Test/Cluster.pm line 3042.
> # Postmaster PID for node "main" is 157863
> ### Stopping node "main" using mode immediate
> # Running: pg_ctl -D /home/pavel/src/postgresql.master/src/bin/psql/tmp_check/t_001_basic_main_data/pgdata -m immediate stop
> waiting for server to shut down.... done
> server stopped
> # No postmaster PID for node "main"
> [08:47:30.361](40.431s) # Tests were run but no plan was declared and done_testing() was not seen.
> [08:47:30.362](0.001s) # Looks like your test exited with 4 just after 67.
> Warning: unable to close filehandle $orig_stderr properly: Broken pipe during global destruction.

I'm unable to reproduce, and this clearly works in the buildfarm and CI.  Did
you run out of disk on the volume during the test or something similar?
Anything interesting in the serverlogs from the tmp_check install?

I have enough free space on disc

I don't see nothing interesting in log (it is another run)

2023-05-09 08:50:04.839 CEST [158930] 001_basic.pl LOG:  statement: COPY  copy_default FROM STDIN with (format 'csv', default 'placeholder');
2023-05-09 08:50:04.841 CEST [158930] 001_basic.pl LOG:  statement: SELECT * FROM copy_default
2023-05-09 08:50:04.879 CEST [158932] 001_basic.pl LOG:  statement: SELECT 1.
2023-05-09 08:50:04.888 CEST [158932] 001_basic.pl LOG:  statement: SELECT 1.
2023-05-09 08:50:04.898 CEST [158932] 001_basic.pl LOG:  statement: SELECT 1.
2023-05-09 08:50:28.375 CEST [158862] LOG:  received immediate shutdown request
2023-05-09 08:50:28.385 CEST [158862] LOG:  database system is shut down

backtrace from perl

Program received signal SIGINT, Interrupt.
0x00007f387ecc1ade in select () from /lib64/libc.so.6
(gdb) bt
#0  0x00007f387ecc1ade in select () from /lib64/libc.so.6
#1  0x00007f387e97363b in Perl_pp_sselect () from /lib64/libperl.so.5.36
#2  0x00007f387e917958 in Perl_runops_standard () from /lib64/libperl.so.5.36
#3  0x00007f387e88259d in perl_run () from /lib64/libperl.so.5.36
#4  0x00005588bceb234a in main ()

Regards

Pavel

1. 
   

 

--
Daniel Gustafsson

út 9. 5. 2023 v 11:07 odesílatel Pavel Stehule <pavel.stehule@gmail.com> napsal:

út 9. 5. 2023 v 10:48 odesílatel Daniel Gustafsson <daniel@yesql.se> napsal:

> On 9 May 2023, at 08:52, Pavel Stehule <pavel.stehule@gmail.com> wrote:
>
> Hi
>
> I try run make check-world. Now I have problems with tests of psql
>
> I had to cancel tests
>
> log:
>
> [08:46:49.828](0.038s) ok 63 - no ON_ERROR_STOP, --single-transaction and multiple -c switches
> [08:46:49.860](0.033s) ok 64 - client-side error commits transaction, no ON_ERROR_STOP and multiple -c switches
> [08:46:49.928](0.067s) ok 65 - \copy from with DEFAULT: exit code 0
> [08:46:49.929](0.001s) ok 66 - \copy from with DEFAULT: no stderr
> [08:46:49.930](0.001s) ok 67 - \copy from with DEFAULT: matches
> death by signal at /home/pavel/src/postgresql.master/src/bin/psql/../../../src/test/perl/PostgreSQL/Test/Cluster.pm line 3042.
> # Postmaster PID for node "main" is 157863
> ### Stopping node "main" using mode immediate
> # Running: pg_ctl -D /home/pavel/src/postgresql.master/src/bin/psql/tmp_check/t_001_basic_main_data/pgdata -m immediate stop
> waiting for server to shut down.... done
> server stopped
> # No postmaster PID for node "main"
> [08:47:30.361](40.431s) # Tests were run but no plan was declared and done_testing() was not seen.
> [08:47:30.362](0.001s) # Looks like your test exited with 4 just after 67.
> Warning: unable to close filehandle $orig_stderr properly: Broken pipe during global destruction.

I'm unable to reproduce, and this clearly works in the buildfarm and CI.  Did
you run out of disk on the volume during the test or something similar?
Anything interesting in the serverlogs from the tmp_check install?

I have enough free space on disc

I don't see nothing interesting in log (it is another run)

2023-05-09 08:50:04.839 CEST [158930] 001_basic.pl LOG:  statement: COPY  copy_default FROM STDIN with (format 'csv', default 'placeholder');
2023-05-09 08:50:04.841 CEST [158930] 001_basic.pl LOG:  statement: SELECT * FROM copy_default
2023-05-09 08:50:04.879 CEST [158932] 001_basic.pl LOG:  statement: SELECT 1.
2023-05-09 08:50:04.888 CEST [158932] 001_basic.pl LOG:  statement: SELECT 1.
2023-05-09 08:50:04.898 CEST [158932] 001_basic.pl LOG:  statement: SELECT 1.
2023-05-09 08:50:28.375 CEST [158862] LOG:  received immediate shutdown request
2023-05-09 08:50:28.385 CEST [158862] LOG:  database system is shut down

backtrace from perl

Program received signal SIGINT, Interrupt.
0x00007f387ecc1ade in select () from /lib64/libc.so.6
(gdb) bt
#0  0x00007f387ecc1ade in select () from /lib64/libc.so.6
#1  0x00007f387e97363b in Perl_pp_sselect () from /lib64/libperl.so.5.36
#2  0x00007f387e917958 in Perl_runops_standard () from /lib64/libperl.so.5.36
#3  0x00007f387e88259d in perl_run () from /lib64/libperl.so.5.36
#4  0x00005588bceb234a in main ()

Regards

I repeated another build with the same result.

Tested REL_15_STABLE branch without any problems.

Regards

Pavel

 

Pavel

1. 
   

 

--
Daniel Gustafsson

> On 10 May 2023, at 09:58, Pavel Stehule <pavel.stehule@gmail.com> wrote:
>
> When I remove this test, then all tests passed

Hi Pavel!

Can you plz share how sprintf('SELECT 1 \watch c=3 i=%g', 0.01) is formatting 0.01 on your system?
And try to run that string against psql.

As an alternative I propose to use "i=0”. I hope 0 is more locale-independent (but I’m not sure)… But the test's coverage will decrease.

Best regards, Andrey Borodin.

Pavel Stehule <pavel.stehule@gmail.com> writes:
> When I remove this test, then all tests passed

This works fine for me on Fedora 37:

$ cd src/bin/psql
$ LANG=cs_CZ.utf8 make installcheck
make -C ../../../src/backend generated-headers
make[1]: Vstupuje se do adresáře „/home/tgl/pgsql/src/backend“
...
# +++ tap install-check in src/bin/psql +++
t/001_basic.pl ........... ok   
t/010_tab_completion.pl .. ok   
t/020_cancel.pl .......... ok   
All tests successful.
Files=3, Tests=169,  6 wallclock secs ( 0.06 usr  0.02 sys +  2.64 cusr  0.99 csys =  3.71 CPU)
Result: PASS

I wonder if you have something inconsistent in your locale
configuration.  What do you see from

$ env | grep '^L[CA]'

                        regards, tom lane

čt 11. 5. 2023 v 20:44 odesílatel Tom Lane <tgl@sss.pgh.pa.us> napsal:

Pavel Stehule <pavel.stehule@gmail.com> writes:
> When I remove this test, then all tests passed

This works fine for me on Fedora 37:

I have Fedora 38

$ cd src/bin/psql
$ LANG=cs_CZ.utf8 make installcheck
make -C ../../../src/backend generated-headers
make[1]: Vstupuje se do adresáře „/home/tgl/pgsql/src/backend“
...
# +++ tap install-check in src/bin/psql +++
t/001_basic.pl ........... ok   
t/010_tab_completion.pl .. ok   
t/020_cancel.pl .......... ok   
All tests successful.
Files=3, Tests=169,  6 wallclock secs ( 0.06 usr  0.02 sys +  2.64 cusr  0.99 csys =  3.71 CPU)
Result: PASS

I wonder if you have something inconsistent in your locale
configuration.  What do you see from

$ env | grep '^L[CA]'

 [pavel@localhost psql]$ env | grep '^L[CA]'
LANG=cs_CZ.UTF-8

Regards

Pavel

                        regards, tom lane

Stranger things, but is LANG case sensitive, or formatted differently?

tom> $ LANG=cs_CZ.utf8 make installcheck

 you> LANG=cs_CZ.UTF-8

                        regards, tom lane

Hi

When I remove this test, then all tests passed

diff --git a/src/bin/psql/t/001_basic.pl b/src/bin/psql/t/001_basic.pl
index 596746de17..631a1a7335 100644
--- a/src/bin/psql/t/001_basic.pl
+++ b/src/bin/psql/t/001_basic.pl
@@ -353,11 +353,6 @@ psql_like(
 
 # Check \watch
 # Note: the interval value is parsed with locale-aware strtod()
-psql_like(
-   $node,
-   sprintf('SELECT 1 \watch c=3 i=%g', 0.01),
-   qr/1\n1\n1/,
-   '\watch with 3 iterations');
 
 # Check \watch errors
 psql_fails_like(

Can somebody repeat this testing of FC38?

Regards

Pavel

Kirk Wolak <wolakk@gmail.com> writes:
> Can you change the 0.01 to just 1 or 0?
> I assume it will work then! (and better than a full removal)?

IMO the point of that test is largely to exercise this locale-dependent
behavior, so I'm very unwilling to dumb it down to that extent.

What seems to be happening is that the spawned psql process is making
a different choice about what the LC_NUMERIC locale is than its parent
perl process did.  That seems like it might be a bug in itself, since
POSIX is pretty clear about how you're supposed to derive the locale
from the relevant environment variables.  But maybe it's Perl's bug?

                        regards, tom lane

Kirk Wolak <wolakk@gmail.com> writes:
> Did you try the print statement that Andrey asked Pavel to try?

Yeah, and I get exactly the results I expect:

On Fri, May 12, 2023 at 12:14 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:

Kirk Wolak <wolakk@gmail.com> writes:
> Did you try the print statement that Andrey asked Pavel to try?

Yeah, and I get exactly the results I expect:

Your results MATCHED Pavels  (Hmm).  Piping ONE of those into psql should fail, and the other one should work, right?

I know Pavel is Czech... So I have to Wonder... 
Are both of you using the same Collation inside of PG? (Or did I miss that the testing forces that setting?)

Kirk...

pá 12. 5. 2023 v 6:50 odesílatel Kirk Wolak <wolakk@gmail.com> napsal:

On Fri, May 12, 2023 at 12:14 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:

Kirk Wolak <wolakk@gmail.com> writes:
> Did you try the print statement that Andrey asked Pavel to try?
...

The strange thing is hanging. Broken tests depending on locale are usual. But I didn't remember hanging.

Regards

Pavel

On Fri, May 12, 2023 at 1:46 AM Pavel Stehule <pavel.stehule@gmail.com> wrote:

pá 12. 5. 2023 v 6:50 odesílatel Kirk Wolak <wolakk@gmail.com> napsal:

On Fri, May 12, 2023 at 12:14 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:

Kirk Wolak <wolakk@gmail.com> writes:
> Did you try the print statement that Andrey asked Pavel to try?
...

The strange thing is hanging. Broken tests depending on locale are usual. But I didn't remember hanging.

Regards

Pavel

So, if you do psql -c "..."

with both of those \watch  instructions, do either one hang? (I am now guessing "no")

I know that perl is using a special library to "remote control psql" (like a pseudo terminal, I guess).

[I had to abort some of the perl testing in Windows because that perl library didn't work with my psql in Windows]

Next, can you detect which process is hanging? (is it perl, the library, psql, ?).

I would be curious now about the details of your perl install, and your perl libraries...

 

pá 12. 5. 2023 v 8:20 odesílatel Kirk Wolak <wolakk@gmail.com> napsal:

On Fri, May 12, 2023 at 1:46 AM Pavel Stehule <pavel.stehule@gmail.com> wrote:

pá 12. 5. 2023 v 6:50 odesílatel Kirk Wolak <wolakk@gmail.com> napsal:

On Fri, May 12, 2023 at 12:14 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:

Kirk Wolak <wolakk@gmail.com> writes:
> Did you try the print statement that Andrey asked Pavel to try?
...

The strange thing is hanging. Broken tests depending on locale are usual. But I didn't remember hanging.

Regards

Pavel

So, if you do psql -c "..."

with both of those \watch  instructions, do either one hang? (I am now guessing "no")

I know that perl is using a special library to "remote control psql" (like a pseudo terminal, I guess).

[I had to abort some of the perl testing in Windows because that perl library didn't work with my psql in Windows]

Next, can you detect which process is hanging? (is it perl, the library, psql, ?).

It hangs in perl

but now I found there is dependency on PSQL_PAGER setting

it started pager in background, I had lot of zombie pspg processes

Unfortunately, when I unset this variable, the test hangs still

here is backtrace

Missing separate debuginfos, use: dnf debuginfo-install perl-interpreter-5.36.1-496.fc38.x86_64
(gdb) bt
#0  0x00007fbbc1129ade in select () from /lib64/libc.so.6
#1  0x00007fbbc137363b in Perl_pp_sselect () from /lib64/libperl.so.5.36
#2  0x00007fbbc1317958 in Perl_runops_standard () from /lib64/libperl.so.5.36
#3  0x00007fbbc128259d in perl_run () from /lib64/libperl.so.5.36
#4  0x000056392bd9034a in main ()

It is waiting on reading from pipe probably

psql is living too, and it is waiting too

Using host libthread_db library "/lib64/libthread_db.so.1".
0x00007f071740bc37 in wait4 () from /lib64/libc.so.6
Missing separate debuginfos, use: dnf debuginfo-install glibc-2.37-4.fc38.x86_64 ncurses-libs-6.4-3.20230114.fc38.x86_64 readline-8.2-3.fc38.x86_64
(gdb) bt
#0  0x00007f071740bc37 in wait4 () from /lib64/libc.so.6
#1  0x00007f07173a9a10 in _IO_proc_close@@GLIBC_2.2.5 () from /lib64/libc.so.6
#2  0x00007f07173b51e9 in __GI__IO_file_close_it () from /lib64/libc.so.6
#3  0x00007f07173a79fb in fclose@@GLIBC_2.2.5 () from /lib64/libc.so.6
#4  0x0000000000406be4 in do_watch (query_buf=query_buf@entry=0x5ae540, sleep=sleep@entry=0.01, iter=0, iter@entry=3) at command.c:5348
#5  0x00000000004087a5 in exec_command_watch (scan_state=scan_state@entry=0x5ae490, active_branch=active_branch@entry=true, query_buf=query_buf@entry=0x5ae540, previous_buf=previous_buf@entry=0x5ae560) at command.c:2875
#6  0x000000000040d4ba in exec_command (previous_buf=0x5ae560, query_buf=0x5ae540, cstack=0x5ae520, scan_state=0x5ae490, cmd=0x5ae9a0 "watch") at command.c:413
#7  HandleSlashCmds (scan_state=scan_state@entry=0x5ae490, cstack=cstack@entry=0x5ae520, query_buf=0x5ae540, previous_buf=0x5ae560) at command.c:230

I am not sure, it is still doesn't work but probably there are some dependencies on my setting

PSQL_PAGER and PSQL_WATCH_PAGER

so this tests fails due my setting

[pavel@localhost postgresql.master]$ set |grep PSQL
PSQL_PAGER='pspg -X'
PSQL_WATCH_PAGER='pspg -X --stream'

Regards

Pavel

On 2023-May-12, Pavel Stehule wrote:

> It hangs in perl

I wonder if "hanging" actually means that it interpreted the sleep time
as a very large integer, so it's just sleeping for a long time.

About the server locale, note that the ->new() call explicitly requests
the C locale -- it's only psql that is using the Czech locale.
Supposedly, the Perl code should also be using the Czech locale, so the
sprintf('%g') should be consistent with what psql \watch expects.
However, you cannot ask the server to be consistent with that -- say, if
you hypothetically tried to use "to_char(9D99)" and \gset that to use as
\watch argument, it wouldn't work, because that'd use the server's C
locale, not Czech.  (I know because I tried.)

--
Álvaro Herrera        Breisgau, Deutschland  —  https://www.EnterpriseDB.com/
"Puedes vivir sólo una vez, pero si lo haces bien, una vez es suficiente"

pá 12. 5. 2023 v 9:46 odesílatel Alvaro Herrera <alvherre@alvh.no-ip.org> napsal:

On 2023-May-12, Pavel Stehule wrote:

> It hangs in perl

I wonder if "hanging" actually means that it interpreted the sleep time
as a very large integer, so it's just sleeping for a long time.

There is some interaction with pspg in stream mode

The probable scenario

It is starting pspg due to my setting PSQL_WATCH_PAGER. pspg is waiting on quit command, or on pipe ending. Quit command cannot to come because it is not on tty, so it is dead lock

I can write to safeguard the fast ending on pspg when it is in stream mode, and tty is not available.

And generally, the root perl should to reset PSQL_WATCH_PAGER env variable before executing psql. Probably it does with PSQL_PAGER, and maybe with PAGER.

Regards

Pavel

 

About the server locale, note that the ->new() call explicitly requests
the C locale -- it's only psql that is using the Czech locale.
Supposedly, the Perl code should also be using the Czech locale, so the
sprintf('%g') should be consistent with what psql \watch expects.
However, you cannot ask the server to be consistent with that -- say, if
you hypothetically tried to use "to_char(9D99)" and \gset that to use as
\watch argument, it wouldn't work, because that'd use the server's C
locale, not Czech.  (I know because I tried.)

--
Álvaro Herrera        Breisgau, Deutschland  —  https://www.EnterpriseDB.com/
"Puedes vivir sólo una vez, pero si lo haces bien, una vez es suficiente"

Pavel Stehule <pavel.stehule@gmail.com> writes:
> And generally, the root perl should to reset PSQL_WATCH_PAGER env variable
> before executing psql. Probably it does with PSQL_PAGER, and maybe with
> PAGER.

Oh!  AFAICS, we don't do any of those things, but I agree it seems like
a good idea.  Can you confirm that if you unset PSQL_WATCH_PAGER then
the test passes for you?

                        regards, tom lane

Pavel Stehule <pavel.stehule@gmail.com> writes:
> pá 12. 5. 2023 v 15:26 odesílatel Tom Lane <tgl@sss.pgh.pa.us> napsal:
>> Oh!  AFAICS, we don't do any of those things, but I agree it seems like
>> a good idea.  Can you confirm that if you unset PSQL_WATCH_PAGER then
>> the test passes for you?

> yes, I tested it now, and unset  PSQL_WATCH_PAGER fixed this issue.

OK.  So after looking at this a bit, the reason PAGER and PSQL_PAGER
don't cause us any problems in the test environment is that they are
not honored unless isatty(fileno(stdin)) && isatty(fileno(stdout)).
It seems to me that it's a bug that there is no such check before
using PSQL_WATCH_PAGER.  Is there actually any defensible reason
for that?

I think we do need to clear out all three variables in
Cluster::interactive_psql.  But our regular psql tests shouldn't
be at risk here.

                        regards, tom lane

I wrote:
> Pavel Stehule <pavel.stehule@gmail.com> writes:
>> Except for testing, using pager in non-interactive mode makes no sense.

> Agreed.  Let's solve this by inserting isatty tests in psql, rather
> than hacking the test environment.

Here's a proposed patch for this.  I noticed that another memo the
PSQL_WATCH_PAGER patch had not gotten was the lesson learned in
commit 18f8f784c, namely that it's a good idea to ignore empty
or all-blank settings.

                        regards, tom lane