go-graphite / go-carbon

Golang implementation of Graphite/Carbon server with classic architecture: Agent -> Cache -> Persister
MIT License
805 stars 123 forks source link

go-carbon crashes when doing deep scan #30

Closed herver closed 8 years ago

herver commented 8 years ago

I had go-carbon crash already once or twice in the last weeks, I didn't pay really attention and updated to the latest version (0.7-beta1) and it still occurs.

These are the "bad lines" found in the logs prior to the crash, as you can see this comes from regular security scans that run inside my company's network and are generated by something like nmap -sV --version-all -p XXXX mymachine

[2015-12-11 14:28:06] W [pickle] Can't read message body: unexpected EOF
[2015-12-11 14:28:06] I bad message: "\x05\x04\x00\x01\x02\x80\x05\x01\x00\x03\n"
[2015-12-11 14:28:06] I bad message: "google.com\x00PGET / HTTP/1.0\r\n"
[2015-12-11 14:28:06] I bad message: "\r\n"
[2015-12-11 14:28:07] I [persister] doCheckpoint() {commitedPoints=173096, created=0, updateOperations=34786}
[2015-12-11 14:28:07] I [udp] doCheckpoint() {errors=0, incompleteReceived=0, metricsReceived=4643}
[2015-12-11 14:28:07] I [tcp] doCheckpoint() {active=2, errors=222, metricsReceived=15780}
[2015-12-11 14:28:07] I [pickle] doCheckpoint() {active=1, errors=11, metricsReceived=151529}
[2015-12-11 14:28:07] I [cache] doCheckpoint() {inputCapacity=51200, inputLenAfterCheckpoint=9, inputLenBeforeCheckpoint=3, metrics=4771, overflow=0, queries=1845, size=4887, time="1.936403ms"}
[2015-12-11 14:28:11] W [pickle] Can't read message body: unexpected EOF
[2015-12-11 14:28:16] W [tcp] Unfinished line: []byte{0x4, 0x1, 0x0, 0x16, 0x7f, 0x0, 0x0, 0x1, 0x72, 0x6f, 0x6f, 0x74, 0x0}
[2015-12-11 14:28:16] W [pickle] Can't read message body: unexpected EOF
[2015-12-11 14:28:21] W [tcp] Unfinished line: []byte{0x12, 0x1, 0x0, 0x34, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x15, 0x0, 0x6, 0x1, 0x0, 0x1b, 0x0, 0x1, 0x2, 0x0, 0x1c, 0x0, 0xc, 0x3, 0x0, 0x28, 0x0, 0x4, 0xff, 0x8, 0x0, 0x1, 0x55, 0x0, 0x0, 0x0, 0x4d, 0x53, 0x53, 0x51, 0x4c, 0x53, 0x65, 0x72, 0x76, 0x65, 0x72, 0x0, 0x48, 0xf, 0x0, 0x0}
[2015-12-11 14:28:21] W [pickle] Can't read message body: unexpected EOF
[2015-12-11 14:28:21] I bad message: "HELP\n"
[2015-12-11 14:28:21] I bad message: "\n"
[2015-12-11 14:28:21] I [pickle] Can't unpickle message: Pickle Machine failed on opcode:0x0. Stack size:0. Memo size:0. Cause:Opcode is invalid
[2015-12-11 14:28:21] I [pickle] Can't unpickle message: Pickle Machine failed on opcode:0x0. Stack size:0. Memo size:0. Cause:EOF
[2015-12-11 14:28:26] W [tcp] Unfinished line: []byte{0x0}
[2015-12-11 14:28:26] W [pickle] Can't read message body: unexpected EOF
[2015-12-11 14:28:26] I bad message: "stats\r\n"
[2015-12-11 14:28:31] W [pickle] Can't read message body: unexpected EOF
[2015-12-11 14:28:31] I bad message: "\x00\x00\x00\x01\x00\x00\x00\x13\x00\x00\x00\x02\x00\x00\x00$\x00\x00\x00\vservice_mgr\x00\x00\x00\x00\x02\x00\x00\x00\x13\x01\bscanner \x04\x05nmap \x06\x00\x00\x00\x00\x00\b\x00\x00\x00\x01\x00\x00\x00\x02\x00\x00\x00\x03\x00\x00\x00\x02\x00\x00\x00\n"
[2015-12-11 14:28:36] W [tcp] Unfinished line: []byte{0x0, 0x0, 0x0, 0x1, 0x0, 0x0, 0x0, 0x2, 0x0, 0x0, 0x0, 0x3, 0x0, 0x0, 0x0, 0x4}
[2015-12-11 14:28:36] W [pickle] Can't read message body: unexpected EOF
[2015-12-11 14:28:41] W [tcp] Unfinished line: []byte{0x0, 0x0, 0x0, 0x0, 0x44, 0x42, 0x32, 0x44, 0x41, 0x53, 0x20, 0x20, 0x20, 0x20, 0x20, 0x20, 0x1, 0x4, 0x0, 0x0, 0x0, 0x10, 0x39, 0x7a, 0x0, 0x1, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x1, 0xc, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xc, 0x0, 0x0, 0x0, 0xc, 0x0, 0x0, 0x0, 0x4}
[2015-12-11 14:28:41] W [pickle] Can't read message body: unexpected EOF
[2015-12-11 14:28:46] W [pickle] Can't read message body: unexpected EOF
[2015-12-11 14:28:46] W [tcp] Unfinished line: []byte{0x1, 0xc2, 0x0, 0x0, 0x0, 0x4, 0x0, 0x0, 0xb6, 0x1, 0x0, 0x0, 0x53, 0x51, 0x4c, 0x44, 0x42, 0x32, 0x52, 0x41, 0x0, 0x1, 0x0, 0x0, 0x4, 0x1, 0x1, 0x0, 0x5, 0x0, 0x1d, 0x0, 0x88, 0x0, 0x0, 0x0, 0x1, 0x0, 0x0, 0x80, 0x0, 0x0, 0x0, 0x1, 0x9, 0x0, 0x0, 0x0, 0x1, 0x0, 0x0, 0x40, 0x0, 0x0, 0x0, 0x1, 0x9, 0x0, 0x0, 0x0, 0x1, 0x0, 0x0, 0x40, 0x0, 0x0, 0x0, 0x1, 0x8, 0x0, 0x0, 0x0, 0x4, 0x0, 0x0, 0x40, 0x0, 0x0, 0x0, 0x1, 0x4, 0x0, 0x0, 0x0, 0x1, 0x0, 0x0, 0x40, 0x0, 0x0, 0x0, 0x40, 0x4, 0x0, 0x0, 0x0, 0x4, 0x0, 0x0, 0x40, 0x0, 0x0, 0x0, 0x1, 0x4, 0x0, 0x0, 0x0, 0x4, 0x0, 0x0, 0x40, 0x0, 0x0, 0x0, 0x1, 0x4, 0x0, 0x0, 0x0, 0x4, 0x0, 0x0, 0x40, 0x0, 0x0, 0x0, 0x1, 0x4, 0x0, 0x0, 0x0, 0x2, 0x0, 0x0, 0x40, 0x0, 0x0, 0x0, 0x1, 0x4, 0x0, 0x0, 0x0, 0x4, 0x0, 0x0, 0x40, 0x0, 0x0, 0x0, 0x1, 0x0, 0x0, 0x0, 0x0, 0x1, 0x0, 0x0, 0x40, 0x0, 0x0, 0x0, 0x0, 0x4, 0x0, 0x0, 0x0, 0x4, 0x0, 0x0, 0x80, 0x0, 0x0, 0x0, 0x1, 0x4, 0x0, 0x0, 0x0, 0x4, 0x0, 0x0, 0x80, 0x0, 0x0, 0x0, 0x1, 0x4, 0x0, 0x0, 0x0, 0x3, 0x0, 0x0, 0x80, 0x0, 0x0, 0x0, 0x1, 0x4, 0x0, 0x0, 0x0, 0x4, 0x0, 0x0, 0x80, 0x0, 0x0, 0x0, 0x1, 0x8, 0x0, 0x0, 0x0, 0x1, 0x0, 0x0, 0x40, 0x0, 0x0, 0x0, 0x1, 0x4, 0x0, 0x0, 0x0, 0x4, 0x0, 0x0, 0x40, 0x0, 0x0, 0x0, 0x1, 0x10, 0x0, 0x0, 0x0, 0x1, 0x0, 0x0, 0x80, 0x0, 0x0, 0x0, 0x1, 0x10, 0x0, 0x0, 0x0, 0x1, 0x0, 0x0, 0x80, 0x0, 0x0, 0x0, 0x1, 0x4, 0x0, 0x0, 0x0, 0x4, 0x0, 0x0, 0x40, 0x0, 0x0, 0x0, 0x1, 0x9, 0x0, 0x0, 0x0, 0x1, 0x0, 0x0, 0x40, 0x0, 0x0, 0x0, 0x1, 0x9, 0x0, 0x0, 0x0, 0x1, 0x0, 0x0, 0x80, 0x0, 0x0, 0x0, 0x1, 0x4, 0x0, 0x0, 0x0, 0x3, 0x0, 0x0, 0x80, 0x0, 0x0, 0x0, 0x1, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x1, 0x4, 0x0, 0x0, 0x1, 0x0, 0x0, 0x80, 0x0, 0x0, 0x0, 0x1, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x1, 0x0, 0x0, 0x40, 0x0, 0x0, 0x0, 0x1, 0x0, 0x0, 0x0, 0x0, 0x1, 0x0, 0x0, 0x40, 0x0, 0x0, 0x0, 0x0, 0x20, 0x20, 0x20, 0x20, 0x20, 0x20, 0x20, 0x20, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x1, 0x0, 0xff, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xe4, 0x4, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x7f}
[2015-12-11 14:28:51] W [pickle] Can't read message body: unexpected EOF
[2015-12-11 14:28:51] W [tcp] Unfinished line: []byte{0x43, 0x6c, 0x69, 0x65, 0x6e, 0x74, 0x20, 0x73, 0x74, 0x72, 0x69, 0x6e, 0x67, 0x20, 0x66, 0x6f, 0x72, 0x20, 0x50, 0x41, 0x52, 0x43, 0x20, 0x76, 0x65, 0x72, 0x73, 0x69, 0x6f, 0x6e, 0x20, 0x31, 0x20, 0x57, 0x69, 0x72, 0x65, 0x20, 0x45, 0x6e, 0x63, 0x72, 0x79, 0x70, 0x74, 0x69, 0x6f, 0x6e, 0x20, 0x76, 0x65, 0x72, 0x73, 0x69, 0x6f, 0x6e, 0x20, 0x31, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}
[2015-12-11 14:28:51] I bad message: "<\x00K\x00\x00\x00 \x00\x00\x00\x00\x00\x00\x00\x00\x00\xff\xff\xff\xff\x00\x00\n"
[2015-12-11 14:28:51] I bad message: "\x04\xa0\xbeS\x03UR\x00\x00<\x00\x00\x00\x05\x00\x00\x00\x00\x00\x00\x00\x00\x00\x1a\x00<\x00\x00\x00\x00\x00\n"

I was able to reproduce this once, but not again after that. I suspect there may be some kind of race there, as go-carbon is running with the following configuration options and receiving ~ 200k metrics.

[common]
...
max-cpu = 6

[whisper]
...
workers = 16
lomik commented 8 years ago

Hi, I need stderr output of crashed go-carbon process for debug.

I suspect there may be some kind of race there

Unlikely. More probability there is an error in the message parser

herver commented 8 years ago

I finally managed to capture stderr of the crashed go-carbon process, please find it attached to this comment. output.txt

lomik commented 8 years ago

Thanks! The reason is really in a bad message (very big size in header of pickle message). In the near future I will correct it (with limiting max pickle message size)

lomik commented 8 years ago

Fixed in 0.7-beta4 https://github.com/lomik/go-carbon/releases/tag/v0.7-beta4

Please, reopen issue if this problem persists