Testing through logging

This article is based on the lecture of Sergey Alexandrov at the “Съесть собаку” meetup.

What is the problem?

If you compare a program to a living organism, a bug in it would qualify as a disease. The occurrence of the ‘disease’ may be affected by a number of factors and a specific environment, especially if we consider a web-platform as a launch. Sometimes cause-effect is very complex and the bug found during testing is a result of a few events.

Similar to human illnesses where only a patient will describe their symptoms most accurately, no QA Engineer is able to identify what happened, better than the program can.

What to do?

For the program to be able to let us know what’s wrong with it, we will get a couple of ready-to-use free solutions — ElasticSearch, LogStash and Kibana — and bind them together.

ElasticSearch, LogStash and Kibana

ElasticSearch — self-adjusting database with a decent text search. Here you can check the ElasticSearch tutor.

LogStash — synchronizer with ElasticSearch and logs collections from sources.

Kibana — web-interface with many add-ons.

All three services are free. They are easily set up and work out of the box.

We will also need a logger and some of the customized code, in order to link all the components together with our app.

How does it work?

Logger and customized codeOur application saves logs on a server. LogStash incrementally transfers data to ElasticSearch into a database. The user enters Kibana and sees their saved logs.

A well-adjusted Kibana can display data as tables, graphs, maps etc.

Case #1

Let’s try to log the app for the sake of decreasing testing time.

Our case was a social network – in real time, served on sockets, with lots of services and data. The base for the app will be React + Redux, but generally the logging approach is not linked to a framework.

What to do?

  1. Select a logger.
  2. Create a class for storing user actions, preceding an error.
  3. Log interactions with the server.
  4. Log socket connections.
  5. Send the data to ElasticStack.

Let’s select a logger for our app. If this is backend, it’s best to use Winston. For the frontend we take JS-logger, because it supports basic logging methods — log, info, warn, debug, error.

 The logger is supposed to transfer data into collection with a limit. If we exceed the limit, the first element will be deleted. This was done to avoid sending too large data.

export default class CollectionWithLimit {

    constructor(props) {
        this.limit = props.limit || 10;
        this.data = [];
    }
    checkLimit() {
        if (this.data.length === this.limit) {
            this.data.shift();
            return true;
        }
    }
    add(data) {
        this.data.push(data);
        return this.checkLimit();
    }
}

We can add metadata into the stack: current language, localization, current subject, information about browser and system, latest activities, userID.

UserID is important because thanks to it we will understand which QA engineer made an error.

this.stack.session.start = getCurrentDateISO();
this.stack.actions = actions;
this.stack.env.lang = lang;
this.stack.env.href = href;
this.stack.env.localization = getItem('localization');
this.stack.env.theme = getItem('theme');
this.stack.env.userID = getItem('userID');

In our case we used Redux. It allows us to import into code logger through middleware and that significantly simplifies data collection. Redux prefix allows to identify the layer of the app, where the mistake was made. We record the type of action and tag it as Redux, as well as the data that was received with the action.

const logActionsMiddleware = store => next => action => {
    let payload = Object.keys(action)
            .filter(key => key !== 'type')
            .reduce((payload, key) => {
                payload[key] = action[key];
                return payload;
        }, {});
    logger.log(`redux|${action.type}|${JSON.stringify(payload)}`);
    return next(action);
};

To cover our server with logs we’ve used Axios. It lets putting middleware into processing of all the requests.

We’ll pin our logger to all the server errors. Now these requests are processed and if the server is dead or sent something wrong, we will know about it.

rest.interceptors.request.use(
    config => config,
    error => {
        if (error.message) {
            logger.error(error.message);
        }
        return Promise.reject(error);
    }
);
rest.interceptors.response.use(
    response => response.data,
    error => {
        if (error.message) {
            logger.error(error.message);
        }
        return Promise.reject(error);
    }
);

The thing with sockets is easy. According to the contract we agree that every message will have its status. If the status was received with an error, we process it.

this.socketManager.io.on(SOCKET_EVENTS.NOTIFICATION, notification => {
    if (notification.status === 'error') {
        logger.info(`socket|Error ${notification.message}`);
        this.props.onAuthUpdate();
    }
    else {
        this.props.onAddNotification(data);
    }
});

Let’s not forget to:

  • Use clear messages;
  • Separate complex algorithms and mix them with logs;
  • Avoid overload of logs;
  • Log components, especially errors.

If necessary, we can insert logs into components in catch methods of React.

We recommend to indicate the component name to see in a minified version, in which of the elements the error occurred.

    static displayName = 'MyComponent';
    ...
    componentDidCatch(err) {
        logger.error(`react.${this.displayName}|${err.toString()}`)
    }

Complex algorithms should be mixed with logs, covering the bottle necks of the app. Then we sign up for onerror and in case of an error send the info with all the data from the stack to our Elastic.

window.onerror = (errorMsg, url, lineNumber, lineCount, trace) => {
    // create critical error
    let critical = {};
    critical[CRITICAL] = serializeError(trace, lineNumber);
    let criticalData = mixParams.call(this, critical, true);
    this.stackCollection.add(criticalData);
    // get stack data
    let stackData = this.getStackData();
    // send log to server
    this.sendLogToServer(stackData);
};

What we got?

  •  We save all the actions, preceding the error and attach metadata.
  • When the error occurred, the data is sent to Elastic.
  • The QA engineer who found an error, attached an ID to the ticket with an error.
  • We enter Kibana, filter by ID, realize which actions took place and fix the bug.

 All of this sounds good, but still not great. There is no backend data, the info isn’t very detailed. In the next example we’ll show how to make it awesome.

Case #2

Let’s develop the approach mentioned above.

What can we do on the project without any Redux? There are 3 ways how to organize a quality application logging:

  1.  @ – decorators — a way to turn our method into a function, in which we can log the state before the method execution and after it. This approach is suitable for legacy code.
  2.  Proxy — a great option to integrate any code into interactions methods with an object. Unfortunately, it is not supported by all the browsers.
  3.  Writing code with logs from the start — a good option in development from scratch. In such a case you won’t miss a thing and the code will be covered by logging to the limit.

If a QA engineer doesn’t understand the action — it is a bug that must be rewritten. In addition, not all the errors lead to critical outcomes. For this purpose, at the staging phrase we can create a button in a header for the forced sending of logs. The QA engineer in that case can see that something is not working right, clicks the button and triggers the same action as on onerror.

a button in a headerIf a critical error has occurred anyway, we have to block interface for the QA engineer to stop clicking further and hitting the wall.

window.onerror = (errorMsg, url, lineNumber, lineCount, trace) => {
...
    // show BSOD
    let bsod = BSOD(stackData);
    document.body.appendChild(bsod);
...
};

If a critical error has occurred during staging, we display the blue screen of death.

At the top we see text with the stack of this critical error, and at the bottom — actions preceding it. Also we get ID errors, so it would do for a QA engineer to highlight it and attach it to the ticket.

ID requestsOur application closely interacts with backend. We’ve recorded the backend from the word go and covered it with logging as well. For that we used Winston + record to the file through Express middleware. Logstash parses logs from the file and sends them to ElasticSearch. To bind the logs of backend and frontend together we can generate ID sessions and send them in a header of every request.

rest.defaults.headers.common.sessionId = global.__session_id__;

Now we have an understanding: we sent a request and this request is executed on a server. We receive a response, continue our work on a client. In Kibana we will filter by ID requests and check what happens.

Whenever we send actions stack to Elastic, a QA engineer receives an ID and attaches it to the ticket.

What we got

  • We save actions preceding to the error in our limited collection, gather metadata on the app.
  • We link session from frontend to backend through request headers.
  • We block interface through the blue screen of death, if a QA engineer sees an error.
  • We display an error button on demand.

Log your apps at a production stage included, because no QA engineer will find bottle-necks better than real users.

Alternatives

I suggest the following alternative approaches:

  • A well-adjusted Rollbar which allows to log 500 thousand errors for $150 a month. I recommend to use it in case you develop apps from scratch.
  • Sentry that is easier in integration but less customizable. Allows to log 1 million events for $200 a month.

Both of the services allow to do basically the same as well as integrate to backend.

What’s next?

Logging is not only an error search, but also monitoring of user actions and data collection. Logging can serve as a good addition to Google Analytics and a checkup of User Experience.

Summary

When you release an application, its life is at a very start. Don’t forget about it: gather feedback, track logs and improve your app. Write high quality software and prosper :)

Leave a Reply

Your email address will not be published. Required fields are marked *

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>