Match engine development: log output

Time:2020-1-4

Welcome to “Keegan small steel” public address for more articles.


Matchmaking engine development: the beginning

Match engine development: MVP version

Match engine development: data structure design

Match engine development: docking black box

Match engine development: decryption black box process

Match engine development: code implementation of process

Matchmaking engine development: caching and MQ


Log requirements

We all know that log plays an important role in a program, and matching engine also needs a perfect log output function to facilitate debugging and data query.

For a matchmaking engine, there are mainly the following types of logs to output:

  1. Log of program startup, including log of successful connection to redis and log of successful web service startup;
  2. Log of interface request and response data;
  3. Started the log of an engine;
  4. Shut down the log of an engine;
  5. The order is added to the orderbook log;
  6. Transaction log;
  7. Log of cancellation results.

In addition, there will be a lot of logs generated by the matching engine, so log segmentation should also be done. Date segmentation is the most commonly used way of log segmentation, so we also split logs of different dates into different log files for saving.

Implementation ideas

First of all, we all know that there are different levels of logs. For example, log4j defines eight levels of logs. However, the four most commonly used levels, from low to high, are:DEBUG、INFO、WARN、ERROR。 Generally, different environments will set different log levels. For example, debug level is generally set only in development and test environment, and production environment will be set to info or higher level. When set to high level, log messages of low level will not be printed out. In order to print different levels of log messages, you can provide different levels of printing functions, such aslog.Debug()、log.Info()Equal function.

Second, the log needs to be output to the file for saving, so you need to specify the directory, file name, and file object of the file for saving. Generally, the saved file directory and the running program should be put together, so the specified file directory is better to be a relative path.

In addition, the file should be divided according to the date, that is, the log messages of different dates should be saved to different log files, so the current log date should be recorded naturally. When it is detected that the latest date is different from the current log date, the current log file needs to be backed up and a new file is created to save the log message of the new date.

Finally, when the log message is written to a file, there is no shortage of time-consuming I / O operations. If the log is written synchronously, the matching performance will undoubtedly be reduced. Therefore, it is better to write the log asynchronously, which can be realized by a buffered channel.

code implementation

I redefined a log package and created a log.go file in which all the code was written.

The first step is to define several log levels, which are directly defined as enumeration types, as follows:

type LEVEL byte

const (
    DEBUG LEVEL = iota
    INFO
    WARN
    ERROR
)

Step 2: define the log structure, which contains many fields, as follows:

type FileLogger struct {
    Filedir string // directory where log files are saved
    Filename string // log filename (no need to include date and extension)
    Prefix string // prefix of the log message
    Loglevel level // log level
    Logfile * os.file // log file
    Date * time. Time // log current date
    LG * log.logger // system log object
    Mu * sync.rwmutex // read / write lock, which needs to be locked during log splitting and writing
    Logchan Chan string // log message channel to write logs asynchronously
    Stoptickerchan Chan bool // channel to stop timer
}

Step 3: in order to apply the log to any part of the program, a global log object needs to be defined and initialized. Initialization is a bit complicated. Let’s look at the code first:

const DATE_FORMAT = "2006-01-02"

var fileLog *FileLogger

func Init(fileDir, fileName, prefix, level string) error {
    CloseLogger()

    f := &FileLogger{
        fileDir:       fileDir,
        fileName:      fileName,
        prefix:        prefix,
        mu:            new(sync.RWMutex),
        logChan:       make(chan string, 5000),
        stopTikerChan: make(chan bool, 1),
    }

    switch strings.ToUpper(level) {
    case "DEBUG":
        f.logLevel = DEBUG
    case "WARN":
        f.logLevel = WARN
    case "ERROR":
        f.logLevel = ERROR
    default:
        f.logLevel = INFO
    }

    t, _ := time.Parse(DATE_FORMAT, time.Now().Format(DATE_FORMAT))
    f.date = &t

    f.isExistOrCreateFileDir()

    fullFileName := filepath.Join(f.fileDir, f.fileName+".log")
    file, err := os.OpenFile(fullFileName, os.O_RDWR|os.O_APPEND|os.O_CREATE, 0666)
    if err != nil {
        return err
    }
    f.logFile = file

    f.lg = log.New(f.logFile, prefix, log.LstdFlags|log.Lmicroseconds)

    go f.logWriter()
    go f.fileMonitor()

    fileLogger = f

    return nil
}

There are a lot of logic in this initialization. Let me explain the split. First of all, the first step is to callCloseLogger()Function to close files and channels. In order to stop a looping goroutine, channel closure is a common solution, which has been mentioned in previous articles. So, since the initialization function can be called many times to implement configuration changes, if the old goroutine is not terminated first, more than one goroutine with the same function will run at the same time, which will undoubtedly cause problems. Therefore, you need to close the logger first. The code to close the logger is as follows:

func CloseLogger() {
    if fileLogger != nil {
        fileLogger.stopTikerChan <- true
        close(fileLogger.stopTikerChan)
        close(fileLogger.logChan)
        fileLogger.lg = nil
        fileLogger.logFile.Close()
    }
}

After the logger is closed, the initialization of some fields is assigned,f.dateSet to the current date, and then judge whether to split based on this date.f.isExistOrCreateFileDir()Whether the log directory exists or not will be determined. If not, the directory will be created. Then, the directory, the set file name and the added. Log file extension are spliced together to splice the full name of the file and open the file. This file is then used to initialize the system log objectf.lgThe log message is actually called when it is written to the fileOutput()Function. Later, two goroutines are started: one is used to listen to logchan and write log messages to files; the other is used to regularly listen to whether files need to be split or not, and when it needs to be split, it needs to be split.

Next, let’s look at the implementation of these two goroutines:

func (f *FileLogger) logWriter() {
    defer func() { recover() }()

    for {
        str, ok := <-f.logChan
        if !ok {
            return
        }

        f.mu.RLock()
        f.lg.Output(2, str)
        f.mu.RUnlock()
    }
}

func (f *FileLogger) fileMonitor() {
    defer func() { recover() }()
    ticker := time.NewTicker(30 * time.Second)
    defer ticker.Stop()
    for {
        select {
        case <-ticker.C:
            if f.isMustSplit() {
                if err := f.split(); err != nil {
                    Error("Log split error: %v\n", err)
                }
            }
        case <-f.stopTikerChan:
            return
        }
    }
}

Can seelogWriter()Loop to read log messages from logchan channel, exit when the channel is closed, otherwise callf.lg.Output()Output the log.fileMonitor()It creates a message sent every 30 secondstickerWhen fromticker.CAfter receiving the data, judge whether segmentation is needed, and call the segmentation function if necessaryf.split()。 And fromf.stopTikerChanWhen the data is received, the timer is about to end.

Next, let’s seeisMustSplit()andsplit()Function. Ismustsplit () is very simple, just two lines of code, as follows:

func (f *FileLogger) isMustSplit() bool {
    t, _ := time.Parse(DATE_FORMAT, time.Now().Format(DATE_FORMAT))
    return t.After(f.date)
}

Split () is more complex. First, you need to add a write lock to the log to avoid log writing when splitting. Then you need to rename and backup the current log file, and then generate a new file to record new log messages, and point the current global log object to the new file, new date and new system log object. The implementation code is as follows:

func (f *FileLogger) split() error {
    f.mu.Lock()
    defer f.mu.Unlock()

    logFile := filepath.Join(f.fileDir, f.fileName)
    logFileBak := logFile + "-" + f.date.Format(DATE_FORMAT) + ".log"

    if f.logFile != nil {
        f.logFile.Close()
    }

    err := os.Rename(logFile, logFileBak)
    if err != nil {
        return err
    }

    t, _ := time.Parse(DATE_FORMAT, time.Now().Format(DATE_FORMAT))
    f.date = &t

    f.logFile, err = os.OpenFile(logFile, os.O_RDWR|os.O_APPEND|os.O_CREATE, 0666)
    if err != nil {
        return err
    }

    f.lg = log.New(f.logFile, f.prefix, log.LstdFlags|log.Lmicroseconds)

    return nil
}

Finally, we have to define some functions to receive log messages. The implementation is very simpleInfo()For example:

func Info(format string, v ...interface{}) {
    _, file, line, _ := runtime.Caller(1)
    if fileLogger.logLevel <= INFO {
        fileLogger.logChan <- fmt.Sprintf("[%v:%v]", filepath.Base(file), line) + fmt.Sprintf("[INFO]"+format, v...)
    }
}

Debug(), warn(), error() and other functions are similar. Just follow the example.

So far, we have completed the log package that can divide the log files by date. The rest is to call the log level function of the response at the corresponding place where the log output needs to be added.

Summary

The core of this summary is to add a general log package, which can be used not only in our matching engine, but also in other projects. If you extend it, you can also split it by other criteria, such as by hour, or by file size. Interested partners can try it on their own.

Today’s question: what are the solutions to achieve unified log output of request and response data of the interface?

Author’s personal blog

Scan the following two-dimensional code to pay attention to the public number (public name: Keegan steel).
Match engine development: log output