Out of memory crash

[Raoul]

Hi,

mtail was running fine on one of my hosts for about 2 weeks now and then crashed with an out of memory error and the following dump:

Dec  7 06:30:42 host01 mtail: fatal error: runtime: out of memory
Dec  7 06:30:42 host01 mtail: runtime stack:
Dec  7 06:30:42 host01 mtail: runtime.throw(0x876750, 0x16)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/runtime/panic.go:608 +0x72
Dec  7 06:30:42 host01 mtail: runtime.sysMap(0xc028000000, 0xc000000, 0xbd08b8)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/runtime/mem_linux.go:156 +0xc7
Dec  7 06:30:42 host01 mtail: runtime.(*mheap).sysAlloc(0xbb7500, 0xc000000, 0x80, 0x0)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/runtime/malloc.go:619 +0x1c7
Dec  7 06:30:42 host01 mtail: runtime.(*mheap).grow(0xbb7500, 0x5940, 0x0)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/runtime/mheap.go:920 +0x42
Dec  7 06:30:42 host01 mtail: runtime.(*mheap).allocSpanLocked(0xbb7500, 0x5940, 0xbd08c8, 0x434d33)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/runtime/mheap.go:848 +0x337
Dec  7 06:30:42 host01 mtail: runtime.(*mheap).alloc_m(0xbb7500, 0x5940, 0x100, 0x7f66701fb500)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/runtime/mheap.go:692 +0x119
Dec  7 06:30:42 host01 mtail: runtime.(*mheap).alloc.func1()
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/runtime/mheap.go:759 +0x4c
Dec  7 06:30:42 host01 mtail: runtime.(*mheap).alloc(0xbb7500, 0x5940, 0x7f6671010100, 0x7f667174ae58)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/runtime/mheap.go:758 +0x8a
Dec  7 06:30:42 host01 mtail: runtime.largeAlloc(0xb280000, 0x1, 0x61172276ce9e)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/runtime/malloc.go:1019 +0x97
Dec  7 06:30:42 host01 mtail: runtime.mallocgc.func1()
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/runtime/malloc.go:914 +0x46
Dec  7 06:30:42 host01 mtail: runtime.systemstack(0x0)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/runtime/asm_amd64.s:351 +0x66
Dec  7 06:30:42 host01 mtail: runtime.mstart()
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/runtime/proc.go:1229
Dec  7 06:30:42 host01 mtail: goroutine 13 [running]:
Dec  7 06:30:42 host01 mtail: runtime.systemstack_switch()
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/runtime/asm_amd64.s:311 fp=0xc00004e6a0 sp=0xc00004e698 pc=0x45b360
Dec  7 06:30:42 host01 mtail: runtime.mallocgc(0xb280000, 0x82e580, 0xc00004e801, 0x77070b)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/runtime/malloc.go:913 +0x896 fp=0xc00004e740 sp=0xc00004e6a0 pc=0x40dde6
Dec  7 06:30:42 host01 mtail: runtime.newarray(0x82e580, 0x88000, 0x0)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/runtime/malloc.go:1048 +0x6a fp=0xc00004e770 sp=0xc00004e740 pc=0x40e1ba
Dec  7 06:30:42 host01 mtail: runtime.makeBucketArray(0x7efd00, 0x13, 0x0, 0x777fa0, 0xc00004e860)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/runtime/map.go:355 +0x184 fp=0xc00004e7a8 sp=0xc00004e770 pc=0x40f084
Dec  7 06:30:42 host01 mtail: runtime.hashGrow(0x7efd00, 0xc000141200)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/runtime/map.go:963 +0x89 fp=0xc00004e7f8 sp=0xc00004e7a8 pc=0x4108d9
Dec  7 06:30:42 host01 mtail: runtime.mapassign_faststr(0x7efd00, 0xc000141200, 0xc0270532c0, 0xf, 0xf)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/runtime/map_faststr.go:256 +0x206 fp=0xc00004e860 sp=0xc00004e7f8 pc=0x4140e6
Dec  7 06:30:42 host01 mtail: github.com/google/mtail/vm.(*VM).execute(0xc000089d60, 0xc00007f9a0, 0x8, 0x7d30a0, 0xc00014c030)
Dec  7 06:30:42 host01 mtail: /go/src/github.com/google/mtail/vm/vm.go:446 +0x3941 fp=0xc00004ef10 sp=0xc00004e860 pc=0x7740f1
Dec  7 06:30:42 host01 mtail: github.com/google/mtail/vm.(*VM).processLine(0xc000089d60, 0xc00049f7e0)
Dec  7 06:30:42 host01 mtail: /go/src/github.com/google/mtail/vm/vm.go:692 +0x140 fp=0xc00004ef58 sp=0xc00004ef10 pc=0x7761f0
Dec  7 06:30:42 host01 mtail: github.com/google/mtail/vm.(*VM).Run(0xc000089d60, 0x69707461, 0xc0000672c0, 0xc000067320, 0xc000067380)
Dec  7 06:30:42 host01 mtail: /go/src/github.com/google/mtail/vm/vm.go:711 +0xf5 fp=0xc00004efb8 sp=0xc00004ef58 pc=0x776385
Dec  7 06:30:42 host01 mtail: runtime.goexit()
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/runtime/asm_amd64.s:1333 +0x1 fp=0xc00004efc0 sp=0xc00004efb8 pc=0x45d441
Dec  7 06:30:42 host01 mtail: created by github.com/google/mtail/vm.(*MasterControl).CompileAndRun
Dec  7 06:30:42 host01 mtail: /go/src/github.com/google/mtail/vm/mcp.go:241 +0x70d
Dec  7 06:30:42 host01 mtail: goroutine 1 [select, 29642 minutes]:
Dec  7 06:30:42 host01 mtail: github.com/google/mtail/mtail.(*MtailServer).WaitForShutdown(0xc0000820c0)
Dec  7 06:30:42 host01 mtail: /go/src/github.com/google/mtail/mtail/mtail.go:362 +0x13b
Dec  7 06:30:42 host01 mtail: github.com/google/mtail/mtail.(*MtailServer).Serve(0xc0000820c0, 0x0, 0x0)
Dec  7 06:30:42 host01 mtail: /go/src/github.com/google/mtail/mtail/mtail.go:344 +0x1f1
Dec  7 06:30:42 host01 mtail: github.com/google/mtail/mtail.(*MtailServer).Run(0xc0000820c0, 0x8e6540, 0xc000020a20)
Dec  7 06:30:42 host01 mtail: /go/src/github.com/google/mtail/mtail/mtail.go:422 +0x176
Dec  7 06:30:42 host01 mtail: main.main()
Dec  7 06:30:42 host01 mtail: /go/src/github.com/google/mtail/main.go:153 +0x6fd
Dec  7 06:30:42 host01 mtail: goroutine 5 [chan receive, 2 minutes]:
Dec  7 06:30:42 host01 mtail: github.com/golang/glog.(*loggingT).flushDaemon(0xbb14a0)
Dec  7 06:30:42 host01 mtail: /go/src/github.com/golang/glog/glog.go:882 +0x8b
Dec  7 06:30:42 host01 mtail: created by github.com/golang/glog.init.0
Dec  7 06:30:42 host01 mtail: /go/src/github.com/golang/glog/glog.go:410 +0x203
Dec  7 06:30:42 host01 mtail: goroutine 6 [syscall, 29642 minutes]:
Dec  7 06:30:42 host01 mtail: os/signal.signal_recv(0x0)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/runtime/sigqueue.go:139 +0x9c
Dec  7 06:30:42 host01 mtail: os/signal.loop()
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/os/signal/signal_unix.go:23 +0x22
Dec  7 06:30:42 host01 mtail: created by os/signal.init.0
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/os/signal/signal_unix.go:29 +0x41
Dec  7 06:30:42 host01 mtail: goroutine 19 [chan receive, 29642 minutes]:
Dec  7 06:30:42 host01 mtail: github.com/google/mtail/watcher.(*LogWatcher).run.func1(0xc000020a20)
Dec  7 06:30:42 host01 mtail: /go/src/github.com/google/mtail/watcher/log_watcher.go:83 +0x98
Dec  7 06:30:42 host01 mtail: created by github.com/google/mtail/watcher.(*LogWatcher).run
Dec  7 06:30:42 host01 mtail: /go/src/github.com/google/mtail/watcher/log_watcher.go:82 +0x85
Dec  7 06:30:42 host01 mtail: goroutine 8 [runnable]:
Dec  7 06:30:42 host01 mtail: syscall.Syscall6(0xe8, 0x5, 0xc000189cf4, 0x7, 0xffffffffffffffff, 0x0, 0x0, 0x1, 0x7, 0x0)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/syscall/asm_linux_amd64.s:44 +0x5
Dec  7 06:30:42 host01 mtail: golang.org/x/sys/unix.EpollWait(0x5, 0xc000189cf4, 0x7, 0x7, 0xffffffffffffffff, 0x498f39, 0x0, 0x0)
Dec  7 06:30:42 host01 mtail: /go/src/golang.org/x/sys/unix/zsyscall_linux_amd64.go:1615 +0x72
Dec  7 06:30:42 host01 mtail: github.com/fsnotify/fsnotify.(*fdPoller).wait(0xc0000262c0, 0xc000189d00, 0x2, 0x0)
Dec  7 06:30:42 host01 mtail: /go/src/github.com/fsnotify/fsnotify/inotify_poller.go:86 +0x91
Dec  7 06:30:42 host01 mtail: github.com/fsnotify/fsnotify.(*Watcher).readEvents(0xc00007e280)
Dec  7 06:30:42 host01 mtail: /go/src/github.com/fsnotify/fsnotify/inotify.go:192 +0x195
Dec  7 06:30:42 host01 mtail: created by github.com/fsnotify/fsnotify.NewWatcher
Dec  7 06:30:42 host01 mtail: /go/src/github.com/fsnotify/fsnotify/inotify.go:59 +0x1a8
Dec  7 06:30:42 host01 mtail: goroutine 9 [chan receive]:
Dec  7 06:30:42 host01 mtail: github.com/google/mtail/watcher.(*LogWatcher).run(0xc000020a20)
Dec  7 06:30:42 host01 mtail: /go/src/github.com/google/mtail/watcher/log_watcher.go:88 +0xcb
Dec  7 06:30:42 host01 mtail: created by github.com/google/mtail/watcher.NewLogWatcher
Dec  7 06:30:42 host01 mtail: /go/src/github.com/google/mtail/watcher/log_watcher.go:48 +0x12b
Dec  7 06:30:42 host01 mtail: goroutine 10 [chan receive, 15669 minutes]:
Dec  7 06:30:42 host01 mtail: github.com/google/mtail/vm.(*MasterControl).processEvents(0xc000088d20, 0xc0000664e0)
Dec  7 06:30:42 host01 mtail: /go/src/github.com/google/mtail/vm/mcp.go:378 +0x98
Dec  7 06:30:42 host01 mtail: created by github.com/google/mtail/vm.NewLoader
Dec  7 06:30:42 host01 mtail: /go/src/github.com/google/mtail/vm/mcp.go:353 +0x256
Dec  7 06:30:42 host01 mtail: goroutine 11 [chan receive]:
Dec  7 06:30:42 host01 mtail: github.com/google/mtail/vm.(*MasterControl).processLines(0xc000088d20, 0xc000066360)
Dec  7 06:30:42 host01 mtail: /go/src/github.com/google/mtail/vm/mcp.go:408 +0x115
Dec  7 06:30:42 host01 mtail: created by github.com/google/mtail/vm.NewLoader
Dec  7 06:30:42 host01 mtail: /go/src/github.com/google/mtail/vm/mcp.go:354 +0x285
Dec  7 06:30:42 host01 mtail: goroutine 12 [runnable]:
Dec  7 06:30:42 host01 mtail: github.com/google/mtail/vm.(*VM).Run(0xc000089b80, 0x62696e64, 0xc000066ba0, 0xc000066c00, 0xc000066c60)
Dec  7 06:30:42 host01 mtail: /go/src/github.com/google/mtail/vm/vm.go:709 +0x10d
Dec  7 06:30:42 host01 mtail: created by github.com/google/mtail/vm.(*MasterControl).CompileAndRun
Dec  7 06:30:42 host01 mtail: /go/src/github.com/google/mtail/vm/mcp.go:241 +0x70d
Dec  7 06:30:42 host01 mtail: goroutine 14 [select]:
Dec  7 06:30:42 host01 mtail: github.com/google/mtail/tailer.(*Tailer).run(0xc0000fc990, 0xc000067440)
Dec  7 06:30:42 host01 mtail: /go/src/github.com/google/mtail/tailer/tail.go:321 +0x152
Dec  7 06:30:42 host01 mtail: created by github.com/google/mtail/tailer.New
Dec  7 06:30:42 host01 mtail: /go/src/github.com/google/mtail/tailer/tail.go:100 +0x1c6
Dec  7 06:30:42 host01 mtail: goroutine 15 [IO wait, 21358 minutes]:
Dec  7 06:30:42 host01 mtail: internal/poll.runtime_pollWait(0x7f6677ad9f00, 0x72, 0x0)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/runtime/netpoll.go:173 +0x66
Dec  7 06:30:42 host01 mtail: internal/poll.(*pollDesc).wait(0xc00001f518, 0x72, 0xc000148200, 0x0, 0x0)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/internal/poll/fd_poll_runtime.go:85 +0x9a
Dec  7 06:30:42 host01 mtail: internal/poll.(*pollDesc).waitRead(0xc00001f518, 0xffffffffffffff00, 0x0, 0x0)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/internal/poll/fd_poll_runtime.go:90 +0x3d
Dec  7 06:30:42 host01 mtail: internal/poll.(*FD).Accept(0xc00001f500, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/internal/poll/fd_unix.go:384 +0x1a0
Dec  7 06:30:42 host01 mtail: net.(*netFD).accept(0xc00001f500, 0x40d83f, 0xc000088640, 0xa0)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/net/fd_unix.go:238 +0x42
Dec  7 06:30:42 host01 mtail: net.(*TCPListener).accept(0xc00000e380, 0xc000049dd8, 0x1b10da07, 0xf605ca9d7095bb55)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/net/tcpsock_posix.go:139 +0x2e
Dec  7 06:30:42 host01 mtail: net.(*TCPListener).AcceptTCP(0xc00000e380, 0xc000049e00, 0x48a176, 0x5bf67824)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/net/tcpsock.go:247 +0x47
Dec  7 06:30:42 host01 mtail: net/http.tcpKeepAliveListener.Accept(0xc00000e380, 0xc000049e50, 0x18, 0xc000108a80, 0x6e3035)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/net/http/server.go:3232 +0x2f
Dec  7 06:30:42 host01 mtail: net/http.(*Server).Serve(0xc00010d930, 0x8e6080, 0xc00000e380, 0x0, 0x0)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/net/http/server.go:2826 +0x22f
Dec  7 06:30:42 host01 mtail: net/http.(*Server).ListenAndServe(0xc00010d930, 0xc00010d930, 0x1)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/net/http/server.go:2764 +0xb6
Dec  7 06:30:42 host01 mtail: net/http.ListenAndServe(0xc0000225e3, 0x5, 0x0, 0x0, 0x1, 0x0)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/net/http/server.go:3004 +0x74
Dec  7 06:30:42 host01 mtail: github.com/google/mtail/mtail.(*MtailServer).Serve.func1(0xc0000820c0)
Dec  7 06:30:42 host01 mtail: /go/src/github.com/google/mtail/mtail/mtail.go:339 +0xb5
Dec  7 06:30:42 host01 mtail: created by github.com/google/mtail/mtail.(*MtailServer).Serve
Dec  7 06:30:42 host01 mtail: /go/src/github.com/google/mtail/mtail/mtail.go:337 +0x1e3
Dec  7 06:30:42 host01 mtail: goroutine 124312 [IO wait, 2 minutes]:
Dec  7 06:30:42 host01 mtail: internal/poll.runtime_pollWait(0x7f6677ad9e30, 0x72, 0xc0000c5858)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/runtime/netpoll.go:173 +0x66
Dec  7 06:30:42 host01 mtail: internal/poll.(*pollDesc).wait(0xc00001e718, 0x72, 0xffffffffffffff00, 0x8e2e00, 0xb6f690)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/internal/poll/fd_poll_runtime.go:85 +0x9a
Dec  7 06:30:42 host01 mtail: internal/poll.(*pollDesc).waitRead(0xc00001e718, 0xc00036c000, 0x1000, 0x1000)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/internal/poll/fd_poll_runtime.go:90 +0x3d
Dec  7 06:30:42 host01 mtail: internal/poll.(*FD).Read(0xc00001e700, 0xc00036c000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/internal/poll/fd_unix.go:169 +0x179
Dec  7 06:30:42 host01 mtail: net.(*netFD).Read(0xc00001e700, 0xc00036c000, 0x1000, 0x1000, 0x3e, 0xc0000c5968, 0x6d976a)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/net/fd_unix.go:202 +0x4f
Dec  7 06:30:42 host01 mtail: net.(*conn).Read(0xc00000e498, 0xc00036c000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/net/net.go:177 +0x68
Dec  7 06:30:42 host01 mtail: net/http.(*connReader).Read(0xc007443a40, 0xc00036c000, 0x1000, 0x1000, 0x3, 0x6dded9, 0x4737c2)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/net/http/server.go:786 +0xfc
Dec  7 06:30:42 host01 mtail: bufio.(*Reader).fill(0xc000020ba0)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/bufio/bufio.go:100 +0x106
Dec  7 06:30:42 host01 mtail: bufio.(*Reader).ReadSlice(0xc000020ba0, 0xc0000f230a, 0xc0000c5ac0, 0x489b74, 0x0, 0x0, 0x203000)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/bufio/bufio.go:341 +0x36
Dec  7 06:30:42 host01 mtail: bufio.(*Reader).ReadLine(0xc000020ba0, 0xc0000f2300, 0x100, 0xf8, 0x85f1a0, 0xc000145c00, 0xc0000c5b18)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/bufio/bufio.go:370 +0x34
Dec  7 06:30:42 host01 mtail: net/textproto.(*Reader).readLineSlice(0xc007443a70, 0xc00001e180, 0xc0000c5b98, 0x40e0c8, 0x100, 0x85f1a0)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/net/textproto/reader.go:55 +0x6f
Dec  7 06:30:42 host01 mtail: net/textproto.(*Reader).ReadLine(0xc007443a70, 0xc0000f2300, 0x0, 0x0, 0x0)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/net/textproto/reader.go:36 +0x2b
Dec  7 06:30:42 host01 mtail: net/http.readRequest(0xc000020ba0, 0x0, 0xc0000f2300, 0x0, 0x0)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/net/http/request.go:958 +0x8c
Dec  7 06:30:42 host01 mtail: net/http.(*conn).readRequest(0xc000088640, 0x8e62c0, 0xc00005ac80, 0x0, 0x0, 0x0)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/net/http/server.go:966 +0x162
Dec  7 06:30:42 host01 mtail: net/http.(*conn).serve(0xc000088640, 0x8e62c0, 0xc00005ac80)
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/net/http/server.go:1788 +0x49e
Dec  7 06:30:42 host01 mtail: created by net/http.(*Server).Serve
Dec  7 06:30:42 host01 mtail: /usr/local/go/src/net/http/server.go:2851 +0x2f5
Dec  7 06:30:42 host01 systemd: mtail.service: main process exited, code=exited, status=2/INVALIDARGUMENT
Dec  7 06:30:42 host01 systemd: Unit mtail.service entered failed state.
Dec  7 06:30:42 host01 systemd: mtail.service failed.

Two log files are watched on this host, with a daily volume of 200k lines. I am running the exact same setup on a second host where I couldn't see the problem. The second host logs about 100k a day.

Will this help you fixing something or would you require more information?

Thanks,

Raoul

[Jamie Wilkinson]

I think I need more information. Let's start with the version, and perhaps the programs being run?

If you can get a heap dump as well before the crash, that might help.  I think I put up instructions how to do this on the GitHub site but will reply in the morning with more details if not.