smoker fail op/magic and io/errnosig under threads

[hvds]

George Greer's blead_clang_quick_sanitize=address smoker has been giving the following two test failures on threaded builds for a while now:

../t/io/errnosig.t..........................................FAILED
    Non-zero exit status: 1
../t/op/magic.t.............................................FAILED
    Non-zero exit status: 1

Looking through the smoke db history, this appears to have started with e8581bc, which was a doc patch.

@greerga is it possible something changed on the machine around 2020-10-19 that could have caused this? Would it be possible to get a manual run of those two tests?

[jkeenan]

George Greer's blead_clang_quick_sanitize=address smoker has been giving the following two test failures on threaded builds for a while now:

../t/io/errnosig.t..........................................FAILED
    Non-zero exit status: 1
../t/op/magic.t.............................................FAILED
    Non-zero exit status: 1

Looking through the smoke db history, this appears to have started with e8581bc, which was a doc patch.

@greerga is it possible something changed on the machine around 2020-10-19 that could have caused this? Would it be possible to get a manual run of those two tests?

Could you provide URLs to those smoke-test reports? Thanks.

[jkeenan]

George Greer's blead_clang_quick_sanitize=address smoker has been giving the following two test failures on threaded builds for a while now:

../t/io/errnosig.t..........................................FAILED
    Non-zero exit status: 1
../t/op/magic.t.............................................FAILED
    Non-zero exit status: 1

Looking through the smoke db history, this appears to have started with e8581bc, which was a doc patch.
@greerga is it possible something changed on the machine around 2020-10-19 that could have caused this? Would it be possible to get a manual run of those two tests?

Could you provide URLs to those smoke-test reports? Thanks.

@hvds, is this one of the relevant smoke-test reports?
http://perl.develop-help.com/raw/?id=265066

[hvds]

Could you provide URLs to those smoke-test reports? Thanks.

I worked back to http://perl.develop-help.com/?s=33b570413b33a4dcbfc49adef206bc73cf5db270, where I saw the failures in http://perl.develop-help.com/raw/?id=259435 for e8581bc but not in the preceding http://perl.develop-help.com/raw/?id=259333 for bb58640. (The issue is slightly muddied by some locale failures introduced at a similar time, but those were quickly resolved.)

@hvds, is this one of the relevant smoke-test reports?
http://perl.develop-help.com/raw/?id=265066

Yes, that's the sort of thing.

[jkeenan]

With the configuration below, I got no test failures in the two files cited by @hvds.

cd t;TEST_JOBS=1 ./perl harness io/errnosig.t op/magic.t; cd -
io/errnosig.t .. ok   
op/magic.t ..... ok       
All tests successful.
Files=2, Tests=193,  5 wallclock secs ( 0.08 usr  0.01 sys +  0.55 cusr  0.49 csys =  1.13 CPU)
Result: PASS

Summary of my perl5 (revision 5 version 33 subversion 7) configuration:
  Commit id: d4c0efc5ecf8e55dc836384c26ca7ba29689caf4
  Platform:
    osname=linux                            archname=x86_64-linux-thread-multi
    osvers=5.1.17-x86_64-linode128
    uname='linux li796-253 5.1.17-x86_64-linode128 #1 smp preempt wed jul 10 17:11:49 utc 2019 x86_64 gnulinux '
    config_args='-des -Dusedevel -Duseithreads -DDEBUGGING -Dcc=clang-6.0 -Accflags=-DPERL_POISON -Werror=declaration-after-statement -fsanitize=address -Aldflags=-fsanitize=address -Doptimize=-g -O3'
    hint=recommended                        use64bitall=define
    useposix=true                           uselongdouble=undef
    d_sigaction=define                      usemymalloc=n
    useithreads=define                      default_inc_excludes_dot=define
    usemultiplicity=define
    use64bitint=define
  Compiler:
    cc='clang-6.0'
    ccflags ='-D_REENTRANT -D_GNU_SOURCE -DPERL_POISON -Werror=declaration-after-statement -fsanitize=address -DDEBUGGING -fno-strict-aliasing -pipe -fstack-protector-strong -I/usr/local/include -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64 -D_FORTIFY_SOURCE=2'
    optimize='-g -O3'
    cppflags='-D_REENTRANT -D_GNU_SOURCE -DPERL_POISON -Werror=declaration-after-statement -fsanitize=address -DDEBUGGING -fno-strict-aliasing -pipe -fstack-protector-strong -I/usr/local/include'
    ccversion=''
    gccversion='4.2.1 Compatible Clang 6.0.1 (tags/RELEASE_601/final)'
    gccosandvers=''                         longdblkind=3
    intsize=4                               ivtype='long'
    longsize=8                              ivsize=8
    ptrsize=8                               nvtype='double'
    doublesize=8                            nvsize=8
    byteorder=12345678                      Off_t='off_t'
    doublekind=3                            lseeksize=8
    d_longlong=define                       alignbytes=8
    longlongsize=8                          prototype=define
    d_longdbl=define
    longdblsize=16
  Linker and Libraries:
    ld='clang-6.0'
    ldflags =' -fsanitize=address -fstack-protector-strong -L/usr/local/lib'
    libpth=/usr/local/lib /usr/lib/llvm-6.0/lib/clang/6.0.1/lib /usr/include/x86_64-linux-gnu /usr/lib /lib/x86_64-linux-gnu /lib/../lib /usr/lib/x86_64-linux-gnu /usr/lib/../lib /lib
    libs=-lpthread -lnsl -ldb -ldl -lm -lcrypt -lutil -lc
    perllibs=-lpthread -lnsl -ldl -lm -lcrypt -lutil -lc
    libc=libc-2.19.so                       libperl=libperl.a
    so=so                                   gnulibc_version='2.19'
    useshrplib=false
  Dynamic Linking:
    dlsrc=dl_dlopen.xs                      ccdlflags='-Wl,-E'
    dlext=so                                cccdlflags='-fPIC'
    d_dlsymun=undef
    lddlflags='-shared -g -O3 -L/usr/local/lib -fstack-protector-strong'


Characteristics of this binary (from libperl): 
  Compile-time options:
    DEBUGGING                               USE_64_BIT_INT
    HAS_TIMES                               USE_ITHREADS
    MULTIPLICITY                            USE_LARGE_FILES
    PERLIO_LAYERS                           USE_LOCALE
    PERL_COPY_ON_WRITE                      USE_LOCALE_COLLATE
    PERL_DONT_CREATE_GVSV                   USE_LOCALE_CTYPE
    PERL_IMPLICIT_CONTEXT                   USE_LOCALE_NUMERIC
    PERL_MALLOC_WRAP                        USE_LOCALE_TIME
    PERL_OP_PARENT                          USE_PERLIO
    PERL_POISON                             USE_PERL_ATOF
    PERL_PRESERVE_IVUV                      USE_REENTRANT_API
    PERL_TRACK_MEMPOOL                      USE_THREAD_SAFE_LOCALE
    PERL_USE_DEVEL
    USE_64_BIT_ALL
  Built under linux
  Compiled at Feb  9 2021 14:16:29
  %ENV:
    PERLBREW_BASHRC_VERSION="0.80"
    PERLBREW_HOME="/tmp/.perlbrew"
    PERLBREW_MANPATH="/tmp/perl5/perlbrew/perls/perl-5.28.0/man"
    PERLBREW_PATH="/tmp/perl5/perlbrew/bin:/tmp/perl5/perlbrew/perls/perl-5.28.0/bin"
    PERLBREW_PERL="perl-5.28.0"
    PERLBREW_ROOT="/tmp/perl5/perlbrew"
    PERLBREW_VERSION="0.80"
    PERL_DESTRUCT_LEVEL="2"
    PERL_WORKDIR="/tmp/gitwork/perl"
  @INC:
    lib
    /usr/local/lib/perl5/site_perl/5.33.7/x86_64-linux-thread-multi
    /usr/local/lib/perl5/site_perl/5.33.7
    /usr/local/lib/perl5/5.33.7/x86_64-linux-thread-multi
    /usr/local/lib/perl5/5.33.7

Am I missing something?

[jkeenan]

However, in a threaded build on FreeBSD-12 at commit ef32c611aa2, I did get a minitest failure for t/op/magic.t:

$ make minitest

t/op/magic ..................... # Failed test 188 - altering $0 is effective (testing with `ps`) at op/magic.t line 840
#      got 'x (miniperl)'
# expected /(?^:^(?:perl: )?x(?: \(perl\))?$)/
FAILED at test 188

Got same result after minitest_prep with

$ cd t;./perl -I../lib op/magic.t; cd -

Configuration:

$ uname -mrs
FreeBSD 12.2-STABLE amd64

$ clang --version
FreeBSD clang version 10.0.1 (git@github.com:llvm/llvm-project.git llvmorg-10.0.1-0-gef32c611aa2)
Target: x86_64-unknown-freebsd12.2
Thread model: posix
InstalledDir: /usr/bin

$ ./perl -Ilib -V
Summary of my perl5 (revision 5 version 33 subversion 7) configuration:
  Commit id: 869f54b5780ae4da897c3d4ea055d708c0281967
  Platform:
    osname=freebsd
    osvers=12.2-stable
    archname=amd64-freebsd-thread-multi
    uname='freebsd perlmonger.nycbug.org 12.2-stable freebsd 12.2-stable r368982 generic amd64 '
    config_args='-des -Dusedevel -Duseithreads -Doptimize=-O2 -pipe -fstack-protector -fno-strict-aliasing'
    hint=recommended                        use64bitall=define
    useposix=true                           uselongdouble=undef
    d_sigaction=define                      usemymalloc=n
    useithreads=define                      default_inc_excludes_dot=define
    usemultiplicity=define
    use64bitint=define
  Compiler:
    cc='cc'
    ccflags ='-DHAS_FPSETMASK -DHAS_FLOATINGPOINT_H -fno-strict-aliasing -pipe -fstack-protector-strong -I/usr/local/include'
    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='FreeBSD Clang 10.0.1 (git@github.com:llvm/llvm-project.git llvmorg-10.0.1-0-gef32c611aa2)'
    gccosandvers=''                         longdblkind=3
    intsize=4                               ivtype='long'
    longsize=8                              ivsize=8
    ptrsize=8                               nvtype='double'
    doublesize=8                            nvsize=8
    byteorder=12345678                      Off_t='off_t'
    doublekind=3                            lseeksize=8
    d_longlong=define                       alignbytes=8
    longlongsize=8                          prototype=define
    d_longdbl=define
    longdblsize=16
  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/10.0.1/lib /usr/lib
    libs=-lpthread -lgdbm -ldl -lm -lcrypt -lutil
    perllibs=-lpthread -ldl -lm -lcrypt -lutil
    libc=                                   libperl=libperl.a
    so=so                                   gnulibc_version=''
    useshrplib=false
  Dynamic Linking:
    dlsrc=dl_dlopen.xs                      ccdlflags=' '
    dlext=so                                cccdlflags='-DPIC -fPIC'
    d_dlsymun=undef
    lddlflags='-shared  -L/usr/local/lib -fstack-protector-strong'


Characteristics of this binary (from libperl): 
  Compile-time options:
    HAS_TIMES                               USE_ITHREADS
    MULTIPLICITY                            USE_LARGE_FILES
    PERLIO_LAYERS                           USE_LOCALE
    PERL_COPY_ON_WRITE                      USE_LOCALE_COLLATE
    PERL_DONT_CREATE_GVSV                   USE_LOCALE_CTYPE
    PERL_IMPLICIT_CONTEXT                   USE_LOCALE_NUMERIC
    PERL_MALLOC_WRAP                        USE_LOCALE_TIME
    PERL_OP_PARENT                          USE_PERLIO
    PERL_PRESERVE_IVUV                      USE_PERL_ATOF
    PERL_USE_DEVEL                          USE_REENTRANT_API
    USE_64_BIT_ALL                          USE_THREAD_SAFE_LOCALE
    USE_64_BIT_INT
  Built under freebsd
  Compiled at Feb 10 2021 00:39:57
  %ENV:
    PERL2DIR="/tmp/gitwork/perl2"
    PERL_WORKDIR="/tmp/gitwork/perl"
  @INC:
    lib
    /usr/local/lib/perl5/site_perl/5.33.7/amd64-freebsd-thread-multi
    /usr/local/lib/perl5/site_perl/5.33.7
    /usr/local/lib/perl5/5.33.7/amd64-freebsd-thread-multi
    /usr/local/lib/perl5/5.33.7

However, after a full build, make test_harness PASSed.

Thank you very much.
Jim Keenan

[tonycoz]

George Greer's blead_clang_quick_sanitize=address smoker has been giving the following two test failures on threaded builds for a while now:

../t/io/errnosig.t..........................................FAILED
    Non-zero exit status: 1
../t/op/magic.t.............................................FAILED
    Non-zero exit status: 1

Looking through the smoke db history, this appears to have started with e8581bc, which was a doc patch.

I haven't been able to reproduce it with clang 11, Configured:

./Configure -des -Dcc=clang-11 -Dusedevel -DDEBUGGING -Dusethreads '-Accflags=-g -fno-omit-frame-pointer -fno-common -fsanitize=address' -Aldflags=-fsanitize=address

I had a look at the log, and found:

Direct leak of 17 byte(s) in 1 object(s) allocated from:
    #0 0x4d963f in malloc ??:0:0
    #1 0x7f419fd8e08f in __vasprintf_internal ??:0:0

which looks like libc is leaking rather than perl, though why that's happening in only two tests I have no idea. I'll have another look on a Fedora VM.

[jkeenan]

The problem I reported in this ticket 4 days ago (FreeBSD t/op/magic.t miniperl) is caused by something other than the issues discussed in this ticket. Please see: #18570.

That being said, we are still getting smoke-test failure reports for the two files cited in the original post in this ticket. See: https://www.nntp.perl.org/group/perl.daily-build.reports/2021/02/msg265330.html.

Thank you very much.
Jim Keenan

[iabyn]

On Wed, Feb 10, 2021 at 07:06:11PM -0800, Tony Cook wrote: > George Greer's `blead_clang_quick_sanitize=address` smoker has been giving the following two test failures on threaded builds for a while now: > > ``` > ../t/io/errnosig.t..........................................FAILED > Non-zero exit status: 1 > ../t/op/magic.t.............................................FAILED > Non-zero exit status: 1 > ``` > > Looking through the smoke db history, this appears to have started with [e8581bc](e8581bc), which was a doc patch. I haven't been able to reproduce it with clang 11, Configured: `./Configure -des -Dcc=clang-11 -Dusedevel -DDEBUGGING -Dusethreads '-Accflags=-g -fno-omit-frame-pointer -fno-common -fsanitize=address' -Aldflags=-fsanitize=address` I had a look at the log, and found: ``` Direct leak of 17 byte(s) in 1 object(s) allocated from: #0 0x4d963f in malloc ??:0:0 #1 0x7f419fd8e08f in __vasprintf_internal ??:0:0 ``` which looks like libc is leaking rather than perl, though why that's happening in only two tests I have no idea. I'll have another look on a Fedora VM.

The ASan smoke failures started soon after I made a few changes to magic in the merge commit below; but when I looked at George's smoke logs it seemed more like an internal error in clang, and I couldn't reproduce locally. I promptly forgot about it. commit 28df11c Merge: b0441c5 02a4896 Author: David Mitchell <davem@iabyn.com> AuthorDate: Fri Oct 23 14:26:11 2020 +0100 Commit: David Mitchell <davem@iabyn.com> CommitDate: Fri Oct 23 14:26:11 2020 +0100 [MERGE] don't do special-cases in S_mg_free_struct Move all the special-case handling of various magic types out into vtable->free() methods.

…

-- Red sky at night - gerroff my land! Red sky at morning - gerroff my land! -- old farmers' sayings #14

[tonycoz]

I did finally reproduce it, but didn't get any further information, installing llvm-symbolizer and setting ASAN_OPTIONS to request a longer stack trace didn't help. I'll see if reverting your change will prevent the leak.

[tonycoz]

It's reproducible in 5.32.0 as well, I expect George (or Fedora) updated clang or glibc which introduced the leak.

I tried debugging it a bit, before ASAN aborted (LeakSanitizer apparently doesn't work with ptrace/debuggers at some level), I saw two calls to __vasprintf_internal:

The first happens before main is reached:

reakpoint 2, 0x00007ffff7cc0f50 in __vasprintf_internal ()
   from /lib64/libc.so.6
(gdb) bt
#0  0x00007ffff7cc0f50 in __vasprintf_internal () from /lib64/libc.so.6
#1  0x00007ffff7c9b4fa in asprintf () from /lib64/libc.so.6
#2  0x00007ffff7f94af9 in dlerror () from /lib64/libdl.so.2
#3  0x00000000004e29bd in __asan::AsanInitInternal() [clone .part.0] ()
#4  0x00007ffff7fe1a2e in _dl_init () from /lib64/ld-linux-x86-64.so.2
#5  0x00007ffff7fd20ca in _dl_start_user () from /lib64/ld-linux-x86-64.so.2
#6  0x0000000000000002 in ?? ()
#7  0x00007fffffffe3ed in ?? ()
#8  0x00007fffffffe411 in ?? ()
#9  0x0000000000000000 in ?? ()
(gdb) finish
Run till exit from #0  0x00007ffff7cc0f50 in __vasprintf_internal ()
   from /lib64/libc.so.6
0x00007ffff7c9b4fa in asprintf () from /lib64/libc.so.6
(gdb) info register rax
rax            0x45                69

and the size doesn't match our leak.

The second:

reakpoint 2, 0x00007ffff7cc0f50 in __vasprintf_internal ()
   from /lib64/libc.so.6
(gdb) bt
#0  0x00007ffff7cc0f50 in __vasprintf_internal () from /lib64/libc.so.6
#1  0x00007ffff7c9b4fa in asprintf () from /lib64/libc.so.6
#2  0x00007ffff7cd91d5 in strerror_l () from /lib64/libc.so.6
#3  0x0000000001444136 in Perl_my_strerror (my_perl=0x620000000080, 
    errnum=9999) at locale.c:5285
#4  0x0000000000c1ab27 in Perl_sv_string_from_errnum (my_perl=0x620000000080, 
    errnum=9999, tgtsv=0x6210000245d8) at mg.c:884
#5  0x0000000000c1c55d in Perl_magic_get (my_perl=0x620000000080, 
    sv=0x6210000245d8, mg=0x60700000a838) at mg.c:1015
#6  0x0000000000c114e5 in Perl_mg_get (my_perl=0x620000000080, 
    sv=0x6210000245d8) at mg.c:196
#7  0x00000000006fc503 in Perl_try_amagic_un (my_perl=0x620000000080, 
    method=16, flags=16) at gv.c:2986
#8  0x0000000000ff7ea1 in Perl_pp_int (my_perl=0x620000000080) at pp.c:2950
#9  0x0000000000bbf239 in Perl_runops_debug (my_perl=0x620000000080)
    at dump.c:2571
#10 0x00000000006634d0 in S_run_body (my_perl=0x620000000080, oldscope=1)
    at perl.c:2756
#11 0x000000000065fe8f in perl_run (my_perl=0x620000000080) at perl.c:2684
#12 0x000000000050e8a5 in main (argc=2, argv=0x7fffffffe0c8, 
    env=0x7fffffffe0e0) at perlmain.c:127
(gdb) finish
Run till exit from #0  0x00007ffff7cc0f50 in __vasprintf_internal ()
   from /lib64/libc.so.6
0x00007ffff7c9b4fa in asprintf () from /lib64/libc.so.6
(gdb) info register rax
rax            0x12                18

is a much closer match.

If I comment out the test at line 591 of magic.t:

{
    #$! = 9999;
    #is int $!, 9999, q{[perl #72850] Core dump in bleadperl from perl -e '$! = 9999; $a = $!;'};
    ;
}

then the leak no longer occurs.

The pointer allocated here is released (by glibc) each time strerror_l() is called for an unknown errno, and we have no ownership over the memory, we can't free it ourselves.

So this looks like a false positive from ASAN, which I expect needs an exclusion list updated.

I expect I couldn't find any matching reports in Google and glibc bugzilla because no-one else looks up such strange errno values.

I think this is closable and not outour problem.