search

anycable / anycable-go

AnyCable real-time server
https://anycable.io
MIT License
364 stars 65 forks source link

Panic during history retrieval #183

Closed yenshirak closed 1 year ago

yenshirak commented 1 year ago

Tell us about your environment

AnyCable-Go version: 1.4.1

AnyCable gem version: 1.4.1

We use the redisx broadcast adapter, the memory broker and the actioncable-v1-ext-json protocol, 1 anycable-go instance, no pub/sub. JWT authentication is enforced, we don't use RPC.

What did you do?

We switched to the actioncable-v1-ext-json protocol.

What did you expect to happen?

No panics.

What actually happened?

The anycable-go service panicked daily with the following error message (the range in the error message varied):

July 29, 2023 at 10:42 (UTC+2:00)   panic: runtime error: slice bounds out of range [9:2]   b67f74a10ba3485499f03bd3929a390b    anycable
July 29, 2023 at 10:42 (UTC+2:00)   goroutine 855225 [running]: b67f74a10ba3485499f03bd3929a390b    anycable
July 29, 2023 at 10:42 (UTC+2:00)   github.com/anycable/anycable-go/broker.(*memstream).filterByOffset(0xc000b894a0, 0xc001194870?, 0xc0002c5c58)   b67f74a10ba3485499f03bd3929a390b    anycable
July 29, 2023 at 10:42 (UTC+2:00)   /home/runner/work/anycable-go/anycable-go/broker/memory.go:99 +0x22c    b67f74a10ba3485499f03bd3929a390b    anycable
July 29, 2023 at 10:42 (UTC+2:00)   github.com/anycable/anycable-go/broker.(*Memory).HistoryFrom(0xc000101440, {0xc001194870, 0x25}, {0xc001cbe24c, 0x4}, 0x0?) b67f74a10ba3485499f03bd3929a390b    anycable
July 29, 2023 at 10:42 (UTC+2:00)   /home/runner/work/anycable-go/anycable-go/broker/memory.go:234 +0x1c5   b67f74a10ba3485499f03bd3929a390b    anycable
July 29, 2023 at 10:42 (UTC+2:00)   github.com/anycable/anycable-go/node.(*Node).retreiveHistory(0xc00021a620, 0xc0002c5da0, {0xc0002b2b80?, 0x1, 0x2c5d70?})   b67f74a10ba3485499f03bd3929a390b    anycable
July 29, 2023 at 10:42 (UTC+2:00)   /home/runner/work/anycable-go/anycable-go/node/node.go:539 +0x229   b67f74a10ba3485499f03bd3929a390b    anycable
July 29, 2023 at 10:42 (UTC+2:00)   github.com/anycable/anycable-go/node.(*Node).History(0xc000101440?, 0xc000156780, 0xc000bfc880) b67f74a10ba3485499f03bd3929a390b    anycable
July 29, 2023 at 10:42 (UTC+2:00)   /home/runner/work/anycable-go/anycable-go/node/node.go:508 +0x213   b67f74a10ba3485499f03bd3929a390b    anycable
July 29, 2023 at 10:42 (UTC+2:00)   github.com/anycable/anycable-go/node.(*Node).Subscribe(0xc00021a620, 0xc000156780, 0xc000bfc880)    b67f74a10ba3485499f03bd3929a390b    anycable
July 29, 2023 at 10:42 (UTC+2:00)   /home/runner/work/anycable-go/anycable-go/node/node.go:402 +0x449   b67f74a10ba3485499f03bd3929a390b    anycable
July 29, 2023 at 10:42 (UTC+2:00)   github.com/anycable/anycable-go/node.(*Node).HandleCommand(0xe3ff17?, 0xc000156780, 0xc000bfc880)   b67f74a10ba3485499f03bd3929a390b    anycable
July 29, 2023 at 10:42 (UTC+2:00)   /home/runner/work/anycable-go/anycable-go/node/node.go:130 +0x111   b67f74a10ba3485499f03bd3929a390b    anycable
July 29, 2023 at 10:42 (UTC+2:00)   github.com/anycable/anycable-go/node.(*Session).ReadMessage(0xc000156780, {0xc00038f400, 0x14f, 0x200}) b67f74a10ba3485499f03bd3929a390b    anycable
July 29, 2023 at 10:42 (UTC+2:00)   /home/runner/work/anycable-go/anycable-go/node/session.go:303 +0xde b67f74a10ba3485499f03bd3929a390b    anycable
July 29, 2023 at 10:42 (UTC+2:00)   github.com/anycable/anycable-go/node.(*Session).Serve.func1()   b67f74a10ba3485499f03bd3929a390b    anycable
July 29, 2023 at 10:42 (UTC+2:00)   /home/runner/work/anycable-go/anycable-go/node/session.go:255 +0x6c b67f74a10ba3485499f03bd3929a390b    anycable
July 29, 2023 at 10:42 (UTC+2:00)   created by github.com/anycable/anycable-go/node.(*Session).Serve    b67f74a10ba3485499f03bd3929a390b    anycable
July 29, 2023 at 10:42 (UTC+2:00)   /home/runner/work/anycable-go/anycable-go/node/session.go:238 +0x72 b67f74a10ba3485499f03bd3929a390b    anycable

These happened in production where debug logging wasn't enabled. We switched back to actioncable-v1-json for now. I couldn't replicate the issue on staging.

I have zero Go experience but it seems to me that the length of ms.data isn't checked in thefilterByOffset function before slicing: https://github.com/anycable/anycable-go/blob/master/broker/memory.go#L99

Please let me know if you need any additional info or help with debugging and fixing the issue.

palkan commented 1 year ago

Thanks for the report! Will take a look today.

palkan commented 1 year ago

The issue is fixed in master (so, you can try using edge or commit-specific version if you're using Docker). The next release is planned for the end of this week.

yenshirak commented 1 year ago

Thank you

palkan commented 1 year ago

Released in 1.4.2