Bad file/lines in error (assert/fail/alt check) messages from inline functions

[marijnh]

Spans of inlined things currently end up pointing at the start of the crate file. This makes them quite useless and confusing.

Example (adapted from pnkfelix's comments below):

% cat -n /tmp/foo.rs
     1  #[link(name="foo", vers="0.0")];
     2  
     3  #[inline(always)]
     4  pub fn access_inline_always(a: &[int], i: uint) -> int {
     5      info!("foo::access_inline_always");
     6      a[i]
     7  }
     8  
     9  #[inline(never)]
    10  pub fn access_inline_never(a: &[int], i: uint) -> int {
    11      info!("foo::access_inline_never");
    12      a[i]
    13  }
% cat -n /tmp/bar.rs
     1  extern mod foo;
     2  
     3  fn main() {
     4      let arr = [1, 2, 3];
     5      let a_0 = foo::access_inline_never(arr, 0);
     6      let a_1 = foo::access_inline_always(arr, 1);
     7      println(format!("arr[0]: {:?} arr[1]: {:?}", a_0, a_1));
     8      let a_4 = foo::access_inline_always(arr, 4);
     9      println(format!("arr[4]: {:?}", a_4));
    10  }
% rustc --cfg debug --lib /tmp/foo.rs
warning: no debug symbols in executable (-arch x86_64)
% rustc -L/tmp /tmp/bar.rs
warning: no debug symbols in executable (-arch x86_64)
% RUST_LOG=foo /tmp/bar
"foo::access_inline_never"
"foo::access_inline_always"
arr[0]: 1 arr[1]: 2
"foo::access_inline_always"
task '<unnamed>' failed at 'index out of bounds: the len is 3 but the index is 4', /tmp/bar.rs:1

Note that the error message points one to /tmp/bar.rs:1 but it should probably point at the vector access itself at line foo.rs:6

[nikomatsakis]

oh yes to do this we have to serialize the codemap info a bit more than we do today (otherwise we cannot interpret the spans)

[marijnh]

the span info will be huge though (and the codemap info also significant). May be better to somehow distinguish 'significant' spans on the few items that output span info to the binary, and only write those out (in explicit line/char/file format).

[nikomatsakis]

We are already serializing all the spans, we just disregard them on deserialization. However, with the new work that I am doing on the serialization process, it should be fairly trivial to customize this so that we do not serialize spans or serialize them in a special way.

[pnkfelix]

Not critical for 0.6; de-milestoning

[metajack]

#3740 is a prereq for this and is in the backwards compatible milestone. Nominating for production ready.

[graydon]

accepted for production-ready milestone

[emberian]

I don't really understand the issue; how can it be reproduced?

[emberian]

(@nikomatsakis, @marijnh ?)

[pnkfelix]

@cmr I'm actually unsure whether this is still broken.

Here is an elaborate attempt to recreate the bug:

% cat -n /tmp/foo.rs
     1  use std::num::Zero;
     2  use std::num::One;
     3  
     4  #[inline(always)]
     5  pub fn add2<I:Integer>(x: I) -> I {
     6      assert!(x >= Zero::zero());
     7      (x + One::one()) + One::one()
     8  }
% cat -n /tmp/bar.rs
     1  extern mod foo;
     2  use foo::*;
     3  
     4  fn main() {
     5      let four = add2(2);
     6      println(fmt!("2+2 == %d", four));
     7      let zero = add2(-2);
     8      println(fmt!("-2+2 == %d", zero));
     9  }
% rustc --lib /tmp/foo.rs && rustc -L/tmp /tmp/bar.rs && /tmp/bar
warning: missing crate link meta `name`, using `foo` as default
warning: missing crate link meta `vers`, using `0.0` as default
warning: no debug symbols in executable (-arch x86_64)
warning: no debug symbols in executable (-arch x86_64)
2+2 == 4
rust: task failed at 'assertion failed: x >= Zero::zero()', /tmp/foo.rs:6
rust: domain main @0x7f965c014c10 root task failed

as you can see, the assertion failure in the call to foo's add2 is indeed printing the correct line number within foo.rs.

(There is an issue that was blocking this that remains unfixed, namely #3740, but that issue was partially fixed, so it may no longer be a blocker for this.)

[nikomatsakis]

Still broken afaik.

[pnkfelix]

@nikomatsakis can you elaborate what sort of inlined thing one would need to use in another crate to illustrate the bug? I started with something small (which seemed to work to me) and added more and more stuff to it (in the hopes of exposing the bug) until I ended up with the example I wrote above.

Do I need to incorporate uses of -Z debug-info or something?

[nikomatsakis]

I believe your example works because the macro-expander is inserting the filename/line-number information before inlining occurs. I imagine you would see the wrong filename/line-number on an out-of-bounds array access, though.

[pnkfelix]

@cmr okay @nikomatsakis is correct. Here is a demo of ... well, a semi-related bug. (I forgot to turn on inlining, but I think we see it here due to the parametric definition. Will switch to something that inlines later.)

% cat /tmp/foo.rs
pub fn access<T:Clone>(a: &[T], i: uint) -> T {
    a[i].clone()
}
% cat /tmp/bar.rs
extern mod foo;
use foo::*;

pub fn main() {
    let arr = [1, 2, 3];
    let a_4 = access(arr, 4);
    println(fmt!("arr[4]: %?", a_4));
}
% rustc --lib /tmp/foo.rs && rustc -L/tmp /tmp/bar.rs && /tmp/bar
warning: missing crate link meta `name`, using `foo` as default
warning: missing crate link meta `vers`, using `0.0` as default
warning: no debug symbols in executable (-arch x86_64)
warning: no debug symbols in executable (-arch x86_64)
rust: task failed at 'index out of bounds: the len is 3 but the index is 4', /tmp/bar.rs:1
rust: domain main @0x7fd1e8814c10 root task failed
% 

[pnkfelix]

@cmr Here is a better example: It shows how the problem arises in the example @nikomatsakis gave (out of bounds array access), but it also shows another instance of the same problem: the info! directive for the inlined functions ends up being associated with the caller module bar rather than the callee module foo where the function is defined, which leads to weird discrepancies for what settings one needs to use for RUST_LOG in order to observe the info! output:

% cat -n /tmp/foo.rs
     1  #[link(name="foo", vers="0.0")];
     2  
     3  #[inline(always)]
     4  pub fn access_inline_always(a: &[int], i: uint) -> int {
     5      info!("foo::access_inline_always");
     6      a[i]
     7  }
     8  
     9  #[inline(never)]
    10  pub fn access_inline_never(a: &[int], i: uint) -> int {
    11      info!("foo::access_inline_never");
    12      a[i]
    13  }
% cat -n /tmp/bar.rs
     1  extern mod foo;
     2  
     3  fn main() {
     4      let arr = [1, 2, 3];
     5      let a_0 = foo::access_inline_never(arr, 0);
     6      let a_1 = foo::access_inline_always(arr, 1);
     7      println(fmt!("arr[0]: %? arr[1]: %?", a_0, a_1));
     8      let a_4 = foo::access_inline_always(arr, 4);
     9      println(fmt!("arr[4]: %?", a_4));
    10  }
% rustc --cfg debug --lib /tmp/foo.rs && rustc -L/tmp /tmp/bar.rs && RUST_LOG=foo=4 /tmp/bar
warning: no debug symbols in executable (-arch x86_64)
warning: no debug symbols in executable (-arch x86_64)
rust: ~"\"foo::access_inline_never\""
arr[0]: 1 arr[1]: 2
rust: task failed at 'index out of bounds: the len is 3 but the index is 4', /tmp/bar.rs:1
rust: domain main @0x7ff333807810 root task failed
% rustc --cfg debug --lib /tmp/foo.rs && rustc -L/tmp /tmp/bar.rs && RUST_LOG=bar=4 /tmp/bar
warning: no debug symbols in executable (-arch x86_64)
warning: no debug symbols in executable (-arch x86_64)
rust: ~"\"foo::access_inline_always\""
arr[0]: 1 arr[1]: 2
rust: ~"\"foo::access_inline_always\""
rust: task failed at 'index out of bounds: the len is 3 but the index is 4', /tmp/bar.rs:1
rust: domain main @0x7fc1b8807810 root task failed
% 

[emberian]

The inline logging issue is a known problem but I can't find the issue for it.

[catamorphism]

We think this is fixed. Reopen if you have a way to reproduce it.

[nikomatsakis]

Out of curiosity, why do we think this is fixed? Certainly, the spans in inlined ASTs are still invalid:

https://github.com/mozilla/rust/blob/master/src/librustc/middle/astencode.rs#L219

I imagine this would mean that a failure that is generated by trans, such as array deref, would report an incorrect span. @pnkfelix's example seems still relevant.

[pnkfelix]

My example still shows a problem. (I had to port it to new format! syntax.) I'll update bug description with it.

[emberian]

Furthermore issues can't just be closed without a test in the suite.

On Thu, Oct 24, 2013 at 7:04 PM, Felix S Klock II
[email protected]:

My example still shows a problem. (I had to port it to new format!syntax.) I'll update bug description with it.

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/1972#issuecomment-27040689
.

[jdm]

Similarly, any cast::transmute from one type to another that is a different size will trigger this error.

[emberian]

@nikomatsakis why would this require anything with serializing spans? afaict, this bug is almost entirely about the span of the expression that caused the error not being correct. Am I missing something?

[nikomatsakis]

@cmr the span is incorrect because the AST was serialized into crate metadata and then de-serialized into another crate during trans as part of cross-crate inlining, and we do not currently preserve spans across serialization

[steveklabnik]

Given that #15199 was merged, I'm giving this a close. Please object if you feel differently 😄