Skip to content

Commit a0de456

Browse files
fglockDevin
fglock
and
Devin
authored
Fix caller() line number bug for deferred subroutine compilation (#336)
* Verify design docs: log4perl and cpan_client status confirmed Both documents verified against current test results: - Log::Log4perl: 18/700 subtests failing (6/73 programs) - CPAN client: Phase 9 complete, jcpan fully functional All remaining Log4perl failures are documented architectural limitations (caller line numbers, DESTROY, Safe.pm, source filters). Generated with [Devin](https://cli.devin.ai/docs) Co-Authored-By: Devin <noreply@cognition.ai> * Fix caller() line number bug for deferred subroutine compilation Root cause: ByteCodeSourceMapper.saveSourceLocation() used getLineNumber() which has a forward-only cache that returns stale values for out-of-order token access during deferred subroutine compilation. Fix: Use getLineNumberAccurate() which always counts from file start, safe for random access. Results: - Log::Log4perl t/024WarnDieCarp.t: 8 failures → 1 failure - Total Log4perl failures: 18/700 → 11/700 subtests Files: - ByteCodeSourceMapper.java: Use accurate line number calculation - caller_line_number_fix.md: Detailed design document - caller_line_number.t: Unit tests for caller() line numbers - log4perl-compatibility.md: Updated status Generated with [Devin](https://cli.devin.ai/docs) Co-Authored-By: Devin <noreply@cognition.ai> * docs: mark caller_line_number_fix as committed Generated with [Devin](https://cli.devin.ai/docs) Co-Authored-By: Devin <noreply@cognition.ai> --------- Co-authored-by: Devin <noreply@cognition.ai>
1 parent 4908709 commit a0de456

5 files changed

Lines changed: 419 additions & 25 deletions

File tree

‎dev/design/caller_line_number_fix.md‎

Lines changed: 306 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,306 @@
1+
# caller() Line Number Fix Plan
2+
3+
## Overview
4+
5+
This document describes the fix for incorrect line numbers reported by `caller()` when accessing stack frames. The issue affects Log::Log4perl and other modules that rely on `caller($level)` with level > 1.
6+
7+
## Problem Statement
8+
9+
When `caller($level)` is called with higher levels to look up the call stack, it reports incorrect line numbers. Instead of the actual source line where the call was made, it reports a line near the end of the file.
10+
11+
### Expected vs Actual Behavior
12+
13+
```perl
14+
# File: test.pl (51 lines total)
15+
package App;
16+
sub handler {
17+
my $logger = Logger->new();
18+
$logger->log("Test"); # LINE 35 - this is the call site we want
19+
}
20+
21+
package main;
22+
App::handler();
23+
24+
# Inside Logger->log():
25+
my @c = caller(2);
26+
# Expected: $c[2] == 35 (the line where $logger->log was called)
27+
# Actual: $c[2] == 48 (near end of file)
28+
```
29+
30+
### Affected Tests
31+
32+
- **Log::Log4perl t/024WarnDieCarp.t**: 8 failing tests (51-53, 58, 60, 62, 67, 69)
33+
- Any module using `caller()` with level > 1 to find "real" callers
34+
35+
## Root Cause Analysis
36+
37+
### The Architecture
38+
39+
PerlOnJava maps Perl source locations to JVM bytecode using:
40+
41+
1. **Token Index**: Each token in the source has a unique index
42+
2. **ByteCodeSourceMapper**: Maps tokenIndex → (lineNumber, package, subroutine, sourceFile)
43+
3. **JVM Line Number Table**: Stores tokenIndex (not actual line) in bytecode metadata
44+
4. **ExceptionFormatter**: Converts JVM stack traces to Perl stack traces using the mapping
45+
46+
### The Bug
47+
48+
In `ByteCodeSourceMapper.saveSourceLocation()` (line 166):
49+
50+
```java
51+
int lineNumber = ctx.errorUtil.getLineNumber(tokenIndex);
52+
```
53+
54+
The `getLineNumber()` method uses a **forward-only cache**:
55+
56+
```java
57+
public int getLineNumber(int index) {
58+
// If requesting a PAST index, return the STALE cached value!
59+
if (index <= tokenIndex) {
60+
return lastLineNumber; // BUG: Returns wrong value
61+
}
62+
// Count forward from cache position...
63+
}
64+
```
65+
66+
**The problem occurs when:**
67+
68+
1. Main code is parsed first (tokenIndex advances to end of file, `lastLineNumber` = 48)
69+
2. Subroutine bodies are compiled later (closure capture deferred compilation)
70+
3. `saveSourceLocation()` is called for subroutine code at tokenIndex 345
71+
4. Since 345 < current cache position, `getLineNumber(345)` returns 48 (cached end-of-file value)
72+
5. TokenIndex 345 is incorrectly mapped to line 48 instead of line 35
73+
74+
### Debug Evidence
75+
76+
```
77+
# First call during parse (CORRECT):
78+
DEBUG saveSourceLocation: STORE tokenIndex=327 line=35 pkg=App sub=handler
79+
80+
# Second call during emit (WRONG - line should be ~35, not 48):
81+
DEBUG saveSourceLocation: STORE tokenIndex=345 line=48 pkg=App sub=handler
82+
83+
# Lookup during caller():
84+
DEBUG parseStackTraceElement: lookupTokenIndex=345 foundTokenIndex=345 line=48 pkg=App
85+
# Returns line=48 (WRONG) instead of line=35 (CORRECT)
86+
```
87+
88+
## Solution
89+
90+
### Fix 1: Use Accurate Line Number Calculation
91+
92+
Replace `getLineNumber()` with `getLineNumberAccurate()` in `saveSourceLocation()`:
93+
94+
**File:** `src/main/java/org/perlonjava/backend/jvm/ByteCodeSourceMapper.java`
95+
96+
```java
97+
// Line 166: Change from
98+
int lineNumber = ctx.errorUtil.getLineNumber(tokenIndex);
99+
100+
// To:
101+
int lineNumber = ctx.errorUtil.getLineNumberAccurate(tokenIndex);
102+
```
103+
104+
The `getLineNumberAccurate()` method always counts from the beginning of the file, so it's safe for out-of-order access:
105+
106+
```java
107+
public int getLineNumberAccurate(int index) {
108+
int lineNumber = 1;
109+
for (int i = 0; i <= index && i < tokens.size(); i++) {
110+
LexerToken tok = tokens.get(i);
111+
if (tok.type == LexerTokenType.EOF) break;
112+
if (tok.type == LexerTokenType.NEWLINE) {
113+
lineNumber++;
114+
}
115+
}
116+
return lineNumber;
117+
}
118+
```
119+
120+
### Fix 2: Performance Optimization (Optional)
121+
122+
If the O(n) counting becomes a performance concern, we can optimize by:
123+
124+
1. Pre-computing line numbers for all tokens during lexing
125+
2. Building a TreeMap<tokenIndex, lineNumber> during the first pass
126+
3. Using binary search for lookups
127+
128+
However, this is likely unnecessary since:
129+
- `saveSourceLocation()` is only called once per bytecode instruction
130+
- The token list is small for most files
131+
- This code path is only hit during compilation, not runtime
132+
133+
## How to Reproduce
134+
135+
### Minimal Test Case
136+
137+
```perl
138+
#!/usr/bin/perl
139+
use strict;
140+
use warnings;
141+
142+
package Logger;
143+
sub format_line {
144+
my ($level) = @_;
145+
my @c = caller($level);
146+
return defined($c[2]) ? $c[2] : "undef";
147+
}
148+
149+
sub log_msg {
150+
my $msg = shift;
151+
my $line = format_line(2);
152+
return "$msg at line $line";
153+
}
154+
155+
package Logger::Logger;
156+
sub new { bless {}, shift }
157+
sub log {
158+
my ($self, $msg) = @_;
159+
return Logger::log_msg($msg);
160+
}
161+
162+
package App;
163+
sub handler {
164+
my $logger = Logger::Logger->new();
165+
my $result = $logger->log("Test message"); # LINE 28
166+
return $result;
167+
}
168+
169+
package main;
170+
my $output = App::handler();
171+
print "Output: $output\n";
172+
print "Expected: 'Test message at line 28'\n";
173+
```
174+
175+
### Running the Test
176+
177+
```bash
178+
# With Perl (correct):
179+
perl test.pl
180+
# Output: Test message at line 28
181+
182+
# With PerlOnJava (wrong before fix):
183+
./jperl test.pl
184+
# Output: Test message at line XX (near end of file)
185+
186+
# Debug mode:
187+
DEBUG_CALLER=1 ./jperl test.pl 2>&1 | grep "STORE\|adding frame"
188+
```
189+
190+
## Unit Test Location
191+
192+
Create test file: `src/test/resources/unit/caller_line_number.t`
193+
194+
```perl
195+
use strict;
196+
use warnings;
197+
use Test::More tests => 6;
198+
199+
# Test 1: Basic caller(0) - same function
200+
sub test_caller_0 {
201+
my @c = caller(0);
202+
return $c[2]; # Return line number
203+
}
204+
my $line1 = __LINE__ + 1;
205+
my $result1 = test_caller_0();
206+
# caller(0) returns info about where test_caller_0 is being called FROM
207+
# which is the current context (main), not inside the function
208+
# Actually, caller(0) inside the function returns the caller OF that function
209+
is($result1, $line1, "caller(0) returns correct line");
210+
211+
# Test 2: caller(1) - one level up
212+
sub inner { my @c = caller(1); return $c[2]; }
213+
sub outer { inner(); }
214+
my $line2 = __LINE__ + 1;
215+
my $result2 = outer();
216+
is($result2, $line2, "caller(1) returns correct line");
217+
218+
# Test 3: caller(2) - two levels up (the bug case)
219+
sub level3 { my @c = caller(2); return $c[2]; }
220+
sub level2 { level3(); }
221+
sub level1 { level2(); }
222+
my $line3 = __LINE__ + 1;
223+
my $result3 = level1();
224+
is($result3, $line3, "caller(2) returns correct line");
225+
226+
# Test 4: caller(3) - three levels up
227+
sub d4 { my @c = caller(3); return $c[2]; }
228+
sub d3 { d4(); }
229+
sub d2 { d3(); }
230+
sub d1 { d2(); }
231+
my $line4 = __LINE__ + 1;
232+
my $result4 = d1();
233+
is($result4, $line4, "caller(3) returns correct line");
234+
235+
# Test 5: Different packages (like Log4perl)
236+
package Logger;
237+
sub format_line {
238+
my @c = caller(2);
239+
return $c[2];
240+
}
241+
sub log_call { format_line(); }
242+
243+
package Wrapper;
244+
sub wrap { Logger::log_call(); }
245+
246+
package main;
247+
my $line5 = __LINE__ + 1;
248+
my $result5 = Wrapper::wrap();
249+
is($result5, $line5, "caller(2) correct across packages");
250+
251+
# Test 6: Line number should NOT be near end of file
252+
# This specifically tests the bug where end-of-file line was returned
253+
my $file_end = __LINE__ + 20; # Approximate end of file
254+
ok($result3 < $file_end - 10, "caller() line is not near EOF (was: $result3, EOF ~$file_end)");
255+
```
256+
257+
## Implementation Steps
258+
259+
1. **Apply the fix** in `ByteCodeSourceMapper.java` line 166
260+
2. **Run the unit test** to verify the fix:
261+
```bash
262+
./jperl src/test/resources/unit/caller_line_number.t
263+
```
264+
3. **Run Log::Log4perl tests** to verify improvement:
265+
```bash
266+
./jcpan -t Log::Log4perl 2>&1 | grep "024WarnDieCarp"
267+
```
268+
4. **Run full test suite** to check for regressions:
269+
```bash
270+
make
271+
```
272+
273+
## Files to Modify
274+
275+
| File | Change |
276+
|------|--------|
277+
| `src/main/java/org/perlonjava/backend/jvm/ByteCodeSourceMapper.java` | Line 166: Use `getLineNumberAccurate()` |
278+
| `src/test/resources/unit/caller_line_number.t` | New unit test file |
279+
280+
## Expected Results After Fix
281+
282+
| Test | Before | After |
283+
|------|--------|-------|
284+
| Log::Log4perl t/024WarnDieCarp.t | 8 failures | 0 failures |
285+
| caller_line_number.t | N/A | 6/6 pass |
286+
| Full test suite | No regression | No regression |
287+
288+
## Related Documentation
289+
290+
- `dev/design/log4perl-compatibility.md` - Log::Log4perl compatibility tracking
291+
- `dev/design/caller_stack_fix_plan.md` - Previous caller() fixes
292+
293+
## Progress Tracking
294+
295+
### Status: FIXED
296+
297+
### Checklist
298+
- [x] Root cause identified
299+
- [x] Minimal reproduction case created
300+
- [x] Fix designed and documented
301+
- [x] Unit test written
302+
- [x] Fix implemented
303+
- [x] Unit test passing
304+
- [x] Log::Log4perl tests improved (8→1 failures in t/024WarnDieCarp.t)
305+
- [x] Full test suite passing (no regressions)
306+
- [x] Code committed and merged (commit d4993893f)

‎dev/design/cpan_client.md‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -500,10 +500,12 @@ cpan> install Module::Name
500500
- ✅ YAML version: Updated to 1.31, silences "version too low" warning
501501
- ✅ Module::Build partial: Base.pm stub disables fork pipes, allowing external Module::Build to work
502502

503-
## Progress Tracking (Updated 2026-03-19)
503+
## Progress Tracking (Verified 2026-03-19)
504504

505505
### Current Status: Phase 9 complete - CPAN client fully functional for pure Perl modules
506506

507+
**Verified working:** `jcpan install`, `jcpan -t`, and `jcpan -f install` all functional.
508+
507509
### Summary Statistics
508510
- **Phases completed:** 9 (plus sub-phases 9a, 9b)
509511
- **Pure Perl modules:** Can be installed via `jcpan install Module::Name`

0 commit comments

Comments
 (0)