Nodejs logging specification

The general front end development students, in fact, not too sensitive to the log, after all, the front end in most cases, do not care too much about the log. Even if there is, it is possible to call some third party statistics, such as Baidu statistics or other statistics. In the process of node.js (hereinafter referred to as Node), we also found that we were too random to type the log. The log was not typed, and some key logs lacked necessary context information, which made it very difficult to locate problems online.

This article focuses on the current problems with logging in nodeJS development and what we hope to achieve by unifying the logging specification.

The problem

  • The Node log is not standard, and the log is too arbitrary
  • There is no good log format, convention field, inELKIs not very good parse & retrieval (PS:ELKArticle on the way)
  • Because the backend connected to Nodes is servified, the invocation chain is not clear, making it difficult to locate problems
  • There is no clear record of node log usage by the data department. The node modifies the log, resulting in abnormal statistics

The target

  • Standardize log print fields & formats for ease of useELKretrieve
  • Enhanced node upstream and downstream (NGINx/backend) log format to include uniquerequestId, which is convenient for locating problems under micro-services
  • Collect application running status and performance data
  • Maintains the data department’s use of Node logs

Implementation scheme

Log type

Referring to some logging best practices, Node logs are currently divided into the following types (scopes) :

  • desc: Logs generated during system startup and operation, indicating that some startup logs and startup parameters of the system are also included in the logs generated when the HTTP context cannot be captured
  • stat: system performance statistics logs. Applications periodically collect performance information to query the current application status
  • visit: The log associated with each HTTP request contains a unique requestId that locates all logs associated with that request
  • biz: Logs related to service data, which are used for data statistics

The level of logging

Only the FATAL, ERROR, WARN, INFO, and DEBUG levels are used.

  • FATAL – FATAL system level errors that cause program exits. When errors occur, the system administrator needs to intervene immediately. Application code is not used.
  • ERROR – Runtime exceptions and unexpected errors that also need to be handled immediately, but with less urgency than FATAL. When errors occur, they affect the correct execution of the program. It should be noted that these two levels are errors of the service itself and require the intervention of the administrator. User input errors do not belong to this category. Requests to the back end, file reading, and database timeout and return ERROR structures belong to ERROR
  • WARN – Unexpected runtime conditions that indicate a possible problem with the system. It is also WARN for conditions that are not currently errors, but could become errors if not handled promptly, such as low disks.
  • INFO – A meaningful event that records the normal running status of a program, such as a request received or successfully executed. You can quickly locate WARN, ERROR, and FATAL by viewing INFO. The amount of INFO should not exceed 10% of DEBUG.
  • DEBUG – Details related to the process in which the program is running and the current state of variables.

Log format/field

The log format is JSON, which facilitates ELK parsing and processing.

The values of each field in logs should be in English rather than Chinese.

Specific log fields are classified into basic data and extended data. The basic data is inherent to the underlying logging framework and is included in all logs. Extended data, different types of logs, containing different fields.

Basic Log Data

The current node-bunyan log library is an official document with the following basic fields:

  • V: an integer. Bunyan log version number
  • Level: an integer. Number of a log level
  • Name: string. The service name
  • The hostname: string. The host name
  • Pid: an integer. Process of no.
  • Time: string. Date in UTC format
  • MSG: string. Log Subject Information

Log extended data

The following defines extended data for each data type, not all fields, but only the required fields for the log type. These required extension fields need to be indexed in ELK to facilitate the location of various problems.

  1. descType log, extended field: TODO
  2. statType log, extended field:{ perf: {rss: xxxx, cpu: xxx} }
  3. visitType log, extended field:
  4. biz
{
    ///////////// Basic data ////////
    v: 1.level: 20.///////////// Extended field ////////
    // indicates the log type
    scope: "visit".// Event type: Different events are subdivided under the visit log type, such as client-req, client-res, plain trace, request back end service-start, service-end, and service-err.
    event: "trace".// Client ID to track user and device sessions. On the Web side, it can be a persistent cookie; On the APP side, it can be device-ID, etc
    rrdid: "".// The unique ID of this request, concatenating all related logs for this request
    req_id: "some-uuid-for-request".// User ID for this request
    uid: "".// The client data of this request will be added automatically when logging through ctx.logger
    d: {
        url: "/some/path? include-query".// Client IP address
        ip: "10.138.10.1".// The client's userAgent
        ua: ""
    },
    // The processing time of this node request is milliseconds
    tm: 500.// The context data related to the log, try to spell a string, put in extra
    extra: "".// Error-level logs, preferably containing error-related information, such as parameters related to the request backend
    err: {
        msg: "".stack: ""
    },

    // Invoke backend service parameters and responses
    service_req: {
        host: "".path: "".payload: ""
    },
    service_res: {
        / / HTTP status code
        http_code: 200.// Response time
        tm: 100.// The body of the response
        body: "".// Exception information
        err: ""}}Copy the code

When should I log in

Developers currently only care about logs of the VISIT type, those associated with a particular HTTP request. Desc and STAT logs are encapsulated by the development framework and implemented. Service development does not care about them. The following describes logs of the VISIT type.

An HTTP request prints a series of associated logs. At the Node layer, a request is typically forwarded to N back-end services, which then do some processing, merging, etc., to render a page or output JSON. Therefore, logs related to a request are generally divided into the following events:

  • client-req: Client request arrives node layer, unified by the framework log, developmentDon’tCare about
  • service-start: Node sends a request to a back-end service. The common request library is responsible for logging and developmentDon’tCare about
  • service-end: Node requests the end of a back-end service, and the common request library is responsible for logging and developmentDon’tCare about
  • service-err: Node request back-end service exception, by the general request library is responsible for log, developmentDon’tCare about. Description The log level was as follows: Failed to invoke the back-end serviceWARN.not ERROR
  • trace: Logs made by the service layer in node. If an exception occurs, the logs help locate problems related to the request
  • client-res: Finishes the client request, prints the HTTP code of the request, and the processing time of the requestDon’tCare about

When logging, developers should carefully select the level of information (including INFO) or higher, which should have requirements for problem location and specific business statistics before logging. In most cases, the DEBUG level can be used and is not enabled online.

Concrete method call

To print visit logs, call the CTx. logger(KOA-based framework) attribute to log. It is recommended that all parameters be passed JSON. The specific method is as follows:

ctx.logger.debug({msg: ""."extra": "a=1 b=2 c=value"});
ctx.logger.info({msg: "xxx"."extra": "Additional fields"});
ctx.logger.warn({msg: "xxx"."extra": "Additional context data"});
//ERROR level logs should provide an ERROR object
ctx.logger.error({msg: 'xxx'.err: error, extra: ""});
Copy the code

Note 1. It is recommended to store extra parameters in the “extra” field and spell them as string. If it is necessary to separate each field, disallow additional parameters from the generic field names above!!

Note 2: The MSG field in the basic data is forbidden to contain specific context data. Context data related to the log should be put into a string and placed in a separate EXTRA field. For example, if a user logs in to an interface and wants to count the number of calls, it can print:

ctx.logger.info({msg: "user login"."extra": 'mobile=18712387101 code=xxxx k3=value3'});
Copy the code

The resources

  • Best Logging Practices (V2.0)
  • Practice summary of Node framework access to ELK
  • Dayso NodeJS log standardization and analysis monitoring
  • Please check list! What are some of these good journaling practices that you’ve followed?
  • Logging best Practices
  • When to use the different log levels
  • Java log management best practices
  • A few suggestions and non-best practices for log printing
  • Logging best practices