
\documentclass[a4paper,10pt]{article}
\usepackage{listings,color,epsfig,amsmath,url}
\definecolor{codecolor}{rgb}{0.99,0.97,0.94} % color values Red, Green, Blue
\definecolor{commentcolor}{rgb}{0.1,0.5,0.1} % color values Red, Green, Blue
\definecolor{stringcolor}{rgb}{0.3,0.1,0.1} % color values Red, Green, Blue
\newcommand{\Code}[1]{\texttt{#1} }
\newcommand{\code}[1]{\Code{#1} }
\newcommand{\DB}   {\code{{MOOSDB}}}
\newcommand{\MA}   {\code{{MOOSApp}}}
\newcommand{\Ignore}[1]   {}



% Title Page
\title{Logging with \code{pLogger}}
\author{Paul Newman}


\begin{document}
\maketitle

\begin{center}
\epsfig{file=images/moose6.eps,width = 0.2\linewidth}
\end{center}

\section{Logging - \code{pLogger}}
The \code{pLogger} process is intended to record the activities of
a MOOS session. It can be configured to record a fraction of or
every publication of any number of MOOS variables. It is an
essential MOOS tool and is worth its weight in gold in terms of
post-mission analysis, data gathering and post-mission replay.

The configuration of \code{pLogger} is trivial and consists of
multiple lines with the following syntax:
\begin{center}
\code{Log} =  {\it{varname}} @ {\it{period}} $[NOSYNC],[MONITOR]$
\end{center}
where {\it{varname}} is any MOOS variable name and {\it{period}}
is the minimum interval between log entries that will be recorded
for the given variable. For example if
{\it{varname}}=\code{INS\_YAW} and {\it{period}} = 0.2 then even
if the variable is published at 20Hz it will only be recorded at
5Hz. The optional \code{NOSYNC} flag indicates that this variable
should not be recorded in the synchronous logs (see section
\ref{sec:LogTypes}). The optional \code{MONITOR} flag tells \code{pLogger} to send a notification if this variable isn't logged at least every 10 seconds. The notification occurs under the \code{MOOS\_DEBUG} variable. If you are running \code{iRemote} (which subscribes to this variable
automatically) you'll see a warning printed to the screen. This can be pretty useful when runnning
a complicated system and you really do want notification that an important variable isn't being logged (probably because the process producing the variable is kaput in some sense.)

\subsection{Logging Session}

The logger supports the notion of Logging Sessions. For each log session the Logger will create a new directory and place all the logged files within that directory. These are typically (see later sections) an alog file a slog file a system log file, a copy of the mission file (moos file) and if applicable a hoof file (if  \code{pHelm} is running). A new log session can be created by writing the variable \code{LOGGER\_RESTART} to the \code{MOOSDB} or if you are using \code{iRemote} by pressing shift-g.

\subsection{Log File Types}\label{sec:LogTypes}
The logger records data in two file formats - synchronous
(``slog'' extensions) and asynchronous (``alog'' extensions). Both
formats are ASCII text -- they can always be compressed later and
usability is more important than disk space. The two formats are
now discussed.

\subsubsection{Synchronous Log Files}
Synchronous logging makes a table of {\em{numerical}} data. Each
line in the file corresponds to a single time interval. Each
column of the table represents the broad evolution of a given
variable over time. The time between lines (and whether
synchronous logging is even required) is specified with the line
\begin{center}
\code{SyncLog}= {\it{true/false @ period}}
\end{center}
where {\it{period}} is the interval time.

If there has been no change in the numeric variable between
successive time steps then its value is written as \code{NaN}. It
is important to note that synchronous logs do not capture all that
happens - they sample it. Synchronous logs are designed to be used
to swiftly appraise the behaviour of a MOOS community by examining
numeric data in a tool such as Matlab or a spreadsheet. The
\code{MOOSData} Matlab script reads in these files and with a
single mouse click can display the time evolution of any logged
variable.


\subsubsection{Asynchronous Log Files}
Asynchronous logging is thorough. The mechanism is designed to be
able to record {\em{every}} delta to the MOOSDB. The use of the
period variable allows the mission designer to back off from this
ultimate limit and record variables at a maximum frequency. The
key properties of asynchronous can be enumerated as follows:
\begin{enumerate}
\item Records both string and numeric data
\item Records data in a list format - one notification per line
\item Entries only made when variable is written
\end{enumerate}
Asynchronous log files are designed to be used with a playback
tool (for example \code{uPlayback} or other purpose-built
executable). Although the handling of strings and numeric data
adds a slight overhead to such a program's complexity the utility
gain from being able to slow, stop and accelerate time during a
post-mission replay/reprocessing session is simply massive.

\subsection{System Log File}
There is a third kind of log file that is produced - a system log file (ylog). This file only contains
data contained in \code{MOOS\_SYSTEM} and \code{MOOS\_DEBUG} messages. The later can be written to by calling the \code{CMOOSApp::MOOSDebugWrite} method from any \code{CMOOSApp} derived class. The thinking behind the ylog files is that its pretty useful to be able to browse through
a text file of events to see when and if things went wrong in a mission. Processes can write to \code{MOOS\_SYSTEM} and or \code{MOOS\_DEBUG} if something happens which they think is salient. Think of this as \code{/var/log}.


\subsection{Dynamic Logging Configuration}
Post V7.0.1 releases of MOOS include a dynamic logging ability. External parties can, at run time request the logger to start logging 
particular (named) variables. The logger subscribes to messages called \code{PLOGGER\_CMD} (if the Logger is being run under the MOOS name ``pLogger'' otherwise subsitute the relevant name) and by correctly formatting the string data of this message dynamic logging can be invoked.

\begin{center}
\code{LOG\_REQUEST} =  {\it{varname}} @ {\it{period}} $[NOSYNC],[MONITOR]$
\end{center}

Note that this string format is identical to that found in the mission file modulo \code{LOG} being replaced with \code{LOG\_REQUEST}. Now dynamic logging sits naturally with ``alog'' (asynchronous) files but not so well with ``slog'' files. These files are easy to use(and hence popular)  because they are rectangular numerical array written to text file (easily parsed by Matlab's load command). But dynamic logging means that by the time a mission ends an unknown number of variables (columns) will occur in every line of the slog. To address this issue the logger can be configured (in its mission file configuration block) with a line like

\begin{center}
\code{DynamicSyncLogColumns} =  30
\end{center}

Here 30 columns are being reserved for variables that are requested at run time. As dynamic requests are received and processed by the logger these unclaimed columns are consumed until none remain. At this point any future dynamic logging requests will still be accepted but the logged variables won't appear in the slog file (they will of course appear in the alog file). Unclaimed slots will be labelled \code{DYNAMIC\_X} until claimed and will always have \code{NaN} entries.


\subsection{Specifying Log File Names and Locations}

Each time the logger starts creates (if required) a new directory in the logging root directory(see below) and performs logging within that directory. \code{pLogger} is quite flexible in terms of log file configuration and is controlled by the following variables.

\begin{description}
\item{\code{GlobalLogPath}} This is a {\textbf{file scope variable}} (ie not in any process configuration block). If it is present in a mission file then it specifies the root directory in which log files will be created.
\item{\code{Path}} specifies the root logging directory but only used if \code{GlobalLogPath} is not set (see above).
\item{\code{File}} this is the stem file name given to logged files (alog/slog and ylog)
\item{\code{FileTimeStamp}} if this is set to true, the name of  each logged file and (created containing directory) will be the concatenation of the \code{File} variable and a time stamp. If \code{FileTimeStamp} is false then each time the logger is run it will write to the same set of log files {\textbf{and destroy the original contents}}. This is by design, when developing it's often useful to not have useless log files take ever more space on you machine.
\end{description}

Note that if the logger is run without a mission file it starts logging to the local directory with file time stamping enabled. See figure \ref{fig:LoggerConfig} for a typical logger configuration block.

If for some reason teh logger was unable to start logging to a location specified in the log file it trys, as a last resort, to open a log directory in the current working directory (`.'). If this fallback fails then all is lost, we are without hope and the Logger exits. If you are running a mission from pAntler you'llbe notified that the logger has quit.



\subsection{Mission Backup}
Simply having the {\it{alog}} and {\it{slog}} files is not enough
to evaluate the mission. One also needs the things that
{\em{caused}} the data to be recorded, namely the *.moos Mission
file and the *.hoof file (if Task redirection was used). To this
end the \code{pLogger} process takes a copy of these files and
places them (name appended with a time stamp if desired) within
the logging directory. The files extensions are renamed to
{\it{*.\_moos}} and {\it{*.\_hoof}} respectively.


\subsection{Example Configuration}
\begin{figure}[ht]\label{fig:LoggerConfig}
\begin{lstlisting}[]{}

//////////////////////////////////////////////
// Logger configuration block
ProcessConfig = pLogger
{
    //over loading basic params..lets be fiesty
    AppTick  = 20.0
    CommsTick   = 20.0

    //all file names begin with this stem
    File        = SciPark29Mar

    //where is the root log directory
    PATH        = /home/doe/MOOSData/SciencePark/

    //yes we want some sync logging for crude 
    //performance checking
    SyncLog     = true @ 0.2
    
    //yes we want async logging so we can replay
    // exactly what happened and record strings
    AsyncLog    = true
    
    //yes append each created directory log file 
    //with a time stamp DAY MONTH YEAR TIME
    FileTimeStamp   = true

    //what do we want to log 
    //(zero means capture everything)
    Log     = LMS_LASER_2D @ 0 MONITOR
    Log     = LMS_LASER_3D @ 0 MONITOR
    Log     = MARGE_ODOMETRY @ 0
    Log     = DESIRED_RUDDER @ 0
    Log     = DESIRED_THRUST @ 0
    Log     = CAMERA_GRAB @ 0
    Log     = GPSData @ 0.4

}

\end{lstlisting}
\caption{A Typical \code{pLogger} configuration block}
\end{figure}

\section{Runtime File Backup}
In Post 7.0.1 releases, by writing a correctly formatted string value to the MOOS variable \code{PLOGGER\_CMD} processes withing the MOOS community can request the logger to back up arbitrary files to the current log directory. For example if the contents of a message with name \code{PLOGGER\_CMD} is set to
\begin{center}
\code{COPY\_FILE\_REQUEST = /home/pnewman/code/TheFile.xzy}
\end{center}
 and published to the \DB  it will result in a copy of `/home/pnewman/code/TheFile.xzy` being placed in the logging directory under the name `TheFile.\_xzy`- note the additional underscore. If the file in question has no extension then `.\_bak` is added appended to the file name.



\section{Replay -- \code{uPB}}
There is a FLTK-based, cross platform GUI application that can
load in {\it{alog}} files and replay them into a MOOS community as
though the originators of the data were really running and issuing
notifications. A typical use of this application is to ``fake''
the presence of sensor processes when reprocessing sensor data and
tuning navigation filters. Alternatively it can be used in pure
replay mode perhaps to render a movie of the recorded mission. The
GUI allows the selection of which processes are ``faked''. Only
data recorded from those applications will be replayed from the
log files.  There is a single class that encapsulates all the
replay functionality - \code{CMOOSPlayback}. The GUI simply hooks
into the methods exported by this class. The GUI is almost self
documenting - start it up and hold the mouse over various buttons.

\begin{figure}
\center \epsfig{file=images/uPB.eps,width = 0.8\linewidth} \caption{A
screen shot of \code{uPB} - a cross platform ``alog'' playback
tool}
\end{figure}

A client process can control the replay of MOOS messages by
writing to the \code{PLAYBACK\_CHOKE} variable add writing a valid
time in the numeric message field. The Playback executable will
not play more than a few seconds past this value before waiting
for a new value to be written. In this way  it is possible to
debug (halt inspect and compile-in-place etc) at source level a
client application using replayed data without having the playback
rush on ahead during periods of thought or code-stepping.

\end{document} 