Why do empty lines are being written into file along with normal messages?

Viewed 39

I'm writing an async logger and using bufio for writing logs into file. This is done in the following way:

type ALogger struct {
    records  chan []byte
    buff     bufio.Writer
    queueLen int32         // amount of items currently awaiting to be written to `records`
    done     chan struct{} // used for signaling inside `alog.Run()` as well as `inactive`
    inactive chan struct{}
}

func (al *ALogger) write(s []byte) (int, error) {
    bytesWritten := 0
    for bytesWritten < len(s) {
        bw, err := al.buff.Write(s[bytesWritten:])
        if err != nil {
            return bytesWritten, err
        }
        bytesWritten += bw
    }
    return bytesWritten, nil
}

func (al *ALogger) Run() error {
    var stow []byte
    for {
        select {
        case <-al.done: // used for sync pur
            al.inactive <- struct{}{}
            return nil
        case r := <-al.records: 
            // from rought testing this approach is faster then flushing the buffer
            r = append(stow, r...)
            if bw, err := al.write(r); err != nil {
                if err == io.ErrShortWrite { // doesn't occur but used to, idk why
                    stow = r[bw:]
                } else {
                    return err
                }
            } else {
                stow = []byte("")
            }
        default:
            continue
        }
    }
}

func (al *ALogger) Print(s ...any) {
    r := []byte(fmt.Sprint(s...))
    atomic.AddInt32(&al.queueLen, 1)
    al.records <- r
    atomic.AddInt32(&al.queueLen, -1)
}

// where print is called

func job(r *rand.Rand) int64 {
    val := r.Int63() % 10000
    ng := int64(runtime.NumGoroutine())

    work := md5.Sum([]byte(fmt.Sprint(ng + val)))    // h(m)
    work = md5.Sum([]byte(fmt.Sprint(work, ng+val))) // h(h(m) || m)

    return int64(binary.BigEndian.Uint16(work[:2])) % 10000
}

// Is run inside a loop each in a seperate goroutine.
func RunALog(wg *sync.WaitGroup, eventCount, threadID int) {
    r := rand.New(rand.NewSource(int64(threadID)))

    for i := 0; i < eventCount; i++ {
        alog.Print(fmt.Sprintf("{\"thread\": %d, \"timestamp\": %v, \"result\": %d}\n",
            threadID,
            time.Now(),
            job(r),
        ))
    }
    wg.Done()
    alog.Print("\n\n")
}

The method above runs in a separate goroutine and accepts records to log from other parts of the program without blocking execution. It runs fine and in fact I'm getting 4-5x gain in speed in comparison to log but for some reason it sometimes writes empty lines to log file. For example:

{"thread": 6, "timestamp": 2022-09-17 23:36:47.543629743 +0400 +04 m=+0.008094248, "result": 932}
{"thread": 6, "timestamp": 2022-09-17 23:36:47.543636105 +0400 +04 m=+0.008100609, "result": 8767}
{"thread": 6, "timestamp": 2022-09-17 23:36:47.543645313 +0400 +04 m=+0.008109817, "result": 2098}
{"thread": 6, "timestamp": 2022-09-17 23:36:47.543657035 +0400 +04 m=+0.008121539, "result": 7888}
// this one
// and this one too
{"thread": 6, "timestamp": 2022-09-17 23:36:47.543664098 +0400 +04 m=+0.008128612, "result": 6601}
{"thread": 4, "timestamp": 2022-09-17 23:36:47.543413818 +0400 +04 m=+0.007878332, "result": 5171}
{"thread": 4, "timestamp": 2022-09-17 23:36:47.543421653 +0400 +04 m=+0.007886167, "result": 5054}
{"thread": 6, "timestamp": 2022-09-17 23:36:47.5436703 +0400 +04 m=+0.008134804, "result": 1885}

UPD0: In debug noticed that r sometimes spontaneously receives [10 10] which is two end line symbols.

UDP1: Blank lines do not substitute normal log messages. If I run 7 goroutines with eventCount equals 50 I will get 350 normal records in log file, plus some blank lines on top.

0 Answers
Related