"panic: MUTEX_LOCK" in blead, but not in maint

I'm a bit lost in finding the cause for this problem and I cannot
currently run a binary search to find out which patch causes it. I
also cannot provide a small testcase because I don't fully understand
the problem.

I just synced blead and maint and out of usual habit tried to build
my CPAN modules with them. Building Convert-Binary-C-0.49 with blead,
I'm getting

[email protected: m...@r2d2] ~/src/perl/Convert-Binary-C/0.49 $ bleadperl -Mblib t/114_cache.t
  1..72
  # Running under perl version 5.009 for linux
  # Current time local: Fri Feb 27 19:34:29 2004
  # Current time GMT:   Fri Feb 27 18:34:29 2004
  # Using Test.pm version 1.24
  ok 1
  [...]
  ok 71
  # failed to create Convert::Binary::C::Cached object
# panic: MUTEX_LOCK at /home/mhx/src/perl/Convert-Binary-C/0.49/blib/lib/Convert/Binary/C/Cached.pm line 233.
  # failed to create Convert::Binary::C::Cached object
# panic: MUTEX_LOCK at /home/mhx/src/perl/Convert-Binary-C/0.49/blib/lib/Convert/Binary/C/Cached.pm line 233.
  # failed to create Convert::Binary::C::Cached object
# panic: MUTEX_LOCK at /home/mhx/src/perl/Convert-Binary-C/0.49/blib/lib/Convert/Binary/C/Cached.pm line 233.
  # failed to create Convert::Binary::C::Cached object
# panic: MUTEX_LOCK at /home/mhx/src/perl/Convert-Binary-C/0.49/blib/lib/Convert/Binary/C/Cached.pm line 233.
  # failed to create Convert::Binary::C::Cached object
# panic: MUTEX_LOCK at /home/mhx/src/perl/Convert-Binary-C/0.49/blib/lib/Convert/Binary/C/Cached.pm line 233.
  Segmentation fault

when running the t/114_cache.t test. There's no such problem with maint.

I rebuilt blead with debugging enabled and patched the MUTEX_LOCK
macro to include __FILE__ and __LINE__ and figured that the panic
is coming from op_free(). So I rewrote that part to be able to set
a breakpoint:

--- op.c.orig   2004-02-27 19:41:01.000000000 +0100
+++ op.c        2004-02-27 19:41:22.000000000 +0100
@@ -227,7 +227,11 @@
        case OP_LEAVE:
        case OP_SCOPE:
        case OP_LEAVEWRITE:
-           OP_REFCNT_LOCK;
+            {
+                int rv;
+                if ((rv = pthread_mutex_lock(&PL_op_mutex)) != 0)
+                    Perl_croak_nocontext("PANIC: MUTEX_LOCK (%d)", rv);
+            }
            if (OpREFCNT_dec(o)) {
                OP_REFCNT_UNLOCK;
                return;

Here's the relevant part of the gdb session:

[email protected: m...@r2d2] ~/src/perl/Convert-Binary-C/0.49 $ gdb bleadperl-debug
  GNU gdb 6.0
  Copyright 2003 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 "i686-pc-linux-gnu"...Using host libthread_db library "/lib/libthread_db.so.1".
  
  (gdb) b op.c:233
  Breakpoint 1 at 0x8099299: file op.c, line 233.
  (gdb) r -Mblib t/114_cache.t 
  Starting program: /home/mhx/apps/bin/bleadperl-debug -Mblib t/114_cache.t
  [Thread debugging using libthread_db enabled]
  [New Thread 16384 (LWP 29251)]
  1..72
  # Running under perl version 5.009001 for linux
  # Current time local: Fri Feb 27 19:44:37 2004
  # Current time GMT:   Fri Feb 27 18:44:37 2004
  # Using Test.pm version 1.24
  ok 1
  [...]
  ok 71
  [Switching to Thread 16384 (LWP 29251)]
  
  Breakpoint 1, Perl_op_free (my_perl=0x81b0eb8, o=0x82a9498) at op.c:233
233 Perl_croak_nocontext("PANIC: MUTEX_LOCK (%d)", rv);
  (gdb) bt
  #0  Perl_op_free (my_perl=0x81b0eb8, o=0x82a9498) at op.c:233
#1 0x080a4925 in Perl_cv_undef (my_perl=0x81b0eb8, cv=0x83922e4) at op.c:3863
#2 0x080fcafb in Perl_sv_clear (my_perl=0x81b0eb8, sv=0x83922e4) at sv.c:5459
#3 0x080fd1f2 in Perl_sv_free2 (my_perl=0x81b0eb8, sv=0x83922e4) at sv.c:5667
#4 0x080fccda in Perl_sv_clear (my_perl=0x81b0eb8, sv=0x8392434) at sv.c:5497
#5 0x080fd1f2 in Perl_sv_free2 (my_perl=0x81b0eb8, sv=0x8392434) at sv.c:5667
#6 0x080d549a in Perl_magic_setsig (my_perl=0x81b0eb8, sv=0x8287a88, mg=0x81d0558) at mg.c:1340
  #7  0x080d2404 in Perl_mg_set (my_perl=0x81b0eb8, sv=0x8287a88) at mg.c:210
#8 0x08126e5e in Perl_leave_scope (my_perl=0x81b0eb8, base=46) at scope.c:788
  #9  0x08124afa in Perl_pop_scope (my_perl=0x81b0eb8) at scope.c:137
  #10 0x08130cc3 in Perl_pp_leaveloop (my_perl=0x81b0eb8) at pp_ctl.c:1863
  #11 0x080c98a2 in Perl_runops_debug (my_perl=0x81b0eb8) at dump.c:1563
  #12 0x08066638 in S_run_body (my_perl=0x81b0eb8, oldscope=1) at perl.c:1724
  #13 0x080660aa in perl_run (my_perl=0x81b0eb8) at perl.c:1647
#14 0x0805fcd4 in main (argc=3, argv=0xbffff1e4, env=0xbffff1f4) at perlmain.c:86
  (gdb) p rv
  $1 = 22

So the error code returned by pthread_mutex_lock() is 22:

  [email protected: m...@r2d2] ~ $ grep -P '\b22\b' /usr/include/asm/errno.h 
  #define EINVAL          22      /* Invalid argument */

Which according to the manpage means that the mutex hasn't been properly
initialized:

  ERRORS
The pthread_mutex_lock function returns the following error code on error:
  
                EINVAL the mutex has not been properly initialized.

The code which seems to be causing the trouble looks like this:

  [...]
  my(@warnings, $error);
  {
    local $SIG{__WARN__} = sub { push @warnings, $_[0] };

    if( $_[0] eq 'file' ) {
      eval { $self->SUPER::parse_file( $_[1] ) };
    }
    else {
      eval { $self->SUPER::parse( $_[1] ) };
    }
  }
  [...]

The panic occurs right after the block is left (I guess) from what
I can tell from the debug output:

  ([...]/lib/Convert/Binary/C/Cached.pm:233)      enterloop
  ([...]/lib/Convert/Binary/C/Cached.pm:233)      nextstate
  ([...]/lib/Convert/Binary/C/Cached.pm:233)      pushmark
  ([...]/lib/Convert/Binary/C/Cached.pm:233)      anoncode
  ([...]/lib/Convert/Binary/C/Cached.pm:233)      refgen
  ([...]/lib/Convert/Binary/C/Cached.pm:233)      gv(main::SIG)
  ([...]/lib/Convert/Binary/C/Cached.pm:233)      rv2hv
  ([...]/lib/Convert/Binary/C/Cached.pm:233)      const(PV("__WARN__"\0))
  ([...]/lib/Convert/Binary/C/Cached.pm:233)      helem
  ([...]/lib/Convert/Binary/C/Cached.pm:233)      sassign
  ([...]/lib/Convert/Binary/C/Cached.pm:233)      nextstate
  ([...]/lib/Convert/Binary/C/Cached.pm:235)      aelemfast
  ([...]/lib/Convert/Binary/C/Cached.pm:235)      const(PV("file"\0))
  ([...]/lib/Convert/Binary/C/Cached.pm:235)      seq
  ([...]/lib/Convert/Binary/C/Cached.pm:235)      cond_expr
  ([...]/lib/Convert/Binary/C/Cached.pm:235)      enter
  ([...]/lib/Convert/Binary/C/Cached.pm:235)      nextstate
  ([...]/lib/Convert/Binary/C/Cached.pm:239)      entertry
  ([...]/lib/Convert/Binary/C/Cached.pm:239)      nextstate
  ([...]/lib/Convert/Binary/C/Cached.pm:239)      pushmark
  ([...]/lib/Convert/Binary/C/Cached.pm:239)      padsv($self)
  ([...]/lib/Convert/Binary/C/Cached.pm:239)      gv(main::_)
  ([...]/lib/Convert/Binary/C/Cached.pm:239)      rv2av
  ([...]/lib/Convert/Binary/C/Cached.pm:239)      const(IV(1))
  ([...]/lib/Convert/Binary/C/Cached.pm:239)      aelem
  ([...]/lib/Convert/Binary/C/Cached.pm:239)      const(PV("SUPER::parse"\0))
  ([...]/lib/Convert/Binary/C/Cached.pm:239)      method
  ([...]/lib/Convert/Binary/C/Cached.pm:239)      entersub
  ([...]/lib/Convert/Binary/C/Cached.pm:239)      leavetry
  ([...]/lib/Convert/Binary/C/Cached.pm:239)      leave
  ([...]/lib/Convert/Binary/C/Cached.pm:235)      leaveloop
  [Switching to Thread 16384 (LWP 29377)]
  
  Breakpoint 1, Perl_op_free (my_perl=0x81b0eb8, o=0x82aa868) at op.c:233
233 Perl_croak_nocontext("PANIC: MUTEX_LOCK (%d)", rv);

At this point, I'm lost. Here's my perl configuration:

[email protected: m...@r2d2] ~/src/perl/dist/rsync/perl-current $ bleadperl-debug -V
Summary of my perl5 (revision 5 version 9 subversion 1 patch 22397) configuration:
    Platform:
      osname=linux, osvers=2.4.22-gentoo-r4, archname=i686-linux-thread-multi
uname='linux r2d2 2.4.22-gentoo-r4 #1 thu jan 29 20:01:30 met 2004 i686 intel(r) pentium(r) iii mobile cpu 1000mhz genuineintel gnulinux '
config_args='-des -Dusedevel -Dusethreads -Dnoextensions=Encode -Dprefix=/home/mhx/perl/blead-debug -Doptimize=-g -Dcc=gcc-3.4'
      hint=recommended, useposix=true, d_sigaction=define
      usethreads=define useithreads=define usemultiplicity=define
      useperlio=define d_sfio=undef uselargefiles=define usesocks=undef
      use64bitint=undef use64bitall=undef uselongdouble=undef
      usemymalloc=n, bincompat5005=undef
    Compiler:
cc='gcc-3.4', ccflags ='-D_REENTRANT -D_GNU_SOURCE -DTHREADS_HAVE_PIDS -DDEBUGGING -fno-strict-aliasing -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64',
      optimize='-g',
cppflags='-D_REENTRANT -D_GNU_SOURCE -DTHREADS_HAVE_PIDS -DDEBUGGING -fno-strict-aliasing'
      ccversion='', gccversion='3.4.0 20031224 (experimental)', gccosandvers=''
      intsize=4, longsize=4, ptrsize=4, doublesize=8, byteorder=1234
      d_longlong=define, longlongsize=8, d_longdbl=define, longdblsize=12
ivtype='long', ivsize=4, nvtype='double', nvsize=8, Off_t='off_t', lseeksize=8
      alignbytes=4, prototype=define
    Linker and Libraries:
      ld='gcc-3.4', ldflags =' -L/usr/local/lib'
      libpth=/usr/local/lib /lib /usr/lib
      libs=-lnsl -lndbm -lgdbm -ldb -ldl -lm -lcrypt -lutil -lpthread -lc
      perllibs=-lnsl -ldl -lm -lcrypt -lutil -lpthread -lc
      libc=/lib/libc-2.3.2.so, so=so, useshrplib=false, libperl=libperl.a
      gnulibc_version='2.3.2'
    Dynamic Linking:
      dlsrc=dl_dlopen.xs, dlext=so, d_dlsymun=undef, ccdlflags='-Wl,-E'
      cccdlflags='-fpic', lddlflags='-shared -L/usr/local/lib'
  
  
  Characteristics of this binary (from libperl): 
Compile-time options: DEBUGGING MULTIPLICITY USE_ITHREADS USE_LARGE_FILES PERL_IMPLICIT_CONTEXT
    Locally applied patches:
          DEVEL21538
    Built under linux
    Compiled at Feb 27 2004 18:51:59
    @INC:
      /home/mhx/perl/blead-debug/lib/5.9.1/i686-linux-thread-multi
      /home/mhx/perl/blead-debug/lib/5.9.1
      /home/mhx/perl/blead-debug/lib/site_perl/5.9.1/i686-linux-thread-multi
      /home/mhx/perl/blead-debug/lib/site_perl/5.9.1
      /home/mhx/perl/blead-debug/lib/site_perl
      .

Building Convert-Binary-C is easy. It doesn't have an prerequisites
and should just "work" (perl Makefile.PL && make). Just get the latest
version (0.49) from CPAN if you want to try to reproduce the problem.

Marcus

Ok, after downloading APC a binary search showed that change #22302
is causing the trouble. That was the switch from byacc to bison.

Unfortunately, I still don't have an idea. I thought that it might
have been a problem that Convert::Binary::C is also using two bison
parsers, but examining the code I don't see why it should.

Dave?

Marcus

I've found the problem - Perl_yylex_r() isn't (and never has been!)
threadsafe. Am working on a fix.

Dave.

Just a couple of minutes ago I've also tracked it down to Perl_yylex_r()...

However, I don't think it's (only) a thread-safety issue. The problem is
that continuously eval()ing wrong code seems to blow the parser stack. The
'panic: YYMAXLEVEL' is trapped in $@. yyactlevel permanently increases
until

  yylval_pointer[yyactlevel] = lvalp;

overwrites the contents of PL_op_mutex, which will in turn cause the
"panic: MUTEX_LOCK" later.

BTW, here's a shorter "pure perl" test case:

[email protected: m...@r2d2] ~ $ bleadperl-debug -e'for (1..200) { eval "\x1"; my $w; local $_ = sub {$w} }'
PANIC: MUTEX_LOCK (22) at -e line 1.
Attempt to free unreferenced scalar: SV 0x81b1a14.
PANIC: MUTEX_LOCK (22).

Interestingly this also triggers a "Attempt to free...".

Marcus

Valgrind might help:

==5979== pthread_mutex_lock/trylock: mutex is invalid
==5979==    at 0x402B1EA3: __pthread_mutex_lock (vg_libpthread.c:944)
==5979==    by 0x8099045: Perl_op_free (op.c:230)
==5979==    by 0x80A4606: Perl_cv_undef (op.c:3859)
==5979==    by 0x80FBFCC: Perl_sv_clear (sv.c:5459)
panic: MUTEX_LOCK at -e line 1.
==5979== warning: Valgrind's siglongjmp is incomplete
==5979==          (it ignores cleanup handlers)
==5979==          your program may misbehave as a result
Attempt to free unreferenced scalar: SV 0x41942e0c.
==5979==
==5979== pthread_mutex_lock/trylock: mutex is invalid
==5979==    at 0x402B1EA3: __pthread_mutex_lock (vg_libpthread.c:944)
==5979==    by 0x8099045: Perl_op_free (op.c:230)
==5979==    by 0x8061EDD: perl_destruct (perl.c:361)
==5979==    by 0x805FD34: main (perlmain.c:88)
panic: MUTEX_LOCK.

I didn't get a panic without running it under valgrind. Maybe I didn't wait
long enough.

Nicholas Clark

Yes, I'm aware of this :-) I'm in the process of excising yylex_r from
bleed even as we speak.

Now fixed by the change below (hopefully).

Very nice!

Marcus