<p><div><div><div><div data-width="100" data-show-faces="false" data-send="true" data-layout="button_count" data-height="21" data-href="https://www.r-bloggers.com/python-style-logging-in-r/"></div></div><div><a data-url="https://www.r-bloggers.com/python-style-logging-in-r/" data-counturl="https://www.r-bloggers.com/python-style-logging-in-r/" data-count="horizontal" data-text="Python style logging in R" class="twitter-share-button" data-via="rbloggers" href="https://twitter.com/share"></a></div><div></div></div><div></div></div>
<div>
(This article was first published on <strong><a href="http://mazamascience.com/WorkingWithData/?p=1727"> R – Working With Data</a></strong>, and kindly contributed to <a rel="nofollow" href="https://www.r-bloggers.com/">R-bloggers)</a> </div>
<div>This entry is part 20 of 20 in the series <a title="Using R" target="_blank" href="http://mazamascience.com/WorkingWithData/?series=using-r">Using R</a></div>
<p>We are increasingly using R in “operational” settings that require robust error handling and logging. In this post we describe a quick-and-dirty way to get python style multi-level log files by wrapping the futile.logger package.</p>
<p><span></span></p>
<h2>Making Messy Data Pretty</h2>
<p>Our real world scenario involves R scripts that process raw smoke monitoring data that is updated hourly. The raw data comes from various different instruments, set up by different agencies and transmitted over at least two satellites before eventually arriving on our computers.</p>
<p>Data can be missing, delayed or corrupted for a variety of reasons before it gets to us. And then our R scripts perform QC based on various columns available in the raw (aka “engineering level”) data.</p>
<p>Ultimately, the cleaned up data gets displayed in a user interface <a target="_blank" href="http://tools.airfire.org/monitoring/v3">here</a>.</p>
<p><a target="_blank" href="https://i2.wp.com/mazamascience.com/WorkingWithData/wp-content/uploads/2016/08/monitoring_v3_map.png"><img alt="monitoring_v3_map" class="wp-image-1729" src="https://i2.wp.com/mazamascience.com/WorkingWithData/wp-content/uploads/2016/08/monitoring_v3_map.png?resize=456%2C336" data-recalc-dims="1"></a>No one needs to know all of the hard work that goes into cleaning and QC’ing the data that goes into this map. Our goal, after all, is to make it easier for stakeholders to make decisions without having to worry about the fussy details of raw data.</p>
<h2>Logging When Things Go Wrong</h2>
<p>However, neither the incoming data nor the R scripts we have written to process it are perfect. Things occasionally go wrong in a variety of ways and, when decision makers depend on the data being available, phone calls and text messages are next.</p>
<p>Bhuddist teacher Pema Chödrön’s book <em>When Things Fall Apart</em> has several advice categories that actually apply in this situation. We will focus on one:</p>
<ul>
<li>Using painful emotions to cultivate wisdom, compassion, and courage</li>
<li>Communicating so as to encourage others to open up rather than shut down</li>
<li>Practices for reversing habitual patterns</li>
<li><strong>Methods for working with chaotic situations</strong></li>
<li>Ways for creating effective social action</li>
</ul>
<p>One of the methods for working with chaotic situations in operational software is to have lots and Lots and LOTS of logging.</p>
<p>Python has the brilliant “logging” module that allows us to quickly set up separate output files for log statements at different levels:
<pre>DEBUG, INFO, WARNING, ERROR, WARNING, CRITICAL</pre>
<p>. Inside our operational code we only need to issue single calls like:</p>
<pre>logger.info('Ingesting data file: %s', data_file)</pre>
<p>and this information will automatically be written out to both the DEBUG and the INFO log files if we have set them up.</p>
<p>In our situation it makes sense to write out three log files for quick perusal by authorized personnel:</p>
<ul>
<li>~_DEBUG.log — for programmers needing to debug what went wrong</li>
<li>~_INFO.log — for managers trying to understand the overall situation</li>
<li>~_ERROR.log — (hopefully zero length!) for programmers and managers</li>
</ul>
<p>These files get written to a uniform directory every time a data processing script runs with the ‘~’ replaced by the name of the processing script.</p>
<h2>Wrapping futile.logger</h2>
<p>Luckily, most of the functionality we need is provided by futile.logger package (<a target="_blank" href="https://cran.r-project.org/web/packages/futile.logger">CRAN</a> or <a target="_blank" href="https://github.com/zatonovo/futile.logger">github</a>). Unfortunately, this package does not currently support multiple “appenders” per “logger” so we found ourselves initializing multiple named loggers to mimic the natural behavior of Python’s logging module:</p>
<pre># Only FATAL messages go to the console
dummy &lt;- flog.threshold(FATAL)

# Set up new log files
if ( file.exists(DEBUG_LOG) ) dummy &lt;- file.remove(DEBUG_LOG)
dummy &lt;- flog.logger(&quot;debug&quot;, DEBUG, appender.file(DEBUG_LOG))

if ( file.exists(INFO_LOG) ) dummy &lt;- file.remove(INFO_LOG)
dummy &lt;- flog.logger(&quot;info&quot;, INFO, appender.file(INFO_LOG))

if ( file.exists(ERROR_LOG) ) dummy &lt;- file.remove(ERROR_LOG)
dummy &lt;- flog.logger(&quot;error&quot;, ERROR, appender.file(ERROR_LOG))

# Silence other warning messages
options(warn=-1) # -1=ignore, 0=save/print, 1=print, 2=error</pre>
<p>Then, inside the code, we created logging and error handling blocks like this:</p>
<pre>if ( class(result)[1] == &quot;try-error&quot; ) {
    err_msg &lt;- geterrmessage()
    flog.error('Error creating SpatialPoitnsDataFrame: %s', err_msg, name='debug')
    flog.error('Error creating SpatialPointsDataFrame: %s', err_msg, name='info')
    flog.error('Error creating SpatialPointsDataFrame: %s', err_msg, name='error')
    stop(err_msg)
  }
  ...
  flog.info('Using rgdal::writeOGR to create geojson file %s', filename, name='debug')
  flog.info('Using rgdal::writeOGR to create geojson file %s', filename, name='info')</pre>
<p><strong>Yuck!</strong></p>
<p>After writing just a few lines like this we tried a different approach and came up with a simple <a target="_blank" href="https://gist.github.com/jonathancallahan/a03b9ee7c1817d74803447856c64e518">py_logging.R</a> script that can be used to wrap futile.logger calls and give us the python style behavior we want. Setup is a cinch:</p>
<pre>source('py_logging.R') # python style logging

# Set up logging
logger.setup(debugLog, infoLog, errorLog)

# Silence other warning messages
options(warn=-1) # -1=ignore, 0=save/print, 1=print, 2=error</pre>
<p>And logging is much more natural:</p>
<pre>if ( class(result)[1] == &quot;try-error&quot; ) {
    err_msg &lt;- geterrmessage()
    logger.error('Error creating SpatialPointsDataFrame: %s', err_msg)
    stop(err_msg)
  }
  ...
  logger.info('Using rgdal::writeOGR to create goejson file %s', filename)</pre>
<p>Output from our logger looks great!</p>
<pre>INFO [2016-08-24 10:11:54] Running process_data.R version 0.1.5

INFO [2016-08-24 10:11:54] Working on /home/data/location/datafile_1.RData
INFO [2016-08-24 10:11:55] Found 1232 data columns
INFO [2016-08-24 10:12:03] Working on /home/data/location/datafile_2.RData
INFO [2016-08-24 10:12:03] Found 103 data columns
INFO [2016-08-24 10:12:03] Working on /home/data/location/datafile_3.RData
INFO [2016-08-24 10:12:03] Found 44 data columns</pre>
<p>At the end of the day, we can only hope we have succeeded at one or another other of:</p>
<ul>
<li>Using painful emotions to cultivate wisdom, compassion, and courage</li>
<li>Communicating so as to encourage others to open up rather than shut down</li>
</ul>
<p>Best wishes for excellent logging!</p>
<p><div><div><div><div data-width="55" data-show-faces="false" data-send="true" data-layout="box_count" data-height="62" data-href="https://www.r-bloggers.com/python-style-logging-in-r/"></div></div><div><a data-url="https://www.r-bloggers.com/python-style-logging-in-r/" data-counturl="https://www.r-bloggers.com/python-style-logging-in-r/" data-count="vertical" data-text="Python style logging in R" class="twitter-share-button" data-via="rbloggers" href="https://twitter.com/share"></a></div><div></div></div><div></div></div>
<div>
<div>To <strong>leave a comment</strong> for the author, please follow the link and comment on their blog: <strong><a href="http://mazamascience.com/WorkingWithData/?p=1727"> R – Working With Data</a></strong>.</div>
<hr>
<a rel="nofollow" href="https://www.r-bloggers.com/">R-bloggers.com</a> offers <strong><a rel="nofollow" href="https://feedburner.google.com/fb/a/mailverify?uri=RBloggers">daily e-mail updates</a></strong> about <a title="The R Project for Statistical Computing" rel="nofollow" href="https://www.r-project.org/">R</a> news and <a title="R tutorials" rel="nofollow" href="https://www.r-bloggers.com/?s=tutorial">tutorials</a> on topics such as: <a title="Data science" rel="nofollow" href="https://www.r-bloggers.com/?s=data%20science">Data science</a>, <a title="Big Data" rel="nofollow" href="https://www.r-bloggers.com/?s=Big%20Data">Big Data, <a title="R jobs" rel="nofollow" href="https://www.r-users.com/">R jobs</a>, visualization (<a title="ggplot and ggplot2 tutorials" rel="nofollow" href="https://www.r-bloggers.com/?s=ggplot2">ggplot2</a>, <a title="Boxplots using lattice and ggplot2 tutorials" rel="nofollow" href="https://www.r-bloggers.com/?s=boxplot">Boxplots</a>, <a title="Maps and gis" rel="nofollow" href="https://www.r-bloggers.com/?s=map">maps</a>, <a title="Animation in R" rel="nofollow" href="https://www.r-bloggers.com/?s=animation">animation</a>), programming (<a title="RStudio IDE for R" rel="nofollow" href="https://www.r-bloggers.com/?s=RStudio">RStudio</a>, <a title="Sweave and literate programming" rel="nofollow" href="https://www.r-bloggers.com/?s=sweave">Sweave</a>, <a title="LaTeX in R" rel="nofollow" href="https://www.r-bloggers.com/?s=LaTeX">LaTeX</a>, <a title="SQL and databases" rel="nofollow" href="https://www.r-bloggers.com/?s=SQL">SQL</a>, <a title="Eclipse IDE for R" rel="nofollow" href="https://www.r-bloggers.com/?s=eclipse">Eclipse</a>, <a title="git and github, Version Control System" rel="nofollow" href="https://www.r-bloggers.com/?s=git">git</a>, <a title="Large data in R using Hadoop" rel="nofollow" href="https://www.r-bloggers.com/?s=hadoop">hadoop</a>, <a title="Web Scraping of google, facebook, yahoo, twitter and more using R" rel="nofollow" href="https://www.r-bloggers.com/?s=Web+Scraping">Web Scraping</a>) statistics (<a title="Regressions and ANOVA analysis tutorials" rel="nofollow" href="https://www.r-bloggers.com/?s=regression">regression</a>, <a title="principal component analysis tutorial" rel="nofollow" href="https://www.r-bloggers.com/?s=PCA">PCA</a>, <a title="Time series" rel="nofollow" href="https://www.r-bloggers.com/?s=time+series">time series</a>, <a title="finance trading" rel="nofollow" href="https://www.r-bloggers.com/?s=trading">trading</a>) and more...
<img height="1" alt="" width="1" src="http://feeds.feedburner.com/~r/RBloggers/~4/7GInFuXJPZs"></a></div>