Bug #110763 for WWW-Scripter-Plugin-JavaScript: Rare segfaults of t/js.t

Wed Dec 30 04:00:59 2015 SREZIC [...] cpan.org - Ticket created

Subject:

Rare segfaults of t/js.t

At CPAN Testers there's currently one report because of a segfault while running js.t: http://www.cpantesters.org/cpan/report/52a73802-6878-11e4-8639-d4c352be3a26 I just created test reports with the same problem with perl 5.23.6 and 5.22.1 (linux debian wheezy).

Fri Jan 01 16:41:34 2016 $_ = 'spro^^*%*^6ut# [...] &$%*c>#!^!#&!pan.org'; y/a-z.@//cd; print - Correspondence added

On Wed Dec 30 04:00:59 2015, SREZIC wrote: Show quoted text

> At CPAN Testers there's currently one report because of a segfault > while running js.t: http://www.cpantesters.org/cpan/report/52a73802- > 6878-11e4-8639-d4c352be3a26 > > I just created test reports with the same problem with perl 5.23.6 and > 5.22.1 (linux debian wheezy).

Could you provide a backtrace? Thank you.

Fri Jan 01 16:41:34 2016 The RT System itself - Status changed from 'new' to 'open'

Fri Jan 01 16:55:56 2016 SREZIC [...] cpan.org - Correspondence added

On 2016-01-01 16:41:34, SPROUT wrote: Show quoted text

> On Wed Dec 30 04:00:59 2015, SREZIC wrote:

> > At CPAN Testers there's currently one report because of a segfault > > while running js.t: http://www.cpantesters.org/cpan/report/52a73802- > > 6878-11e4-8639-d4c352be3a26 > > > > I just created test reports with the same problem with perl 5.23.6 and > > 5.22.1 (linux debian wheezy).

> > Could you provide a backtrace? > > Thank you.

I have only non-debugging perls available. Here's one: Core was generated by `perl5.23.6 -Mblib t/js.t'. Program terminated with signal 11, Segmentation fault. #0 0x000000000044a1fb in S_gv_fetchmeth_internal () (gdb) bt #0 0x000000000044a1fb in S_gv_fetchmeth_internal () #1 0x000000000044ab2b in Perl_Gv_AMupdate () #2 0x000000000044b00f in Perl_amagic_call () #3 0x000000000044c45d in Perl_amagic_deref_call () #4 0x00000000004b6f32 in Perl_pp_multideref () #5 0x00000000004ae583 in Perl_runops_standard () #6 0x0000000000445800 in perl_run () #7 0x00000000004243c5 in main ()

Fri Jan 01 21:04:18 2016 $_ = 'spro^^*%*^6ut# [...] &$%*c>#!^!#&!pan.org'; y/a-z.@//cd; print - Correspondence added

RT-Send-CC:

ANDK [...] cpan.org

On Fri Jan 01 16:55:56 2016, SREZIC wrote: Show quoted text

> On 2016-01-01 16:41:34, SPROUT wrote:

> > On Wed Dec 30 04:00:59 2015, SREZIC wrote:

> > > At CPAN Testers there's currently one report because of a segfault > > > while running js.t: http://www.cpantesters.org/cpan/report/52a73802- > > > 6878-11e4-8639-d4c352be3a26 > > > > > > I just created test reports with the same problem with perl 5.23.6 and > > > 5.22.1 (linux debian wheezy).

> > > > Could you provide a backtrace? > > > > Thank you.

> > I have only non-debugging perls available. Here's one: > > Core was generated by `perl5.23.6 -Mblib t/js.t'. > Program terminated with signal 11, Segmentation fault. > #0 0x000000000044a1fb in S_gv_fetchmeth_internal () > (gdb) bt > #0 0x000000000044a1fb in S_gv_fetchmeth_internal () > #1 0x000000000044ab2b in Perl_Gv_AMupdate () > #2 0x000000000044b00f in Perl_amagic_call () > #3 0x000000000044c45d in Perl_amagic_deref_call () > #4 0x00000000004b6f32 in Perl_pp_multideref () > #5 0x00000000004ae583 in Perl_runops_standard () > #6 0x0000000000445800 in perl_run () > #7 0x00000000004243c5 in main ()

Thank you. Unfortunately that’s not much to go by. Is this reproducible enough for a bisect?

Sat Jan 02 06:02:32 2016 SREZIC [...] cpan.org - Correspondence added

RT-Send-CC:

ANDK [...] cpan.org

On 2016-01-01 21:04:18, SPROUT wrote: Show quoted text

> On Fri Jan 01 16:55:56 2016, SREZIC wrote:

> > On 2016-01-01 16:41:34, SPROUT wrote:

> > > On Wed Dec 30 04:00:59 2015, SREZIC wrote:

> > > > At CPAN Testers there's currently one report because of a > > > > segfault > > > > while running js.t: > > > > http://www.cpantesters.org/cpan/report/52a73802- > > > > 6878-11e4-8639-d4c352be3a26 > > > > > > > > I just created test reports with the same problem with perl > > > > 5.23.6 and > > > > 5.22.1 (linux debian wheezy).

> > > > > > Could you provide a backtrace? > > > > > > Thank you.

> > > > I have only non-debugging perls available. Here's one: > > > > Core was generated by `perl5.23.6 -Mblib t/js.t'. > > Program terminated with signal 11, Segmentation fault. > > #0 0x000000000044a1fb in S_gv_fetchmeth_internal () > > (gdb) bt > > #0 0x000000000044a1fb in S_gv_fetchmeth_internal () > > #1 0x000000000044ab2b in Perl_Gv_AMupdate () > > #2 0x000000000044b00f in Perl_amagic_call () > > #3 0x000000000044c45d in Perl_amagic_deref_call () > > #4 0x00000000004b6f32 in Perl_pp_multideref () > > #5 0x00000000004ae583 in Perl_runops_standard () > > #6 0x0000000000445800 in perl_run () > > #7 0x00000000004243c5 in main ()

> > Thank you. Unfortunately that’s not much to go by. Is this > reproducible enough for a bisect?

The random nature makes it somewhat difficult. I tried /opt/perl-5.X.Y/bin/perl -Mblib t/js.t repeatedly on some perl 5.21.x installations and found the following: * 5.21.8 -> fail after 195 iterations * 5.21.5 -> fail after 5 iterations * 5.21.4 -> fail after 111 iterations * 5.21.3 -> no fail after 1328 iterations So maybe the problem appeared between 5.21.3 and 5.21.4, and a bisect process should probably try up to 1000 iterations to be sure.

Sat Jan 02 08:36:59 2016 ANDK [...] cpan.org - Correspondence added

Got this with 5.21.4. Will try to bisect if still necessary. (gdb) bt #0 0x0000000000443397 in Perl_gv_fetchmeth_pvn (stash=stash@entry=0x332f0e0, name=name@entry=0x547f69 "(${}", len=4, level=level@entry=-1, flags=flags@entry=0) at gv.c:775 #1 0x0000000000443f3f in Perl_Gv_AMupdate (stash=stash@entry=0x332f0e0, destructing=destructing@entry=false) at gv.c:2654 #2 0x00000000004444b0 in Perl_amagic_call (left=left@entry=0x3606880, right=0x7917e0 <PL_sv_undef>, method=method@entry=2, flags=flags@entry=9) at gv.c:2971 #3 0x000000000044602b in Perl_amagic_deref_call (ref=ref@entry=0x3606880, method=2) at gv.c:2905 #4 0x00000000004a6b01 in Perl_pp_rv2av () at pp_hot.c:902 #5 0x00000000004a40f3 in Perl_runops_standard () at run.c:41 #6 0x000000000043da99 in S_run_body (oldscope=<optimized out>) at perl.c:2411 #7 perl_run (my_perl=<optimized out>) at perl.c:2339 #8 0x000000000041e145 in main (argc=2, argv=0x7fff0f08c118, env=0x7fff0f08c130) at perlmain.c:114

Sat Jan 02 13:11:04 2016 ANDK [...] cpan.org - Correspondence added

Bisect: v5.21.3-174-g4dda930 Already known from BBC on PEVANS/Future-0.29.tar.gz https://rt.perl.org/rt3/Ticket/Display.html?id=122735

Fri May 27 12:57:30 2016 $_ = 'spro^^*%*^6ut# [...] &$%*c>#!^!#&!pan.org'; y/a-z.@//cd; print - Correspondence added

On Sat Jan 02 13:11:04 2016, ANDK wrote: Show quoted text

> Bisect: v5.21.3-174-g4dda930 > > Already known from BBC on PEVANS/Future-0.29.tar.gz > > https://rt.perl.org/rt3/Ticket/Display.html?id=122735

Thank you. I have only now got around to debugging this. I cannot reproduce the crash in current bleadperl (v5.25.1-75-gcbef69c). Are you able to produce it? If not, could you do a bisect to see when it was fixed? I want to see which perl versions will need a workaround.

Sun May 29 14:11:31 2016 $_ = 'spro^^*%*^6ut# [...] &$%*c>#!^!#&!pan.org'; y/a-z.@//cd; print - Forwarded Transaction #1631281 to ANDK@cpan.org

Mon May 30 16:03:44 2016 $_ = 'spro^^*%*^6ut# [...] &$%*c>#!^!#&!pan.org'; y/a-z.@//cd; print - Correspondence added

RT-Send-CC:

ANDK [...] cpan.org

On Fri May 27 12:57:30 2016, SPROUT wrote: Show quoted text

> On Sat Jan 02 13:11:04 2016, ANDK wrote:

> > Bisect: v5.21.3-174-g4dda930 > > > > Already known from BBC on PEVANS/Future-0.29.tar.gz > > > > https://rt.perl.org/rt3/Ticket/Display.html?id=122735

> > Thank you. I have only now got around to debugging this. I cannot > reproduce the crash in current bleadperl (v5.25.1-75-gcbef69c). Are > you able to produce it? If not, could you do a bisect to see when it > was fixed? I want to see which perl versions will need a workaround.

I managed to do my own bisect: 958cdeac409681891afe77bf60db047296523465 is the first bad commit commit 958cdeac409681891afe77bf60db047296523465 Author: Tony Cook <tony@develop-help.com> Date: Wed Feb 10 14:30:08 2016 +1100 [perl #127494] don't cache AUTOLOAD as DESTROY but in some of the commits leading up to it the bisect script was not installing required modules due to test failures. I have not yet figured out how to get Nicholas’ bisect-runner.pl to skip tests. So, I don’t trust the bisect result. In any case, neither the first bad commit nor the first good commits really tells me anything. It seems like a latent bug that was uncovered and then hidden again. I tried using gdb to see what was going on, and it is a corrupt stash, whose internal fields have been written over. But the memory gets corrupted some time before the crash, so it’s extremely hard to find the cause. So now I’m trying to reduce the test script to something that will fail without modules.

Mon May 30 16:06:13 2016 $_ = 'spro^^*%*^6ut# [...] &$%*c>#!^!#&!pan.org'; y/a-z.@//cd; print - Correspondence added

RT-Send-CC:

ANDK [...] cpan.org

On Mon May 30 16:03:44 2016, SPROUT wrote: Show quoted text

> I have not yet > figured out how to get Nicholas’ bisect-runner.pl to skip tests.

Because I had the logic backwards. :-)

Mon May 30 20:48:04 2016 $_ = 'spro^^*%*^6ut# [...] &$%*c>#!^!#&!pan.org'; y/a-z.@//cd; print - Correspondence added

RT-Send-CC:

ANDK [...] cpan.org

On Mon May 30 16:03:44 2016, SPROUT wrote: Show quoted text

> I managed to do my own bisect: > > 958cdeac409681891afe77bf60db047296523465 is the first bad commit > commit 958cdeac409681891afe77bf60db047296523465 > Author: Tony Cook <tony@develop-help.com> > Date: Wed Feb 10 14:30:08 2016 +1100 > > [perl #127494] don't cache AUTOLOAD as DESTROY > > but in some of the commits leading up to it the bisect script was not > installing required modules due to test failures. I have not yet > figured out how to get Nicholas’ bisect-runner.pl to skip tests.

With module tests skipped, I’m getting the same results. Show quoted text

> So now I’m trying to reduce the test script to something that will > fail without modules.

Still trying to do this, but it’s so slow it could take weeks.

Tue May 31 09:31:36 2016 $_ = 'spro^^*%*^6ut# [...] &$%*c>#!^!#&!pan.org'; y/a-z.@//cd; print - Correspondence added

For my own future reference: ../perl.git/Porting/bisect.pl --no-module-tests --start=v5.21.3 --end=v5.21.4 --with-module=WWW::Scripter::Plugin::JavaScript --cpan-config-dir=/Users/sprout/ -e 'chdir "/Users/sprout/perl/dist/WWW-Scripter-Plugin-JavaScript"; for (1..1000) { print "$_\n";system "$^X t/js.t" and die}' (That finds when it started crashing. --expect-fail finds when it stopped crashing.)

Tue May 31 15:46:07 2016 ANDK [...] cpan.org - Correspondence added

v5.23.7-263-ged8ff0f

Tue May 31 21:05:01 2016 $_ = 'spro^^*%*^6ut# [...] &$%*c>#!^!#&!pan.org'; y/a-z.@//cd; print - Correspondence added

RT-Send-CC:

ANDK [...] cpan.org

On Tue May 31 15:46:07 2016, ANDK wrote: Show quoted text

> v5.23.7-263-ged8ff0f

Thank you for taking the time to help. Interestingly, it’s not the same commit I came up with, but maybe that’s not surprising, considering how elusive this bug is. The commit you cite just changes some macros to inline functions, so it *shouldn’t* change anything, so all it tells me is that the bug may well be present in perl still. It’s just hiding.