Skip to content

smoker fail op/magic and io/errnosig under threads #18547

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
hvds opened this issue Feb 9, 2021 · 12 comments
Open

smoker fail op/magic and io/errnosig under threads #18547

hvds opened this issue Feb 9, 2021 · 12 comments
Labels
smoke Report derived from smoke-testing

Comments

@hvds
Copy link
Contributor

hvds commented Feb 9, 2021

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
Copy link
Contributor

jkeenan commented Feb 9, 2021

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
Copy link
Contributor

jkeenan commented Feb 9, 2021

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
Copy link
Contributor Author

hvds commented Feb 9, 2021

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.

@hvds hvds added the smoke Report derived from smoke-testing label Feb 9, 2021
@jkeenan
Copy link
Contributor

jkeenan commented Feb 9, 2021

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
Copy link
Contributor

jkeenan commented Feb 10, 2021

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 ([email protected]: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 ([email protected]: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
Copy link
Contributor

tonycoz commented Feb 11, 2021

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
Copy link
Contributor

jkeenan commented Feb 13, 2021

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
Copy link
Contributor

iabyn commented Feb 15, 2021 via email

@tonycoz
Copy link
Contributor

tonycoz commented Feb 15, 2021

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
Copy link
Contributor

tonycoz commented Feb 16, 2021

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.

@iabyn
Copy link
Contributor

iabyn commented Mar 29, 2021 via email

@hvds
Copy link
Contributor Author

hvds commented Mar 29, 2021

With the commit below, the ASan smoke failures in magic.t and errnosig.t seem to have gone away.

That seems to coincide with the smokers themselves going away - the last report from the affected smoker (and as far as I can see all of George Greer's smokers) was about 13 commits earlier at 1db31a9.

Some similar but not identical looking smokers appear soon after, now attributed to Carlos Guevara, but the details are not the same: 5.3.12-200.fc30.x86_64 v. 5.10.16-200.fc33.x86_64, "ccache clang" v. gcc or g++.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
smoke Report derived from smoke-testing
Projects
None yet
Development

No branches or pull requests

4 participants