hhkbp2/go-logging

Getting a map concurrency issue during a load test

Closed this issue · 2 comments

smaheshs commented

Hi,

Though I have been using this library for quite some time, got this crash for the very first time.

fatal error: concurrent map iteration and map write

goroutine 8 [running]:
runtime.throw(0x12b7bdb, 0x26)
        /usr/local/go/src/runtime/panic.go:1117 +0x72 fp=0xc0009907e8 sp=0xc0009907b8 pc=0x4380f2
runtime.mapiternext(0xc00511a3c0)
        /usr/local/go/src/runtime/map.go:858 +0x54c fp=0xc000990868 sp=0xc0009907e8 pc=0x41270c
runtime.mapiterinit(0x1155060, 0xc0017e8750, 0xc00511a3c0)
        /usr/local/go/src/runtime/map.go:848 +0x1c5 fp=0xc000990888 sp=0xc000990868 pc=0x4120c5
reflect.mapiterinit(0x1155060, 0xc0017e8750, 0xc0004f9aa0)
        /usr/local/go/src/runtime/map.go:1340 +0x54 fp=0xc0009908b8 sp=0xc000990888 pc=0x467c14
reflect.(*MapIter).Next(0xc0001697a0, 0xc0017e8750)
        /usr/local/go/src/reflect/value.go:1272 +0x6a fp=0xc0009908e0 sp=0xc0009908b8 pc=0x4a290a
internal/fmtsort.Sort(0x1155060, 0xc0017e8750, 0x15, 0x120)
        /usr/local/go/src/internal/fmtsort/sort.go:63 +0x1af fp=0xc000990990 sp=0xc0009908e0 pc=0x4b3d2f
fmt.(*pp).printValue(0xc0003eb6c0, 0x1155060, 0xc0017e8750, 0x15, 0x76, 0x0)
        /usr/local/go/src/fmt/print.go:769 +0xca5 fp=0xc000990b50 sp=0xc000990990 pc=0x4f76a5
fmt.(*pp).printArg(0xc0003eb6c0, 0x1155060, 0xc0017e8750, 0x76)
        /usr/local/go/src/fmt/print.go:712 +0x2d3 fp=0xc000990be8 sp=0xc000990b50 pc=0x4f62d3
fmt.(*pp).doPrintf(0xc0003eb6c0, 0x12bda4b, 0x2a, 0xc003a0d870, 0x1, 0x1)
        /usr/local/go/src/fmt/print.go:1026 +0x168 fp=0xc000990cd8 sp=0xc000990be8 pc=0x4f9908
fmt.Sprintf(0x12bda4b, 0x2a, 0xc003a0d870, 0x1, 0x1, 0xe, 0x0)
        /usr/local/go/src/fmt/print.go:219 +0x66 fp=0xc000990d30 sp=0xc000990cd8 pc=0x4f2c46
github.com/hhkbp2/go-logging.(*LogRecord).GetMessage(0xc00373ed80, 0x453ee5, 0xc00323fce0)
        /home/newgo/pkg/mod/github.com/hhkbp2/go-logging@v0.3.0/record.go:69 +0x8a fp=0xc000990d80 sp=0xc000990d30 pc=0x9ccb8a
github.com/hhkbp2/go-logging.(*StandardFormatter).Format(0xc00008e910, 0xc00373ed80, 0x0, 0xc000990f10)
        /home/newgo/pkg/mod/github.com/hhkbp2/go-logging@v0.3.0/formatter.go:174 +0x2f fp=0xc000990dc0 sp=0xc000990d80 pc=0x9c1f2f
github.com/hhkbp2/go-logging.(*BaseHandler).Format(0xc000118380, 0xc00373ed80, 0x0, 0x0)
        /home/newgo/pkg/mod/github.com/hhkbp2/go-logging@v0.3.0/handler.go:124 +0x86 fp=0xc000990e08 sp=0xc000990dc0 pc=0x9c2646
github.com/hhkbp2/go-logging.(*RotatingFileHandler).ShouldRollover(0xc0002f6e80, 0xc00373ed80, 0xd2, 0x1, 0x2)
        /home/newgo/pkg/mod/github.com/hhkbp2/go-logging@v0.3.0/handler_rotating_file.go:193 +0x47 fp=0xc000990e48 sp=0xc000990e08 pc=0x9c4aa7
github.com/hhkbp2/go-logging.(*BaseRotatingHandler).RolloverEmit(0xc0001223c8, 0x1518ff8, 0xc0002f6e80, 0xc00373ed80, 0x0, 0x0)
        /home/newgo/pkg/mod/github.com/hhkbp2/go-logging@v0.3.0/handler_rotating_file.go:59 +0x42 fp=0xc000990e90 sp=0xc000990e48 pc=0x9c4622
github.com/hhkbp2/go-logging.(*RotatingFileHandler).Emit(0xc0002f6e80, 0xc00373ed80, 0x1, 0x0)
        /home/newgo/pkg/mod/github.com/hhkbp2/go-logging@v0.3.0/handler_rotating_file.go:251 +0x49 fp=0xc000990ed0 sp=0xc000990e90 pc=0x9c5109
github.com/hhkbp2/go-logging.(*BaseHandler).Handle2(0xc000118380, 0x1517570, 0xc0002f6e80, 0xc00373ed80, 0x0)
        /home/newgo/pkg/mod/github.com/hhkbp2/go-logging@v0.3.0/handler.go:137 +0xbc fp=0xc000990f20 sp=0xc000990ed0 pc=0x9c279c
github.com/hhkbp2/go-logging.(*RotatingFileHandler).loop(0xc0002f6e80)
        /home/newgo/pkg/mod/github.com/hhkbp2/go-logging@v0.3.0/handler_rotating_file.go:272 +0xf8 fp=0xc000990fa8 sp=0xc000990f20 pc=0x9c5238
github.com/hhkbp2/go-logging.NewRotatingFileHandler.func1(0xc0002f6e80)
        /home/newgo/pkg/mod/github.com/hhkbp2/go-logging@v0.3.0/handler_rotating_file.go:156 +0x52 fp=0xc000990fd8 sp=0xc000990fa8 pc=0x9cdcb2
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1371 +0x1 fp=0xc000990fe0 sp=0xc000990fd8 pc=0x46db61
created by github.com/hhkbp2/go-logging.NewRotatingFileHandler
        /home/newgo/pkg/mod/github.com/hhkbp2/go-logging@v0.3.0/handler_rotating_file.go:154 +0x215

There is no information in the stack trace about my application code that could be causing this issue and all the coroutines are in IO Wait or select states.

The config file I use for logging is attached and I use Go 1.16.

Any help would be greatly appreciated.

Thanks.
logconfig.txt

hhkbp2 commented

Hi,

The last function call on this printed stack before entering standard fmt library

github.com/hhkbp2/go-logging.(*LogRecord).GetMessage(0xc00373ed80, 0x453ee5, 0xc00323fce0)
        /home/newgo/pkg/mod/github.com/hhkbp2/go-logging@v0.3.0/record.go:69 +0x8a fp=0xc000990d80 sp=0xc000990d30 pc=0x9ccb8a

does simply format the log message using application specified format and arguments, as the following code shows

self.Message = fmt.Sprintf(self.Format, self.Args...)

There is no map in struct LogRecord. So I suspect that a map was used as format argument, and while the background flush goroutine of RotatingFileHandler was calling the code above(record.go:69) to read this map to construct the log message, this map was written somewhere else(in another goroutine of course), and then you got crash.

Please check if there is a map involved in log message argument list and how this map is used later in your application code.

smaheshs commented

Thanks a lot. Your input really helped in finding the cause of the issue. Problem was that was seeing the log line as a synchronous call instead of asynchronous. A map was being written after it was being logged.