search

daroczig / logger

A lightweight, modern and flexible, log4j and futile.logger inspired logging utility for R
https://daroczig.github.io/logger
280 stars 41 forks source link

Logger producing unknown binary symbols #87

Closed nlarusstone closed 2 years ago

nlarusstone commented 3 years ago

Here's my logger setup (this is in a file called logger.R). 

library(glue)
library(logger)
layout <- layout_glue_generator(format = "{user}/{namespace}/{pid}/{fn} [{time}] {level}: {msg}")
log_layout(layout)
# Log INFO or above to console
log_threshold(INFO)
# Log everything to file
log_threshold(TRACE, index = 2)
log_file <- file.path("logs", format(as.POSIXct(Sys.time()), "%m-%d-%Y-%H:%M:%S"))
log_appender(appender_file(log_file), index = 2)
log_layout(layout, index = 2)

When I source this file from another script I run, I get strange binary symbols in an output file (NOT the log file). Here's the relevant part of the script that runs:

write(group_vars, here::here("pipeline", experiment, "group_vars.txt"), ncolumns = 1)
log_info("Finished preprocess.R")

And this is part of group_vars.txt: Screen Shot 2021-06-28 at 8 52 52 AM

nlarusstone commented 3 years ago

Here's my environment info:

─ Session info ───────────────────────────────────────────────────────────────
 setting  value                       
 version  R version 3.6.1 (2019-07-05)
 os       Ubuntu 16.04.6 LTS          
 system   x86_64, linux-gnu           
 ui       X11                         
 language (EN)                        
 collate  en_US.UTF-8                 
 ctype    en_US.UTF-8                 
 tz       America/Los_Angeles         
 date     2021-06-28                  

─ Packages ───────────────────────────────────────────────────────────────────
 package     * version    date       lib source                          
 abind         1.4-5      2016-07-21 [1] CRAN (R 3.6.1)                  
 assertthat    0.2.1      2019-03-21 [1] CRAN (R 3.6.1)                  
 cachem        1.0.1      2021-01-21 [1] CRAN (R 3.6.1)                  
 callr         3.5.1      2020-10-13 [1] CRAN (R 3.6.1)                  
 car           3.0-10     2020-09-29 [1] CRAN (R 3.6.1)                  
 carData       3.0-4      2020-05-22 [1] CRAN (R 3.6.1)                  
 cellranger    1.1.0      2016-07-27 [2] CRAN (R 3.5.1)                  
 cli           2.5.0      2021-04-26 [1] CRAN (R 3.6.1)                  
 codetools     0.2-18     2020-11-04 [1] CRAN (R 3.6.1)                  
 colorspace    2.0-1      2021-05-04 [1] CRAN (R 3.6.1)                  
 crayon        1.4.1      2021-02-08 [1] CRAN (R 3.6.1)                  
 curl          4.3.1      2021-04-30 [1] CRAN (R 3.6.1)                  
 data.table    1.14.0     2021-02-21 [1] CRAN (R 3.6.1)                  
 DBI           1.1.1      2021-01-15 [1] CRAN (R 3.6.1)                  
 desc          1.3.0      2021-03-05 [1] CRAN (R 3.6.1)                  
 devtools    * 2.3.2      2020-09-18 [1] CRAN (R 3.6.1)                  
 dplyr         1.0.4      2021-02-02 [1] CRAN (R 3.6.1)                  
 drc           3.0-1      2016-08-30 [1] CRAN (R 3.6.1)                  
 ellipsis      0.3.1      2020-05-15 [1] CRAN (R 3.6.1)                  
 fansi         0.5.0      2021-05-25 [1] CRAN (R 3.6.1)                  
 fastmap       1.1.0      2021-01-25 [1] CRAN (R 3.6.1)                  
 forcats       0.5.1      2021-01-27 [1] CRAN (R 3.6.1)                  
 foreign       0.8-72     2019-08-02 [4] CRAN (R 3.6.1)                  
 fs            1.5.0      2020-07-31 [1] CRAN (R 3.6.1)                  
 generics      0.1.0      2020-10-31 [1] CRAN (R 3.6.1)                  
 glue          1.4.1.9000 2021-02-02 [1] Github (tidyverse/glue@f0a7b2a) 
 gtools        3.9.2      2021-06-06 [1] CRAN (R 3.6.1)                  
 haven         2.3.1      2020-06-01 [1] CRAN (R 3.6.1)                  
 hms           1.0.0      2021-01-13 [1] CRAN (R 3.6.1)                  
 lattice       0.20-41    2020-04-02 [1] CRAN (R 3.6.1)                  
 lifecycle     1.0.0      2021-02-15 [1] CRAN (R 3.6.1)                  
 logger        0.2.0      2021-03-04 [1] Github (daroczig/logger@e88153b)
 magrittr      2.0.1      2020-11-17 [1] CRAN (R 3.6.1)                  
 MASS          7.3-53     2020-09-09 [1] CRAN (R 3.6.1)                  
 Matrix        1.3-2      2021-01-06 [1] CRAN (R 3.6.1)                  
 memoise       2.0.0      2021-01-26 [1] CRAN (R 3.6.1)                  
 multcomp      1.4-16     2021-02-08 [1] CRAN (R 3.6.1)                  
 munsell       0.5.0      2018-06-12 [2] CRAN (R 3.5.1)                  
 mvtnorm       1.1-2      2021-06-07 [1] CRAN (R 3.6.1)                  
 openxlsx      4.2.3      2020-10-27 [1] CRAN (R 3.6.1)                  
 pillar        1.5.0      2021-02-22 [1] CRAN (R 3.6.1)                  
 pkgbuild      1.2.0      2020-12-15 [1] CRAN (R 3.6.1)                  
 pkgconfig     2.0.3      2019-09-22 [1] CRAN (R 3.6.1)                  
 pkgload       1.1.0      2020-05-29 [1] CRAN (R 3.6.1)                  
 plotrix       3.8-1      2021-01-21 [1] CRAN (R 3.6.1)                  
 prettyunits   1.1.1      2020-01-24 [1] CRAN (R 3.6.1)                  
 processx      3.5.2      2021-04-30 [1] CRAN (R 3.6.1)                  
 ps            1.6.0      2021-02-28 [1] CRAN (R 3.6.1)                  
 purrr         0.3.4      2020-04-17 [1] CRAN (R 3.6.1)                  
 R6            2.5.0      2020-10-28 [1] CRAN (R 3.6.1)                  
 Rcpp          1.0.6      2021-01-15 [1] CRAN (R 3.6.1)                  
 readxl        1.3.1      2019-03-13 [1] CRAN (R 3.6.1)                  
 remotes       2.4.0      2021-06-02 [1] CRAN (R 3.6.1)                  
 rio           0.5.26     2021-03-01 [1] CRAN (R 3.6.1)                  
 rlang         0.4.11     2021-04-30 [1] CRAN (R 3.6.1)                  
 rprojroot     2.0.2      2020-11-15 [1] CRAN (R 3.6.1)                  
 sandwich      3.0-0      2020-10-02 [1] CRAN (R 3.6.1)                  
 scales        1.1.1      2020-05-11 [1] CRAN (R 3.6.1)                  
 sessioninfo   1.1.1      2018-11-05 [1] CRAN (R 3.6.1)                  
 stringi       1.6.2      2021-05-17 [1] CRAN (R 3.6.1)                  
 survival      3.2-7      2020-09-28 [1] CRAN (R 3.6.1)                  
 testthat      3.0.1      2020-12-17 [1] CRAN (R 3.6.1)                  
 TH.data       1.0-10     2019-01-21 [1] CRAN (R 3.6.1)                  
 tibble        3.0.6      2021-01-29 [1] CRAN (R 3.6.1)                  
 tidyselect    1.1.0      2020-05-11 [1] CRAN (R 3.6.1)                  
 usethis     * 2.0.0      2020-12-10 [1] CRAN (R 3.6.1)                  
 utf8          1.2.1      2021-03-12 [1] CRAN (R 3.6.1)                  
 vctrs         0.3.6      2020-12-17 [1] CRAN (R 3.6.1)                  
 withr         2.4.2      2021-04-18 [1] CRAN (R 3.6.1)                  
 zip           2.2.0      2021-05-31 [1] CRAN (R 3.6.1)                  
 zoo           1.8-9      2021-03-09 [1] CRAN (R 3.6.1)                  

[1] /data/home/nicholas/R/x86_64-pc-linux-gnu-library/3.6
[2] /usr/local/lib/R/site-library
[3] /usr/lib/R/site-library
[4] /usr/lib/R/library
daroczig commented 3 years ago

Can you please update with a reproducible minimal example, e.g. a minimal second script sourcing the first one so that I can run and check what's going on? I was not able to reproduce as per the description on my own.

nlarusstone commented 3 years ago

Here's a reprex:

#!/usr/bin/env Rscript
library(here)
# local files
source(here::here("src", "logger.R"))
group_vars <- c("foo", "bar", "baz")
write(group_vars, here::here("pipeline", "foo", "group_vars.txt"), ncolumns = 1)
log_info("Finished preprocess.R")

Gives me:

foo
bar
baz
nicholas/global/17962/NA [2021-06-29 11:55:59] INFO: Finished preprocess.R
nlarusstone commented 3 years ago

Note that this happens regardless of whether or not the logger.R file is sourced or if that code is directly in this file.

nlarusstone commented 3 years ago

This is NOT happening in R 4.0.3 on my Mac by the way -- just on 3.6.1 on Linux

daroczig commented 2 years ago

Sorry for the late reply, I did not have any clues on what might have been going on there -- but now taking another look, I suspect there might have been something in your .Rprofile file or similar setting a custom layout, or something is missing from the minimal example?

I am closing this, as I suppose it's not relevant anymore, but please feel free to reopen if you can still reproduce and can provide more info.