commit 027471cf breaks t/op/sprintf2.t on FreeBSD-11

[p5pRT]

Migrated from rt.perl.org#134172 (status was 'pending release')

Searchable as RT134172$

[p5pRT]

From @jkeenan

The following smoke test indicates that a recent change to blead is
causing failures in t/op/sprintf2.t on FreeBSD-11.

#####
http​://perl5.test-smoke.org/report/88863
#####

In each of 36 different configurations in the smoke test run, all tests
pass individually, but the file has a whole is graded FAIL.

#####
$ cd t; ./perl harness -v op/sprintf2.t;cd -

ok 1 - the sprintf "%.<number>g" optimization
ok 2 - the sprintf "%.<number>f" optimization
ok 3 - width calculation under utf8 upgrade, length=1
...
ok 1698 - special-case %.0f on -4503599627370503
ok 1699 - croak for very large numeric format results
Dubious, test returned 9 (wstat 2304, 0x900)
All 1699 subtests passed
  (less 30 skipped subtests​: 1669 okay)

Test Summary Report

---

op/sprintf2.t (Wstat​: 2304 Tests​: 1699 Failed​: 0)
  Non-zero exit status​: 9
Files=1, Tests=1699, 0 wallclock secs ( 0.20 usr 0.01 sys + 0.16 cusr
  0.11 csys = 0.48 CPU)
Result​: FAIL
#####

Bisecting with the following command ...

#####
perl Porting/bisect.pl --start=e3c1dc81bd --end=9f58603ced --target
t/op/sprintf2.t
#####

... gave this result​:

#####
...
good - zero exit from ./perl -Ilib t/op/sprintf2.t
Runner returned 0 for end revision at Porting/bisect.pl line 233.
That took 114 seconds.
#####

... which is not useful. I hypothesized that something is tickling
.t/TEST or ./t perl harness with respect to the failing test (or vice
versa).

To test this hypothesis, I reviewed 'git log' and noticed two commits
which might have touched sprintf functionality. I built perl at each of
them, saw that one PASS and one FAIL; confirmed the FAIL.

#####
commit 027471c
Author​: Tony Cook <tony@​develop-help.com>
AuthorDate​: Wed Mar 20 16​:47​:49 2019 +1100
Commit​: Tony Cook <tony@​develop-help.com>
CommitDate​: Mon Jun 3 15​:48​:34 2019 +1000

(perl #133913) limit numeric format results to INT_MAX

The return value of v?snprintf() is int, and we pay attention to that
return value, so limit the expected size of numeric formats to INT_MAX.
#####

Thank you very much.
Jim Keenan

#####
Summary of my perl5 (revision 5 version 31 subversion 1) configuration​:
  Commit id​: 027471c
  Platform​:
  osname=freebsd
  osvers=11.2-stable
  archname=amd64-freebsd-thread-multi
  uname='freebsd perlmonger.nycbug.org 11.2-stable freebsd
11.2-stable #0 r339445​: sat oct 20 00​:08​:11 utc 2018
root@​perlmonger.nycbug.org​:usrobjusrsrcsysgeneric amd64 '
  config_args='-des -Dusedevel -Duseithreads -Doptimize=-O2 -pipe
-fstack-protector -fno-strict-aliasing'
  hint=recommended
  useposix=true
  d_sigaction=define
  useithreads=define
  usemultiplicity=define
  use64bitint=define
  use64bitall=define
  uselongdouble=undef
  usemymalloc=n
  default_inc_excludes_dot=define
  bincompat5005=undef
  Compiler​:
  cc='cc'
  ccflags ='-DHAS_FPSETMASK -DHAS_FLOATINGPOINT_H
-fno-strict-aliasing -pipe -fstack-protector-strong -I/usr/local/include
-D_FORTIFY_SOURCE=2'
  optimize='-O2 -pipe -fstack-protector -fno-strict-aliasing'
  cppflags='-DHAS_FPSETMASK -DHAS_FLOATINGPOINT_H
-fno-strict-aliasing -pipe -fstack-protector-strong -I/usr/local/include'
  ccversion=''
  gccversion='4.2.1 Compatible FreeBSD Clang 6.0.1
(tags/RELEASE_601/final 335540)'
  gccosandvers=''
  intsize=4
  longsize=8
  ptrsize=8
  doublesize=8
  byteorder=12345678
  doublekind=3
  d_longlong=define
  longlongsize=8
  d_longdbl=define
  longdblsize=16
  longdblkind=3
  ivtype='long'
  ivsize=8
  nvtype='double'
  nvsize=8
  Off_t='off_t'
  lseeksize=8
  alignbytes=8
  prototype=define
  Linker and Libraries​:
  ld='cc'
  ldflags ='-pthread -Wl,-E -fstack-protector-strong -L/usr/local/lib'
  libpth=/usr/lib /usr/local/lib /usr/lib/clang/6.0.1/lib /usr/lib
  libs=-lpthread -lgdbm -ldl -lm -lcrypt -lutil
  perllibs=-lpthread -ldl -lm -lcrypt -lutil
  libc=
  so=so
  useshrplib=false
  libperl=libperl.a
  gnulibc_version=''
  Dynamic Linking​:
  dlsrc=dl_dlopen.xs
  dlext=so
  d_dlsymun=undef
  ccdlflags=' '
  cccdlflags='-DPIC -fPIC'
  lddlflags='-shared -L/usr/local/lib -fstack-protector-strong'

Characteristics of this binary (from libperl)​:
  Compile-time options​:
  HAS_TIMES
  MULTIPLICITY
  PERLIO_LAYERS
  PERL_COPY_ON_WRITE
  PERL_DONT_CREATE_GVSV
  PERL_IMPLICIT_CONTEXT
  PERL_MALLOC_WRAP
  PERL_OP_PARENT
  PERL_PRESERVE_IVUV
  PERL_USE_DEVEL
  USE_64_BIT_ALL
  USE_64_BIT_INT
  USE_ITHREADS
  USE_LARGE_FILES
  USE_LOCALE
  USE_LOCALE_COLLATE
  USE_LOCALE_CTYPE
  USE_LOCALE_NUMERIC
  USE_LOCALE_TIME
  USE_PERLIO
  USE_PERL_ATOF
  USE_REENTRANT_API
  Built under freebsd
  Compiled at Jun 4 2019 00​:08​:26
  %ENV​:
  PERL2DIR="/home/jkeenan/gitwork/perl2"
  PERL_WORKDIR="/home/jkeenan/gitwork/perl"
  @​INC​:
  lib
  /usr/local/lib/perl5/site_perl/5.31.1/amd64-freebsd-thread-multi
  /usr/local/lib/perl5/site_perl/5.31.1
  /usr/local/lib/perl5/5.31.1/amd64-freebsd-thread-multi
  /usr/local/lib/perl5/5.31.1

[p5pRT]

From @jkeenan

On Tue, 04 Jun 2019 00​:14​:02 GMT, jkeenan@​pobox.com wrote​:

The following smoke test indicates that a recent change to blead is
causing failures in t/op/sprintf2.t on FreeBSD-11.

#####
http​://perl5.test-smoke.org/report/88863
#####

In each of 36 different configurations in the smoke test run, all tests
pass individually, but the file has a whole is graded FAIL.

#####
$ cd t; ./perl harness -v op/sprintf2.t;cd -

ok 1 - the sprintf "%.<number>g" optimization
ok 2 - the sprintf "%.<number>f" optimization
ok 3 - width calculation under utf8 upgrade, length=1
...
ok 1698 - special-case %.0f on -4503599627370503
ok 1699 - croak for very large numeric format results
Dubious, test returned 9 (wstat 2304, 0x900)
All 1699 subtests passed
(less 30 skipped subtests​: 1669 okay)

Test Summary Report
-------------------
op/sprintf2.t (Wstat​: 2304 Tests​: 1699 Failed​: 0)
Non-zero exit status​: 9
Files=1, Tests=1699, 0 wallclock secs ( 0.20 usr 0.01 sys + 0.16 cusr
0.11 csys = 0.48 CPU)
Result​: FAIL
#####

Bisecting with the following command ...

#####
perl Porting/bisect.pl --start=e3c1dc81bd --end=9f58603ced --target
t/op/sprintf2.t
#####

... gave this result​:

#####
...
good - zero exit from ./perl -Ilib t/op/sprintf2.t
Runner returned 0 for end revision at Porting/bisect.pl line 233.
That took 114 seconds.
#####

... which is not useful. I hypothesized that something is tickling
.t/TEST or ./t perl harness with respect to the failing test (or vice
versa).

To test this hypothesis, I reviewed 'git log' and noticed two commits
which might have touched sprintf functionality. I built perl at each of
them, saw that one PASS and one FAIL; confirmed the FAIL.

#####
commit 027471c
Author​: Tony Cook <tony@​develop-help.com>
AuthorDate​: Wed Mar 20 16​:47​:49 2019 +1100
Commit​: Tony Cook <tony@​develop-help.com>
CommitDate​: Mon Jun 3 15​:48​:34 2019 +1000

(perl #133913) limit numeric format results to INT_MAX

The return value of v?snprintf() is int, and we pay attention to that
return value, so limit the expected size of numeric formats to INT_MAX.
#####

Thank you very much.
Jim Keenan

The problem lies in this unit test which was added to t/op/sprintf2.t in the commit in question​:

#####
# large uvsize needed so the large width is parsed properly
# large sizesize needed so the STRLEN check doesn't
if ($Config{intsize} == 4 && $Config{uvsize} > 4 && $Config{sizesize} > 4) {
  eval { my $x = sprintf("%7000000000E", 0) };
  like($@​, qr/^Numeric format result too large at /,
  "croak for very large numeric format results");
}
#####

If I comment out this test, I get a PASS.

So something's amiss with that test in relation to the harness.

Thank you very much.

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

[p5pRT]

From [Unknown Contact. See original ticket]

On Tue, 04 Jun 2019 00​:14​:02 GMT, jkeenan@​pobox.com wrote​:

The following smoke test indicates that a recent change to blead is
causing failures in t/op/sprintf2.t on FreeBSD-11.

#####
http​://perl5.test-smoke.org/report/88863
#####

In each of 36 different configurations in the smoke test run, all tests
pass individually, but the file has a whole is graded FAIL.

#####
$ cd t; ./perl harness -v op/sprintf2.t;cd -

ok 1 - the sprintf "%.<number>g" optimization
ok 2 - the sprintf "%.<number>f" optimization
ok 3 - width calculation under utf8 upgrade, length=1
...
ok 1698 - special-case %.0f on -4503599627370503
ok 1699 - croak for very large numeric format results
Dubious, test returned 9 (wstat 2304, 0x900)
All 1699 subtests passed
(less 30 skipped subtests​: 1669 okay)

Test Summary Report
-------------------
op/sprintf2.t (Wstat​: 2304 Tests​: 1699 Failed​: 0)
Non-zero exit status​: 9
Files=1, Tests=1699, 0 wallclock secs ( 0.20 usr 0.01 sys + 0.16 cusr
0.11 csys = 0.48 CPU)
Result​: FAIL
#####

Bisecting with the following command ...

#####
perl Porting/bisect.pl --start=e3c1dc81bd --end=9f58603ced --target
t/op/sprintf2.t
#####

... gave this result​:

#####
...
good - zero exit from ./perl -Ilib t/op/sprintf2.t
Runner returned 0 for end revision at Porting/bisect.pl line 233.
That took 114 seconds.
#####

... which is not useful. I hypothesized that something is tickling
.t/TEST or ./t perl harness with respect to the failing test (or vice
versa).

To test this hypothesis, I reviewed 'git log' and noticed two commits
which might have touched sprintf functionality. I built perl at each of
them, saw that one PASS and one FAIL; confirmed the FAIL.

#####
commit 027471c
Author​: Tony Cook <tony@​develop-help.com>
AuthorDate​: Wed Mar 20 16​:47​:49 2019 +1100
Commit​: Tony Cook <tony@​develop-help.com>
CommitDate​: Mon Jun 3 15​:48​:34 2019 +1000

(perl #133913) limit numeric format results to INT_MAX

The return value of v?snprintf() is int, and we pay attention to that
return value, so limit the expected size of numeric formats to INT_MAX.
#####

Thank you very much.
Jim Keenan

The problem lies in this unit test which was added to t/op/sprintf2.t in the commit in question​:

#####
# large uvsize needed so the large width is parsed properly
# large sizesize needed so the STRLEN check doesn't
if ($Config{intsize} == 4 && $Config{uvsize} > 4 && $Config{sizesize} > 4) {
  eval { my $x = sprintf("%7000000000E", 0) };
  like($@​, qr/^Numeric format result too large at /,
  "croak for very large numeric format results");
}
#####

If I comment out this test, I get a PASS.

So something's amiss with that test in relation to the harness.

Thank you very much.

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

[p5pRT]

From @hvds

On Mon, 03 Jun 2019 17​:14​:02 -0700, jkeenan@​pobox.com wrote​:

The following smoke test indicates that a recent change to blead is
causing failures in t/op/sprintf2.t on FreeBSD-11.
[...]
op/sprintf2.t (Wstat​: 2304 Tests​: 1699 Failed​: 0)
Non-zero exit status​: 9

It's this non-zero exit status that's making it a fail. That's reporting that it terminated with a SEGV. It's a bit strange that a change is causing a segv only after that test has run successfully, but definitely a good reason for calling it failure.

I can't yet reproduce it here, but you should be getting a core dump. If you can generate one (ideally on a debugging perl) and get a stack trace out of gdb it should be possible to diagnose the problem.

Hugo

[p5pRT]

The RT System itself - Status changed from 'new' to 'open'

[p5pRT]

From @jkeenan

On Tue, 04 Jun 2019 01​:15​:35 GMT, hv wrote​:

On Mon, 03 Jun 2019 17​:14​:02 -0700, jkeenan@​pobox.com wrote​:

The following smoke test indicates that a recent change to blead is
causing failures in t/op/sprintf2.t on FreeBSD-11.
[...]
op/sprintf2.t (Wstat​: 2304 Tests​: 1699 Failed​: 0)
Non-zero exit status​: 9

It's this non-zero exit status that's making it a fail. That's
reporting that it terminated with a SEGV. It's a bit strange that a
change is causing a segv only after that test has run successfully,
but definitely a good reason for calling it failure.

I can't yet reproduce it here, but you should be getting a core dump.
If you can generate one (ideally on a debugging perl) and get a stack
trace out of gdb it should be possible to diagnose the problem.

Hugo

I haven't used gdb in years, so I'm fumbling around.

Does this help?

#####
[t] $ gdb ./perl perl.core
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"...
Core was generated by `./perl -I.. -MTestInit op/sprintf2.t'.
Program terminated with signal 11, Segmentation fault.
Reading symbols from /lib/libthr.so.3...Reading symbols from /usr/lib/debug//lib/libthr.so.3.debug...done.
done.
Loaded symbols for /lib/libthr.so.3
Reading symbols from /usr/lib/libdl.so.1...Reading symbols from /usr/lib/debug//usr/lib/libdl.so.1.debug...done.
done.
Loaded symbols for /usr/lib/libdl.so.1
Reading symbols from /lib/libm.so.5...Reading symbols from /usr/lib/debug//lib/libm.so.5.debug...done.
done.
Loaded symbols for /lib/libm.so.5
Reading symbols from /lib/libcrypt.so.5...Reading symbols from /usr/lib/debug//lib/libcrypt.so.5.debug...done.
done.
Loaded symbols for /lib/libcrypt.so.5
Reading symbols from /lib/libutil.so.9...Reading symbols from /usr/lib/debug//lib/libutil.so.9.debug...done.
done.
Loaded symbols for /lib/libutil.so.9
Reading symbols from /lib/libc.so.7...Reading symbols from /usr/lib/debug//lib/libc.so.7.debug...done.
done.
Loaded symbols for /lib/libc.so.7
Reading symbols from /libexec/ld-elf.so.1...Reading symbols from /usr/lib/debug//libexec/ld-elf.so.1.debug...done.
done.
Loaded symbols for /libexec/ld-elf.so.1
#0 S_my_exit_jump (my_perl=0x801e22000) at perl.c​:5261
5261 if (cxstack_ix >= 0) {
(gdb) bt
#0 S_my_exit_jump (my_perl=0x801e22000) at perl.c​:5261
#1 0x0000000000458107 in Perl_my_failure_exit (my_perl=0x801e22000) at perl.c​:5249
#2 0x00000000005987e2 in Perl_die_unwind (my_perl=0x801e22000, msv=0x801f56838) at pp_ctl.c​:1797
#3 0x00000000004f4788 in Perl_vcroak (my_perl=0x801e22000, pat=0x801f56838 "\030 �\001\b", args=0x7fffffffe2a0)
  at util.c​:1711
#4 0x00000000004f1b27 in Perl_croak_nocontext (pat=<value optimized out>) at util.c​:1745
#5 0x00000000006128bb in PerlIOUnix_refcnt_inc (fd=0) at perlio.c​:2309
#6 0x0000000000613298 in PerlIOUnix_open (my_perl=0x801e22000, self=0x81dd30, layers=0x801e1b8d8, n=0,
  mode=0x81e4c0 "r", fd=0, imode=0, perm=0, f=0x801eac038, narg=0, args=0x0) at perlio.c​:2607
#7 0x000000000061519c in PerlIOBuf_open (my_perl=0x801e22000, self=0x81da90, layers=0x801e1b8d8, n=1,
  mode=<value optimized out>, fd=1, imode=0, perm=0, f=0x0, narg=0, args=0x0) at perlio.c​:3897
#8 0x0000000000611238 in PerlIO_openn (my_perl=0x801e22000, layers=<value optimized out>,
  mode=<value optimized out>, fd=0, imode=<value optimized out>, perm=<value optimized out>, f=0x0, narg=0,
  args=0x0) at perlio.c​:1550
#9 0x000000000061010e in PerlIO_stdstreams (my_perl=0x801e22000) at perlio.c​:4928
#10 0x0000000000616ecd in Perl_PerlIO_stderr (my_perl=0x801e22000) at perlio.c​:4884
#11 0x00000000004f4463 in Perl_write_to_stderr (my_perl=0x801e22000, msv=0x801f56838) at util.c​:1516
#12 0x00000000005987da in Perl_die_unwind (my_perl=0x801e22000, msv=0x801f56838) at pp_ctl.c​:1796
#13 0x00000000004f4788 in Perl_vcroak (my_perl=0x801e22000, pat=0x801f56838 "\030 �\001\b", args=0x7fffffffe680)
  at util.c​:1711
#14 0x00000000004f1b27 in Perl_croak_nocontext (pat=<value optimized out>) at util.c​:1745
#15 0x000000000044c57e in Perl_sys_term () at perl.c​:146
#16 0x0000000000421472 in main (argc=<value optimized out>, argv=<value optimized out>, env=0x7fffffffe770)
---Type <return> to continue, or q <return> to quit---
  at perlmain.c​:155
#####
--
James E Keenan (jkeenan@​cpan.org)

[p5pRT]

From @jkeenan

On Tue, 04 Jun 2019 02​:22​:56 GMT, jkeenan wrote​:

#3 0x00000000004f4788 in Perl_vcroak (my_perl=0x801e22000,
pat=0x801f56838 "\030 �\001\b", args=0x7fffffffe2a0)
at util.c​:1711

That non-printing character is octal​:

357 277 275

#4 0x00000000004f1b27 in Perl_croak_nocontext (pat=<value optimized
out>) at util.c​:1745
...
#12 0x00000000005987da in Perl_die_unwind (my_perl=0x801e22000,
msv=0x801f56838) at pp_ctl.c​:1796
#13 0x00000000004f4788 in Perl_vcroak (my_perl=0x801e22000,
pat=0x801f56838 "\030 �\001\b", args=0x7fffffffe680)
at util.c​:1711

Same here.

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

[p5pRT]

From @khwilliamson

On 6/3/19 8​:35 PM, James E Keenan via RT wrote​:

On Tue, 04 Jun 2019 02​:22​:56 GMT, jkeenan wrote​:

#3 0x00000000004f4788 in Perl_vcroak (my_perl=0x801e22000,
pat=0x801f56838 "\030 �\001\b", args=0x7fffffffe2a0)
at util.c​:1711

That non-printing character is octal​:

357 277 275

which is REPLACEMENT CHARACTER

#4 0x00000000004f1b27 in Perl_croak_nocontext (pat=<value optimized
out>) at util.c​:1745
...
#12 0x00000000005987da in Perl_die_unwind (my_perl=0x801e22000,
msv=0x801f56838) at pp_ctl.c​:1796
#13 0x00000000004f4788 in Perl_vcroak (my_perl=0x801e22000,
pat=0x801f56838 "\030 �\001\b", args=0x7fffffffe680)
at util.c​:1711

Same here.

[p5pRT]

From @hvds

On Mon, 03 Jun 2019 19​:22​:56 -0700, jkeenan wrote​:

On Tue, 04 Jun 2019 01​:15​:35 GMT, hv wrote​:

On Mon, 03 Jun 2019 17​:14​:02 -0700, jkeenan@​pobox.com wrote​:

The following smoke test indicates that a recent change to blead is
causing failures in t/op/sprintf2.t on FreeBSD-11.
[...]
op/sprintf2.t (Wstat​: 2304 Tests​: 1699 Failed​: 0)
Non-zero exit status​: 9

It's this non-zero exit status that's making it a fail. That's
reporting that it terminated with a SEGV.

I haven't used gdb in years, so I'm fumbling around.

Does this help?

Well, it is exactly what I asked for.

#13 0x00000000004f4788 in Perl_vcroak (my_perl=0x801e22000, pat=0x801f56838 "\030 �\001\b", args=0x7fffffffe680) at util.c​:1711
#14 0x00000000004f1b27 in Perl_croak_nocontext (pat=<value optimized
out>) at util.c​:1745
#15 0x000000000044c57e in Perl_sys_term () at perl.c​:146
#16 0x0000000000421472 in main (argc=<value optimized out>,
argv=<value optimized out>, env=0x7fffffffe770)
at perlmain.c​:155

We're in sys_term, so most of the interpreter has already been wiped out, but we're then calling croak(), which relies on the interpreter's infrastructure.

My best guess is that we're hitting 'Perl_croak_nocontext("panic​: MUTEX_UNLOCK (%d) [%s​:%d]" ...)' in one of the MUTEX_UNLOCK calls, and some wild writes have corrupted both one of our mutexes and perhaps this panic string.

It seems like it'd be hard for it to get this far with that level of corruption though.

I'll try harder to reproduce it​: I'd need some interactive gdb work to diagnose it.

Hugo

[p5pRT]

From @hvds

On Mon, 03 Jun 2019 21​:15​:59 -0700, hv wrote​:

On Mon, 03 Jun 2019 19​:22​:56 -0700, jkeenan wrote​:

On Tue, 04 Jun 2019 01​:15​:35 GMT, hv wrote​:

On Mon, 03 Jun 2019 17​:14​:02 -0700, jkeenan@​pobox.com wrote​:

The following smoke test indicates that a recent change to blead
is
causing failures in t/op/sprintf2.t on FreeBSD-11.
[...]
op/sprintf2.t (Wstat​: 2304 Tests​: 1699 Failed​: 0)
Non-zero exit status​: 9

It's this non-zero exit status that's making it a fail. That's
reporting that it terminated with a SEGV.

I haven't used gdb in years, so I'm fumbling around.

Does this help?

Well, it is exactly what I asked for.

#13 0x00000000004f4788 in Perl_vcroak (my_perl=0x801e22000,
pat=0x801f56838 "\030 �\001\b", args=0x7fffffffe680) at util.c​:1711
#14 0x00000000004f1b27 in Perl_croak_nocontext (pat=<value optimized
out> ) at util.c​:1745
#15 0x000000000044c57e in Perl_sys_term () at perl.c​:146
#16 0x0000000000421472 in main (argc=<value optimized out>,
argv=<value optimized out>, env=0x7fffffffe770)
at perlmain.c​:155

We're in sys_term, so most of the interpreter has already been wiped
out, but we're then calling croak(), which relies on the interpreter's
infrastructure.

My best guess is that we're hitting 'Perl_croak_nocontext("panic​:
MUTEX_UNLOCK (%d) [%s​:%d]" ...)' in one of the MUTEX_UNLOCK calls, and
some wild writes have corrupted both one of our mutexes and perhaps
this panic string.

Oops, s/MUTEX_UNLOCK/MUTEX_DESTROY/g

It seems like it'd be hard for it to get this far with that level of
corruption though.

I'll try harder to reproduce it​: I'd need some interactive gdb work to
diagnose it.

Hugo

[p5pRT]

From @jkeenan

On Tue, 04 Jun 2019 04​:15​:59 GMT, hv wrote​:

On Mon, 03 Jun 2019 19​:22​:56 -0700, jkeenan wrote​:

On Tue, 04 Jun 2019 01​:15​:35 GMT, hv wrote​:

On Mon, 03 Jun 2019 17​:14​:02 -0700, jkeenan@​pobox.com wrote​:

The following smoke test indicates that a recent change to blead
is
causing failures in t/op/sprintf2.t on FreeBSD-11.
[...]
op/sprintf2.t (Wstat​: 2304 Tests​: 1699 Failed​: 0)
Non-zero exit status​: 9

It's this non-zero exit status that's making it a fail. That's
reporting that it terminated with a SEGV.

I haven't used gdb in years, so I'm fumbling around.

Does this help?

Well, it is exactly what I asked for.

#13 0x00000000004f4788 in Perl_vcroak (my_perl=0x801e22000,
pat=0x801f56838 "\030 �\001\b", args=0x7fffffffe680) at util.c​:1711
#14 0x00000000004f1b27 in Perl_croak_nocontext (pat=<value optimized
out> ) at util.c​:1745
#15 0x000000000044c57e in Perl_sys_term () at perl.c​:146
#16 0x0000000000421472 in main (argc=<value optimized out>,
argv=<value optimized out>, env=0x7fffffffe770)
at perlmain.c​:155

We're in sys_term, so most of the interpreter has already been wiped
out, but we're then calling croak(), which relies on the interpreter's
infrastructure.

My best guess is that we're hitting 'Perl_croak_nocontext("panic​:
MUTEX_UNLOCK (%d) [%s​:%d]" ...)' in one of the MUTEX_UNLOCK calls, and
some wild writes have corrupted both one of our mutexes and perhaps
this panic string.

It seems like it'd be hard for it to get this far with that level of
corruption though.

I'll try harder to reproduce it​: I'd need some interactive gdb work to
diagnose it.

Hugo

This is now showing up on other OSes. See​:
http​://perl5.test-smoke.org/submatrix?test=../t/op/sprintf2.t&pversion=5.31.1

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

[p5pRT]

From @hvds

On Mon, 03 Jun 2019 21​:15​:59 -0700, hv wrote​:

On Mon, 03 Jun 2019 19​:22​:56 -0700, jkeenan wrote​:

#13 0x00000000004f4788 in Perl_vcroak (my_perl=0x801e22000,
pat=0x801f56838 "\030 �\001\b", args=0x7fffffffe680) at util.c​:1711
#14 0x00000000004f1b27 in Perl_croak_nocontext (pat=<value optimized
out> ) at util.c​:1745
#15 0x000000000044c57e in Perl_sys_term () at perl.c​:146
#16 0x0000000000421472 in main (argc=<value optimized out>,
argv=<value optimized out>, env=0x7fffffffe770)
at perlmain.c​:155

We're in sys_term, so most of the interpreter has already been wiped
out, but we're then calling croak(), which relies on the interpreter's
infrastructure.
[...]
I'll try harder to reproduce it​: I'd need some interactive gdb work to
diagnose it.

I still cannot reproduce here. Please could you try getting another stacktrace with the attached patch applied, to narrow down which bit of Perl_sys_term() we're in?

To help with subsequent tests, it would also be useful to narrow down the testcase. Please check if any of these reproduce the SEGV​:
  ./perl -e 'my $x = sprintf("%7000000000E", 0)'
  ./perl -e 'eval { my $x = sprintf("%7000000000E", 0) }; print "ok\n"'
  the attached sprintf2-short.t, with all but the new test removed

Cheers,

Hugo

[p5pRT]

From @hvds

0001-DO-NOT-COMMIT-expand-PERL_SYS_TERM_BODY.patch

From 03ad1fae97d9b34922e0e00f387cebe466ca13ef Mon Sep 17 00:00:00 2001
From: Hugo van der Sanden <hv@crypt.org>
Date: Wed, 5 Jun 2019 11:29:12 +0100
Subject: [PATCH] DO NOT COMMIT: expand PERL_SYS_TERM_BODY

Expand the unixish body for Perl_sys_term() for more useful stacktrace.
---
 perl.c | 9 ++++++++-
 1 file changed, 8 insertions(+), 1 deletion(-)

diff --git a/perl.c b/perl.c
index 69e3efcd70..acb7c4f2a2 100644
--- a/perl.c
+++ b/perl.c
@@ -143,7 +143,14 @@ Perl_sys_term(void)
 {
     dVAR;
     if (!PL_veto_cleanup) {
-	PERL_SYS_TERM_BODY();
+	HINTS_REFCNT_TERM;          /* PL_hints_mutex */
+        KEYWORD_PLUGIN_MUTEX_TERM;  /* PL_keyword_plugin_mutex */
+        OP_CHECK_MUTEX_TERM;        /* PL_check_mutex */
+        OP_REFCNT_TERM;             /* PL_op_mutex */
+        PERLIO_TERM;                /* PerlIO_teardown() */
+        MALLOC_TERM;                /* PL_malloc_mutex */
+        LOCALE_TERM;                /* PL_locale_mutex */
+        USER_PROP_MUTEX_TERM;       /* PL_user_prop_mutex */
     }
 }
 
-- 
2.17.1

[p5pRT]

From @hvds

#!./perl -w

# Tests for sprintf that do not fit the format of sprintf.t.

BEGIN {
  chdir 't' if -d 't';
  require './test.pl';
  require './charset_tools.pl';
  set_up_inc('../lib');
}

use strict;
use Config;

# large uvsize needed so the large width is parsed properly
# large sizesize needed so the STRLEN check doesn't
if ($Config{intsize} == 4 && $Config{uvsize} > 4 && $Config{sizesize} > 4) {
  eval { my $x = sprintf("%7000000000E", 0) };
  like($@​, qr/^Numeric format result too large at /,
  "croak for very large numeric format results");
}
done_testing();

[p5pRT]

From @jkeenan

On Wed, 05 Jun 2019 10​:39​:48 GMT, hv wrote​:

On Mon, 03 Jun 2019 21​:15​:59 -0700, hv wrote​:

On Mon, 03 Jun 2019 19​:22​:56 -0700, jkeenan wrote​:

#13 0x00000000004f4788 in Perl_vcroak (my_perl=0x801e22000,
pat=0x801f56838 "\030 �\001\b", args=0x7fffffffe680) at util.c​:1711
#14 0x00000000004f1b27 in Perl_croak_nocontext (pat=<value
optimized
out> ) at util.c​:1745
#15 0x000000000044c57e in Perl_sys_term () at perl.c​:146
#16 0x0000000000421472 in main (argc=<value optimized out>,
argv=<value optimized out>, env=0x7fffffffe770)
at perlmain.c​:155

We're in sys_term, so most of the interpreter has already been wiped
out, but we're then calling croak(), which relies on the
interpreter's
infrastructure.
[...]
I'll try harder to reproduce it​: I'd need some interactive gdb work
to
diagnose it.

I still cannot reproduce here. Please could you try getting another
stacktrace with the attached patch applied, to narrow down which bit
of Perl_sys_term() we're in?

To help with subsequent tests, it would also be useful to narrow down
the testcase. Please check if any of these reproduce the SEGV​:
./perl -e 'my $x = sprintf("%7000000000E", 0)'
./perl -e 'eval { my $x = sprintf("%7000000000E", 0) }; print
"ok\n"'
the attached sprintf2-short.t, with all but the new test removed

(The previously reported backtrace was from a version of t/op/sprintf2.t with all tests but the final one commented out.)

See attachment, hugo-results-20190605.txt.

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