Notes about logs
Sooner or later, the work on information systems raises the subject of logs, which, in turn, raises the subject of data exchanged within the system.
Often, if it is not always, startups start building their own information systems. And, for various raisons, they don't pay attention to logs. By the time they realize the importance of the subject, it could be too late : their developers strive to keep the system running, but they become less and less successful. They need visibility over the system. They would like to review all the logging strategy. But this is an enormous amount of work and they don't have time. The company is struggling to keep its head above the water. There is no time, and no money, to invest into refactoring.
The architecture may not be adapted to the environmental's constraints. Or may be, some parts of the system are poorly implemented. But, in order to diagnose the causes of the problem, we need visibility. We need information about the system. Logs may be the best way to provide information. Good logs can provide valuable information for planning efficient intervention.
How to design good logs ?
In order to answer this question we should ask other questions :
When do we need to consult the logs ?
When we need information about the system’s behavior. Typically : something went wrong, and we need to find out why. Or we want to get synthetic data about the system in order to classify some priorities. That is, we need to consult the logs any time we need information about the system’s behavior. Therefore, the next question is :
What defines the global behavior of a system ?
The system’s global behavior results from :
- The interactions of all the parts that make up the system.
- The interactions between the system and the outside world.
Therefore, before we can give an answer to the question « How to design good logs ? » we need to describe the interactions within the information system and the interaction between the system and the outside world.
This study will allow us to describe the « main content » of the logs’ messages.
So let’s talk about systems.
Often, if it is not always, when we start talking about logging system, developers adopt the paradigm that characterise the information system they are working on. For example, if their information system is based upon the WOA paradigm (Web-oriented architecture), then they use the expressions "WEB services", requests...
That's all right. But there are many paradigms. For example, WOA is just one declination of SOA (Service Oriented Architecture) among others. And, if you take some distance from the information system's point of view, you realize that SOA is just a projection of some more general concepts.
So let's take some distance with the SOA paradigm. Let's try to formulate the issue regardless of a specific application.
The general issue is :
We have a system.
- This system has an interface that sperates what's within the system from the outside world.
- Whitin the system we have « functional units » (FU). Some functional units interact only with other functional units. Other function units may as well interact with the system’s outside world (through the system’s interface).
- Functional units interact with each other through « requests ». One functional unit requests another functional unit, through an internal interface, to perform a task. Requests may be synchronous or asynchronous.
- When a functional unit performs a synchronous request to another functional unit, it waits for a response. The requested functional unit performs the required task and emit a « response ». Please note that we simply use the word « request » to refer to a synchronous request.
- When a functional unit performs an asynchronous request to another functional unit, it waits for an acknowledgement. The requested functional unit receives the request and informs the requester that it received it. The requester does not wait for the requested task to be done. The task will eventually be done in the future.
- Functional units that interact with the system’s outside world may interact in two ways.
- Through an entry point (EP). Actions from the outside world to the system go through entry points. We will use the words « incoming action » to refer to an action from the outside world to the system through an entry point. In the same way as for requests, we can distinguish between « incoming synchronous actions » and « incoming asynchronous actions ».
- An « incoming synchronous action » from the outside world to the system (through an entry point) triggers an « outgoing reaction ». Please note that we simply use the words « incoming action » to refer to an « incoming synchronous action ». Please not that the outgoing reaction is sent through the same entry point (that the incoming synchronous action went through).
- An « incoming asynchronous action » from the outside world to the system (through an entry point) triggers an « outgoing acknowledgement ». Please not that the outgoing acknowledgement is sent through the same entry point (that the incoming asynchronous action went through).
- Through an exit point (XP). Actions from the system to the outside world go through exit points. We will use the words « outgoing action » to refer to an action from the system to the outside world. In the same way as for requests, we can distinguish between « outgoing synchronous actions » and « outgoing asynchronous actions ».
- An « outgoing synchronous action » from the system to the outside world (through an exit point) triggers an « incoming reaction ». Please note that we simply use the words « outgoing action » to refer to an outgoing synchronous action. Please note that the incoming reaction passes through the same exit point (that the outgoing synchronous action was performed from).
- An « outgoing asynchronous action » from the system to the outsite world (through an exit point) triggers an « incoming acknowledgement ». Please note that the incoming acknowledgement passes through the same exit point (that the outgoing asynchronous action was performed from).
- An « outgoing synchronous action » from the system to the outside world (through an exit point) triggers an « incoming reaction ». Please note that we simply use the words « outgoing action » to refer to an outgoing synchronous action. Please note that the incoming reaction passes through the same exit point (that the outgoing synchronous action was performed from).
An observer located outside the system only see the entry points and the exit points. He has no knowledge about the « functional units ».
Let’s review the concepts expressed earlier. The global behavior of a system results from interactions:
- Interactions between function unit:
- (Synchronous) request / response.
- Asynchronous request / acknowledgement.
- Interactions between the outside world and the system may result from another system (located in the outside world, from the system’s point of view), or from the system itself.
- Interactions that result of an action of the « outside world » to the system itself (through an entry point):
- (Synchronous) incoming action / outgoing reaction.
- Asynchronous incoming action / outgoing acknowledgement.
- Interactions that result of an action of the system itself to the « outside world » (through an exit point):
- (Synchronous) outgoing action / incoming reaction.
- Asynchronous outgoing action / incoming acknowledgement.
- Interactions that result of an action of the « outside world » to the system itself (through an entry point):
The following image resumes and illustrates the concepts previously introduced.
This schema represents a system composed of 9 functional units (FU1, FU2…). The system interacts with 4 other systems: « Client », « Big Client », « Google » and « Yahoo ».
Next, we will focus on data needed to manage the log messages.
First, let's make some assumptions :
- We consider that the messages may not be saved in the order in which they are issued.
- We consider that the tool used to transport and save the messages is reliable, in the sense that no message is lost.
The first assumption is inevitable : in large information systems it is impossible to guarantee that logs are saved in the order in which they are issued. This assumption implies that we need to include into each message data that will be used to reconstruct the flow of messages as it should (chronologically) be.
The second assumption implies that redundancy is not necessary in order to ensure resilience : we don't have to inject the same data into distinct messages in order to ensure that the information is correctly saved, despite the loss of a certain proportion of messages.
That said, here is the data that should be included in the messages :
- A timestamp, that represents the date of the message.
- An incoming action ID. This value identifies a « (synchronous or asynchronous) incoming action » on the system, through an entry point. This ID is generated by the entry point (since the system that performed the action may not provide an ID). All messages that were issued in response to the same (synchronous or asynchronous) incoming action have the same incoming action ID.
- A request's ID. If the message results from the treatment of a « (synchronous or asynchronous) request » (issued by a functional unit to another functional unit), then this value identifies the « request ». Please note that for messages issued by the entry point that was the target of an « (synchronous or asynchronous) incoming action » to the system, this value is not defined.
- An order number. This value represents the position of a message within the flow of messages in relation to a functional unit's execution. It allows the reordering of messages in case messages are not guaranteed to be saved in the order in which they are issued.
- An environment ID. Several instances of a given functional unit may be installed in different environments. Typically, the same WEB services may be installed on several servers. This value is used to create a mapping between functional and physical topology.
- A type. The type of a message may be:
- For « behavior related messages »:
- REQUEST / RESPONSE: a synchronous request triggers a response.
- A-REQUEST / ACK: a synchronous request triggers an acknowledgment
- I-ACTION / O-REACTION: an incoming synchronous action triggers an outgoing reaction.
- IA-ACTION / O-ACK: an incoming asynchronous action triggers an outgoing acknowledgment
- O-ACTION / I-REACTION: an outgoing synchronous action triggers an incoming reaction.
- OA-ACTION / I-ACK: an outgoing asynchronous action triggers an incoming acknowledgment.
- For « informative messages »:
- DEBUG: debug messages
- INFO: informative messages.
- WARNING: warning messages.
- ERROR: error massages.
- FATAL: messages that carry fatal errors.
- For « behavior related messages »:
- A body that contains « functionnal data ». The content of this message’s part depends the the message’s type. The bodies’ contents will be discussed in the next sections.
The following JSON structure presents the message’ structure :
{
"timestamp":...,
"actionId":"...",
"requestId":"...",
"order":...,
"environnement":"...",
"type":"...",
"body":{
...
}
}
}
The body of a message of type REQUEST must contain:
- a unique ID that identifies the request.
- an ID that identifies the functional unit of destination.
all the data sent to the functional unit of destination.
"body":{ "requestId":"theRequestId", "addressee":"calledFU", "data":{ ... } }
The body of a message of type RESPONSE must contain:
- the unique ID that identifies the request that triggered the response.
- the status of the operation triggered by the request to the functional unit. The value can be : SUCCESS, WARNING, ERROR or TIMEOUT.
all the data returned by the called functional unit to the caller.
"body":{ "requestId":"theRequestId", "status":"SUCCESS", "data":{ ... } }
The body of a message of type « (synchronous or asynchronous) incoming action » (I-ACTION, IA-ACTION) must contain:
- all the data sent to the entry point (by aother system).
an ID that identifies the (other) system that performed the action.
"body":{ "id":"myClient", "data":{ } }
The body of a message of type « outgoing reaction » (O-REACTION) or « outgoing acknowledgement » (O-ACK) must contain:
- the status of the operation. The value can be : SUCCESS, WARNING, ERROR or TIMEOUT.
all the data sent through the entry point (to another system).
"body":{ "status":"SUCCESS", "data":{ ... } }
The body of a message of type « (synchronous or asynchronous) outgoing action » (O-ACTION, OA-ACTION) must contain:
- a unique ID, set by the exit point that performed the action, that identifies the action.
- an ID that identifies the (other) system of destination.
all the data sent through the exit point (to another system).
"body":{ "actionId":"theOutGoingActionId", "addressee":"Client", "data":{ ... } }
The body of a message of type « incoming reaction » (I-REACTION) or « incoming acknowledgement » (I-ACK) must contain:
- the unique ID that represents the « (synchronous or asynchronous) outgoing action » that triggered the incoming reaction or acknowledgement.
- the status of the operation. The value can be : SUCCESS, WARNING, ERROR or TIMEOUT.
all the data sent to the exit point (by another system).
"body":{ "actionId":"theOutGoingActionId", "status":"SUCCESS", "data":{ ... } }
The body for all types of informative messages depends on the information within the message. There is no predefined structure to describe this information.
"body":{
...
}{
"timestamp":1419767441,
"actionId":"randomValue",
"requestId":"",
"order":1,
"environnement":"Paris-1",
"type":"I-ACTION",
"body":{
"id":"myClient",
"data":{
}
}
}
{
"timestamp":1419767000,
"actionId":"randomValue",
"requestId":"",
"order":1000,
"environnement":"Paris-1",
"type":"O-REACTION",
"body":{
"status":"SUCCESS",
"data":{
...
}
}
}
{
"timestamp":1419767441,
"actionId":"randomValue",
"requestId":"",
"order":1,
"environnement":"Paris-1",
"type":"IA-ACTION",
"body":{
"id":"myClient",
"data":{
...
}
}
}
{
"timestamp":1419767000,
"actionId":"randomValue",
"requestId":"",
"order":1000,
"environnement":"Paris-1",
"type":"O-ACK",
"body":{
"status":"SUCCESS",
"data":{
...
}
}
}
{
"timestamp":1419767450,
"actionId":"randomValue",
"requestId":"theRequestId",
"order":10,
"environnement":"Paris-3",
"type":"O-ACTION",
"body":{
"actionId":"theOutGoingActionId",
"addressee":"Client",
"data":{
...
}
}
}
{
"timestamp":1419767480,
"actionId":"randomValue",
"requestId":"theRequestId",
"order":10,
"environnement":"Paris-3",
"type":"I-REACTION",
"body":{
"actionId":"theOutGoingActionId",
"status":"SUCCESS",
"data":{
...
}
}
}
{
"timestamp":1419767450,
"actionId":"randomValue",
"requestId":"theRequestId",
"order":10,
"environnement":"Paris-3",
"type":"OA-ACTION",
"body":{
"actionId":"the-OA-ActionId"
"addressee":"Google",
"data":{
...
}
}
}
{
"timestamp":1419767480,
"actionId":"randomValue",
"requestId":"theRequestId",
"order":10,
"environnement":"Paris-3",
"type":"I-ACK",
"body":{
"actionId":"the-OA-ActionId",
"status":"SUCCESS",
"data":{
...
}
}
}
{
"timestamp":1419767700,
"actionId":"randomValue",
"requestId":"see note",
"order":1,
"environnement":"Paris-1",
"type":"REQUEST",
"body":{
"requestId":"theRequestId",
"addressee":"calledFU",
"data":{
...
}
}
}
Note about the key « message.requestId » Please note that for messages issued by the entry point that was the target of an « (synchronous or asynchronous) incoming action » to the system, this value is not defined. For messages issued by any other of other interface (exit points or internal interfaces), then this value is not empty. In the latter, the key’s value is the ID of the request (between functional units) that triggered the actual request.
{
"timestamp":1419767484,
"actionId":"randomValue",
"requestId":"theRequestId",
"order":10,
"environnement":"Paris-3",
"type":"RESPONSE",
"body":{
"requestId":"theRequestId",
"status":"SUCCESS",
"data":{
...
}
}
}
