Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

now() raises warning re: unrecognized time zone #945

Closed
mmuurr opened this issue Jan 18, 2021 · 8 comments
Closed

now() raises warning re: unrecognized time zone #945

mmuurr opened this issue Jan 18, 2021 · 8 comments

Comments

@mmuurr
Copy link

mmuurr commented Jan 18, 2021

This is a novel warning (that I only just detected while testthat-ing a package update):

lubridate::now()
# [1] "2021-01-17 21:33:32 MST"
# Warning message:
# In with_tz(Sys.time(), tzone) : Unrecognized time zone ''

packageVersion("lubridate")
#  [1] ‘1.7.9.2’

R 4.0.3, Mac OS 10.15.7.

Unfortunately, I don't know when (re: the various versions above) this showed up ... it seems like it might be related to #928, though even with the warning above the resultant output is indeed in the appropriate timezone (MST for me).

@mmuurr
Copy link
Author

mmuurr commented Jan 18, 2021

I haven't tried the fix attempts listed in #928, but I'm also seeing inconsistency with warnings and timezones, and still don't know if these two issues are fundamentally linked, so I'll add a bit more to this thread (though it may help provide insight over there, too?).

The order in which I make some lubridate calls seems to matter.

Here's an example clean session (no .Rprofile or other custom settings) and these are the first two commands given to R:

lubridate::now("America/Denver")
# [1] "2021-01-17 22:36:19 MST"

lubridate::now()
# [1] "2021-01-17 22:36:22 MST"

Works just fine.

Now here's another clean session with those two commands reversed in order:

lubridate::now()
# [1] "2021-01-17 22:37:09 MST"
# Warning message:
# In with_tz(Sys.time(), tzone) : Unrecognized time zone ''

lubridate::now("America/Denver")
# [1] "2021-01-17 22:37:12 MST"
# Warning message:
# In with_tz(Sys.time(), tzone) : Unrecognized time zone 'America/Denver'

This 'order dependence' is reproducible (on my machine).

Session Info
R version 4.0.3 (2020-10-10)
Platform: x86_64-apple-darwin19.6.0 (64-bit)
Running under: macOS Catalina 10.15.7

Matrix products: default
BLAS:   /usr/local/Cellar/openblas/0.3.13/lib/libopenblasp-r0.3.13.dylib
LAPACK: /usr/local/Cellar/r/4.0.3_2/lib/R/lib/libRlapack.dylib

locale:
[1] en_US.UTF-8/en_US.UTF-8/en_US.UTF-8/C/en_US.UTF-8/en_US.UTF-8

attached base packages:
[1] stats     graphics  grDevices utils     datasets  methods   base

loaded via a namespace (and not attached):
[1] compiler_4.0.3    generics_0.1.0    Rcpp_1.0.5        lubridate_1.7.9.2

@hadley
Copy link
Member

hadley commented Jan 18, 2021

Could you please run:

Sys.getenv("TZDIR")
lubridate::now()
Sys.getenv("TZDIR")
lubridate::now("America/Denver")

@mmuurr
Copy link
Author

mmuurr commented Jan 19, 2021

@hadley So I think the only differentiator I've landed upon is the error/warning popping up when running R in an renv-ed directory. What's confusing to me is there's no specific .Renviron, .Rprofile, or other shell environment variables that are set between the two conditions. The only difference is the renv version's .Rprofile which contains the minimal sourcing of renv/activate.R, and I've looked through that file but nothing stands out to me that would lead to the differences.

Below are all the details, but the take-aways (to my eyes) are:

  • when running from within an renv-ed session:
    • "TZDIR" gets set to "macOS" after the first call requesting timezones
    • errors/warnings are present, but are order-dependent (as mentioned in the earlier post)
  • when running from a non-renv-ed session:
    • "TZDIR" gets set to "/usr/share/zoneinfo"
    • no errors/warnings present

Other trivia:

  • The lubridate version is identical (1.7.9.2) in both the renv and non-renv case (in fact, renv is simply using the cached shim of the system-level lubridate).
  • All other loaded packages have matching versions.
  • The R version is identical (4.0.3).

In any case, from within the renv-ed R session:

## WITH renv

Sys.getenv("TZDIR")
# [1] ""

lubridate::now()
# [1] "2021-01-19 14:12:35 MST"
# Warning message:
# In with_tz(Sys.time(), tzone) : Unrecognized time zone ''

Sys.getenv("TZDIR")
# [1] "macOS"

lubridate::now("America/Denver")
# [1] "2021-01-19 14:12:42 MST"
# Warning message:
# In with_tz(Sys.time(), tzone) : Unrecognized time zone 'America/Denver'

... and now in reverse order (after restarting R):

## WITH renv

Sys.getenv("TZDIR")
# [1] ""

lubridate::now("America/Denver")
# [1] "2021-01-19 14:13:24 MST"

Sys.getenv("TZDIR")
# [1] "macOS"

lubridate::now("America/Denver")
# [1] "2021-01-19 14:13:28 MST"

When run outside of my renv directory (i.e. using system libraries only):

## WITHOUT renv

Sys.getenv("TZDIR")
# [1] ""

lubridate::now()
# [1] "2021-01-19 14:15:16 MST"

Sys.getenv("TZDIR")
# [1] "/usr/share/zoneinfo"

lubridate::now("America/Denver")
# [1] "2021-01-19 14:15:28 MST"

... and the reverse order:

## WITHOUT renv

Sys.getenv("TZDIR")
# [1] ""

lubridate::now("America/Denver")
# [1] "2021-01-19 14:17:08 MST"

Sys.getenv("TZDIR")
# [1] "/usr/share/zoneinfo"

lubridate::now()
# [1] "2021-01-19 14:17:12 MST"

@hadley
Copy link
Member

hadley commented Jan 19, 2021

Are you sure you don't have an older version of lubridate installed in your renv-ed project?

@mmuurr
Copy link
Author

mmuurr commented Jan 20, 2021

Yeah I checked that: both the system version and renv version are 1.7.9.2.
Running R -e packageVersion('lubridate') outside-of and inside-of an renv project yields:

## WITHOUT renv (i.e. system)
> packageVersion("lubridate")
[1] ‘1.7.9.2
## WITH renv
* Project '~/path/to/my/project' loaded. [renv 0.11.0]
> packageVersion("lubridate")
[1] ‘1.7.9.2

As another means of double-checking, I inspected the renv.lock file (and ran renv::status() to make sure there weren't any lingering changes waiting to be renv::snapshot()-ed):

    "lubridate": {
      "Package": "lubridate",
      "Version": "1.7.9.2",
      "Source": "Repository",
      "Repository": "CRAN",
      "Hash": "5b5b02f621d39a499def7923a5aee746"
    },

I've managed to work around the TZ issue in the meantime (specifically by putting some non-interactive scripts inside Docker containers ... hooray immutable infrastructure!), so it's not a big deal for my workflows, but I also want to help in whatever way I can, especially for other users (who may not have the container toolkit available to them). So with that in mind, I'm happy being a lab-rat for pinpointing issues. I'll also try to initialize a new minimal renv project and see if I can replicate.

@vspinu
Copy link
Member

vspinu commented Jan 20, 2021

The behavior is as if lubridate::.onLoad() is not run when the package is loaded from renv, but that would be crazy. Could you run lubridate:::.onLoad() first thing in a renv session and try to reproduce the issue?

@mmuurr
Copy link
Author

mmuurr commented Jan 22, 2021

@vspinu explicitly running lubridate:::.onLoad() within the renv project still leads to the error.

But(!), I was able to create something much closer to a renv reprex, see below. (In all of the R sessions below, I redact the R console's startup preamble for brevity, but do provide sessionInfo(). Also I'm not using the reprex-style output to try to be as true as possible in capturing the exact input/output of each shell/R interaction (literally copy/paste from my terminal).)

No renv Project (silent)

Create a brand new directory from the shell, switch into it, launch R and run lubridate function. In this mode, no warning is generated.

$ mkdir lubridate-tz-issue
$ cd lubridate-tz-issue
$ R
> lubridate::now()
[1] "2021-01-21 18:50:07 MST"

> sessionInfo()
R version 4.0.3 (2020-10-10)
Platform: x86_64-apple-darwin19.6.0 (64-bit)
Running under: macOS Catalina 10.15.7

Matrix products: default
BLAS:   /usr/local/Cellar/openblas/0.3.13/lib/libopenblasp-r0.3.13.dylib
LAPACK: /usr/local/Cellar/r/4.0.3_2/lib/R/lib/libRlapack.dylib

locale:
[1] en_US.UTF-8/en_US.UTF-8/en_US.UTF-8/C/en_US.UTF-8/en_US.UTF-8

attached base packages:
[1] stats     graphics  grDevices utils     datasets  methods   base

loaded via a namespace (and not attached):
[1] compiler_4.0.3    generics_0.1.0    Rcpp_1.0.5        lubridate_1.7.9.2

> q()
Save workspace image? [y/n/c]: n

Within renv Project (warns)

In same directory, start R, init a new renv project, following the renv best-practice of restarting R after renv initialization:

$ R
> renv::init()
* Initializing project ...
* Discovering package dependencies ... Done!
* Copying packages into the cache ... Done!
The following package(s) will be updated in the lockfile:

# CRAN ===============================
- renv   [* -> 0.12.3]

* Lockfile written to '~/tmp/lubridate-tz-issue/renv.lock'.
* Project '~/tmp/lubridate-tz-issue' loaded. [renv 0.12.3]
* renv activated -- please restart the R session.

> sessionInfo()
R version 4.0.3 (2020-10-10)
Platform: x86_64-apple-darwin19.6.0 (64-bit)
Running under: macOS Catalina 10.15.7

Matrix products: default
BLAS:   /usr/local/Cellar/openblas/0.3.13/lib/libopenblasp-r0.3.13.dylib
LAPACK: /usr/local/Cellar/r/4.0.3_2/lib/R/lib/libRlapack.dylib

locale:
[1] en_US.UTF-8/en_US.UTF-8/en_US.UTF-8/C/en_US.UTF-8/en_US.UTF-8

attached base packages:
[1] stats     graphics  grDevices utils     datasets  methods   base

loaded via a namespace (and not attached):
[1] compiler_4.0.3 tools_4.0.3    renv_0.12.3

> q()
Save workspace image? [y/n/c]: n

Restarting R, installing lubridate into the renv project, and running now(). Note that lubridate's installation simply uses the system version (cache-linked). lubridate::now() now warns.

$ R
* Project '~/tmp/lubridate-tz-issue' loaded. [renv 0.12.3]

> renv::install("lubridate")
Installing generics [0.1.0] ...
	OK [linked cache]
Installing Rcpp [1.0.6] ...
	OK [linked cache]
Installing lubridate [1.7.9.2] ...
	OK [linked cache]

> lubridate::now()
[1] "2021-01-21 18:57:56 MST"
Warning message:
In with_tz(Sys.time(), tzone) : Unrecognized time zone ''

> sessionInfo()
R version 4.0.3 (2020-10-10)
Platform: x86_64-apple-darwin19.6.0 (64-bit)
Running under: macOS Catalina 10.15.7

Matrix products: default
BLAS:   /usr/local/Cellar/openblas/0.3.13/lib/libopenblasp-r0.3.13.dylib
LAPACK: /usr/local/Cellar/r/4.0.3_2/lib/R/lib/libRlapack.dylib

locale:
[1] en_US.UTF-8/en_US.UTF-8/en_US.UTF-8/C/en_US.UTF-8/en_US.UTF-8

attached base packages:
[1] stats     graphics  grDevices datasets  utils     methods   base

loaded via a namespace (and not attached):
[1] compiler_4.0.3    generics_0.1.0    tools_4.0.3       Rcpp_1.0.6
[5] lubridate_1.7.9.2 renv_0.12.3

> q()
Save workspace image? [y/n/c]: n

As seen in the sessionInfo, this is on Mac OS 10.15.7 and with R 4.0.3. R was installed via brew.

[EDIT] ... oh, and finally, with lubridate:::.onLoad() called explicitly:

$ R
* Project '~/tmp/lubridate-tz-issue' loaded. [renv 0.12.3]
> lubridate:::.onLoad()
> lubridate::now()
[1] "2021-01-21 19:04:04 MST"
Warning message:
In with_tz(Sys.time(), tzone) : Unrecognized time zone ''

Other Notes/Observations

A few other things things that I've checked and to note about the two scenarios (renv and non-renv):

  • I have no user- or directory-level .Rprofile or .Renviron in place, besides the minimal .Rprofile created by renv, which simply sources renv/activate.R.
  • base::OlsonNames() returns identical output in both cases.
  • Sys.getenv("TZDIR") returns different value after initialization between the two cases:
    • no-renv, no-warning:
      > Sys.getenv("TZDIR")
      [1] ""
      > lubridate::now()
      [1] "2021-01-21 19:24:47 MST"
      > Sys.getenv("TZDIR")
      [1] "/usr/share/zoneinfo"
    • renv, warning:
      * Project '~/tmp/lubridate-tz-issue' loaded. [renv 0.12.3]
      > Sys.getenv("TZDIR")
      [1] ""
      > lubridate::now()
      [1] "2021-01-21 19:27:18 MST"
      Warning message:
      In with_tz(Sys.time(), tzone) : Unrecognized time zone ''
      > Sys.getenv("TZDIR")
      [1] "macOS"
  • More-minimal (is that an oxymoron?):
    • no-renv: lubridate:::C_valid_tz("") returns TRUE
    • renv: lubridate:::C_valid_tz("") returns FALSE
  • ^ That observation leads me to think somehow any initialization code in cctz is being called differently, since load_tz leads down to time_zone::Impl::LoadTimeZone ... 🤷‍♂️

@mmuurr
Copy link
Author

mmuurr commented Jan 22, 2021

So I can confirm that the most recent GitHub tzdir-verbose branch commit (1a809d3) seems to work fine (within renv, outside of renv, and tested against Rcpp 1.0.5 and 1.0.6), and thus it seems on the next CRAN release this issue may likely be resolved.

Apologies for not trying to build from that branch earlier! Also worth noting that master still shows being at 1.7.9.2, though that seems to have been committed in December with changes since, while CRAN shows 1.7.9.2 as being submitted in November 😕 ... I think this caused me some confusion when checking packageVersions during testing.

(Since so many packages' sources are managed by git/GitHub, it'd be neat if at some point there was the option to include the commit hash on the package description page.)

As always, thanks much for everything!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants