[R-package] silence logs in print(), show(), summary() tests

[jameslamb]

Contributes to #4862.

This PR proposes capturing the logs printed from tests on show(), summary(), and print() methods for Booster, added in #4686.

Using the following code, I found that this PR reduces the output of the R package's tests from 73 lines to 28 lines.

sh build-cran-package --no-build-vignettes
R CMD INSTALL --with-keep.source ./lightgbm_3.3.2.99.tar.gz
cd R-package/tests
Rscript testthat.R > ../../out.log 2>&1
echo "log lines from tests: $(cat ../../out.log | wc -l)"

[jmoralez]

Nice! I see only the test files names and the dots. What are the tasks left to close #4862?

[jameslamb]

What are the tasks left to close #4862

It's really weird to me that the logs at https://pipelines.actions.githubusercontent.com/serviceHosts/1f53ab1f-1bd7-45b1-9237-cc6b054df090/_apis/pipelines/1/runs/30984/signedlogcontent/17?urlExpires=2022-05-24T16%3A18%3A43.5279800Z&urlSigningMethod=HMACV1&urlSignature=3rzC%2F8PrYEI46MUXIzdWrTHDcMPMfcLJPuT7wmriySk%3D (for example) are getting truncated after the dataset tests.

basic: ............................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................
custom_objective: ........
dataset: ................................No issues were found checking the R package

There should actually be many more. Here's what I see running Rscript testthat.R on my laptop.

Predictor: ..................................................................................................................................................................
basic: ...........................................................[LightGBM] [Fatal] Unknown objective type name: not_a_real_objective
..........................[LightGBM] [Fatal] Unknown objective type name: not_a_real_objective
..................................................................................................................................................................................................................................[LightGBM] [Fatal] Cannot change linear_tree after constructed Dataset handle.
.....................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................
custom_objective: ........
dataset: ................................[LightGBM] [Fatal] Initial score size doesn't match data size
..............................................
learning_to_rank: ...............................................
lgb.Booster: .........................................................................[LightGBM] [Fatal] Unknown importance type: only support split=0 and gain=1
...................................[LightGBM] [Fatal] Unknown objective type name: not_a_real_objective
...[LightGBM] [Fatal] Could not open file-that-does-not-exist.model
.[LightGBM] [Fatal] Unknown model format or submodel type in model file /var/folders/b4/rzfqc68n4nj5flhvf3041ycr0000gr/T//Rtmpo8uaJX/file83d75faa23ce.model
.[LightGBM] [Fatal] Model file doesn't specify the number of classes
............................................................................................
lgb.convert_with_rules: .........................................................................................................................................
lgb.importance: ...........
lgb.interprete: ........
lgb.plot.importance: .........
lgb.plot.interpretation: ...
metrics: ...
parameters: ..........................
utils: ......................
weighted_loss: ...

The last piece for #4862 is to eliminate those Fatal logs that make it through. Those happen because for the R package, Log::Fatal() on the C++ side writes to stderr

LightGBM/include/LightGBM/utils/log.h

Lines 121 to 130 in f2e1ad6

	// R code should write back to R's error stream,
	// otherwise to stderr
	#ifndef LGB_R_BUILD
	fprintf(stderr, "[LightGBM] [Fatal] %s\n", str_buf);
	fflush(stderr);
	#else
	REprintf("[LightGBM] [Fatal] %s\n", str_buf);
	R_FlushConsole();
	#endif
	throw std::runtime_error(std::string(str_buf));

AND raises an R exception (which again writes to stderr).

LightGBM/R-package/src/lightgbm_R.cpp

Lines 37 to 42 in f2e1ad6

	#define R_API_END() } \
	catch(LGBM_R_ErrorClass &cont) { R_ContinueUnwind(cont.cont_token); } \
	catch(std::exception& ex) { LGBM_R_save_exception_msg(ex); } \
	catch(std::string& ex) { LGBM_R_save_exception_msg(ex); } \
	catch(...) { Rf_error("unknown exception"); } \
	Rf_error(R_errmsg_buffer); \

The R exception is trapped and its output suppressed by testthat::expect_error(), but not that first print.

[jmoralez]

Oh I was looking at the MSVC logs and they look perfect but I see the same as you do on my laptop, I thought it was something on my side because it has M1 but I run it with Rosetta so I figured it didn't work correctly.

[github-actions]

This pull request has been automatically locked since there has not been any recent activity since it was closed. To start a new related discussion, open a new issue at https://github.com/microsoft/LightGBM/issues including a reference to this.