After using some R packages for logging in shiny dashboard development and inspiration from function logtime in python library dslib I decided to write R package logtime.

Why to use logtime package?

It’s easy to use

User-friendly interface

Besides logging the package provides you with possibility of tracking time of code execution

Makes code much more readable

No dependencies on other packages

Install

devtools :: install_github ( 'delta1epsilon/logtime' )

logtime package overview

logtime package consists of just five functions log_time, log_message, create_logger, configure_logging and get_logging_configs. The functions names are self-explaining.

log_time

The core function is log_time which enables logging and time tracking and makes code much more readable. Its usage:

log_time ( 'message' , level = 'DEBUG' ) %<% { # expression } # 2016-10-12 12:31:47 - DEBUG - [Start] - [message] # 2016-10-12 12:31:47 - DEBUG - [End ] - [message] - [Done in 0 sec. (0 min.)]

It evaluates an expression in calling environment. Uses pipe operator %<% which is inspired by pipe operators family introduced in magrittr package. It allows nested calls. The call below will output execution time for all tree blocks

log_time ( 'message' , level = 'DEBUG' ) %<% { # expression 1 log_time ( 'sub_message_1' , level = 'DEBUG' ) %<% { # expression 2 } log_time ( 'sub_message_2' , level = 'WARNING' ) %<% { # expression 3 } } # 2016-10-12 12:34:06 - DEBUG - [Start] - [message] # 2016-10-12 12:34:06 - DEBUG - [Start] - [sub_message_1] # 2016-10-12 12:34:06 - DEBUG - [End ] - [sub_message_1] - [Done in 0 sec. (0 min.)] # 2016-10-12 12:34:06 - WARNING - [Start] - [sub_message_2] # 2016-10-12 12:34:06 - WARNING - [End ] - [sub_message_2] - [Done in 0 sec. (0 min.)] # 2016-10-12 12:34:06 - DEBUG - [End ] - [message] - [Done in 0 sec. (0 min.)]

By default it has level DEBUG but the package supports DEBUG, INFO, WARNING and ERROR levels.

log_message

log_message prints a log message with specified logging level. The usage is simple:

log_message ( 'message' , level = 'DEBUG' ) # 2016-10-12 12:36:46 - DEBUG - [message]

create_logger

To have more control on different logging parts of the script create_logger function was designed. It has three arguments: logger name, logging level and optional file path or connection for writing logs to.

logger <- create_logger ( 'name' , level = 'INFO' , file = "" )

configure_logging

And last but not least, configure_logging allows you to set overall threshold logging level for printing logs and to set file destination for writing logs. The usage is:

configure_logging ( threshold_level = "INFO" , output_file = "" )

Examples

Let’s say I would like to logtime generating of random numbers.

log_time ( 'Generate random numbers' ) %<% { log_time ( 'Set 1' ) %<% { norm_dist_random_numbers <- rnorm ( 10000000 ) } log_time ( 'Set 2' ) %<% { exp_dist_random_numbers <- rexp ( 10000000 ) } log_time ( 'Set 3' ) %<% { pois_dist_random_numbers <- rpois ( 10000000 , lambda = 1 ) } } # 2016-10-12 12:45:29 - DEBUG - [Start] - [Generate random numbers] # 2016-10-12 12:45:29 - DEBUG - [Start] - [Set 1] # 2016-10-12 12:45:32 - DEBUG - [End ] - [Set 1] - [Done in 2.8 sec. (0 min.)] # 2016-10-12 12:45:32 - DEBUG - [Start] - [Set 2] # 2016-10-12 12:45:34 - DEBUG - [End ] - [Set 2] - [Done in 1.8 sec. (0 min.)] # 2016-10-12 12:45:34 - DEBUG - [Start] - [Set 3] # 2016-10-12 12:45:36 - DEBUG - [End ] - [Set 3] - [Done in 1.9 sec. (0 min.)] # 2016-10-12 12:45:36 - DEBUG - [End ] - [Generate random numbers] - [ Done in 6.4 sec. ( 0.1 min. )]

Or let’s create a log with level ‘WARNING’ which tells that data frame is empty.

log_message ( 'The data frame is empty' , level = 'WARNING' ) # 2016-10-12 12:46:39 - WARNING - [The data frame is empty]

Let’s move on and create a logger called clean_data with default level INFO which will write all the logs to file clean_data.log.

clean_data_logger <- create_logger ( name = 'clean_data' , level = 'INFO' , file = 'clean_data.log' )

And let’s logtime some process in data cleaning procedure.

clean_data_logger $ log_time ( 'Data cleaning step X' ) %<% { # some code } # this logs go to clean_data.log file: # 2016-10-12 12:48:50 - [clean_data] - INFO - [Start] - [Data cleaning step X] # 2016-10-12 12:48:50 - [clean_data] - INFO - [End ] - [Data cleaning step X] - [Done in 0 sec. (0 min.)]

The code above writes logs to clean_data.log file with logging level INFO. By default the logger’s log_time and log_message have level INFO and can be changed.

Now let’s create simple log with changed level to ERROR.

clean_data_logger $ log_message ( 'Something awful happened' , level = 'ERROR' ) # goes to clean_data.log file: # 2016-10-12 12:50:55 - [clean_data] - ERROR - [Something awful happened]

To set the package for printing only logs with levels INFO and higher (namely INFO, WARNING and ERROR) we write:

configure_logging ( threshold_level = 'INFO' )

To set the package for printing logs to log.log file with levels WARNING and higher we write:

configure_logging ( threshold_level = 'WARNING' , output_file = 'log.log' )

Below is the table which indicates when a log with specific level is printed depending on threshold logging level defined in configure_logging .