# Matching Engine 06:Log

By [iwalk.eth](https://paragraph.com/@iwalk) · 2022-06-13

---

### Log Requirements

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

For a matching engine, the logs that need to be output mainly include the following categories:

1.  The log of program startup, including the log of successful connection to Redis and the log of successful startup of Web service;
    
2.  Logs of interface request and response data;
    
3.  The log of an engine is started;
    
4.  The log of an engine is closed;
    
5.  The order is added to the log of orderBook;
    
6.  The log of transaction records;
    
7.  Log of cancellation results.
    

In addition, the matching engine will generate a lot of logs, so log segmentation should also be done. Splitting by date is the most commonly used log splitting method, so we also divide logs of different dates into different log files for preservation.

### Implementation ideas

First of all, we all know that logs are divided into levels. For example, log4j defines 8 levels of logs. However, there are 4 most commonly used levels, with priority from low to high: DEBUG, INFO, WARN, ERROR. Generally, different environments will set different log levels. For example, the DEBUG level is generally only set in the development and test environments, and the production environment will be set to INFO or higher. When set to high level, low level log messages are not printed. In order to print different levels of log messages, you can provide different levels of printing functions, such as log.Debug(), [log.Info](http://log.Info)() and other functions.

Secondly, the log needs to be output to a file for saving, so it is necessary to specify the directory, file name and file object for the file to be saved. Generally, the saved file directory and the running program should be put together, so the specified file directory should preferably 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 naturally, the date of the current log should be recorded. And it needs to be monitored regularly. When it is detected that the latest date has crossed the date compared with the current log date, it means that the log needs to be split, then the current log file is backed up, and a new file is created to save the log of the new date. information.

Finally, if log messages are written to files, time-consuming I/O operations are indispensable. If the log is written synchronously, it will undoubtedly reduce the matching performance. Therefore, it is better to write the log asynchronously, which can be implemented by a buffered channel. .

### Code

I re-customized a log package and created the log.go file where all the code is written.

The first step is to define several log levels and directly define them as enumeration types, as follows:

    type LEVEL byte
    
    const (
        DEBUG LEVEL = iota
        INFO
        WARN
        ERROR
    )
    

The second step is to define the structure of the log, which contains many fields, as follows:

    type FileLogger struct {
        fileDir string // Directory where log files are saved
        fileName string // log file name (no need to include date and extension)
        prefix string // prefix for log messages
        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 log writing
        logChan chan string // log message channel for asynchronous log writing
        stopTickerChan chan bool // stop the channel of the timer
    }
    

The third step, in order to apply the log to any place in the program, it is necessary to define a global log object and initialize the log object. The initialization operation 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
    }
    

The logic of this initialization is a bit too much, so let me split it up. First of all, the first step is to call the CloseLogger() function, which mainly closes files, closes channels, and other operations. To stop a constantly looping goroutine, closing the channel is a common solution, which was also mentioned in the previous article. Then, since the initialization function can be called multiple 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, some fields are initialized and assigned. Among them, f.date is set to the current date, and the later judgment is based on this date. f.isExistOrCreateFileDir() will judge whether the log directory exists, and if not, it will be created. Next, concatenate the directory, the set filename, and the added .log file extension, concatenate the full name of the file, and open the file. After that, the file is used to initialize the system log object f.lg. When the log message is written to the file, the Output() function of the object is actually called. Two goroutines are started later: one is used to monitor logChan to write log messages into files; the other is used to regularly monitor whether the file needs to be divided, and when it needs to be divided, it will be divided.

Next, let's take a 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
            }
        }
    }
    

You can see that the logWriter() loop reads log messages from the logChan channel, and exits when the channel is closed, otherwise it calls f.lg.Output() to output the log. In fileMonitor(), a ticker is created that is sent every 30 seconds. When data is received from ticker.C, it is judged whether it needs to be split, and if so, the split function f.split() is called. And when data is received from f.stopTikerChan, it means that the timer will also end.

Next, let's look at the isMustSplit() and split() functions. 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 a bit more complicated. First, add a write lock to the log to avoid log writing during splitting, then rename and backup the current log file, and then generate a new file to record new log messages. The current global log object points to the new file, new date, and new syslog 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"
        
        iff.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, it is left to define some functions that receive log messages. The implementation is very simple. Take Info() as an 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 cat and draw the tiger.

At this point, our log package that can split log files by date is complete. For the rest, just call the corresponding log level function 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 expand it, you can also split by other criteria, such as split by hour, or split by file size. Those who are interested can try it out for themselves. \`\`\`

---

*Originally published on [iwalk.eth](https://paragraph.com/@iwalk/matching-engine-06-log)*