持续运行几个小时后日志调用会阻塞。

ghost commented 8 years ago

我英语不太好，事情比较复杂，还是写中文吧。

环境是 windows 10 和 ubuntu x32 1404 ，语言版本：go version go1.6.2 windows/amd64

程序创建了一个模块来配置日志共享给其他模块，相关代码：


package logger

import (
    "github.com/go-ozzo/ozzo-log"
)

var logger = log.NewLogger()

// main 函数调用这个函数初始化 log
func Open(fileName string) {
    ct := log.NewConsoleTarget()
    ct.MaxLevel = log.LevelDebug

    ft := log.NewFileTarget()
    ft.FileName = fileName
    ft.MaxLevel = log.LevelInfo
    ft.MaxBytes = 1 * 1024 * 1024 //2M
    ft.BackupCount = 10
    ft.Rotate = true //自动切割旋转日志文件

    logger.Targets = append(logger.Targets, ct, ft)

    logger.Open()

    logger.Debug("日志完成初始化...")
}

// 其他模块调用这个函数获得自己的 Logger 并使用
func GetLogger(category string, formatter ...log.Formatter) *log.Logger {
    return logger.GetLogger(category, formatter...)
}

func Close() {
    logger.Close()
}

日志被设置为控制台输出DEBUG日志，文件记录INFO以上级别的日志。1M文件自动切割。

故障现象是：

持续运行几个小时(最近这次是2个小时)后，日志调用阻塞，任何涉及到日志的流程全部阻塞，同时控制台、日志文件不会再输出新内容。完全没有调用 ozzo 的代码能正常运行：我同时使用了 xorm ，打开了打印sql语句功能。有一个定时调用正常时不会调用 ozzo 打印日志， ozzo 完全阻塞后能看到这个流程还在继续运行，能够看到 xorm 定时打印到控制台的sql语句。

故障时控制台最后的日志输出：

2016-06-30T15:50:02+08:00 [Debug][yfforward] .......
2016-06-30T15:50:02+08:00 [Info][yfforward] .......
2016-06-30T15:50:03+08:00 [Info][yfforward] ......
2016-06-30T15:50:03+08:00 [Debug][yfforward] ......
2016-06-30T15:50:03+08:00 [Info][yfforward] ......
2016-06-30T15:50:04+08:00 [Info][yfforward] ......
[xorm] [info]  2016/06/30 15:50:19.176599 [sql] SELECT........
[xorm] [info]  2016/06/30 15:50:19.177598 [sql] UPDATE.......
[xorm] [info]  2016/06/30 15:50:40.648707 [sql] SELECT ........

日志文件最后的内容：

2016-06-30T15:50:00+08:00 [Info][yfforward] .....
2016-06-30T15:50:01+08:00 [Info][yfforward] ........
2016-06-30T15:50:01+08:00 [Info][yfforward] ......
2016-06-30T15:50:02+08:00 [Info][yfforward] ......
2016-06-30T15:50:02+08:00 [Info][yfforward] .....
2016-06-30T15:50:03+08:00 [Info][yfforward] ......
2016-06-30T15:50:03+08:00 [Info][yfforward] ........

猜测可能是多线程竟态问题，但是使用 tace 选项编译的程序运行中并没有报任何错误...

为了确认故障位置，针对 http api 服务 handle 函数增加了 fmt.Print ，代码如下：

    fmt.Printf("fmt.Print [ping] %v %v ping %v", r.RemoteAddr, rtype, raddr)
    log.Info("[ping] %v %v ping %v", r.RemoteAddr, rtype, raddr)
    fmt.Println("fmt.Print end")

然后访问这个 api，控制台输出如下：

··· [xorm] [info] 2016/06/30 15:58:57.089083 [sql] UPDATEXXXXXXXXXXXXXX fmt.Print [ping] 127.0.0.1:52080 TCP ping www.163.com:80[xorm] [info] 2016/06/30 15:59:07.088631 [sql] SELECT XXXXXXXXXXXXXXXXXXXXXXX [xorm] [info] XXXXXXXXXXXXXXXXXXXXXX [xorm] [info] 2016/06/30 15:59:17.104377 XXXXXXXXXXXXXXXXXXXXXXXXX ···

可以看到是ozzo日志调用阻塞了。xorm 的输出是上面那个不涉及 ozzo 的定时调用的输出。

目前正在想办法确定更具体的位置，挂载调试器的程序还未故障，稍故障后设置断点确定更准确的位置。

还有一个地方比较奇怪，日志切割设置并没有生效，故障时查看日志文件已经1.39M了，但是并没有执行切割，不知道是不是和这个有关。

ghost commented 8 years ago

拿到了故障时的调用堆栈

goroutine 31 [running]:
runtime/pprof.writeGoroutineStacks(0x1154f10, 0xc08203a0d0, 0x0, 0x0)
    C:/go/src/runtime/pprof/pprof.go:516 +0x8b
runtime/pprof.writeGoroutine(0x1154f10, 0xc08203a0d0, 0x2, 0x0, 0x0)
    C:/go/src/runtime/pprof/pprof.go:505 +0x4d
runtime/pprof.(*Profile).WriteTo(0xd90e60, 0x1154f10, 0xc08203a0d0, 0x2, 0x0, 0x0)
    C:/go/src/runtime/pprof/pprof.go:236 +0xdb
net/http/pprof.handler.ServeHTTP(0xc0823320d1, 0x9, 0x1154df8, 0xc08203a0d0, 0xc0820509a0)
    C:/go/src/net/http/pprof/pprof.go:210 +0x385
net/http/pprof.Index(0x1154df8, 0xc08203a0d0, 0xc0820509a0)
    C:/go/src/net/http/pprof/pprof.go:222 +0x207
net/http.HandlerFunc.ServeHTTP(0xb2cb58, 0x1154df8, 0xc08203a0d0, 0xc0820509a0)
    C:/go/src/net/http/server.go:1618 +0x41
net/http.(*ServeMux).ServeHTTP(0xc082053260, 0x1154df8, 0xc08203a0d0, 0xc0820509a0)
    C:/go/src/net/http/server.go:1910 +0x184
net/http.(*ServeMux).ServeHTTP(0xc082148c30, 0x1154df8, 0xc08203a0d0, 0xc0820509a0)
    C:/go/src/net/http/server.go:1910 +0x184
net/http.serverHandler.ServeHTTP(0xc0821680b0, 0x1154df8, 0xc08203a0d0, 0xc0820509a0)
    C:/go/src/net/http/server.go:2081 +0x1a5
net/http.(*conn).serve(0xc082328b00)
    C:/go/src/net/http/server.go:1472 +0xf35
created by net/http.(*Server).Serve
    C:/go/src/net/http/server.go:2137 +0x455

goroutine 1 [chan receive, 122 minutes]:
bitbucket.org/gamexg/..........(*Server).Server(0xc082147940, 0x0, 0x0)
    D:/golang/src/bitbucket.org/gamexg/......./server.go:54 +0x122
main.main()
    D:/golang/src/bitbucket.org/gamexg/...../main.go:49 +0x75e

goroutine 17 [syscall, 122 minutes, locked to thread]:
runtime.goexit()
    C:/go/src/runtime/asm_amd64.s:1998 +0x1

goroutine 18 [runnable, locked to thread]:
syscall.Syscall(0x7ffa104ada60, 0x3, 0xc0823c4360, 0x0, 0xc08245ad90, 0x15, 0xc0823c4360, 0x16)
    C:/go/src/runtime/syscall_windows.go:163 +0x5c
syscall.GetFileAttributesEx(0xc0823c4360, 0x0, 0xc08245ad90, 0x0, 0x0)
    C:/go/src/syscall/zsyscall_windows.go:867 +0x7d
os.Lstat(0xc082284d80, 0x15, 0x0, 0x0, 0x0, 0x0)
    C:/go/src/os/stat_windows.go:85 +0x498
github.com/go-ozzo/ozzo-log.(*FileTarget).rotate(0xc082136120, 0x42)
    D:/golang/src/github.com/go-ozzo/ozzo-log/file.go:112 +0x25d
github.com/go-ozzo/ozzo-log.(*FileTarget).Process(0xc082136120, 0xc082207560)
    D:/golang/src/github.com/go-ozzo/ozzo-log/file.go:84 +0x11d
github.com/go-ozzo/ozzo-log.(*coreLogger).process(0xc0820140e0)
    D:/golang/src/github.com/go-ozzo/ozzo-log/logger.go:250 +0xd7
created by github.com/go-ozzo/ozzo-log.(*coreLogger).Open
    D:/golang/src/github.com/go-ozzo/ozzo-log/logger.go:238 +0x6a6

goroutine 19 [chan receive, 122 minutes]:
database/sql.(*DB).connectionOpener(0xc082168000)
    C:/go/src/database/sql/sql.go:727 +0x4c
created by database/sql.Open
    C:/go/src/database/sql/sql.go:493 +0x346

goroutine 20 [select, 122 minutes]:
bitbucket.org/gamexg/.......Server(0xc082137a40, 0x0, 0x0)
    D:/golang/src/bitbucket.org/gamexg/.......go:104 +0x233
bitbucket.org/gamexg/......func2(0xc082147940, 0xc082137aa0)
    D:/golang/src/bitbucket.org/gamexg/........go:40 +0x2c
created by bitbucket.org/gamexg/.......Server
    D:/golang/src/bitbucket.org/gamexg/...........go:42 +0x9a

goroutine 21 [IO wait]:
net.runtime_pollWait(0x1604920, 0x72, 0xc082002038)
    C:/go/src/runtime/netpoll.go:160 +0x67
net.(*pollDesc).Wait(0xc082021670, 0x72, 0x0, 0x0)
    C:/go/src/net/fd_poll_runtime.go:73 +0x41
net.(*ioSrv).ExecIO(0xc082186148, 0xc082021560, 0xa30100, 0x8, 0xc0822ae040, 0xc082133c80, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:183 +0x177
net.(*netFD).acceptOne(0xc082021500, 0xc082050000, 0x2, 0x2, 0xc082021560, 0x98000004, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:583 +0x26c
net.(*netFD).accept(0xc082021500, 0x0, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:613 +0x173
net.(*TCPListener).AcceptTCP(0xc08202a070, 0x456520, 0x0, 0x0)
    C:/go/src/net/tcpsock_posix.go:254 +0x54
net/http.tcpKeepAliveListener.Accept(0xc08202a070, 0x0, 0x0, 0x0, 0x0)
    C:/go/src/net/http/server.go:2427 +0x48
net/http.(*Server).Serve(0xc0821680b0, 0x1b46f0, 0xc08202a070, 0x0, 0x0)
    C:/go/src/net/http/server.go:2117 +0x130
net/http.(*Server).ListenAndServe(0xc0821680b0, 0x0, 0x0)
    C:/go/src/net/http/server.go:2098 +0x13d
bitbucket.org/gamexg/......ListenAndServe(0xc0821680b0, 0x0, 0x0)
    D:/golang/src/bitbucket.org/gamexg/.......httpserver.go:253 +0x11d
bitbucket.org/gamexg/.........Server.func3(0xc082147940, 0xc082137aa0)
    D:/golang/src/bitbucket.org/gamexg/......./server.go:45 +0x2c
created by bitbucket.org/gamexg/.........Server
    D:/golang/src/bitbucket.org/gamexg/........server.go:47 +0xc6

goroutine 22 [chan send, 40 minutes]:
github.com/go-ozzo/ozzo-log.(*Logger).Log(0xc08212a0c0, 0x6, 0xafa0e0, 0x54, 0xc08211dde8, 0x2, 0x2)
    D:/golang/src/github.com/go-ozzo/ozzo-log/logger.go:204 +0x2d9
github.com/go-ozzo/ozzo-log.(*Logger).Info(0xc08212a0c0, 0xafa0e0, 0x54, 0xc08211dde8, 0x2, 0x2)
    D:/golang/src/github.com/go-ozzo/ozzo-log/logger.go:176 +0x63
bitbucket.org/gamexg/..........0xc082124bc0)
    D:/golang/src/bitbucket.org/........158 +0x66e
bitbucket.org/gamexg/yfforward/common/yfforward.(*flowServer).Server(0xc082124bc0, 0x0, 0x0)
    D:/golang/src/bitbucket.org/.........o:99 +0x31e
bitbucket.org/gamexg/yfforward/common/......erver.func4(0xc082147940, 0xc082137aa0)
    D:/golang/src/bitbucket.org/gamexg/.....50 +0x2c
created by bitbucket.org/gamexg/......).Server
    D:/golang/src/bitbucket.org/gamexg/......go:52 +0xf2

goroutine 34 [IO wait, 122 minutes]:
net.runtime_pollWait(0x16050a0, 0x72, 0xc082003498)
    C:/go/src/runtime/netpoll.go:160 +0x67
net.(*pollDesc).Wait(0xc08219e170, 0x72, 0x0, 0x0)
    C:/go/src/net/fd_poll_runtime.go:73 +0x41
net.(*ioSrv).ExecIO(0xc082186148, 0xc08219e060, 0xa30100, 0x8, 0xc0820c79a0, 0xc082021200, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:183 +0x177
net.(*netFD).acceptOne(0xc08219e000, 0xc0820502a0, 0x2, 0x2, 0xc08219e060, 0x1000, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:583 +0x26c
net.(*netFD).accept(0xc08219e000, 0x0, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:613 +0x173
net.(*TCPListener).AcceptTCP(0xc082186158, 0x455c30, 0x0, 0x0)
    C:/go/src/net/tcpsock_posix.go:254 +0x54
net.(*TCPListener).Accept(0xc082186158, 0x0, 0x0, 0x0, 0x0)
    C:/go/src/net/tcpsock_posix.go:264 +0x44
bitbucket.org/gamexg/........Server(0xc08217c320, 0x0, 0x0)
    D:/golang/src/bitbucket.org/gamexg/......go:98 +0xc1
created by bitbucket.org/gamexg/......
    D:/golang/src/bitbucket.org/gamexg/.......:195 +0xef6

goroutine 35 [IO wait, 122 minutes]:
net.runtime_pollWait(0x1604fe0, 0x72, 0xc082003530)
    C:/go/src/runtime/netpoll.go:160 +0x67
net.(*pollDesc).Wait(0xc08219e470, 0x72, 0x0, 0x0)
    C:/go/src/net/fd_poll_runtime.go:73 +0x41
net.(*ioSrv).ExecIO(0xc082186148, 0xc08219e360, 0xa30100, 0x8, 0xc0820c79c0, 0xc082021380, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:183 +0x177
net.(*netFD).acceptOne(0xc08219e300, 0xc082050380, 0x2, 0x2, 0xc08219e360, 0x0, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:583 +0x26c
net.(*netFD).accept(0xc08219e300, 0x0, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:613 +0x173
net.(*TCPListener).AcceptTCP(0xc082186160, 0x455c30, 0x0, 0x0)
    C:/go/src/net/tcpsock_posix.go:254 +0x54
net.(*TCPListener).Accept(0xc082186160, 0x0, 0x0, 0x0, 0x0)
    C:/go/src/net/tcpsock_posix.go:264 +0x44
bitbucket.org/gamexg/.......Server(0xc08217c3c0, 0x0, 0x0)
    D:/golang/src/bitbucket.org/gamexg/.......go:98 +0xc1
created by bitbucket.org/gamexg/....
    D:/golang/src/bitbucket.org/gamexg/.......:195 +0xef6

goroutine 36 [IO wait, 122 minutes]:
net.runtime_pollWait(0x1604f20, 0x72, 0xc082003490)
    C:/go/src/runtime/netpoll.go:160 +0x67
net.(*pollDesc).Wait(0xc08219e770, 0x72, 0x0, 0x0)
    C:/go/src/net/fd_poll_runtime.go:73 +0x41
net.(*ioSrv).ExecIO(0xc082186148, 0xc08219e660, 0xa30100, 0x8, 0xc0820c7920, 0xc082021080, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:183 +0x177
net.(*netFD).acceptOne(0xc08219e600, 0xc0820501c0, 0x2, 0x2, 0xc08219e660, 0x0, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:583 +0x26c
net.(*netFD).accept(0xc08219e600, 0x0, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:613 +0x173
net.(*TCPListener).AcceptTCP(0xc082186168, 0x455c30, 0x0, 0x0)
    C:/go/src/net/tcpsock_posix.go:254 +0x54
net.(*TCPListener).Accept(0xc082186168, 0x0, 0x0, 0x0, 0x0)
    C:/go/src/net/tcpsock_posix.go:264 +0x44
bitbucket.org/gamexg/..........Server(0xc08217c460, 0x0, 0x0)
    D:/golang/src/bitbucket.org/gamexg/......:98 +0xc1
created by bitbucket.org/gamexg/.....
    D:/golang/src/bitbucket.org/gamexg/......:195 +0xef6

goroutine 37 [IO wait, 122 minutes]:
net.runtime_pollWait(0x1604e60, 0x72, 0xc082003610)
    C:/go/src/runtime/netpoll.go:160 +0x67
net.(*pollDesc).Wait(0xc08219ea70, 0x72, 0x0, 0x0)
    C:/go/src/net/fd_poll_runtime.go:73 +0x41
net.(*ioSrv).ExecIO(0xc082186148, 0xc08219e960, 0xa30100, 0x8, 0xc0820c7aa0, 0xc082021980, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:183 +0x177
net.(*netFD).acceptOne(0xc08219e900, 0xc082050620, 0x2, 0x2, 0xc08219e960, 0x0, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:583 +0x26c
net.(*netFD).accept(0xc08219e900, 0x0, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:613 +0x173
net.(*TCPListener).AcceptTCP(0xc082186170, 0x455c30, 0x0, 0x0)
    C:/go/src/net/tcpsock_posix.go:254 +0x54
net.(*TCPListener).Accept(0xc082186170, 0x0, 0x0, 0x0, 0x0)
    C:/go/src/net/tcpsock_posix.go:264 +0x44
bitbucket.org/gamexg/........Server(0xc08217c500, 0x0, 0x0)
    D:/golang/src/bitbucket.org/gamexg/......go:98 +0xc1
created by bitbucket.org/gamexg/..........
    D:/golang/src/bitbucket.org/gamexg/yfforward/common/.....:195 +0xef6

goroutine 38 [IO wait, 122 minutes]:
net.runtime_pollWait(0x1604da0, 0x72, 0xc0820035f8)
    C:/go/src/runtime/netpoll.go:160 +0x67
net.(*pollDesc).Wait(0xc08219ed70, 0x72, 0x0, 0x0)
    C:/go/src/net/fd_poll_runtime.go:73 +0x41
net.(*ioSrv).ExecIO(0xc082186148, 0xc08219ec60, 0xa30100, 0x8, 0xc0820c7a80, 0xc082021800, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:183 +0x177
net.(*netFD).acceptOne(0xc08219ec00, 0xc082050540, 0x2, 0x2, 0xc08219ec60, 0x0, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:583 +0x26c
net.(*netFD).accept(0xc08219ec00, 0x0, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:613 +0x173
net.(*TCPListener).AcceptTCP(0xc082186178, 0x455c30, 0x0, 0x0)
    C:/go/src/net/tcpsock_posix.go:254 +0x54
net.(*TCPListener).Accept(0xc082186178, 0x0, 0x0, 0x0, 0x0)
    C:/go/src/net/tcpsock_posix.go:264 +0x44
bitbucket.org/gamexg/yfforward/common/........Server(0xc08217c5a0, 0x0, 0x0)
    D:/golang/src/bitbucket.org/gamexg/.......go:98 +0xc1
created by bitbucket.org/gamexg/........
    D:/golang/src/bitbucket.org/gamexg/.........195 +0xef6

goroutine 39 [IO wait, 122 minutes]:
net.runtime_pollWait(0x1604ce0, 0x72, 0xc082003618)
    C:/go/src/runtime/netpoll.go:160 +0x67
net.(*pollDesc).Wait(0xc08219f070, 0x72, 0x0, 0x0)
    C:/go/src/net/fd_poll_runtime.go:73 +0x41
net.(*ioSrv).ExecIO(0xc082186148, 0xc08219ef60, 0xa30100, 0x8, 0xc0820c7ac0, 0xc082021b00, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:183 +0x177
net.(*netFD).acceptOne(0xc08219ef00, 0xc082050700, 0x2, 0x2, 0xc08219ef60, 0x0, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:583 +0x26c
net.(*netFD).accept(0xc08219ef00, 0x0, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:613 +0x173
net.(*TCPListener).AcceptTCP(0xc082186180, 0x455c30, 0x0, 0x0)
    C:/go/src/net/tcpsock_posix.go:254 +0x54
net.(*TCPListener).Accept(0xc082186180, 0x0, 0x0, 0x0, 0x0)
    C:/go/src/net/tcpsock_posix.go:264 +0x44
bitbucket.org/gamexg/.......Server(0xc08217c640, 0x0, 0x0)
    D:/golang/src/bitbucket.org/gamexg/.......:98 +0xc1
created by bitbucket.org/gamexg/yfforward/common/........
    D:/golang/src/bitbucket.org/gamexg/.......go:195 +0xef6

goroutine 40 [IO wait, 122 minutes]:
net.runtime_pollWait(0x1604c20, 0x72, 0xc082176c60)
    C:/go/src/runtime/netpoll.go:160 +0x67
net.(*pollDesc).Wait(0xc08219f370, 0x72, 0x0, 0x0)
    C:/go/src/net/fd_poll_runtime.go:73 +0x41
net.(*ioSrv).ExecIO(0xc082186148, 0xc08219f260, 0xa30100, 0x8, 0xc082180ec0, 0xc08219f800, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:183 +0x177
net.(*netFD).acceptOne(0xc08219f200, 0xc08221c000, 0x2, 0x2, 0xc08219f260, 0x0, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:583 +0x26c
net.(*netFD).accept(0xc08219f200, 0x0, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:613 +0x173
net.(*TCPListener).AcceptTCP(0xc082186188, 0x455c30, 0x0, 0x0)
    C:/go/src/net/tcpsock_posix.go:254 +0x54
net.(*TCPListener).Accept(0xc082186188, 0x0, 0x0, 0x0, 0x0)
    C:/go/src/net/tcpsock_posix.go:264 +0x44
bitbucket.org/gamexg/..........Server(0xc08217c6e0, 0x0, 0x0)
    D:/golang/src/bitbucket.org/gamexg/.......go:98 +0xc1
created by bitbucket.org/gamexg/yfforward/common/.......
    D:/golang/src/bitbucket.org/gamexg/.......go:195 +0xef6

goroutine 7 [IO wait]:
net.runtime_pollWait(0x16044a0, 0x72, 0xc08226a8d0)
    C:/go/src/runtime/netpoll.go:160 +0x67
net.(*pollDesc).Wait(0xc082021df0, 0x72, 0x0, 0x0)
    C:/go/src/net/fd_poll_runtime.go:73 +0x41
net.(*ioSrv).ExecIO(0xc082186148, 0xc082021ce0, 0xa26ee0, 0x7, 0xb2c7f0, 0x22c, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:183 +0x177
net.(*netFD).Read(0xc082021c80, 0xc082220000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    C:/go/src/net/fd_windows.go:482 +0x17e
net.(*conn).Read(0xc08202a1a8, 0xc082220000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    C:/go/src/net/net.go:172 +0xeb
net/http.(*connReader).Read(0xc082239620, 0xc082220000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    C:/go/src/net/http/server.go:526 +0x19d
bufio.(*Reader).fill(0xc082013560)
    C:/go/src/bufio/bufio.go:97 +0x1f0
bufio.(*Reader).Peek(0xc082013560, 0x4, 0x0, 0x0, 0x0, 0x0, 0x0)
    C:/go/src/bufio/bufio.go:132 +0xd3
net/http.(*conn).readRequest(0xc08228d400, 0x0, 0x0, 0x0)
    C:/go/src/net/http/server.go:702 +0x2ed
net/http.(*conn).serve(0xc08228d400)
    C:/go/src/net/http/server.go:1425 +0x94e
created by net/http.(*Server).Serve
    C:/go/src/net/http/server.go:2137 +0x455

goroutine 27 [chan send, 36 minutes]:
github.com/go-ozzo/ozzo-log.(*Logger).Log(0xc08212a0c0, 0x6, 0xa89160, 0x14, 0xc0824539f0, 0x3, 0x3)
    D:/golang/src/github.com/go-ozzo/ozzo-log/logger.go:204 +0x2d9
github.com/go-ozzo/ozzo-log.(*Logger).Info(0xc08212a0c0, 0xa89160, 0x14, 0xc0824539f0, 0x3, 0x3)
    D:/golang/src/github.com/go-ozzo/ozzo-log/logger.go:176 +0x63
bitbucket.org/gamexg/........(0xc0821680b0, 0x1154df8, 0xc0820d0000, 0xc08221c0e0)
    D:/golang/src/bitbucket.org/gamexg/...........:81 +0x58c
bitbucket.org/gamexg/..........-fm(0x1154df8, 0xc0820d0000, 0xc08221c0e0)
    D:/golang/src/bitbucket.org/gamexg/.........:64 +0x45
net/http.HandlerFunc.ServeHTTP(0xc08212db90, 0x1154df8, 0xc0820d0000, 0xc08221c0e0)
    C:/go/src/net/http/server.go:1618 +0x41
net/http.(*ServeMux).ServeHTTP(0xc082148c30, 0x1154df8, 0xc0820d0000, 0xc08221c0e0)
    C:/go/src/net/http/server.go:1910 +0x184
net/http.serverHandler.ServeHTTP(0xc0821680b0, 0x1154df8, 0xc0820d0000, 0xc08221c0e0)
    C:/go/src/net/http/server.go:2081 +0x1a5
net/http.(*conn).serve(0xc082134080)
    C:/go/src/net/http/server.go:1472 +0xf35
created by net/http.(*Server).Serve
    C:/go/src/net/http/server.go:2137 +0x455

goroutine 9 [chan send, 7 minutes]:
github.com/go-ozzo/ozzo-log.(*Logger).Log(0xc08212a0c0, 0x6, 0xa89160, 0x14, 0xc0822d99f0, 0x3, 0x3)
    D:/golang/src/github.com/go-ozzo/ozzo-log/logger.go:204 +0x2d9
github.com/go-ozzo/ozzo-log.(*Logger).Info(0xc08212a0c0, 0xa89160, 0x14, 0xc0822d99f0, 0x3, 0x3)
    D:/golang/src/github.com/go-ozzo/ozzo-log/logger.go:176 +0x63
bitbucket.org/gamexg/.....(0xc0821680b0, 0x1154df8, 0xc0821381a0, 0xc082050a80)
    D:/golang/src/bitbucket.org/gamexg/.....81 +0x58c
bitbucket.org/gamexg/yfforward/common/......m(0x1154df8, 0xc0821381a0, 0xc082050a80)
    D:/golang/src/bitbucket.org/gamexg/......go:64 +0x45
net/http.HandlerFunc.ServeHTTP(0xc08212db90, 0x1154df8, 0xc0821381a0, 0xc082050a80)
    C:/go/src/net/http/server.go:1618 +0x41
net/http.(*ServeMux).ServeHTTP(0xc082148c30, 0x1154df8, 0xc0821381a0, 0xc082050a80)
    C:/go/src/net/http/server.go:1910 +0x184
net/http.serverHandler.ServeHTTP(0xc0821680b0, 0x1154df8, 0xc0821381a0, 0xc082050a80)
    C:/go/src/net/http/server.go:2081 +0x1a5
net/http.(*conn).serve(0xc082328980)
    C:/go/src/net/http/server.go:1472 +0xf35
created by net/http.(*Server).Serve
    C:/go/src/net/http/server.go:2137 +0x455

几个写日志操作都是阻塞在 l.entries <- entry

ghost commented 8 years ago

··· goroutine 18 [runnable, locked to thread]: syscall.Syscall(0x7ffa104ada60, 0x3, 0xc0823c4360, 0x0, 0xc08245ad90, 0x15, 0xc0823c4360, 0x16) C:/go/src/runtime/syscall_windows.go:163 +0x5c syscall.GetFileAttributesEx(0xc0823c4360, 0x0, 0xc08245ad90, 0x0, 0x0) C:/go/src/syscall/zsyscall_windows.go:867 +0x7d os.Lstat(0xc082284d80, 0x15, 0x0, 0x0, 0x0, 0x0) C:/go/src/os/stat_windows.go:85 +0x498 github.com/go-ozzo/ozzo-log.(_FileTarget).rotate(0xc082136120, 0x42) D:/golang/src/github.com/go-ozzo/ozzo-log/file.go:112 +0x25d github.com/go-ozzo/ozzo-log.(_FileTarget).Process(0xc082136120, 0xc082207560) D:/golang/src/github.com/go-ozzo/ozzo-log/file.go:84 +0x11d github.com/go-ozzo/ozzo-log.(_coreLogger).process(0xc0820140e0) D:/golang/src/github.com/go-ozzo/ozzo-log/logger.go:250 +0xd7 created by github.com/go-ozzo/ozzo-log.(_coreLogger).Open D:/golang/src/github.com/go-ozzo/ozzo-log/logger.go:238 +0x6a6 ···

确认故障位置，但是更难处理了... windows 系统问题？只能继续测试了...

ghost commented 8 years ago

确定了故障原因，稍后提交补丁。

go-ozzo / ozzo-log

持续运行几个小时后日志调用会阻塞。 #8