[perl #134172] commit 027471cf breaks t/op/sprintf2.t on FreeBSD-11

On Thu, 06 Jun 2019 15:54:29 GMT, jkeenan wrote:
> On Thu, 06 Jun 2019 15:47:02 GMT, hv wrote:
> > On Thu, 06 Jun 2019 08:16:29 -0700, jkeenan wrote:
> > > > (gdb) next
> > > > 13092                   Perl_croak(aTHX_ "Numeric format result
> > > > too
> > > > large");
> > > > 2: *PL_locale_mutex = {m_lock = {m_owner = 0, m_flags = 0,
> > > > m_ceilings
> > > > = 0x801e1c1e8, m_rb_lnk = 0,
> > > >     m_spare = 0x801e1c1f8}, m_flags = 1, m_count = 0, m_spinloops
> > > > =
> > > > 0,
> > > > m_yieldloops = 0, m_ps = 0,
> > > >  m_qe = {tqe_next = 0x0, tqe_prev = 0x0}, m_pqe = {tqe_next =
> > > > 0x0,
> > > > tqe_prev = 0x0}, m_rb_prev = 0x0}
> > > > 1: PL_locale_mutex = 0x801e1c1e0
> >
> > Ok, so at this point it still looks valid ...
> >
> > > > Program received signal SIGSEGV, Segmentation fault.
> > > > 0x0000000000597ad9 in Perl_dounwind (my_perl=0x801e22000, cxix=-
> > > > 1)
> > > > at
> > > > pp_ctl.c:1550
> > > > 1550            CX_LEAVE_SCOPE(cx);
> > > > 2: *PL_locale_mutex = Error accessing memory address 0x2: Bad
> > > > address.
> > > > Disabling display 2 to avoid infinite recursion.
> >
> > .. but by the time we get here it has been corrupted to 0x2.
> >
> > I think it's worth another go at the 'watch', but if that fails we
> > may
> > have to step through with 'next' and 'step' until the displayed value
> > changes. If we set the watchpoint later, it may work better:
> >
> > shell% gdb --args ./perl -we 'my $x = sprintf("%7000000000E", 0)'
> > (gdb) break sv.c:13092
> > (gdb) run
> > .. break at sv.c:13092 (the croak call)
> > (gdb) watch PL_locale_mutex
> > (gdb) cont
> >
> > As before, it should not take more than a few minutes after the
> > 'cont'.
> >
> > Hugo
> 
> 'cont' returned within 1 second.
> 
> #####
> $ gdb --args ./perl -we 'my $x = sprintf("%7000000000E", 0)'
> GNU gdb 6.1.1 [FreeBSD]
> Copyright 2004 Free Software Foundation, Inc.
> GDB is free software, covered by the GNU General Public License, and
> you are
> welcome to change it and/or distribute copies of it under certain
> conditions.
> Type "show copying" to see the conditions.
> There is absolutely no warranty for GDB.  Type "show warranty" for
> details.
> This GDB was configured as "amd64-marcel-freebsd"...
> (gdb) break sv.c:13092
> Breakpoint 1 at 0x55b2f0: file sv.c, line 13092.
> (gdb) run
> Starting program: /usr/home/jkeenan/gitwork/perl/perl -we my\ \$x\ =\
> sprintf\(\"%7000000000E\",\ 0\)
> 
> Breakpoint 1, Perl_sv_vcatpvfn_flags (my_perl=<value optimized out>,
> sv=<value optimized out>,
>     pat=<value optimized out>, patlen=<value optimized out>, args=0x0,
> svargs=0x801e16528,
>    sv_count=1, maybe_tainted=0x801c02200, flags=0) at sv.c:13092
> 13092                   Perl_croak(aTHX_ "Numeric format result too
> large");
> (gdb) watch PL_locale_mutex
> Watchpoint 2: PL_locale_mutex
> (gdb) cont
> Continuing.
> 
> Breakpoint 1, Perl_sv_vcatpvfn_flags (my_perl=<value optimized out>,
> sv=<value optimized out>,
>     pat=<value optimized out>, patlen=<value optimized out>, args=0x0,
> svargs=0x801e16530,
>    sv_count=1, maybe_tainted=0x452591, flags=0) at sv.c:13092
> 13092                   Perl_croak(aTHX_ "Numeric format result too
> large");
> (gdb) bt
> #0  Perl_sv_vcatpvfn_flags (my_perl=<value optimized out>, sv=<value
> optimized out>,
>     pat=<value optimized out>, patlen=<value optimized out>, args=0x0,
> svargs=0x801e16530,
>    sv_count=1, maybe_tainted=0x452591, flags=0) at sv.c:13092
> #1  0x0000000000553045 in Perl_sv_vsetpvfn (my_perl=0x801e22000,
> sv=0x801e98610,
>     pat=0x801e20128 "%7000000000E", patlen=<value optimized out>,
> args=<value optimized out>,
>    svargs=0x801e16530, sv_count=1, maybe_tainted=0x7fffffffe577) at
> sv.c:10984
> #2  0x00000000005c4f31 in Perl_do_sprintf (my_perl=0x801e22000,
> sv=0x801e98610,
>    len=<value optimized out>, sarg=<value optimized out>) at
> doop.c:734
> #3  0x0000000000579ac0 in Perl_pp_sprintf (my_perl=0x801e22000) at
> pp.c:3559
> #4  0x00000000004f0340 in Perl_runops_debug (my_perl=0x801e22000) at
> dump.c:2537
> #5  0x0000000000453464 in S_run_body (my_perl=0x801e22000, oldscope=1)
> at inline.h:65
> #6  0x00000000004532d9 in perl_run (my_perl=0x801e22000) at
> perl.c:2646
> #7  0x00000000004213fa in main (argc=<value optimized out>,
> argv=<value optimized out>,
>    env=0x7fffffffe7a0) at perlmain.c:127
> #####

We're getting the same test failure on threaded builds on OpenBSD-6.4 and 6.5.

On 6.5, this is not showing up in the regular smoke-testing reports, but if you go to the "log" version of Carlos's reports, you can see it.  See, e.g., http://perl5.test-smoke.org/logfile/89510, where t/op/sprintf2.t is graded '?????' on threaded builds.

I build a threaded perl on blead on an OpenBSD-6.4 VM.  Some results for t/op/sprintf2.t and for Hugo's one-liner.

#####
$ uname -mrs
OpenBSD 6.4 amd64

$ ./perl -Ilib -V:config_args
config_args='-des -Dusedevel -Duseithreads';

$ ./perl -Ilib -v | head -2 | tail -1
This is perl 5, version 31, subversion 1 (v5.31.1 (v5.31.0-159-g84ab3b6908)) built for OpenBSD.amd64-openbsd-thread-multi

$ cd t;./perl harness -v op/sprintf2.t;cd -
[snip]
ok 1699 - croak for very large numeric format results
pthread_mutex_destroy on mutex with waiters!
All 1699 subtests passed 
        (less 30 skipped subtests: 1669 okay)

Test Summary Report
-------------------
op/sprintf2.t (Wstat: 138 Tests: 1699 Failed: 0)
  Non-zero wait status: 138
Files=1, Tests=1699,  1 wallclock secs ( 0.22 usr  0.15 sys +  0.11 cusr  0.53 csys =  1.01 CPU)
Result: FAIL
#####

Note how on this platform an error message is printed:

pthread_mutex_destroy on mutex with waiters!

#####
$ uname -mrs
OpenBSD 6.4 amd64

$ ./perl -Ilib -v | head -2 | tail -1
This is perl 5, version 31, subversion 1 (v5.31.1 (v5.31.0-159-g84ab3b6908)) built for OpenBSD.amd64-openbsd-thread-multi

$ ./perl -Ilib -V:config_args         
config_args='-des -Dusedevel -Duseithreads -DDEBUGGING';

$ gdb --args ./perl -we 'my $x = sprintf("%7000000000E", 0)'
GNU gdb 6.3
Copyright 2004 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB.  Type "show warranty" for details.
This GDB was configured as "amd64-unknown-openbsd6.4"...
(gdb) break sv.c:13092
Breakpoint 1 at 0x15aa82: file sv.c, line 13092.
(gdb) run
Starting program: /home/jkeenan/gitwork/perl/perl -we my\ \$x\ =\ sprintf\(\"%7000000000E\",\ 0\)
Breakpoint 1 at 0x18a24b55aa82: file sv.c, line 13092.

Breakpoint 1, Perl_sv_vcatpvfn_flags (my_perl=Variable "my_perl" is not available.
) at sv.c:13095
13095                   Perl_croak(aTHX_ "Numeric format result too large");
(gdb) watch PL_locale_mutex
Watchpoint 2: PL_locale_mutex
(gdb) cont
Continuing.

Breakpoint 1, Perl_sv_vcatpvfn_flags (my_perl=Variable "my_perl" is not available.
) at sv.c:13095
13095                   Perl_croak(aTHX_ "Numeric format result too large");
(gdb) cont
Continuing.
Numeric format result too large at -e line 1.
Watchpoint 2: PL_locale_mutex

Old value = 0x18a52d7d7160
New value = 0x0
0x000018a50c654f06 in _libc_pthread_mutex_destroy (mutexp=0x18a24ba98c40)
    at /usr/src/lib/libc/thread/rthread_mutex.c:89
89      /usr/src/lib/libc/thread/rthread_mutex.c: No such file or directory.
        in /usr/src/lib/libc/thread/rthread_mutex.c
Current language:  auto; currently minimal
(gdb) bt
#0  0x000018a50c654f06 in _libc_pthread_mutex_destroy (mutexp=0x18a24ba98c40)
    at /usr/src/lib/libc/thread/rthread_mutex.c:89
#1  0x000018a24b430af5 in Perl_sys_term () at perl.c:146
#2  0x000018a24b4015ee in main (argc=Variable "argc" is not available.
) at perlmain.c:155
#####

Thank you very much.

-- 
James E Keenan (jkeenan@cpan.org)

---
via perlbug:  queue: perl5 status: open
https://rt.perl.org/Ticket/Display.html?id=134172

• [perl #134172] commit 027471cf breaks t/op/sprintf2.t on FreeBSD-11 by James E Keenan via RT