panic: runtime error: slice bounds out of range

[srenatus]

# packetbeat -e -c /etc/packetbeat/packetbeat.conf
....
mysql.go:357: WARN Two requests without a Response. Dropping old request
mysql.go:412: WARN Response from unknown transaction. Ignoring.
mysql.go:412: WARN Response from unknown transaction. Ignoring.
mysql.go:412: WARN Response from unknown transaction. Ignoring.
mysql.go:357: WARN Two requests without a Response. Dropping old request
mysql.go:357: WARN Two requests without a Response. Dropping old request
mysql.go:357: WARN Two requests without a Response. Dropping old request
mysql.go:357: WARN Two requests without a Response. Dropping old request
mysql.go:357: WARN Two requests without a Response. Dropping old request
mysql.go:357: WARN Two requests without a Response. Dropping old request
mysql.go:357: WARN Two requests without a Response. Dropping old request
mysql.go:357: WARN Two requests without a Response. Dropping old request
panic: runtime error: slice bounds out of range

goroutine 1 [syscall]:

goroutine 2 [syscall]:

goroutine 8 [chan receive]:
main.(*PublisherType).UpdateTopologyPeriodically(0xa19a00)
        /home/vagrant/src/packetbeat/publish.go:178 +0x3c
created by main.(*PublisherType).Init
        /home/vagrant/src/packetbeat/publish.go:319 +0x511

goroutine 6 [IO wait]:
net.runtime_pollWait(0x7fc541104f00, 0x72, 0x0)
        /usr/local/go/src/pkg/runtime/znetpoll_linux_amd64.c:118 +0x82
net.(*pollDesc).WaitRead(0xc2000bb350, 0xb, 0xc2000d52d0)
        /usr/local/go/src/pkg/net/fd_poll_runtime.go:75 +0x31
net.(*netFD).Read(0xc2000bb2d0, 0xc2001e4000, 0x1000, 0x1000, 0x0, ...)
        /usr/local/go/src/pkg/net/fd_unix.go:195 +0x2b3
net.(*conn).Read(0xc2001d9ea0, 0xc2001e4000, 0x1000, 0x1000, 0x0, ...)
        /usr/local/go/src/pkg/net/net.go:123 +0xc3
bufio.(*Reader).fill(0xc2000c57e0)
        /usr/local/go/src/pkg/bufio/bufio.go:79 +0x10c
bufio.(*Reader).Peek(0xc2000c57e0, 0x1, 0x0, 0x0, 0x0, ...)
        /usr/local/go/src/pkg/bufio/bufio.go:107 +0xc9
net/http.(*persistConn).readLoop(0xc2001c4d80)
        /usr/local/go/src/pkg/net/http/transport.go:670 +0xc4
created by net/http.(*Transport).dialConn
        /usr/local/go/src/pkg/net/http/transport.go:511 +0x574

goroutine 7 [select]:
net/http.(*persistConn).writeLoop(0xc2001c4d80)
        /usr/local/go/src/pkg/net/http/transport.go:774 +0x26f
created by net/http.(*Transport).dialConn
        /usr/local/go/src/pkg/net/http/transport.go:512 +0x58b

goroutine 9 [chan send (nil chan)]:
main.(*Process).RefreshPids(0xc200165c80)
        /home/vagrant/src/packetbeat/procs.go:139 +0x399
created by main.NewProcess
        /home/vagrant/src/packetbeat/procs.go:123 +0x8e

goroutine 10 [chan send (nil chan)]:
main.(*Process).RefreshPids(0xc200165cd0)
        /home/vagrant/src/packetbeat/procs.go:139 +0x399
created by main.NewProcess
        /home/vagrant/src/packetbeat/procs.go:123 +0x8e

goroutine 11 [chan send (nil chan)]:
main.(*Process).RefreshPids(0xc200165d20)
        /home/vagrant/src/packetbeat/procs.go:139 +0x399
created by main.NewProcess
        /home/vagrant/src/packetbeat/procs.go:123 +0x8e

goroutine 12 [finalizer wait]:

goroutine 98 [IO wait]:
net.runtime_pollWait(0x7fc541104dc0, 0x72, 0x0)
        /usr/local/go/src/pkg/runtime/znetpoll_linux_amd64.c:118 +0x82
net.(*pollDesc).WaitRead(0xc2002071a0, 0xb, 0xc2000d52d0)
        /usr/local/go/src/pkg/net/fd_poll_runtime.go:75 +0x31
net.(*netFD).Read(0xc200207120, 0xc200483000, 0x1000, 0x1000, 0x0, ...)
        /usr/local/go/src/pkg/net/fd_unix.go:195 +0x2b3
net.(*conn).Read(0xc200666088, 0xc200483000, 0x1000, 0x1000, 0x0, ...)
        /usr/local/go/src/pkg/net/net.go:123 +0xc3
bufio.(*Reader).fill(0xc200218180)
        /usr/local/go/src/pkg/bufio/bufio.go:79 +0x10c
bufio.(*Reader).Peek(0xc200218180, 0x1, 0x0, 0x0, 0x0, ...)
        /usr/local/go/src/pkg/bufio/bufio.go:107 +0xc9
net/http.(*persistConn).readLoop(0xc2001b3c80)
        /usr/local/go/src/pkg/net/http/transport.go:670 +0xc4
created by net/http.(*Transport).dialConn
        /usr/local/go/src/pkg/net/http/transport.go:511 +0x574

goroutine 99 [select]:
net/http.(*persistConn).writeLoop(0xc2001b3c80)
        /usr/local/go/src/pkg/net/http/transport.go:774 +0x26f
created by net/http.(*Transport).dialConn
        /usr/local/go/src/pkg/net/http/transport.go:512 +0x58b
#

I haven't captured the packets that created this (as I have no clue what exactly caused this), but maybe the traceback already helps...?

Cheers
Stephan

[packetb-old]

Unfortunately the stack trace is not very useful, because all goroutines seem to be waiting for IO or in a system call. Based on the logs it looks like there might be an issue parsing the MySQL messages. Which version of MySQL do you have?

Also, if this happens quickly enough, can you please run packetbeat like this? It will add more debugging info:

packetbeat -e -c /etc/packetbeat/packetbeat.conf -d mysql,mysqldetailed

Thanks.

[srenatus]

It happens quickly enough, hope this helps gaining insights:

....
mysql.go:118: DBG  extract mysql message
mysql.go:133: DBG  Seq=1, type=0, start=0
mysql.go:154: DBG  OK response
mysql.go:440: DBG  fields: 0
mysql.go:448: DBG  response raw: {}
mysql.go:455: DBG  Mysql transaction completed: map[query:UPDATE agents SET heartbeat_timestamp='2014-05-09 08:11:44.224058' WHERE agents.id = '5621ac36-b411-4cae-bfeb-4ce8f8e4b27b
' tables: num_fields:%!s(int=0) error_code:%!s(int=0) isok:%!s(bool=true) iserror:%!s(bool=false) method:UPDATE affected_rows:%!s(int=1) num_rows:%!s(int=0) insert_id:%!s(int=0) si
ze:%!s(uint64=0) error_message:]
mysql.go:118: DBG  extract mysql message
mysql.go:133: DBG  Seq=1, type=0, start=0
mysql.go:154: DBG  OK response
mysql.go:440: DBG  fields: 0
mysql.go:448: DBG  response raw: {}
mysql.go:455: DBG  Mysql transaction completed: map[isok:%!s(bool=true) affected_rows:%!s(int=1) insert_id:%!s(int=0) num_rows:%!s(int=0) num_fields:%!s(int=0) error_message: table
s: query:UPDATE agents SET heartbeat_timestamp='2014-05-09 08:11:44.224058' WHERE agents.id = '5621ac36-b411-4cae-bfeb-4ce8f8e4b27b' method:UPDATE size:%!s(uint64=0) iserror:%!s(bo
ol=false) error_code:%!s(int=0)]
panic: runtime error: slice bounds out of range

goroutine 1 [running]:
main.decodePktEth(0x71, 0xc2003ee460)
        /home/vagrant/src/packetbeat/main.go:147 +0x711
main.main()
        /home/vagrant/src/packetbeat/main.go:336 +0x1467
...

MySQL in this case means Percona 5.5.

[badcrc]

Hello,

I'm seeing this error as well, it randomly crashes, with mysql 5.0 on Centos 5.9 using the binary package.

Also I'm trying it in FreeBSD 9 and one time it crashed with the same error but parsing http (nginx proxy), although only happened once for now (in a server with 3000 reqs/minute):

http.go:495: WARN Response from unknown transaction. Ignoring.
http.go:434: WARN Two requests without a response. Dropping old request
panic: runtime error: slice bounds out of range

goroutine 1 [running]:
runtime.panic(0x6774e0, 0xb8450a)
    /usr/local/go/src/pkg/runtime/panic.c:266 +0xb6
main.httpMessageParser(0xc2102a4cc0, 0xc213886036)
    /root/software/packetbeat-0.1.0/http.go:316 +0x1b3d
main.ParseHttp(0xc213952b80, 0xc2100fd700, 0xc213952b00)
    /root/software/packetbeat-0.1.0/http.go:362 +0x2d1
main.(*TcpStream).AddPacket(0xc2100fd700, 0xc213952b80, 0xc21e00c296f10010)
    /root/software/packetbeat-0.1.0/tcp.go:89 +0x10d
main.FollowTcp(0xc213886022, 0x14, 0x145c, 0xc213952b80)
    /root/software/packetbeat-0.1.0/tcp.go:135 +0x22b
main.decodePktEth(0x1, 0xc210cc6f00)
    /root/software/packetbeat-0.1.0/main.go:149 +0x6d8
main.main()
    /root/software/packetbeat-0.1.0/main.go:336 +0x13ae

goroutine 3 [syscall]:
runtime.goexit()
    /usr/local/go/src/pkg/runtime/proc.c:1394

goroutine 8 [chan receive]:
main.(*PublisherType).UpdateTopologyPeriodically(0xb9c760)
    /root/software/packetbeat-0.1.0/publish.go:178 +0x3e
created by main.(*PublisherType).Init
    /root/software/packetbeat-0.1.0/publish.go:319 +0x58c

goroutine 6 [runnable]:
net/http.(*persistConn).readLoop(0xc210058a00)
    /usr/local/go/src/pkg/net/http/transport.go:778 +0x68f
created by net/http.(*Transport).dialConn
    /usr/local/go/src/pkg/net/http/transport.go:528 +0x607

goroutine 7 [select]:
net/http.(*persistConn).writeLoop(0xc210058a00)
    /usr/local/go/src/pkg/net/http/transport.go:791 +0x271
created by net/http.(*Transport).dialConn
    /usr/local/go/src/pkg/net/http/transport.go:529 +0x61e

goroutine 3928 [select]:
net/http.(*persistConn).writeLoop(0xc21294f480)
    /usr/local/go/src/pkg/net/http/transport.go:791 +0x271
created by net/http.(*Transport).dialConn
    /usr/local/go/src/pkg/net/http/transport.go:529 +0x61e

goroutine 3927 [IO wait]:
net.runtime_pollWait(0x800bc99d8, 0x72, 0x0)
    /usr/local/go/src/pkg/runtime/netpoll.goc:116 +0x6a
net.(*pollDesc).Wait(0xc210944d10, 0x72, 0x800bc8190, 0x23)
    /usr/local/go/src/pkg/net/fd_poll_runtime.go:81 +0x34
net.(*pollDesc).WaitRead(0xc210944d10, 0x23, 0x800bc8190)
    /usr/local/go/src/pkg/net/fd_poll_runtime.go:86 +0x30
net.(*netFD).Read(0xc210944cb0, 0xc21304f000, 0x1000, 0x1000, 0x0, ...)
    /usr/local/go/src/pkg/net/fd_unix.go:204 +0x2a0
net.(*conn).Read(0xc210942120, 0xc21304f000, 0x1000, 0x1000, 0x755dc0, ...)
    /usr/local/go/src/pkg/net/net.go:122 +0xc5
bufio.(*Reader).fill(0xc211a9f840)
    /usr/local/go/src/pkg/bufio/bufio.go:91 +0x110
bufio.(*Reader).Peek(0xc211a9f840, 0x1, 0x423f98, 0xc211a9f3b0, 0x42e689, ...)
    /usr/local/go/src/pkg/bufio/bufio.go:119 +0xcb
net/http.(*persistConn).readLoop(0xc21294f480)
    /usr/local/go/src/pkg/net/http/transport.go:687 +0xb7
created by net/http.(*Transport).dialConn
    /usr/local/go/src/pkg/net/http/transport.go:528 +0x607

[packetb-old]

We have just released v0.1.1 which should not crash anymore in these cases. Instead it will print a stacktrace to the logs and continue. Please continue to post us the stacktraces if you see them in the logs.

Btw, I'm glad to hear that it works in FreeBSD, apart of the above issues :).

[packetb-old]

This fixes the stack trace from @badcrc. The one from @srenatus might still be there, but hopefully you'll get a better trace when running v0.1.1.