跑了一个小例子：

config := rollingwriter.Config{
	LogPath:           "./log",
	TimeTagFormat:     "060102150405",
	FileName:          "test",
	MaxRemain:         5,
	RollingPolicy:     rollingwriter.VolumeRolling,
	RollingVolumeSize: "2K",
	Asynchronous:      true,
}
writer, err := rollingwriter.NewWriterFromConfig(&config)
if err != nil {
	// 应该处理错误
	panic(err)
}
wg := sync.WaitGroup{}
wg.Add(1)
go func() {
	for {
		bf := []byte(fmt.Sprintf("rollingwriter test write gorounter time %v\n", time.Now()))
		writer.Write(bf)
	}
}()
wg.Wait()

运行了一段时间，输出如下，也没有按照2k切分： 里面的内容也是不可读的

在配合 zap 使用时，当要切分时，出现以下错误 write error: rename log/logs.log log/logs.log.201905111642: The process cannot access the file because it is being used by another process.

从提示上看，当要切分时，log 文件被占用了，不能重命名

我构建 zap logger 代码如下： ` // 基本上与 demo 例子相同的配置进行构建的 RollingWriter 实例 rw, _ := newRollingWriter(&config)

// 基于 RollingWriter 构建 *zap.Logger
ws := zapcore.AddSync(rw)
core := zapcore.NewCore(
	zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()),
	ws,
	zap.InfoLevel,
)

logger = zap.New(core)`

ps. rollingWriter 代码获取的是 master 分支

go env:1.13.1 go.mod:

require (
	github.com/arthurkiller/rollingwriter v1.1.1
	github.com/gin-contrib/logger v0.0.1
	github.com/gin-gonic/gin v1.4.0
	github.com/gobuffalo/envy v1.7.1
	github.com/rs/zerolog v1.9.1
)

replace github.com/ugorji/go v1.1.4 => github.com/ugorji/go/codec v0.0.0-20190204201341-e444a5086c43

config := &rollingwriter.Config{
		LogPath:       "./storage/logs",        //日志路径
		TimeTagFormat: "20060102", //时间格式串
		FileName:      "test",         //日志文件名
		MaxRemain:     5,              //配置日志最大存留数

		// 目前有2中滚动策略: 按照时间滚动按照大小滚动
		// - 时间滚动: 配置策略如同 crontable, 例如,每天0:0切分, 则配置 0 0 0 * * *
		// - 大小滚动: 配置单个日志文件(未压缩)的滚动大小门限, 入1G, 500M
		RollingPolicy:      rollingwriter.TimeRolling, //配置滚动策略 norolling timerolling volumerolling
		RollingTimePattern: "* * * * * *",             //配置时间滚动策略
		RollingVolumeSize:  "2k",                      //配置截断文件下限大小

		// writer 支持4种不同的 mode:
		// 1. none 2. lock
		// 3. async 4. buffer
		// - 无保护的 writer: 不提供并发安全保障
		// - lock 保护的 writer: 提供由 mutex 保护的并发安全保障
		// - 异步 writer: 异步 write, 并发安全. 异步开启后忽略 Lock 选项
		WriterMode: "lock",
		// BufferWriterThershould in B
		BufferWriterThershould: 8 * 1024 * 1024,
		// Compress will compress log file with gzip
		Compress: false,
	}


	writer ,_:= rollingwriter.NewWriterFromConfig(config)

        logger = zerolog.New(writer).With().Timestamp().Logger()

       router.GET("/ping", func(c *gin.Context) {
		logger.Info().Msg("test")
		c.String(200, "pong "+fmt.Sprint(time.Now().Unix()))
	})

不断刷新 /ping

{"level":"info","time":"2019-10-30T19:29:14+08:00","message":"test"} //仅有此

test.log 里只有会一条数据，日志内容的时间戳会不断的更新，判断你写入文件的时候使用的是覆盖

1. env

▶ go version
go version go1.12.4 darwin/amd64
---
GoLand 2019.1.1
Build #GO-191.6707.68, built on April 17, 2019
JRE: 1.8.0_202-release-1483-b44 x86_64
JVM: OpenJDK 64-Bit Server VM by JetBrains s.r.o
macOS 10.14.4

2. 复现步骤

go run -race demo/writer.go

3. 结果

WARNING: DATA RACE
Read at 0x00c00009e0a8 by goroutine 25:
  github.com/arthurkiller/rollingWriter.(*manager).GenLogFileName()
      /Users/chaomai/Documents/workspace/github/rollingWriter/manager.go:140 +0x88
  github.com/arthurkiller/rollingWriter.NewManager.func1()
      /Users/chaomai/Documents/workspace/github/rollingWriter/manager.go:43 +0x53
  github.com/robfig/cron.FuncJob.Run()
      /Users/chaomai/Documents/workspace/go/pkg/mod/github.com/robfig/[email protected]/cron.go:92 +0x34
  github.com/robfig/cron.(*Cron).runWithRecovery()
      /Users/chaomai/Documents/workspace/go/pkg/mod/github.com/robfig/[email protected]/cron.go:165 +0x68

Previous write at 0x00c00009e0a8 by goroutine 22:
  github.com/arthurkiller/rollingWriter.(*manager).GenLogFileName()
      /Users/chaomai/Documents/workspace/github/rollingWriter/manager.go:145 +0x243
  github.com/arthurkiller/rollingWriter.NewManager.func1()
      /Users/chaomai/Documents/workspace/github/rollingWriter/manager.go:43 +0x53
  github.com/robfig/cron.FuncJob.Run()
      /Users/chaomai/Documents/workspace/go/pkg/mod/github.com/robfig/[email protected]/cron.go:92 +0x34
  github.com/robfig/cron.(*Cron).runWithRecovery()
      /Users/chaomai/Documents/workspace/go/pkg/mod/github.com/robfig/[email protected]/cron.go:165 +0x68

Goroutine 25 (running) created at:
  github.com/robfig/cron.(*Cron).run()
      /Users/chaomai/Documents/workspace/go/pkg/mod/github.com/robfig/[email protected]/cron.go:199 +0xa65

Goroutine 22 (finished) created at:
  github.com/robfig/cron.(*Cron).run()
      /Users/chaomai/Documents/workspace/go/pkg/mod/github.com/robfig/[email protected]/cron.go:199 +0xa65

4. 分析

初步看了，(*manager).GenLogFileName()最终是由github.com/robfig/cron/cron.go执行的，可见cron中并无无任何同步机制。

极端情况下，如果(*manager).GenLogFileName()的执行时间长于调度间隔，那同一时刻就会有两个goroutine在执行(*manager).GenLogFileName()，m.startAt就可能会有问题了。

5. 解决

type manager struct {
	// ...
	lock          sync.Mutex
}

// ...

// GenLogFileName generate the new log file name, filename should be absolute path
func (m *manager) GenLogFileName(c *Config) (filename string) {
	m.lock.Lock()
	// ...
	m.lock.Lock()
	// reset the start time to now
	m.startAt = time.Now()
	return
}

Found a bug when using it on windows: renaming fails because the file is open. I modified the code to only do renaming and removing operations with closed files to avoid these issues on windows. Also, there are some auto-fixes (just 3 space deletes and moving one defer) by the IDE that are nice IMO :)

Closes: #40

Signed-off-by: Guillem Bonet [email protected]

修复了上次提到的几个问题。

但是遇到了一个新的问题，开启compress的情况下，会随机出现压缩后文件为空的情况。暂时没有找到是什么原因导致的，还请帮忙看一下。

我移除return os.Remove(cmpname + ".tmp") // remove *.log.tmp file后测试，确认了原文件是正常的。

如果不传递oldfile指针，在CompressFile中打开原文件，这样不会出现压缩后文件为空的情况。

Thanks for the great package! We use it with zerolog, and it works well, however we met a bug recently, large amount of goroutines hang at writing log, all with the following stack trace:

(dlv) bt
 0  0x0000000000439405 in runtime.gopark
    at go/src/runtime/proc.go:337
 1  0x000000000044a385 in runtime.goparkunlock
    at go/src/runtime/proc.go:342
 2  0x000000000044a385 in runtime.semacquire1
    at go/src/runtime/sema.go:144
 3  0x0000000000468967 in sync.runtime_SemacquireMutex
    at go/src/runtime/sema.go:71
 4  0x00000000004721e5 in sync.(*Mutex).lockSlow
    at go/src/sync/mutex.go:138
 5  0x0000000000b4ee0b in sync.(*Mutex).Lock
    at go/src/sync/mutex.go:81
 6  0x0000000000b4ee0b in github.com/arthurkiller/rollingwriter.(*LockedWriter).Write
    at go-mod-cache/github.com/arthurkiller/[email protected]/writer.go:254
 7  0x0000000000695703 in github.com/rs/zerolog.levelWriterAdapter.WriteLevel
    at go-mod-cache/github.com/rs/[email protected]/writer.go:20
 8  0x0000000000695703 in github.com/rs/zerolog.(*levelWriterAdapter).WriteLevel
    at <autogenerated>:1
 9  0x0000000000689625 in github.com/rs/zerolog.(*Event).write
    at go-mod-cache/github.com/rs/[email protected]/event.go:76
10  0x0000000000689b1b in github.com/rs/zerolog.(*Event).msg
    at go-mod-cache/github.com/rs/[email protected]/event.go:140
11  0x0000000000b39f70 in github.com/rs/zerolog.(*Event).Msg
    at go-mod-cache/github.com/rs/[email protected]/event.go:106
...

I'm not familiar with the code, however, after a quick search, I found the following suspicious function:

func (w *LockedWriter) Write(b []byte) (n int, err error) {
	w.Lock()
	select {
	case filename := <-w.fire:
		if err := w.Reopen(filename); err != nil {
			return 0, err                      // <-- here
		}
	default:
	}
	n, err = w.file.Write(b)
	w.Unlock()
	return
}

I don't know if there is a chance that the function returns at the comment line, leaves the lock acquired without release. Is this the root cause of the bug above? Any help is appreciated, thanks.

We already have []byte allocated, since the signature of Write([]byte) method, why use _asyncBufferPool? It add additional copy which seems unnecessary?

当 RollingPolicy 为 VolumeRolling 时你启动了一个 goroutine， 然后我没有人关闭它， 调 writer 的 Close() 时不能关闭这个 goroutine

而且这个 goroutine 中的 timer 就算是 goroutine 退出了，也没有有停止这个 Ticker

在基于TimeRolling和VolumeRolling 切割的时候，容易阻塞

switch c.RollingPolicy {
	default:
		fallthrough
	case WithoutRolling:
		return m, nil
	case TimeRolling:
		if err := m.cr.AddFunc(c.RollingTimePattern, func() {
			m.fire <- m.GenLogFileName(c) // 长时间没有写日志，会阻塞
		}); err != nil {
			return nil, err
		}
		m.cr.Start()
	case VolumeRolling:
		m.ParseVolume(c)
		m.wg.Add(1)
		go func() {
			timer := time.Tick(time.Duration(Precision) * time.Second)
			filepath := LogFilePath(c)
			var file *os.File
			var err error
			m.wg.Done()

			for {
				select {
				case <-m.context:
					return
				case <-timer:
					if file, err = os.Open(filepath); err != nil {
						continue
					}
					if info, err := file.Stat(); err == nil && info.Size() > m.thresholdSize {
						m.fire <- m.GenLogFileName(c) // 长时间没有写日志，会阻塞
					}
					file.Close()
				}
			}
		}()
		m.wg.Wait()
	}
	return m, nil

针对VolumeRolling而言，一旦阻塞，会导致日志归档到错误的文件中。我觉得可以通过如下方式来修复一下：

func (w *LockedWriter) Write(b []byte) (n int, err error) {
	w.Lock()
DoWrite:// 解决fire阻塞带来的文件错位问题
	select {
	case filename := <-w.fire:
		if err := w.Reopen(filename); err != nil {
			return 0, err
		}
		goto DoWrite
	default:
	}
	n, err = w.file.Write(b)
	w.Unlock()
	return
}

https://github.com/arthurkiller/rollingwriter/blob/master/writer.go#L365

func (w *BufferWriter) Write(b []byte) (int, error) {
	// ...
	buf := append(*w.buf, b...)
	atomic.StorePointer((*unsafe.Pointer)(unsafe.Pointer(&w.buf)), (unsafe.Pointer)(&buf))

Hi，我使用到了贵包rollingwriter的buffer writer，测试时候发现会有丢日志的情况(高并发场景)。初步分析发现应该是这里的buffer append 非并发安全导致的。

比如buffer里已有 line1，并发两个Write，分别写入 line2、line3，竞争激烈的情况下，StorePointer可能会出现 [line1, line3] 覆盖 [line1, line2]，从而导致line2丢失。

测试时加上了给这行代码加了个mutex or trylock，发现可以解决丢日志的问题。这个问题也希望跟 @arthurkiller 作者大大确认下有无理解上的偏差。

From

buf := append(*w.buf, b...)
atomic.StorePointer((*unsafe.Pointer)(unsafe.Pointer(&w.buf)), (unsafe.Pointer)(&buf))

To

w.lockBuf.Lock()
*(w.buf) = append(*w.buf, b...)
w.lockBuf.Unlock()

另，spinlock简单实现

type Locker struct {
	lock uintptr
}

func (l *Locker) Lock() {
	for !atomic.CompareAndSwapUintptr(&l.lock, 0, 1) {
		runtime.Gosched()
	}
}

func (l *Locker) Unlock() {
	atomic.StoreUintptr(&l.lock, 0)
}

For FileName, consider using template strings, such as foo-${date}.log.gz, which makes the file suffix reasonable. It's strange to force a TimeTag spliced to the end of FileName. Last, thanks for your components, which helped me a lot~