Closed aquanight closed 2 years ago
Description Under -DDEBUGGING, the debug flags Xvt (-DXvt or $^D = "Xvt" at runtime) crashes when strict.pm is loaded via require/use.
Steps to Reproduce Perl must be built with -DDEBUGGING perl -DXvt -Mstrict -e 'print "Hello\n"'
Problem reproduced on blead on FreeBSD-12:
$ uname -mrs
FreeBSD 12.3-RELEASE amd64
$ ./perl -v | head -2 | tail -1
This is perl 5, version 35, subversion 10 (v5.35.10 (v5.35.9-18-g714a0a851b)) built for amd64-freebsd-thread-multi
Config args:
$ sh ./Configure -des -Dusedevel -Duseithreads -Dcc=clang10 -DDEBUGGING
Bisecting with:
./Porting/bisect.pl --start v5.20.0 --end v5.22.1 -DDEBUGGING --target miniperl \
--crash -- ./miniperl -Ilib -DXvt -Mstrict -e 1
points to commit ed958fa315. It looks like the crash is triggered by the attempt to inject a couple of constant subs in a BEGIN block: removing the prototype from all_bits
and all_explicit_bits
is enough to stop it crashing.
I'll try to look further tomorrow if I can make time, but please don't let that stop anyone else from investigating. :)
It seems the const sub needs to close over a lexical variable that has ??gone out of scope - if I move the declarations of my($inline_all_bits, $inline_all_explicit_bits)
above the BEGIN block the crash disappears, but I can reproduce the crash with eg:
./miniperl -DXv -e 'BEGIN { my $c = 1; *subc = sub () { $c }; }'
If I recall correctly, isn't the sub () { $lex }
pattern for capturing a lexical as a constant? Devel::Peek shows the resulting CV of that pattern is flagged as both CONST and XSUB:
$ debugperl -MDevel::Peek -E 'BEGIN { my $lex = 42; *foo = sub () { $lex } } Dump(\&foo); say foo;'
SV = IV(0x55c798161510) at 0x55c798161520
REFCNT = 1
FLAGS = (TEMP,ROK)
RV = 0x55c7981f0990
SV = PVCV(0x55c7981c1b18) at 0x55c7981f0990
REFCNT = 2
FLAGS = (POK,pPOK,ANON,CONST,CVGV_RC,DYNFILE,ISXSUB)
PROTOTYPE = ""
COMP_STASH = 0x0
XSUB = 0x55c797322000
XSUBANY = 0x55c7981f09a8 (CONST SV)
SV = IV(0x55c7981f0998) at 0x55c7981f09a8
REFCNT = 2
FLAGS = (PADTMP,IOK,READONLY,PROTECT,pIOK)
IV = 42
GVGV::GV = 0x55c7981f08d0 "main" :: "__ANON__"
FILE = "-e"
DEPTH = 0
FLAGS = 0x148c
OUTSIDE_SEQ = 0
HSCXT = 0xefefefefefefefef
OUTSIDE = 0x0 (null)
42
The XSUB flag appears to be responsible for triggering the assert in S_cv_dump (called during Perl_cv_clone under -DXv), due to this:
const CV * const outside = CvOUTSIDE(cv);
PADLIST* const padlist = CvPADLIST(cv);
The CvPADLIST macro asserts because cv
is an XSUB.
On Sat, 26 Feb 2022 at 03:41, Hugo van der Sanden @.***> wrote:
Bisecting with:
./Porting/bisect.pl --start v5.20.0 --end v5.22.1 -DDEBUGGING --target miniperl \ --crash -- ./miniperl -Ilib -DXvt -Mstrict -e 1
How/why did you decide to bisect that version range? I mean that patch is OLD.
points to commit ed958fa https://github.com/Perl/perl5/commit/ed958fa3156084f3cf4d8c4768716d9e1a11ce91. It looks like the crash is triggered by the attempt to inject a couple of constant subs in a BEGIN block: removing the prototype from all_bits and all_explicit_bits is enough to stop it crashing.
I'll try to look further tomorrow if I can make time, but please don't let that stop anyone else from investigating. :)
Well if it werent for the version range and bisect results you posted here I would have guessed this was related to some recent work on subroutine stubs.
Ill take a look tomorrow.
Yves
-- perl -Mre=debug -e "/just|another|perl|hacker/"
How/why did you decide to bisect that version range? I mean that patch is OLD.
Before bisecting, I tested with an assortment of debugging perls I happened to have installed. But note that the OP was reporting against 5.32.1.
I'll take a look tomorrow.
Ok, I'll leave it to you.
On Sat, 26 Feb 2022 at 17:13, Hugo van der Sanden @.***> wrote:
How/why did you decide to bisect that version range? I mean that patch is OLD.
Before bisecting, I tested with an assortment of debugging perls I happened to have installed. But note that the OP was reporting against 5.32.1.
I'll take a look tomorrow.
Ok, I'll leave it to you.
I was able to minimize the failure to:
./perl -Ilib -DXv -e '{ my $n=1; *foo= sub () { $n }; }'
and I pushed a fix for this in
https://github.com/Perl/perl5/pull/19466
I haven't set up a bisect to determine exactly when this broke yet, but I will leave one running while I go to breakfast and maybe update the PR to reflect that info.
Thanks for the report aquanight, our testing of -D switches is pretty impoverished, we should fix that.
Cheers, Yves
-- perl -Mre=debug -e "/just|another|perl|hacker/"
On Sun, 27 Feb 2022 at 03:52, demerphq @.***> wrote:
I haven't set up a bisect to determine exactly when this broke yet, but I will leave one running while I go to breakfast and maybe update the PR to reflect that info.
Bisect says it was 5.21.6, commit 1567c65ac069266bfe65959430c185babd476538.
../perl2/Porting/bisect.pl --start v5.18.4 --end ed958fa3156084f3cf4d8c4768716d9e1a11ce91 -DDEBUGGING --target miniperl --crash -- ./miniperl -Ilib -DXv -e '{ my $n=1; *foo= sub () { $n }; }'
I pushed an update to the PR to reflect this.
Hugo, thanks for the example of how to use bisect for stuff like this, it is very useful!
cheers, yves
-- perl -Mre=debug -e "/just|another|perl|hacker/"
On Sun, 27 Feb 2022 at 03:52, demerphq @.**> wrote: I haven't set up a bisect to determine exactly when this broke yet, but I will leave one running while I go to breakfast and maybe update the PR to reflect that info. Bisect says it was 5.21.6, commit 1567c65. ../perl2/Porting/bisect.pl --start v5.18.4 --end ed958fa -DDEBUGGING --target miniperl --crash -- ./miniperl -Ilib -DXv -e '{ my $n=1; foo= sub () { $n }; }' I pushed an update to the PR to reflect this. Hugo, thanks for the example of how to use bisect for stuff like this, it is very useful! cheers, yves … -- perl -Mre=debug -e "/just|another|perl|hacker/"
Two-stage bisection! This deserves entry as an example in the documentation for bisection. See https://github.com/Perl/perl5/pull/19468.
[snip]
I was able to minimize the failure to: ./perl -Ilib -DXv -e '{ my $n=1; *foo= sub () { $n }; }'
How you were able to achieve this reduction would be a good subject for a pull request. It's more general than bisection, so perhaps a modification to something like pod/perldebtut.pod
.
[snip]
I was able to minimize the failure to: ./perl -Ilib -DXv -e '{ my $n=1; *foo= sub () { $n }; }'
How you were able to achieve this reduction would be a good subject for a pull request. It's more general than bisection, so perhaps a modification to something like
pod/perldebtut.pod
.
Well I posted much of the reduction the previous day, it's not clear if Yves saw that and refined from there.
Generally, such reduction is always a mix of art and science. The difficult part is usually finding the patience and perseverance to proceed one step at a time.
In this case, the first part of the process was instinct: I saw that the code change found by the first bisect introduced some const subs, and having some awareness of the special handling they involve I immediately focused on them as a possible source of the problem.
Step 1 was to validate that guess. I know that the prototype is the trigger for making a sub constant, and removing the prototype should leave the code acting the same except without the const sub optimization. So I tested that, found that on removing the prototype it no longer crashed, and thus confirmed the focus.
If a crash is reproducible with miniperl, that's always a helpful reduction in itself. So I tried that, and found that it was indeed reproducible.
Step 3 was to see if I could short-circuit the minimization process by jumping straight to a guess:
% ./miniperl -DXv -e 'my $foo = 1; sub bar () { $foo }'
.. but that did not crash. So I needed to proceed in smaller steps.
The next target was to get the sub declaration outside the BEGIN block, to remove another source of potential obfuscation. But the subs were using lexical variables declared and assigned inside the block. So before I could move the sub declarations, I first had to move the variable declarations, in this case to before the block.
So I tried just moving the variable declarations - but again that change was enough to stop it crashing. So I reasoned that maybe the original variable going out of scope was also critical to the crash, tried:
% ./miniperl -DXv -e 'BEGIN { my $c = 1; *subc = sub () { $c }; }'
.. found that that was enough to reproduce the crash, decided it was getting late, and posted it. :)
I really have no idea though how to turn a description of reducing a specific case like this into something more general-purpose like a tutorial.
On Mon, 28 Feb 2022, 00:17 Hugo van der Sanden, @.***> wrote:
[snip]
I was able to minimize the failure to: ./perl -Ilib -DXv -e '{ my $n=1; *foo= sub () { $n }; }'
How you were able to achieve this reduction would be a good subject for a pull request. It's more general than bisection, so perhaps a modification to something like pod/perldebtut.pod.
Well I posted much of the reduction the previous day, it's not clear if Yves saw that and refined from there.
Yeah I saw it, I just ground it down a bit more by removing the BEGIN, and removing the t option from the -D flags.
Generally, such reduction is always a mix of art and science. The difficult
part is usually finding the patience and perseverance to proceed one step at a time.
Agreed and well put.
In this case, the first part of the process was instinct: I saw that the code change found by the first bisect introduced some const subs, and having some awareness of the special handling they involve I immediately focused on them as a possible source of the problem.
Step 1 was to validate that guess. I know that the prototype is the trigger for making a sub constant, and removing the prototype should leave the code acting the same except without the const sub optimization. So I tested that, found that on removing the prototype it no longer crashed, and thus confirmed the focus.
Minor note, with the case of a closure it's a combo of refcount==1 AND the prototype. That is why hoisting the var to package level "fixes" the problem, the refcount ends up at 2 ( one from the enclosing sub and one from the file level my declaration) thus the resulting sub is no longer marked CONST and relevant to this case no longer an XSUB.
If a crash is reproducible with miniperl, that's always a helpful reduction
in itself. So I tried that, and found that it was indeed reproducible.
I normally haven't used miniperl as a lot of regex bugs aren't revealed easily with it, whereas full perl basically won't build if the regex engine is even a little bit broken. The build process itself utilizes a wide range of regex features so if it builds usually any bugs left are esoteric or minor.
But working recently with Hugo, on this case and others, and especially seeing the speed impact on this bisect has taught me a new and much deeper appreciation for using it, and I now see it as a new tool in my toolbox. Thanks Hugo.
Step 3 was to see if I could short-circuit the minimization process by
jumping straight to a guess:
% ./miniperl -DXv -e 'my $foo = 1; sub bar () { $foo }'
.. but that did not crash. So I needed to proceed in smaller steps.
The next target was to get the sub declaration outside the BEGIN block, to remove another source of potential obfuscation. But the subs were using lexical variables declared and assigned inside the block. So before I could move the sub declarations, I first had to move the variable declarations, in this case to before the block.
So I tried just moving the variable declarations - but again that change was enough to stop it crashing. So I reasoned that maybe the original variable going out of scope was also critical to the crash, tried:
% ./miniperl -DXv -e 'BEGIN { my $c = 1; *subc = sub () { $c }; }'
.. found that that was enough to reproduce the crash, decided it was getting late, and posted it. :)
And I picked up from there... BEGIN blocks are special blocks so I tried various things to verify if they were relevant, including duplicating some of the steps that Hugo outlines above, but especially removing the BEGIN, and trying variants the code with and without BEGIN and with and without the -D switches and with and without Devel::Peek assistance (it loads strict so it was not possible to use it to debug some variants as it would trigfer the assert when it was used). I also checked to see if all the switches provided originaly were required. I also checked if this happens with a BEGIN or block wrapping a named sub with a true constant inside triggers the issue, (it doesn't) etc.
At some point I was able to determine that this happens when the anonymous sub created during compilation is cloned and assigned to the glob.
I then ran the minimized code under gdb, after the assert triggered typed 'bt' to get a back trace (c level stack trace) which told me the bug came from an assert at a specific line in cv_dump() in pad.c, inspecting this line I found CvPADLIST() which is a macro. Inspecting the macro definition I found the assert was to ensure that the macro shouldn't be used on CVs marked as XSUB, along with a comment that maybe the assert can be removed one day.
I then spent some time working out why this sub is marked as an XSUB even though it started off as perl, the XSUB flag means a XS sub so it's a bit weird a perl sub gets marked that way. My thought was that setting the flag might be an error so I tried commenting it out. That didn't help, removing it just changed the assert fail to a SEGV, suggesting the flag was likely correctly applied. I knew at some point FC had worked on optimizing constant subs, and he was the author of the commit that broke so I decided that probably the two were related and likely he had just never tested the -DXv switch on his patches; the -D switches have very little tests, and personally I have never used most of them, and never ever used this particular combination, so it made sense to me that FC might have missed them too.
So I then inspected cv_dump() and realized that the bulk of the code in it didn't need the padlist data, so I decide to move the CvPADLIST() call and the logic that used it into an if block guarded by the CvISXSUB() check, verified that it fixed the bug and didn't create any others and the adjusted debug output was reasonable and then finally created the PR.
Note that at this time I had not run the second bisect, I had put that off on the assumption it would take a long time. But once I had created the PR I wanted to improve the commit message and verify my assumptions about the XSUB flag. In order to do this I needed to find the change that actually broke the test case. Hugo's bisect was about when strict started dying, not for the change that caused that change to die so it gave me an end point but not a start point. I happened to have 5.18.4 handy to test and it did not die so that gave me a start point to start the second bisect.
So I then kicked off the bisect. What I did not expect was that it would run as quickly as it did, I expected that it would take a while and started getting ready to go out for breakfast with my wife with the expectation I would not see results until I returned sometime later. However Hugo's trick of using miniperl in the bisect meant it had completed before I had even left the house, IOW in a matter of minutes! That result confirmed my initial analysis, I updated the PR before we left and the task was done.
I really have no idea though how to turn a description of reducing a
specific case like this into something more general-purpose like a tutorial.
Maybe James can take what we both have written here and put something together, after all he has a bit more distance from it than we do.
I think some key points here are (in no specific order, every situation is different and depends on the bug and your personal prior knowledge).
One thing I really like about digging into Perl bug reports is I almost always learn something new, be it about perl itself, C, gdb, or just general coding or debugging techniques or a combination. The result I feel is every bug I investigate, particularly when I find a fix but even sometimes when I don't, makes me a better programmer. If I concede defeat then I watch what Nicholas or Dave M or Karl (or whoever, but its usually one of them) do to fix the bug and learn from that. Fixing Perl bugs is not just a matter of grinding off an esoteric rough edge in perl itself, I find that I make myself better, and more useful, to this project and future projects and future employers. In this case I learned:
So for me personally this bug was fun and educational even if it only fixes a very esoteric part of perl and I think it was worth my time and effort to dig into it.
HTH, Cheers Yves
Status of ticket: waiting for code review of p.r. in https://github.com/Perl/perl5/pull/19466
On Wed, 2 Mar 2022, 21:25 James E Keenan, @.***> wrote:
Status of ticket: waiting for code review of p.r. in #19466 https://github.com/Perl/perl5/pull/19466
I was going to merge it today. I don't think there is much to review, the patch is trivial. But I'll give it a few more days if you want?
Yves
On 3/2/22 09:23, Yves Orton wrote:
On Wed, 2 Mar 2022, 21:25 James E Keenan, @.***> wrote:
Status of ticket: waiting for code review of p.r. in #19466 https://github.com/Perl/perl5/pull/19466
I was going to merge it today. I don't think there is much to review, the patch is trivial. But I'll give it a few more days if you want?
As we're nearing code freeze, the value of a code review for anything touching the internals increases significantly. That's why I've requested that it be reviewed by people familiar with the internals.
On Wed, 2 Mar 2022 at 16:30, James E Keenan @.***> wrote:
On 3/2/22 09:23, Yves Orton wrote:
On Wed, 2 Mar 2022, 21:25 James E Keenan, @.***> wrote:
Status of ticket: waiting for code review of p.r. in #19466 https://github.com/Perl/perl5/pull/19466
I was going to merge it today. I don't think there is much to review, the patch is trivial. But I'll give it a few more days if you want?
As we're nearing code freeze, the value of a code review for anything touching the internals increases significantly. That's why I've requested that it be reviewed by people familiar with the internals.
It's debug code, so i wouldn't worry about that, especially as if it doesn't get patched we either ship an assert fail or a segv and -DXv will be useless. But it's been useless since 5.20 so I guess it's not used much.
Plus the patch was trivial. But sure, I added Karl too, as a C expert if not an expert on this part of the internals. :-)
cheers, Yves
Thanks for the report, this will be included in 5.36.0
Description Under -DDEBUGGING, the debug flags Xvt (-DXvt or $^D = "Xvt" at runtime) crashes when strict.pm is loaded via require/use.
Steps to Reproduce Perl must be built with -DDEBUGGING perl -DXvt -Mstrict -e 'print "Hello\n"'
Expected behavior The requested debug output (Xvt traces execution and dumps PADs and reports when CVs are cloned) alongside executed script behavior.
Actual results The last few lines of output are as such:
The line 31 from strict.pm in question is this:
This is inside a BEGIN {} block so it is occurring as soon as strict.pm is require()d (including via 'use').
Workaround Code wishing to
use strict
(including indirectly via other modules) and also utilize -DXvt must instead use the following before anyuse strict
statements occur:Perl configuration