r-lib / rlang

Low-level API for programming with R
https://rlang.r-lib.org
Other
498 stars 136 forks source link

`rlang::trace_back(bottom = 2)` returns incorrect result if parent of last frame is globalenv #1620

Open t-kalinowski opened 1 year ago

t-kalinowski commented 1 year ago

In attempting to produce a reprex, I found two other different failure modes :crying_cat_face:.

First failure mode with reprex in the mix:

f1 <- function() f2()
f2 <- function() f3()
f3 <- function() eval(quote(save_r_trace()), globalenv())
save_r_trace <- function() rlang::trace_back(bottom = bottom)

bottom <- 2L
f1()
#> ▆

bottom <- 0L
f1()
#>     ▆
#>  1. └─global save_r_trace()
#>  2.   └─rlang::trace_back(bottom = bottom)

Created on 2023-04-26 with reprex v2.0.2

Both calls to f1() in the reprex give an incorrect result. Running it in the IDE directly (without reprex), I see this:

> f1 <- function() f2()
> f2 <- function() f3()
> f3 <- function() eval(quote(save_r_trace()), globalenv())
> save_r_trace <- function() rlang::trace_back(bottom = bottom)
> 
> bottom <- 2L
> f1()
▆
> 
> bottom <- 0L
> f1()
    ▆
 1. ├─global f1()
 2. │ └─global f2()
 3. │   └─global f3()
 4. │     └─base::eval(quote(save_r_trace()), globalenv())
 5. │       └─base::eval(quote(save_r_trace()), globalenv())
 6. └─global save_r_trace()
 7.   └─rlang::trace_back(bottom = bottom)

Here, only the first call to f1() is incorrect, and the 2nd call is what I expect.

The actual error I encountered while working on reticulate was slightly different, and more difficult to reproduce. In C I was doing something like this (simplified for this issue):

SEXP save_r_trace_call = Rf_lang1(Rf_install("save_r_trace"));
SEXP reticulate_ns = R_FindNamespace(Rf_mkString("reticulate"));
Rf_eval(save_r_trace_call, reticulate_ns);

with this in the reticulate namespace:

save_r_trace <- function() {
  .globals$last_r_trace <- rlang::trace_back(bottom = 2L)
}

save_r_trace() works fine when called from a regular R function, but fails when called from C like in the snippet above, because the parent of the evaluation frame there is reported as 0 (I'm guessing because the package namespace is a topenv? Sidenote, the docs should perhaps be updated, parent == 0 is documented as only occurring if parent == globalenv()).

If I drop into a debugger in save_r_trace() I see this:

Browse[2]> for(bottom in 1:8) print(nrow(rlang::trace_back(bottom = bottom)))
debug at /home/tomasz/github/rstudio/reticulate/R/utils.R#71: print(nrow(rlang::trace_back(bottom = bottom)))
Browse[3]> f
[1] 10
[1] 10
[1] 10
[1] 10
[1] 10
[1] 10
[1] 10
[1] 10
Browse[2]> rlang::trace_back()
     ▆
  1. ├─base::source("~/github/t-kalinowski/llama-keras/load-tf-llama.R")
  2. │ ├─base::withVisible(eval(ei, envir))
  3. │ └─base::eval(ei, envir)
  4. │   └─base::eval(ei, envir)
  5. ├─TransformerBlock(layer_id, params)(x, start_pos) at t-kalinowski/llama-keras/load-tf-llama.R:74:0
  6. │ ├─keras:::compose_layer(object, x, ...)
  7. │ └─keras:::compose_layer.default(object, x, ...)
  8. │   └─reticulate (local) layer(object, ...)
  9. │     └─reticulate:::py_call_impl(callable, call_args$unnamed, call_args$named) at reticulate/R/python.R:1370:4
 10. └─reticulate:::save_r_trace() at reticulate/R/RcppExports.R:162:4
Browse[2]> rlang::trace_back(bottom = 2L) -> z; z %>% as_tibble() %>% mutate(call2 = sapply(call, deparse1)) %>% print(n = Inf)
# A tibble: 10 × 6
   call       parent visible namespace  scope call2                                                          
   <list>      <int> <lgl>   <chr>      <chr> <chr>                                                          
 1 <language>      0 TRUE    base       ::    "source(\"~/github/t-kalinowski/llama-keras/load-tf-llama.R\")"
 2 <language>      1 TRUE    base       ::    "withVisible(eval(ei, envir))"                                 
 3 <language>      1 TRUE    base       ::    "eval(ei, envir)"                                              
 4 <language>      3 TRUE    base       ::    "eval(ei, envir)"                                              
 5 <language>      0 TRUE    NA         NA    "TransformerBlock(layer_id, params)(x, start_pos)"             
 6 <language>      5 TRUE    keras      :::   "compose_layer(object, x, ...)"                                
 7 <language>      5 TRUE    keras      :::   "compose_layer.default(object, x, ...)"                        
 8 <language>      7 TRUE    reticulate local "layer(object, ...)"                                           
 9 <language>      8 TRUE    reticulate :::   "py_call_impl(callable, call_args$unnamed, call_args$named)"   
10 <language>      0 TRUE    reticulate :::   "save_r_trace()"  

Here, the value supplied to bottom appears to have not effect on the return value.