refactor debug log code to eliminate duplication

blockstore/splitstore/debug.go

@@ -20,60 +20,58 @@ import (
 )
 
 type debugLog struct {
-	readPath, writePath, deletePath, stackPath string
+	readLog, writeLog, deleteLog, stackLog *debugLogOp
-	readMx, writeMx, deleteMx, stackMx         sync.Mutex
+
-	readLog, writeLog, deleteLog, stackLog     *os.File
+	stackMx  sync.Mutex
-	readCnt, writeCnt, deleteCnt, stackCnt     int
+	stackMap map[string]string
-	stackMap                                   map[string]string
+}
+
+type debugLogOp struct {
+	path  string
+	mx    sync.Mutex
+	log   *os.File
+	count int
 }
 
 func openDebugLog(path string) (*debugLog, error) {
 	basePath := filepath.Join(path, "debug")
 	err := os.MkdirAll(basePath, 0755)
 	if err != nil {
-		return nil, xerrors.Errorf("error creating debug log directory: %w", err)
+		return nil, err
 	}
 
-	readPath := filepath.Join(basePath, "read.log")
+	readLog, err := openDebugLogOp(basePath, "read.log")
-	readFile, err := os.OpenFile(readPath, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644)
 	if err != nil {
-		return nil, xerrors.Errorf("error opening read log: %w", err)
+		return nil, err
 	}
 
-	writePath := filepath.Join(basePath, "write.log")
+	writeLog, err := openDebugLogOp(basePath, "write.log")
-	writeFile, err := os.OpenFile(writePath, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644)
 	if err != nil {
-		_ = readFile.Close()
+		_ = readLog.Close()
-		return nil, xerrors.Errorf("error opening write log: %w", err)
+		return nil, err
 	}
 
-	deletePath := filepath.Join(basePath, "delete.log")
+	deleteLog, err := openDebugLogOp(basePath, "delete.log")
-	deleteFile, err := os.OpenFile(deletePath, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644)
 	if err != nil {
-		_ = readFile.Close()
+		_ = readLog.Close()
-		_ = writeFile.Close()
+		_ = writeLog.Close()
-		return nil, xerrors.Errorf("error opening delete log: %w", err)
+		return nil, err
 	}
 
-	stackPath := filepath.Join(basePath, "stack.log")
+	stackLog, err := openDebugLogOp(basePath, "stack.log")
-	stackFile, err := os.OpenFile(stackPath, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644)
 	if err != nil {
-		_ = readFile.Close()
+		_ = readLog.Close()
-		_ = writeFile.Close()
+		_ = writeLog.Close()
-		_ = deleteFile.Close()
+		_ = deleteLog.Close()
 		return nil, xerrors.Errorf("error opening stack log: %w", err)
 	}
 
 	return &debugLog{
-		readPath:   readPath,
+		readLog:   readLog,
-		writePath:  writePath,
+		writeLog:  writeLog,
-		deletePath: deletePath,
+		deleteLog: deleteLog,
-		stackPath:  stackPath,
+		stackLog:  stackLog,
-		readLog:    readFile,
+		stackMap:  make(map[string]string),
-		writeLog:   writeFile,
-		deleteLog:  deleteFile,
-		stackLog:   stackFile,
-		stackMap:   make(map[string]string),
 	}, nil
 }
 
@@ -83,13 +81,7 @@ func (d *debugLog) LogReadMiss(cid cid.Cid) {
 	}
 
 	stack := d.getStack()
-
+	err := d.readLog.Log("%s %s %s\n", d.timestamp(), cid, stack)
-	d.readMx.Lock()
-	defer d.readMx.Unlock()
-
-	d.readCnt++
-
-	_, err := fmt.Fprintf(d.readLog, "%s %s %s\n", d.timestamp(), cid, stack)
 	if err != nil {
 		log.Warnf("error writing read log: %s", err)
 	}
@@ -105,12 +97,7 @@ func (d *debugLog) LogWrite(blk blocks.Block) {
 		stack = " " + d.getStack()
 	}
 
-	d.writeMx.Lock()
+	err := d.writeLog.Log("%s %s%s\n", d.timestamp(), blk.Cid(), stack)
-	defer d.writeMx.Unlock()
-
-	d.writeCnt++
-
-	_, err := fmt.Fprintf(d.writeLog, "%s %s%s\n", d.timestamp(), blk.Cid(), stack)
 	if err != nil {
 		log.Warnf("error writing write log: %s", err)
 	}
@@ -126,14 +113,9 @@ func (d *debugLog) LogWriteMany(blks []blocks.Block) {
 		stack = " " + d.getStack()
 	}
 
-	d.writeMx.Lock()
-	defer d.writeMx.Unlock()
-
-	d.writeCnt += len(blks)
-
 	now := d.timestamp()
 	for _, blk := range blks {
-		_, err := fmt.Fprintf(d.writeLog, "%s %s%s\n", now, blk.Cid(), stack)
+		err := d.writeLog.Log("%s %s%s\n", now, blk.Cid(), stack)
 		if err != nil {
 			log.Warnf("error writing write log: %s", err)
 			break
@@ -146,14 +128,9 @@ func (d *debugLog) LogDelete(cids []cid.Cid) {
 		return
 	}
 
-	d.deleteMx.Lock()
-	defer d.deleteMx.Unlock()
-
-	d.deleteCnt += len(cids)
-
 	now := d.timestamp()
 	for _, c := range cids {
-		_, err := fmt.Fprintf(d.deleteLog, "%s %s\n", now, c)
+		err := d.deleteLog.Log("%s %s\n", now, c)
 		if err != nil {
 			log.Warnf("error writing delete log: %s", err)
 			break
@@ -167,125 +144,10 @@ func (d *debugLog) Flush() {
 	}
 
 	// rotate non-empty logs
-	d.rotateReadLog()
+	d.readLog.Rotate()
-	d.rotateWriteLog()
+	d.writeLog.Rotate()
-	d.rotateDeleteLog()
+	d.deleteLog.Rotate()
-	d.rotateStackLog()
+	d.stackLog.Rotate()
-}
-
-func (d *debugLog) rotateReadLog() {
-	d.readMx.Lock()
-	defer d.readMx.Unlock()
-
-	if d.readCnt == 0 {
-		return
-	}
-
-	err := d.rotate(d.readLog, d.readPath)
-	if err != nil {
-		log.Warnf("error rotating read log: %s", err)
-		return
-	}
-
-	d.readLog, err = os.OpenFile(d.readPath, os.O_WRONLY|os.O_CREATE, 0644)
-	if err != nil {
-		log.Warnf("error opening log file: %s", err)
-		return
-	}
-
-	d.readCnt = 0
-}
-
-func (d *debugLog) rotateWriteLog() {
-	d.writeMx.Lock()
-	defer d.writeMx.Unlock()
-
-	if d.writeCnt == 0 {
-		return
-	}
-
-	err := d.rotate(d.writeLog, d.writePath)
-	if err != nil {
-		log.Warnf("error rotating write log: %s", err)
-		return
-	}
-
-	d.writeLog, err = os.OpenFile(d.writePath, os.O_WRONLY|os.O_CREATE, 0644)
-	if err != nil {
-		log.Warnf("error opening write log file: %s", err)
-		return
-	}
-
-	d.writeCnt = 0
-}
-
-func (d *debugLog) rotateDeleteLog() {
-	d.deleteMx.Lock()
-	defer d.deleteMx.Unlock()
-
-	if d.deleteCnt == 0 {
-		return
-	}
-
-	err := d.rotate(d.deleteLog, d.deletePath)
-	if err != nil {
-		log.Warnf("error rotating delete log: %s", err)
-		return
-	}
-
-	d.deleteLog, err = os.OpenFile(d.deletePath, os.O_WRONLY|os.O_CREATE, 0644)
-	if err != nil {
-		log.Warnf("error opening delete log file: %s", err)
-		return
-	}
-
-	d.deleteCnt = 0
-}
-
-func (d *debugLog) rotateStackLog() {
-	d.stackMx.Lock()
-	defer d.stackMx.Unlock()
-
-	if d.stackCnt == 0 {
-		return
-	}
-
-	err := d.rotate(d.stackLog, d.stackPath)
-	if err != nil {
-		log.Warnf("error rotating stack log: %s", err)
-		return
-	}
-
-	d.stackLog, err = os.OpenFile(d.stackPath, os.O_WRONLY|os.O_CREATE, 0644)
-	if err != nil {
-		log.Warnf("error opening stack log file: %s", err)
-		return
-	}
-
-	d.stackCnt = 0
-}
-
-func (d *debugLog) rotate(f *os.File, path string) error {
-	err := f.Close()
-	if err != nil {
-		return xerrors.Errorf("error closing file: %w", err)
-	}
-
-	arxivPath := fmt.Sprintf("%s-%d", path, time.Now().Unix())
-	err = os.Rename(path, arxivPath)
-	if err != nil {
-		return xerrors.Errorf("error moving file: %w", err)
-	}
-
-	go func() {
-		cmd := exec.Command("gzip", arxivPath)
-		err := cmd.Run()
-		if err != nil {
-			log.Warnf("error compressing log: %s", err)
-		}
-	}()
-
-	return nil
 }
 
 func (d *debugLog) Close() error {
@@ -293,21 +155,10 @@ func (d *debugLog) Close() error {
 		return nil
 	}
 
-	d.readMx.Lock()
 	err1 := d.readLog.Close()
-	d.readMx.Unlock()
-
-	d.writeMx.Lock()
 	err2 := d.writeLog.Close()
-	d.writeMx.Unlock()
-
-	d.deleteMx.Lock()
 	err3 := d.deleteLog.Close()
-	d.deleteMx.Unlock()
-
-	d.stackMx.Lock()
 	err4 := d.stackLog.Close()
-	d.stackMx.Unlock()
 
 	return multierr.Combine(err1, err2, err3, err4)
 }
@@ -322,9 +173,8 @@ func (d *debugLog) getStack() string {
 	if !ok {
 		repr = hex.EncodeToString(hash[:])
 		d.stackMap[key] = repr
-		d.stackCnt++
 
-		_, err := fmt.Fprintf(d.stackLog, "%s\n%s\n", repr, sk)
+		err := d.stackLog.Log("%s\n%s\n", repr, sk)
 		if err != nil {
 			log.Warnf("error writing stack trace for %s: %s", repr, err)
 		}
@@ -358,3 +208,66 @@ func (d *debugLog) timestamp() string {
 	ts, _ := time.Now().MarshalText()
 	return string(ts)
 }
+
+func openDebugLogOp(basePath, name string) (*debugLogOp, error) {
+	path := filepath.Join(basePath, name)
+	file, err := os.OpenFile(path, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644)
+	if err != nil {
+		return nil, xerrors.Errorf("error opening %s: %w", name, err)
+	}
+
+	return &debugLogOp{path: path, log: file}, nil
+}
+
+func (d *debugLogOp) Close() error {
+	d.mx.Lock()
+	defer d.mx.Unlock()
+
+	return d.log.Close()
+}
+
+func (d *debugLogOp) Log(template string, arg ...interface{}) error {
+	d.mx.Lock()
+	defer d.mx.Unlock()
+
+	d.count++
+	_, err := fmt.Fprintf(d.log, template, arg...)
+	return err
+}
+
+func (d *debugLogOp) Rotate() {
+	d.mx.Lock()
+	defer d.mx.Unlock()
+
+	if d.count == 0 {
+		return
+	}
+
+	err := d.log.Close()
+	if err != nil {
+		log.Warnf("error closing log (file: %s): %s", d.path, err)
+		return
+	}
+
+	arxivPath := fmt.Sprintf("%s-%d", d.path, time.Now().Unix())
+	err = os.Rename(d.path, arxivPath)
+	if err != nil {
+		log.Warnf("error moving log (file: %s): %s", d.path, err)
+		return
+	}
+
+	go func() {
+		cmd := exec.Command("gzip", arxivPath)
+		err := cmd.Run()
+		if err != nil {
+			log.Warnf("error compressing log (file: %s): %s", arxivPath, err)
+		}
+	}()
+
+	d.count = 0
+	d.log, err = os.OpenFile(d.path, os.O_WRONLY|os.O_CREATE, 0644)
+	if err != nil {
+		log.Warnf("error opening log (file: %s): %s", d.path, err)
+		return
+	}
+}