missing error messages after failed initialization

[bob-carpenter]

Summary:

Error messages get lost after failed initialization.

Reproducible Steps:

In RStan 2.18.1 on Mac OS X, this command

stan(model_code = 'parameters { real x; } model { reject("foo"); }', chains=1, iter=10)

fails initialization.

Current Output:

15 verbose warning messages, then

SAMPLING FOR MODEL '61b0f66ecff6751e01f0b5e389249dfd' NOW (CHAIN 1).
Chain 1: Initialization between (-2, 2) failed after 100 attempts. 
[1] "Error in sampler$call_sampler(args_list[[i]]) : Initialization failed."
error occurred during calling the sampler; sampling not done

Expected Output:

Something that includes the error message, which here should be "foo".

RStan Version:

> sessionInfo()
R version 3.5.0 (2018-04-23)
Platform: x86_64-apple-darwin15.6.0 (64-bit)
Running under: macOS High Sierra 10.13.6

Matrix products: default
BLAS: /Library/Frameworks/R.framework/Versions/3.5/Resources/lib/libRblas.0.dylib
LAPACK: /Library/Frameworks/R.framework/Versions/3.5/Resources/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     

other attached packages:
[1] rstan_2.18.1       StanHeaders_2.18.0 ggplot2_2.2.1     

loaded via a namespace (and not attached):
 [1] Rcpp_0.12.18       magrittr_1.5       munsell_0.4.3      colorspace_1.3-2  
 [5] R6_2.2.2           rlang_0.2.1        plyr_1.8.4         tools_3.5.0       
 [9] parallel_3.5.0     pkgbuild_1.0.2     grid_3.5.0         gtable_0.2.0      
[13] loo_2.0.0          cli_1.0.0          matrixStats_0.54.0 lazyeval_0.2.1    
[17] assertthat_0.2.0   tibble_1.4.2       crayon_1.3.4       processx_3.2.0    
[21] gridExtra_2.3      callr_3.0.0        codetools_0.2-15   base64enc_0.1-3   
[25] ps_1.2.0           inline_0.3.15      compiler_3.5.0     pillar_1.2.3      
[29] scales_0.5.0       prettyunits_1.0.2  stats4_3.5.0      

Operating System:

OS X 10.13.6 (High Sierra)

[bgoodri]

For this example, I am seeing

Rejecting initial value:
  Error evaluating the log probability at the initial value.
Exception: foo  (in 'model431f17c7ae3e_61b0f66ecff6751e01f0b5e389249dfd' at line 1)

Are you using the Mac GUI or something?

[bob-carpenter]

I get the same result in terminal, GUI, and RStudio. The good news is I didn't have trouble installing anywhere---it all just worked.

I also don't see anything like the "Rejecting initial value:" you reported.

This isn't an initialization, though---I'm using random initialization, which is why I had to declare a parameter. When I have explicit initialization,

stan(model_code = 'parameters { real<lower = 0, upper = 1> x; } model { reject("foo"); }',
     init = function(n) list(x = 0.5),
     chains = 1)

I get the same result as without an initialization function:

...
/Library/Frameworks/R.framework/Versions/3.5/Resources/library/StanHeaders/include/stan/math/prim/mat/fun/autocorrelation.hpp:18:8: warning: function 'fft_next_good_size' is not needed and will not be emitted [-Wunneeded-internal-declaration]
size_t fft_next_good_size(size_t N) {
       ^
15 warnings generated.

SAMPLING FOR MODEL 'c2ab716c8ec36152f8efb594a05005e6' NOW (CHAIN 1).
Chain 1: Initialization between (-2, 2) failed after 1 attempts. 
[1] "Error in sampler$call_sampler(args_list[[i]]) : Initialization failed."
error occurred during calling the sampler; sampling not done

So there's no other output than this.

This is very curious, because I called it with an explicit initialization function---does it always just report the random thing because some parameters might be randomly generated?

[bgoodri]

Yeah, the potential for partial initialization means it just goes through its normal routine. There's certainly not supposed to be any difference between what it prints out between Linux and Mac. Do you have any text files in the temporary directory that have more messages: dir(tempdir(), pattern = "txt$") ?

[slaweku]

Hi, If I may interject: I am getting the same message as Bob on Windows and Linux. My Linux info: sessionInfo() R version 3.4.4 (2018-03-15) Platform: x86_64-pc-linux-gnu (64-bit) Running under: Debian GNU/Linux 8 (jessie)

Matrix products: default BLAS: /usr/lib/libblas/libblas.so.3.0 LAPACK: /usr/lib/lapack/liblapack.so.3.0

locale: [1] LC_CTYPE=en_US.UTF-8 LC_NUMERIC=C LC_TIME=en_US.UTF-8 LC_COLLATE=en_US.UTF-8 LC_MONETARY=en_US.UTF-8 LC_MESSAGES=en_US.UTF-8
[7] LC_PAPER=en_US.UTF-8 LC_NAME=C LC_ADDRESS=C LC_TELEPHONE=C LC_MEASUREMENT=en_US.UTF-8 LC_IDENTIFICATION=C

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

other attached packages: [1] Rlgt_0.1-0 forecast_8.4 rstantools_1.5.1 Rcpp_0.12.19

loaded via a namespace (and not attached): [1] rstan_2.18.1 zoo_1.8-4 tidyselect_0.2.5 purrr_0.2.5 urca_1.3-0 lattice_0.20-35 colorspace_1.3-2 stats4_3.4.4 loo_2.0.0
[10] base64enc_0.1-3 rlang_0.2.2 pkgbuild_1.0.2 pillar_1.3.0 sn_1.5-2 glue_1.3.0 TTR_0.23-4 bindrcpp_0.2.2 matrixStats_0.54.0 [19] bindr_0.1.1 plyr_1.8.4 quantmod_0.4-13 timeDate_3043.102 munsell_0.5.0 gtable_0.2.0 codetools_0.2-15 inline_0.3.15 tseries_0.10-45
[28] callr_3.0.0 ps_1.1.0 lmtest_0.9-36 parallel_3.4.4 curl_3.2 xts_0.11-1 scales_1.0.0 StanHeaders_2.18.0 fracdiff_1.4-2
[37] gridExtra_2.3 mnormt_1.5-5 ggplot2_3.0.0 processx_3.2.0 dplyr_0.7.7 numDeriv_2016.8-1 grid_3.4.4 quadprog_1.5-5 cli_1.0.1
[46] magrittr_1.5 lazyeval_0.2.1 tibble_1.4.2 crayon_1.3.4 pkgconfig_2.0.2 prettyunits_1.0.2 assertthat_0.2.0 R6_2.3.0 nnet_7.3-12
[55] uroot_2.0-9 nlme_3.1-131.1 compiler_3.4.4

Regards, Slawek

[bgoodri]

OK, I can see it on Windows

On Wed, Oct 24, 2018 at 11:01 AM slaweku notifications@github.com wrote:

Hi, If I may interject: I am getting the same message as Bob on Windows and Linux. My Linux info: sessionInfo() R version 3.4.4 (2018-03-15) Platform: x86_64-pc-linux-gnu (64-bit) Running under: Debian GNU/Linux 8 (jessie)

Matrix products: default BLAS: /usr/lib/libblas/libblas.so.3.0 LAPACK: /usr/lib/lapack/liblapack.so.3.0

locale: [1] LC_CTYPE=en_US.UTF-8 LC_NUMERIC=C LC_TIME=en_US.UTF-8 LC_COLLATE=en_US.UTF-8 LC_MONETARY=en_US.UTF-8 LC_MESSAGES=en_US.UTF-8 [7] LC_PAPER=en_US.UTF-8 LC_NAME=C LC_ADDRESS=C LC_TELEPHONE=C LC_MEASUREMENT=en_US.UTF-8 LC_IDENTIFICATION=C

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

other attached packages: [1] Rlgt_0.1-0 forecast_8.4 rstantools_1.5.1 Rcpp_0.12.19

loaded via a namespace (and not attached): [1] rstan_2.18.1 zoo_1.8-4 tidyselect_0.2.5 purrr_0.2.5 urca_1.3-0 lattice_0.20-35 colorspace_1.3-2 stats4_3.4.4 loo_2.0.0 [10] base64enc_0.1-3 rlang_0.2.2 pkgbuild_1.0.2 pillar_1.3.0 sn_1.5-2 glue_1.3.0 TTR_0.23-4 bindrcpp_0.2.2 matrixStats_0.54.0 [19] bindr_0.1.1 plyr_1.8.4 quantmod_0.4-13 timeDate_3043.102 munsell_0.5.0 gtable_0.2.0 codetools_0.2-15 inline_0.3.15 tseries_0.10-45 [28] callr_3.0.0 ps_1.1.0 lmtest_0.9-36 parallel_3.4.4 curl_3.2 xts_0.11-1 scales_1.0.0 StanHeaders_2.18.0 fracdiff_1.4-2 [37] gridExtra_2.3 mnormt_1.5-5 ggplot2_3.0.0 processx_3.2.0 dplyr_0.7.7 numDeriv_2016.8-1 grid_3.4.4 quadprog_1.5-5 cli_1.0.1 [46] magrittr_1.5 lazyeval_0.2.1 tibble_1.4.2 crayon_1.3.4 pkgconfig_2.0.2 prettyunits_1.0.2 assertthat_0.2.0 R6_2.3.0 nnet_7.3-12 [55] uroot_2.0-9 nlme_3.1-131.1 compiler_3.4.4

Regards, Slawek

— You are receiving this because you were assigned. Reply to this email directly, view it on GitHub https://github.com/stan-dev/rstan/issues/577#issuecomment-432694959, or mute the thread https://github.com/notifications/unsubscribe-auth/ADOrqjZFrE36MtdHb45izGPiLGGhq3Glks5uoIDngaJpZM4X16iJ .

[bgoodri]

@bob-carpenter The problem seems to be commit https://github.com/stan-dev/rstan/commit/a249bec95f4e4b2b34eb0da8b3f97c9fa9c32c07#diff-6f71230a3e987d03fdf2763abf502967 which Daniel had me do in order to make it possible to not show any progress output. But it is also eating the exception messages. If I revert that, then it goes back to the expected behavior. Do you see the reason why it is flawed?

[bgoodri]

@bob-carpenter In the Error and Fatal case, what is actually printing the logger's content to the screen?

[bgoodri]

If I put a Hello in

      void error(const T& msg) {
        std::cout << "Hello" << std::endl;
        error_ << "Chain " << chain_id_  << ": ";
        copy_string(msg, error_);
        error_ << std::endl;
      }

it never gets called. Is there something that is supposed to flush those?

[bob-carpenter]

std::endl automatically flushes the stream---it's why it's not very efficient.

I didn't write that logger code, but that calling pattern looks OK. Definitely not a problem with flushing from the raw C++ side. Is there something in R that might be doing buffering on those streams?

[bgoodri]

Can't rule it out. But I don't know why R would buffer a just the Error_ in a stream_logger_with_chain_id but not a stream_logger

On Wed, Oct 24, 2018 at 11:28 PM Bob Carpenter notifications@github.com wrote:

std::endl automatically flushes the stream---it's why it's not very efficient.

I didn't write that logger code, but that calling pattern looks OK. Definitely not a problem with flushing from the raw C++ side. Is there something in R that might be doing buffering on those streams?

— You are receiving this because you were assigned. Reply to this email directly, view it on GitHub https://github.com/stan-dev/rstan/issues/577#issuecomment-432902014, or mute the thread https://github.com/notifications/unsubscribe-auth/ADOrqm0RajXUuVDPttY0PmxFu8DIqpcJks5uoS_4gaJpZM4X16iJ .

[bob-carpenter]

Also, what happens to std::cout in the environemtn you're calling it from? I sometimes just open a file and write directly to it to make sure I have control of what's getting written.

[bgoodri]

A std::cout will appear for me on Linux . I put some in rethrow_located to verify that it was a domain_error getting rethrown and it comes up like this when I use the old stream_logger

domain_error (this was a std::cout << "domain_error" << std::endl;) Rejecting initial value: Error evaluating the log probability at the initial value. Exception: foo (in 'model63f151d338b5_61b0f66ecff6751e01f0b5e389249dfd' at line 1)

On Wed, Oct 24, 2018 at 11:50 PM Bob Carpenter notifications@github.com wrote:

Also, what happens to std::cout in the environemtn you're calling it from? I sometimes just open a file and write directly to it to make sure I have control of what's getting written.

— You are receiving this because you were assigned. Reply to this email directly, view it on GitHub https://github.com/stan-dev/rstan/issues/577#issuecomment-432905185, or mute the thread https://github.com/notifications/unsubscribe-auth/ADOrqrQiUU6qD1Wo5j68Lc-SMES1u1udks5uoTT1gaJpZM4X16iJ .

[bob-carpenter]

I'm pretty sure the problem is that you added overloaded methods with arguments const T&, so the base class methods with arguments const std::string& (and no-op definitions) match more closely.

The way it works is that C++ looks for the base template method that maches the best, then finds the best matching specialization.

If you change the const T& to const std::string&, it will work for std::string, but it looks like you'll also have to add versions for std::stringstream& that delegate to the std::string methods after calling .str() on the stream.

[bgoodri]

ok that seems to have fixed it

On Wed, Oct 24, 2018 at 11:57 PM Bob Carpenter notifications@github.com wrote:

I'm pretty sure the problem is that you added overloaded methods with arguments const T&, so the base class methods with arguments const std::string& (and no-op definitions) match more closely.

The way it works is that C++ looks for the base template method that maches the best, then finds the best matching specialization.

If you change the const T& to const std::string&, it will work for std::string, but it looks like you'll also have to add versions for std::stringstream& if you want that which call .str() and delegate to the other methods.

I think what's going on is that the base class's implementations are being selected over the subclasses because they are defined for std::string, whereas the subclass uses T&.

— You are receiving this because you were assigned. Reply to this email directly, view it on GitHub https://github.com/stan-dev/rstan/issues/577#issuecomment-432906213, or mute the thread https://github.com/notifications/unsubscribe-auth/ADOrqh1f0C_i4PUeg_W1ulDtwD_EXWhMks5uoTapgaJpZM4X16iJ .

[slaweku]

Hi, May I ask when are you planning to release 2.18.2?

[bgoodri]

It is on CRAN now, but there are no binaries yet.

On Wed, Nov 7, 2018 at 6:27 PM slaweku notifications@github.com wrote:

Hi, May I ask when are you planning to release 2.18.2?

— You are receiving this because you were assigned. Reply to this email directly, view it on GitHub https://github.com/stan-dev/rstan/issues/577#issuecomment-436815661, or mute the thread https://github.com/notifications/unsubscribe-auth/ADOrqiLyaUEL8a6g0PrHWVVniElL17qHks5us2xogaJpZM4X16iJ .

[slaweku]

I have just seen 2.18.2 on CRAN. Thanks!

[slaweku]

I will try to compile. Thank you!

On Wed, Nov 7, 2018 at 4:55 PM bgoodri notifications@github.com wrote:

It is on CRAN now, but there are no binaries yet.

On Wed, Nov 7, 2018 at 6:27 PM slaweku notifications@github.com wrote:

Hi, May I ask when are you planning to release 2.18.2?

— You are receiving this because you were assigned. Reply to this email directly, view it on GitHub https://github.com/stan-dev/rstan/issues/577#issuecomment-436815661, or mute the thread < https://github.com/notifications/unsubscribe-auth/ADOrqiLyaUEL8a6g0PrHWVVniElL17qHks5us2xogaJpZM4X16iJ

.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/stan-dev/rstan/issues/577#issuecomment-436833634, or mute the thread https://github.com/notifications/unsubscribe-auth/AYIz0ipTjDaZmi5Z1VL_bEPw2Mm6-s1vks5us4DqgaJpZM4X16iJ .

[slaweku]

Hi, I compiled and the bug is gone, thank you!