Log files are often the only way to identify and locate errors in a deployed system. This paper presents a new log file analyzing framework, LOGDIG, for checking expected system behavior from log files. LOGDIG is a generic framework, but it is motivated by logs that include temporal data (timestamps) and system-specific data (e.g. spatial data with coordinates of moving objects), which are present e.g. in Real Time Passenger Information Systems (RTPIS). The behavior mining in LOGDIG is state-machine-based, where a search algorithm in states tries to find desired events (by certain accuracy) from log files. That is different from related work, in which transitions are directly connected to lines of log files. LOGDIG reads any log files and uses metadata to interpret input data. The output is static behavioral knowledge and human friendly composite log for reporting results in legacy tools. Field data from a commercial RTPIS called ELMI is used as a proof-of-concept case study. LOGDIG can also be configured to analyze other systems log files by its flexible metadata formats and a new behavior mining language.
Log files are often the only way to identify and locate errors in deployed software
[
Our work originally started 15 years ago with a commercial Real Time Passenger Information System (RTPIS) product called ELMI. It included real-time bus tracking and bus stop monitors displaying time of arrival estimates. ELMI consisted of several mobile and embedded devices and a proprietary radio network. The system was too heterogeneous for traditional debugging, which led to log file analysis as the primary method. In addition, log file analysis helped discovering the behavior of some blackbox parts of the system, which contributed to the development of open ELMI parts.
The first log tools were TCL scripts that were gradually improved in an ad-hoc manner. The tooling fulfilled the needs very well, but the maintenance got complicated and the tools fit only for the specific system. This paper presents a new, general purpose log analyzer tool framework called LOGDIG based on the previous experience. It is purposed for logs that include temporal data (timestamps) and optionally systemspecific data (i.e. spatial data with coordinates of moving objects).
Large embedded and distributed systems generate many types of log files from
multiple points of the system. One problem is that log information might not be
purposed for error detection but e.g. for business, user or application context. This requires
capability to interpret log information. In addition, there can be complex behaviors like
a chain of sequential interdependent events, for which simple statistical methods are
not sufficient [
State-of-the art log analyzers connect the state transitions one by one to the log lines (i.e. events or records). LOGDIG has an opposite new idea, in which log events do not directly trigger transitions but events are searched for states by special state functions. The benefit is much more versatile searches and inclusion of already read old log lines in the searches, which is not the case in state-of-the-art. LOGDIG includes also our new Python based language Behavior Mining Language (BML), but this is out of the scope of this paper.
The new contributions in this paper are i) New method for searching log events for state transitions, ii) LOGDIG architecture and implementation iii) Proof-of-concept by real RTPIS field data.
This paper is organized as follows. Section 2 describes the related work and Section 3 the architecture of LOGDIG. Section 4 presents an RTPIS case study with real bus transportation field data. The paper is concluded in Section 5. 2
We focus on discovering the realized behavior from logs, which is required to figure out if the system works as expected. The behavior appears as an execution trace or sequential interdependent events in log files. The search means detecting events that contribute to the trace described as expected behavior.
A typical log analyzer tool includes metamodels for the log file information,
specification of analytical tasks, and engines to execute the tasks and report the results [
The most straightforward log analyzing methods is to use small utility commands
like grep and awk, spreadsheet like Excel or database queries. More flexibility comes
with scripts, e.g. Python (NumPy/SciPy), Tcl, Expect, Matlab, SciLab, R and Java
(Hadoop). There are also commercial log analyzers like [
Valdman [
LFA [
Yes (PPL)
BML By index not limited Multiple-pass
Yes
1 ES algorithm Limited (F,N,E)
Yes
Yes
LFA/LFA2
No
LFAL Only forward Single-pass
Yes Not limited
No Not limited Yes
Yes
3
The LOGDIG processing has two main phases: log data pre-processing and behavior mining. Pre-processing transforms the original log files into uniform, miningfriendly format, which is defined by our own Pre-Processing Language (PPL). PPL is not discussed further in this paper, but we use the common csv format with named columns as output of the transform. The behavior mining phase uses our BML language to define searching the events of expected behavior.
Logs may consist of rows of unstructured text that can be parsed with regular expressions (Python). Timestamp is mandatory in every line. Pre-processed logs are structured in rows and columns as csv files. The first row is header line that includes column (variable) names. The columns are row number, timestamp and log file specific data.
Sometimes analyzing needs systems specific utility data to make decisions in behavior mining phase. This is called System Specific Data (SSD) and it is not log data. SSD files can come from system documentation and databases without any standard structure and format as in our case study. SSD can be e.g. spatial data like position boundary boxes for bus stops in RTPIS. SSD is parsed using System Specific Code (SSC) written in Python. RESULT FILES (E.g.): -histograms -visualizations 17. WRITE EXTERNAL TOOL (E.g. Spreadsheet)
16. READ BEHAVIOR MINING STORAGE, BMS global variable dictionary 4. READ 12. READ
KNOWLEDGE RESULTS:
STATIC BEHAVIOUR KNOWLEDGE FILE (SBK) 15. READ
REFINED COMPOSITE LOG FILE (RCL) 11. WRITE
EVENT SEARCH UNIT’s, ESU’s ES algorithm
Base System code (BSC) Optional System
Specific Code (SSC) 8. READ
9. READ
PREPROCESSED LOGFILE
SYSTEM SPECIFIC DATA (SSD) FILES (E.g. position boundary boxes) 5. EXECUTE 6. BS PARAMS 7. SS PARAMS 10. Result: Found, Not found or Exit
BEHAVIOR MINING UNIT, BMU e c a ftr e n i U S E
Statemachine
State transition Functions
Composite Timetable for refined composite log Preprocessor for BMS variable names of state transition functions (3) 14. 13. 4. WRITE WRITE WRITE
2. READ Platform
Script language
(Python) Utility commands and
Operating system
Framework BMU library functions (Python) DATA FLOW
CONTROL FLOW Command line parameters: - BMS variables with values 1. EXECUTE
BML-language 3. 1) Init values of READ variables in BMS 2) Statemachine: ESU states and params 3) State transition functions
The detailed behavioral mining process is presented in Fig. 2. We first describe the concepts and functional units. There are two main functional units: Behavior Mining Unit (BMU) and Event Search Unit (ESU) and also one global data structure named as Behavior Mining Storage (BMS). There can be many ESU’s, one BMU and one BMS in LOGDIG.
BMS is a global and common dictionary type data structure, which includes variable names and their values used in LOGDIG. Initial BMS can be described in BMLlanguage or given in command line parameters. It is possible to add new variables and values to BMS on the fly. Used variables can be grouped as follows: command line, internal, and result variables. The result variables are grouped as identify, log, time, searched, calculated, counter, error flags and warning flag variables (See example in table 2). BMS can be implemented as shared memory structure wherein it is very fast and it can be used in many (external) tools and commands even in real time. BMU consists of five parts: pre-processor of variable names, state-machine, statetransition functions, ESU interface and composite timetable. Pre-processor converts variable names in state transition functions of a BML code to be used in Python. State machine is the main engine of BMU that is described in BML language. State transition functions are called from the state machine and they are also described in BMLlanguage.
ESU interface connects the state machine to ESU. It converts execute command and parameters suitable to ESU and converts the result of ESU for the state machine. The ESU interface can be modified depending on how ESU has been implemented and where it is located, compared to BMU. ESU can be a separate command line command and it can be even located on separate computers. This gives interesting possibilities for the future to decentralization and performance.
A composite timetable-structure is for the Refined Composite Log (RCL) file to collect together all time indexed “print”-notifications from state transitions. The timetable is needed because all searched data from log files are not always read in time (forwarding) order, because BMU has capability to re-read old lines from same log and also to read older line from other logs.
BML language presents the expected behavior with certain accuracy and it is straightforward representation of state machine, (ESU) states with input parameters and state transition functions. It can also include initialization of BMS variables and values. State transition functions can include Python code and BMS variables. Because BML is out of the scope of this paper, we do not go into details.
ESU is a state of the state machine and it includes state function which is named Event Search (ES) algorithm. ES algorithm includes a Basic System Code (BSC) and optionally a System Specific Code (SSC). The BSC is the body of ES algorithm and SSC is an extension to BSC. BSC reads Basic System (BS) parameters from the state machine and on their basis start searching from log. If SSC is in use (set in mode parameter), also System Specific (SS) parameters are read.
Base System (BS) parameters are needed to set the search mode, log file name expression, searched BMS log variable names, time column name, as well as start and stop time expressions for ES algorithm. System Specific (SS) parameters are used in SSC-part of ES algorithm. E.g. in case of spatial data like in our case study, SS parameters are: latitude and longitude column name and also SSD filename expression. Each search mode has the common task: searches an event between the start and the stop time (ESU time windows in figure 5) that values of variable names are same in log and BMS.
The search modes can be: • “EVENT:First”: Searches the first event from the log • “EVENT:Last”: Searches the last event from the log In the case of SSC, search modes can also be System Specific (SS) modes (as in our case study): • “POSITION:Entering”: Searches object’s entering position to boundary box area (desciped in SSD) from the log • “POSITION:Leaving”: Searches object’s leaving from boundary box area (described in SSD) from the log 3.1
The mining process is described in figure 2. The user of LOGDIG starts the BMU execution (1), which reads command line parameters (2) and BML language (3) as input. On their basis BMU writes (4) BMS variable values directly or via state transition function, and executes (5) ESU with search BS parameters (6). If SS mode is in use in current ESU, also SS parameters (7) are read. Then ESU reads (8) pre-processed log file. If SS mode in use, it reads also (9) SSD file. Then starts the searching.
After ESU has finished the searching, it returns (10) the result of the search, which can be “Found” (F), “Not found” (N) or “Exit” (E). If “Found”, ESU writes (11) found variables from the log file to the BMS variables. Then, BMU reasons what to do next based on the action attached to the result. This is described in BML language. Depending on the action, BMU runs possible state transition function which can read (12) BMS variables. Based on the action, a transition function may write one row to (13) RCL or (14) SBK knowledge-result files.
After that BMU normally executes (5) a new search by starting ESU with new parameters. BMU exits the mining phase if there are no searches left or “Exit” has been returned. “Exit” is a problem exception that should never happen, but if it occurs, user is notified and LOGDIG is closed cleanly.
When BMU has completed, the SBK file can be read (15) by an external tool (like spreadsheet) to write (17) better visualizations from the knowledge results. All tools supporting the csv format can be used. Another option is to read (16) directly data from the BMS variables by a suitable tool to write (17) other (visualization) knowledgeresults.
State transition functions can use framework BMU library functions, like setting and writing RCL and SBK files and also calculating time differences between timestamp. It is also possible to add new library-functions depending on the needs.
Because LOGDIG analyzer has been implemented in Python and it works on top of any operating system, all features of Python and the operating system can be used as a platform in BMU and ESU. 4
The real time passenger information system ELMI [
We have named the main requirement as EPT (Estimated Passing Time) to see when the bus pass the stop. The expected behavior can include one or more EPT’s.
Other definitions include RTAT (Real bus Theoretical Arrival Time), including bus number, line and monitor, as well as AD (Advanced or Delayed) compared to RTAT.
The sequence of requirements for one EPT case is: 1) a bus driver sent a login for a line in a bus terminal, 2) the bus started to drive from the terminal, 3) when the bus is in the line and if necessary (started, delayed or advanced of schedule) CCS calculated estimated waiting times and sent to target monitors, 4) the bus arrived to a bus stop and its monitor, and 5) COMSE removed the waiting time from monitor.
There are two SSD’s (System Specific Data) in this case: 1) customer’s requirement document that requires the error of estimation should be below 120 seconds and 2) boundary box areas of bus stop’s from database of ELMI-system.
Various EPT cases are processed by the LOGDIG state machine shown in Fig. 4. It can search and analyze all EPT’s in a time window of Expected Behavior (EB) for specific lines and monitor as described in Fig. 3. The time window can be set from the command line or BML language.
CCS_AD log BUS_LOGIN logs BUS_LOCAT logs COMSE log 00:00 03:00 Start T1
of Expected Behavior (EB)
EPT3
INPUT: Start time of EB or RTAT start time of ESU (T11)
EPT 4. Coords and times before and after stop (S4)
INPUT:Stop time of EB 2. Searchs LOGIN (S2) All logs: CCS, BUS, COMSE 2. LOGIN 3. START
ESU time windows 1. Searchs RTAT (S1) 3. Searchs START (S3) 4. Searchs REAL PASS (S4) 6. Searchs COMSE PASS (S5) 7. Searchs AD (S6) 1. RTAT
Behavior and ESU-states of the state machine of LOGDIG in EPT’s case is depicted in Fig. 5. Inputs of the EPT’s case (from T1 transition function or command line) are start time, stop time, line, max login (means maximum time from LOGIN to RTAT) and max rtat (means maximum time from RTAT to PASS) and also maximum error values (SSD 1: -120 – 120 seconds) for the estimations of CCS and COMSE. The sequence is following: • S1: Searches first RTAT message (inputs: line) from CCS_RTAT log file in given ESU time window (see Fig. 5): ─ On entry function (before searching), calls T11: Sets start time of ESU time window to search next RTAT message or original EB start time in first “round” of search ─ Found: Sets RTAT variables. Calls T2: Sets input variables for next state. ─ Not found: Calls T10: Prints final results. • S2: Searches first LOGIN message (inputs: log-type, bus, line, direction) from BUS_LOGIN log file in given ESU time window: ─ Found: Sets LOGIN variables. Calls T3: Sets input variables for next state. ─ Not found: Calls T4: Sets input variables for next state. • S3: Searches starting (leaving) place of the bus from terminal bus stop in given ESU time window from BUS_LOCAT log file (input: bus). This needs SSD 2 to check positions: ─ Found: Sets LOCAT variables. Calls T5: Sets input variables for next state. ─ Not found: • S4: Searches arriving place of the bus to the target bus stop in given ESU time window from BUS_LOCAT log file. This needs SSD 2 to check position: ─ Found: Sets LOCAT variables. Calls T6: Sets input-variables for next state.
Calculates the real passing time of the bus ─ Not found: • S5: Searches first BQD message (inputs: bus, line) from COMSE log file in given ESU time window: ─ Found: Sets BQD variables. Calls T7: Sets input variables for next state. ─ Not found: Calls T8: Sets input variables for next state. • S6: Searches last AD message (inputs: line, direction, bus) from CCS_AD log file in given ESU time window: ─ Found: Sets AD variables. Calls T9: Calculates errors of the estimated waiting time, writes one row to SBK file and writes RCL knowledge from the composite timetable structure to RCL file ─ Not found:
There are exit transitions in every ESU state if a problem reading a log file occurs, e.g. the file is missing or there is a syntax error. Variables and their values (BMS variables in Fig. 2) comes directly from the log files and the command line initialization parameters, but there are also result specific variables in the SBK files. Result variables of SBK file are set in almost every state and state transition function and they are added (by one row) to SBK file at the end of successfully analyzing of one EPT in the last transition (T9 in Fig. 4). RCL knowledge is written in almost every state transition function to the composite timetable-structure (see Fig. 2) and in T9 they are added to RCL file. Searching time windows in every state can vary depending on (initializing variables and) variable values (found events timestamps) given from previous states.
Time indexing and possibility to read already processed log lines is utilized in two ways. See the re-read between EPT1 and EPT2 in Fig. 3. When searching different log files, RTAT-message from CCS_RTAT log is read before LOGIN message from BUS_LOGIN log even though LOGIN (EPT requirement step 1) comes before RTAT (EPT requirement step 2) in time. This way we can limit the complexity of the search and analyze only certain RTAT and its line or monitor. Within the same log file, RTAT or AD messages in many EPT cases exist. If we want to analyze only one monitor and its line, we will re-read the old log lines. 4.1
The content of the SBK file in the ELMI case study is given in Table 2. There are described three example EPT’s (bus drives in line 2132 and towards bus stop monitor 1031), which are also shown in Fig. 6. We consider a more detailed reading of the first EPT (EPT1). At 6:24:31 (LOGIN_MSG) in the terminal, the bus driver (number111) has logged in to line 2132 and its direction 1. Then at 6:25:01 (DRIVE) the bus has started from the terminal. At 6:42:33 (RTAT_MSG) CCS has sent the first estimated arrival time (6:45:52, RTAT_VAL) to the monitor. At 6:45:03 (AD_MSG) CCS has sent the last time correction for the waiting time. AD_VAL -25 tells that the bus has been 25 seconds in advance of the schedule. At 6:45:40 (PASS) the bus has passed the bus stop that is the estimation of LOGDIG. COMSE has estimated the arrival time to be 6:46:02 (BQD_MSG). That means there has been 13s error (PASS_TIME_ERR) between the estimated arrival time (RTAT_AD_VAL: 6:45:27) and real arrival time (PASS: 6:45:40). The error to the COMSE estimation has been 22 seconds (BQD_TIME_ERR). Because absolute values of the errors are smaller than 120 seconds, error flag EPT_ERR is 0. Warning flags are 0, that means there have been found LOGIN and BQD messages from the logs. In this case the whole EPT has lasted from 6:24:31 (LOGIN_MSG) to 6:46:02 (BQD_MSG) in total of 21:31 minutes.
The same EPT’s has also been presented in a visual form in Fig. 6. The visual presentation has been generated from the SBK file using gnuplot and Tcl script language. The horizontal axis represents the time of day and the vertical axis time differences in relation to the passing time. The values can be directly found from the SBK variables numbers: 16-20. We can reason a few things in Fig. 6. Times between 14 EPT’s have been varied a lot. For example “LOGIN time” in about 8:00 – 9:00 and 16:00 - 17:00 seems to be smaller. These times are typically morning and afternoon rush hours. We see also that real waiting time values have been quite short time (RTAT time: 200s) in monitors, but that is because in this case the trip from the terminal bus stop to the monitor was quite short. Estimation of waiting times are seemed to work quite well, because error values (WT-error and BQD-error) are between +120 - -120 seconds in all EPT cases. These were quite normal results. Additionally traffic jams or other problems can also be easily see from the visual presentation like that.
All detected errors can later be explored statistically from SBK file to get more detailed information of causes of errors. For example bus, line and sign (bus stop) specific errors such as the following error percentages: BUS,463 = 1 / 24 = 4.2 % BUS,53 = 1 / 29 = 3.4 % LINE,2132 DIR 1 = 1 / 42 = 2.4 % LINE,2132 DIR 2 = 4 / 139 = 2.9 % SIGN,1033 = 1 / 62 = 1.6 % SIGN,1061 = 3 / 77 = 3.9 %
These kind of results gave valuable “feedback” knowledge to understand the real behavior of the system. The results also helped to fix bugs and behavior of the system and thus improve the quality of the system.
The execution time of analyzing of one bus line (2132 in this case study) was about 15 seconds using normal PC. There was at all 181 EPT’s in the analysis. Other EPT’s were for other bus stop monitors. The execution time depends on the amount of daily log data and analyzed bus line. There have been three key bus lines and its monitors used for analyzing the ELMI system.
LOGDIG can also be used to detect anomalies, like work flow error or low performance of the execution. For example, the work flow error can be checked by structure of the state machine, and the low performance by time window limits of the ESU’s. 5
We have introduced the LOGDIG analyzer framework that is capable to analyze very complex expected behavior from the logs. LOGDIG was motivated by the fact that there were no other tools flexible enough, even though LFA is very close to the needs. Visualizations and other statistical post-processing have been left out, since there are lots of them available.
LOGDIG is best suited for complex behavior problems, since the setup takes some time compared to e.g. simpler command line search tools. To improve the performance, the Python implementation can be further optimized or even written in compiled language, and the overall execution distributed. If the source log files are available in different machines, the ESUs can be distributed directly there.
In the future, LOGDIG could be used as a higher-level analyzer that uses lower level analyzers. For example, the event search algorithm can be replaced by e.g. LFA/LFA2. To conclude, LOGDIG fulfills the requirements for RTPIS kind of applications, and offers a flexible framework for other domains. 6