mautrix / go

A Golang Matrix framework.
https://maunium.net/go/mautrix
Mozilla Public License 2.0
416 stars 74 forks source link

OlmMachine.ProcessSyncResponse panic #52

Closed rakshazi closed 2 years ago

rakshazi commented 2 years ago

Hello,

I'm trying to develop a bot on top of mautrix-go and faced odd issue - OlmMachine.ProcessSyncResponse panics on canonicaljson.RawJSONFromResult. The issue reproduced on synapse 1.49.1, 1.49.2 and different matrix accounts (I created a new account just to be sure the issue is not caused by some kind of "state" saved into that account) and different mautrix-go versions (0.10.5, 0.10.7, 0.10.8).

here log (level=trace) with stacktrace:

api.DEBUG req #1: POST https://matrix.example.com/_matrix/client/r0/login <sensitive content omitted>
api.DEBUG Stored credentials for @bot2:example.com/MEYOTENOCI after login
matrix.DEBUG restoring previous session...
api.DEBUG req #2: GET https://matrix.example.com/_matrix/client/r0/user/@bot2:example.com/account_data/com.example.bot.session_token
api.DEBUG req #3: GET https://matrix.example.com/_matrix/client/r0/presence/@bot2:example.com/status
matrix.DEBUG previous session restored successfully. Closing current session...
api.DEBUG req #4: POST https://matrix.example.com/_matrix/client/r0/logout
matrix.DEBUG hydrating bot...
api.DEBUG req #5: GET https://matrix.example.com/_matrix/client/r0/profile/@bot2:example.com/displayname
bot.DEBUG bot has been created
api.DEBUG req #6: GET https://matrix.example.com/_matrix/client/r0/user/@bot2:example.com/account_data/com.example.bot.batch_token
api.DEBUG req #7: PUT https://matrix.example.com/_matrix/client/r0/user/@bot2:example.com/account_data/com.example.bot.batch_token {"NextBatch":""}
bot.DEBUG data store initialized
bot.DEBUG end-to-end encryption support initialized
bot.DEBUG starting bot...
api.DEBUG req #8: PUT https://matrix.example.com/_matrix/client/r0/presence/@bot2:example.com/status {"presence":"online"}
matrix.INFO bot has been started
api.DEBUG req #9: GET https://matrix.example.com/_matrix/client/r0/sync?filter=0&since=s547269_18739377_0_454979_142756_283_12908_826018_10&timeout=30000
olm.TRACE Device list changes in /sync: [@bot2:example.com] (trace: 00:47:43.282723)
olm.TRACE Finished handling device list changes (trace: 00:47:43.282723)
olm.DEBUG Sync response said we have 0 signed curve25519 keys left, sharing new ones... (trace: 00:47:43.282933)
bot.FATAL matrix bot crashed: ProcessResponse panicked! since=s547269_18739377_0_454979_142756_283_12908_826018_10 panic=runtime error: slice bounds out of range [:157] with capacity 155
goroutine 1 [running]:
runtime/debug.Stack()
    /usr/lib/go/src/runtime/debug/stack.go:24 +0x65
maunium.net/go/mautrix.(*DefaultSyncer).ProcessResponse.func1()
    /home/user/go/pkg/mod/maunium.net/go/mautrix@v0.10.7/sync.go:133 +0x66
panic({0x8f9e60, 0xc00062e348})
    /usr/lib/go/src/runtime/panic.go:1038 +0x215
maunium.net/go/mautrix/crypto/canonicaljson.RawJSONFromResult(...)
    /home/user/go/pkg/mod/maunium.net/go/mautrix@v0.10.7/crypto/canonicaljson/json.go:274
maunium.net/go/mautrix/crypto/canonicaljson.sortJSONObject.func1({0x3, {0xc0006783e6, 0x17}, {0xc0006783e7, 0x15}, 0x0, 0x86, {0x0, 0x0, 0x0}}, ...)
    /home/user/go/pkg/mod/maunium.net/go/mautrix@v0.10.7/crypto/canonicaljson/json.go:113 +0x2d4
github.com/tidwall/gjson.Result.ForEach({0x5, {0xc0006783e5, 0x8a}, {0x0, 0x0}, 0x0, 0x85, {0x0, 0x0, 0x0}}, ...)
    /home/user/go/pkg/mod/github.com/tidwall/gjson@v1.12.1/gjson.go:293 +0x52c
maunium.net/go/mautrix/crypto/canonicaljson.sortJSONObject({0x5, {0xc0006783e5, 0x8a}, {0x0, 0x0}, 0x0, 0x85, {0x0, 0x0, 0x0}}, ...)
    /home/user/go/pkg/mod/maunium.net/go/mautrix@v0.10.7/crypto/canonicaljson/json.go:110 +0x165
maunium.net/go/mautrix/crypto/canonicaljson.sortJSONValue({0x5, {0xc0006783e5, 0x8a}, {0x0, 0x0}, 0x0, 0x85, {0x0, 0x0, 0x0}}, ...)
    /home/user/go/pkg/mod/maunium.net/go/mautrix@v0.10.7/crypto/canonicaljson/json.go:62 +0x289
maunium.net/go/mautrix/crypto/canonicaljson.sortJSONObject({0x5, {0xc000678360, 0x110}, {0x0, 0x0}, 0x0, 0x0, {0x0, 0x0, 0x0}}, ...)
    /home/user/go/pkg/mod/maunium.net/go/mautrix@v0.10.7/crypto/canonicaljson/json.go:136 +0x5f3
maunium.net/go/mautrix/crypto/canonicaljson.sortJSONValue({0x5, {0xc000678360, 0x110}, {0x0, 0x0}, 0x0, 0x0, {0x0, 0x0, 0x0}}, ...)
    /home/user/go/pkg/mod/maunium.net/go/mautrix@v0.10.7/crypto/canonicaljson/json.go:62 +0x289
maunium.net/go/mautrix/crypto/canonicaljson.SortJSON({0xc000678120, 0xc000676140, 0x110}, {0xc000678240, 0x0, 0x110})
    /home/user/go/pkg/mod/maunium.net/go/mautrix@v0.10.7/crypto/canonicaljson/json.go:51 +0x23a
maunium.net/go/mautrix/crypto/canonicaljson.CanonicalJSONAssumeValid({0xc000678000, 0x110, 0x120})
    /home/user/go/pkg/mod/maunium.net/go/mautrix@v0.10.7/crypto/canonicaljson/json.go:42 +0x96
maunium.net/go/mautrix/crypto/olm.(*Account).SignJSON(0x8b5ea0, {0x88ad60, 0xc000626230})
    /home/user/go/pkg/mod/maunium.net/go/mautrix@v0.10.7/crypto/olm/account.go:244 +0x72
maunium.net/go/mautrix/crypto.(*OlmAccount).getInitialKeys(0xc0005e4230, {0xc0000d2138, 0xc0001c8000}, {0xc0001ae040, 0xc0000c25e0})
    /home/user/go/pkg/mod/maunium.net/go/mautrix@v0.10.7/crypto/account.go:60 +0x439
maunium.net/go/mautrix/crypto.(*OlmMachine).ShareKeys(0xc00014e000, 0x940ad0)
    /home/user/go/pkg/mod/maunium.net/go/mautrix@v0.10.7/crypto/machine.go:486 +0x4b
maunium.net/go/mautrix/crypto.(*OlmMachine).HandleOTKCounts(0xc00014e000, 0xc000652088)
    /home/user/go/pkg/mod/maunium.net/go/mautrix@v0.10.7/crypto/machine.go:202 +0x2ac
maunium.net/go/mautrix/crypto.(*OlmMachine).ProcessSyncResponse(0xc00014e000, 0xc000652000, {0xc0000da5c0, 0xc000663b68})
    /home/user/go/pkg/mod/maunium.net/go/mautrix@v0.10.7/crypto/machine.go:229 +0x1b6
maunium.net/go/mautrix.(*DefaultSyncer).ProcessResponse(0xc0000ce7d0, 0xc000652000, {0xc0000da5c0, 0x34})
    /home/user/go/pkg/mod/maunium.net/go/mautrix@v0.10.7/sync.go:138 +0x12e
maunium.net/go/mautrix.(*Client).SyncWithContext(0xc00011c2a0, {0x9b9730, 0xc0000a2000})
    /home/user/go/pkg/mod/maunium.net/go/mautrix@v0.10.7/client.go:284 +0x46f
maunium.net/go/mautrix.(*Client).Sync(...)
    /home/user/go/pkg/mod/maunium.net/go/mautrix@v0.10.7/client.go:225
gitlab.com/example.com/bot/matrix.(*Bot).Start(0xc00014c400)
    /home/user/projects/example.com/bot/matrix/bot.go:159 +0x8c
main.main()
    /home/user/projects/example.com/bot/cmd/cmd.go:46 +0x19f

Please, help me to fix that

edwargix commented 2 years ago

Hi, I am experiencing an issue that looks to be the same as what you're facing:

time="2021-12-31T20:10:05Z" level=fatal msg="error syncing: ProcessResponse panicked! since= panic=runtime error: slice bounds out of range [:160] with capacity 152\ngoroutine 1 [running]:\nruntime/debug.Stack()\n\t/usr/lib/go/src/runtime/debug/stack.go:24 +0x65\nmaunium.net/go/mautrix.(*DefaultSyncer).ProcessResponse.func1()\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/sync.go:133 +0x66\npanic({0x8ba520, 0xc000400690})\n\t/usr/lib/go/src/runtime/panic.go:1038 +0x215\nmaunium.net/go/mautrix/crypto/canonicaljson.RawJSONFromResult(...)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:274\nmaunium.net/go/mautrix/crypto/canonicaljson.sortJSONObject.func1({0x3, {0xc000356869, 0x17}, {0xc00035686a, 0x15}, 0x0, 0x89, {0x0, 0x0, 0x0}}, ...)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:113 +0x2d4\ngithub.com/tidwall/gjson.Result.ForEach({0x5, {0xc000356868, 0x8a}, {0x0, 0x0}, 0x0, 0x88, {0x0, 0x0, 0x0}}, ...)\n\t/root/go/pkg/mod/github.com/tidwall/gjson@v1.12.1/gjson.go:293 +0x52c\nmaunium.net/go/mautrix/crypto/canonicaljson.sortJSONObject({0x5, {0xc000356868, 0x8a}, {0x0, 0x0}, 0x0, 0x88, {0x0, 0x0, 0x0}}, ...)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:110 +0x165\nmaunium.net/go/mautrix/crypto/canonicaljson.sortJSONValue({0x5, {0xc000356868, 0x8a}, {0x0, 0x0}, 0x0, 0x88, {0x0, 0x0, 0x0}}, ...)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:62 +0x289\nmaunium.net/go/mautrix/crypto/canonicaljson.sortJSONObject({0x5, {0xc0003567e0, 0x113}, {0x0, 0x0}, 0x0, 0x0, {0x0, 0x0, 0x0}}, ...)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:136 +0x5f3\nmaunium.net/go/mautrix/crypto/canonicaljson.sortJSONValue({0x5, {0xc0003567e0, 0x113}, {0x0, 0x0}, 0x0, 0x0, {0x0, 0x0, 0x0}}, ...)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:62 +0x289\nmaunium.net/go/mautrix/crypto/canonicaljson.SortJSON({0xc000356360, 0xc000258f00, 0x113}, {0xc0003565a0, 0x0, 0x113})\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:51 +0x23a\nmaunium.net/go/mautrix/crypto/canonicaljson.CanonicalJSONAssumeValid({0xc000356120, 0x113, 0x120})\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:42 +0x96\nmaunium.net/go/mautrix/crypto/olm.(*Utility).VerifySignatureJSON(0x50, {0x8bc0e0, 0xc0003920f0}, {0xc000400408, 0x15}, {0xc0004140f0, 0xa}, {0xc000424210, 0x2b})\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/olm/utility.go:146 +0x2c7\nmaunium.net/go/mautrix/crypto/olm.VerifySignatureJSON({0x8bc0e0, 0xc0003920f0}, {0xc000400408, 0x15}, {0xc0004140f0, 0xa}, {0xc000424210, 0x2b})\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/olm/utility.go:159 +0xe5\nmaunium.net/go/mautrix/crypto.(*OlmMachine).validateDevice(0x0, {0xc000400408, 0x2}, {0xc0004140f0, 0xa}, {{0xc0004003c0, 0x15}, {0xc0004140d0, 0xa}, {0xc0001ae880, ...}, ...}, ...)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/devicelist.go:165 +0x21d\nmaunium.net/go/mautrix/crypto.(*OlmMachine).fetchKeys(0xc0000fc300, {0xc0003dc520, 0x1, 0x1}, {0x0, 0x0}, 0x1)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/devicelist.go:75 +0xf2c\nmaunium.net/go/mautrix/crypto.(*OlmMachine).GetOrFetchDevice(0xc0000fc300, {0xc000437a10, 0x2b}, {0xc0003e03a0, 0xa})\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/machine.go:343 +0x108\nmaunium.net/go/mautrix/crypto.(*OlmMachine).DecryptMegolmEvent(0xc0000fc300, 0xc000202780)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/decryptmegolm.go:58 +0x457\nmain.main.func3(0x878d60, 0xc000202780)\n\t/main.go:70 +0x54\nmaunium.net/go/mautrix.(*DefaultSyncer).notifyListeners(0xc0000667d0, 0xc000296510, 0xc000202780)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/sync.go:203 +0xd7\nmaunium.net/go/mautrix.(*DefaultSyncer).processSyncEvent(0xc0000667d0, {0xc0000193b0, 0xc00018fcb0}, 0xc000202780, 0x22)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/sync.go:193 +0x105\nmaunium.net/go/mautrix.(*DefaultSyncer).processSyncEvents(0xc000159ab8, {0xc0000193b0, 0x21}, {0xc00017e200, 0x32, 0xc00010e540}, 0xc000108d00)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/sync.go:164 +0x4a\nmaunium.net/go/mautrix.(*DefaultSyncer).ProcessResponse(0xc0000667d0, 0xc0000ce000, {0x0, 0x0})\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/sync.go:148 +0x293\nmaunium.net/go/mautrix.(*Client).SyncWithContext(0xc0000c82a0, {0x96c470, 0xc00001c038})\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/client.go:284 +0x46f\nmaunium.net/go/mautrix.(*Client).Sync(...)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/client.go:225\nmain.main()\n\t/main.go:114 +0x10f9\n"

Here's the log message with actual newlines and tabs:

time="2021-12-31T20:10:05Z" level=fatal msg="error syncing: ProcessResponse panicked! since= panic=runtime error: slice bounds out of range [:160] with capacity 152
goroutine 1 [running]:
runtime/debug.Stack()
    /usr/lib/go/src/runtime/debug/stack.go:24 +0x65
maunium.net/go/mautrix.(*DefaultSyncer).ProcessResponse.func1()
    /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/sync.go:133 +0x66
panic({0x8ba520, 0xc000400690})
    /usr/lib/go/src/runtime/panic.go:1038 +0x215
maunium.net/go/mautrix/crypto/canonicaljson.RawJSONFromResult(...)
    /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:274
maunium.net/go/mautrix/crypto/canonicaljson.sortJSONObject.func1({0x3, {0xc000356869, 0x17}, {0xc00035686a, 0x15}, 0x0, 0x89, {0x0, 0x0, 0x0}}, ...)
    /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:113 +0x2d4
github.com/tidwall/gjson.Result.ForEach({0x5, {0xc000356868, 0x8a}, {0x0, 0x0}, 0x0, 0x88, {0x0, 0x0, 0x0}}, ...)
    /root/go/pkg/mod/github.com/tidwall/gjson@v1.12.1/gjson.go:293 +0x52c
maunium.net/go/mautrix/crypto/canonicaljson.sortJSONObject({0x5, {0xc000356868, 0x8a}, {0x0, 0x0}, 0x0, 0x88, {0x0, 0x0, 0x0}}, ...)
    /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:110 +0x165
maunium.net/go/mautrix/crypto/canonicaljson.sortJSONValue({0x5, {0xc000356868, 0x8a}, {0x0, 0x0}, 0x0, 0x88, {0x0, 0x0, 0x0}}, ...)
    /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:62 +0x289
maunium.net/go/mautrix/crypto/canonicaljson.sortJSONObject({0x5, {0xc0003567e0, 0x113}, {0x0, 0x0}, 0x0, 0x0, {0x0, 0x0, 0x0}}, ...)
    /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:136 +0x5f3
maunium.net/go/mautrix/crypto/canonicaljson.sortJSONValue({0x5, {0xc0003567e0, 0x113}, {0x0, 0x0}, 0x0, 0x0, {0x0, 0x0, 0x0}}, ...)
    /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:62 +0x289
maunium.net/go/mautrix/crypto/canonicaljson.SortJSON({0xc000356360, 0xc000258f00, 0x113}, {0xc0003565a0, 0x0, 0x113})
    /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:51 +0x23a
maunium.net/go/mautrix/crypto/canonicaljson.CanonicalJSONAssumeValid({0xc000356120, 0x113, 0x120})
    /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:42 +0x96
maunium.net/go/mautrix/crypto/olm.(*Utility).VerifySignatureJSON(0x50, {0x8bc0e0, 0xc0003920f0}, {0xc000400408, 0x15}, {0xc0004140f0, 0xa}, {0xc000424210, 0x2b})
    /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/olm/utility.go:146 +0x2c7
maunium.net/go/mautrix/crypto/olm.VerifySignatureJSON({0x8bc0e0, 0xc0003920f0}, {0xc000400408, 0x15}, {0xc0004140f0, 0xa}, {0xc000424210, 0x2b})
    /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/olm/utility.go:159 +0xe5
maunium.net/go/mautrix/crypto.(*OlmMachine).validateDevice(0x0, {0xc000400408, 0x2}, {0xc0004140f0, 0xa}, {{0xc0004003c0, 0x15}, {0xc0004140d0, 0xa}, {0xc0001ae880, ...}, ...}, ...)
    /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/devicelist.go:165 +0x21d
maunium.net/go/mautrix/crypto.(*OlmMachine).fetchKeys(0xc0000fc300, {0xc0003dc520, 0x1, 0x1}, {0x0, 0x0}, 0x1)
    /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/devicelist.go:75 +0xf2c
maunium.net/go/mautrix/crypto.(*OlmMachine).GetOrFetchDevice(0xc0000fc300, {0xc000437a10, 0x2b}, {0xc0003e03a0, 0xa})
    /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/machine.go:343 +0x108
maunium.net/go/mautrix/crypto.(*OlmMachine).DecryptMegolmEvent(0xc0000fc300, 0xc000202780)
    /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/decryptmegolm.go:58 +0x457
main.main.func3(0x878d60, 0xc000202780)
    /main.go:70 +0x54
maunium.net/go/mautrix.(*DefaultSyncer).notifyListeners(0xc0000667d0, 0xc000296510, 0xc000202780)
    /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/sync.go:203 +0xd7
maunium.net/go/mautrix.(*DefaultSyncer).processSyncEvent(0xc0000667d0, {0xc0000193b0, 0xc00018fcb0}, 0xc000202780, 0x22)
    /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/sync.go:193 +0x105
maunium.net/go/mautrix.(*DefaultSyncer).processSyncEvents(0xc000159ab8, {0xc0000193b0, 0x21}, {0xc00017e200, 0x32, 0xc00010e540}, 0xc000108d00)
    /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/sync.go:164 +0x4a
maunium.net/go/mautrix.(*DefaultSyncer).ProcessResponse(0xc0000667d0, 0xc0000ce000, {0x0, 0x0})
    /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/sync.go:148 +0x293
maunium.net/go/mautrix.(*Client).SyncWithContext(0xc0000c82a0, {0x96c470, 0xc00001c038})
    /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/client.go:284 +0x46f
maunium.net/go/mautrix.(*Client).Sync(...)
    /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/client.go:225
main.main()
    /main.go:114 +0x10f9
"

I've found that the following patch fixes the issue, though at the expense of removing an optimization for gjson:

From f4965a653a70e66786665431442c607b54de73e4 Mon Sep 17 00:00:00 2001
From: David Florness <david@florness.com>
Date: Fri, 31 Dec 2021 14:19:28 -0600
Subject: [PATCH] Don't use gjson slice optimization

This is a workaround for https://github.com/mautrix/go/issues/52
---
 crypto/canonicaljson/json.go | 10 +---------
 1 file changed, 1 insertion(+), 9 deletions(-)

diff --git a/crypto/canonicaljson/json.go b/crypto/canonicaljson/json.go
index 8c12176..231d798 100644
--- a/crypto/canonicaljson/json.go
+++ b/crypto/canonicaljson/json.go
@@ -266,15 +266,7 @@ func readHexDigits(input []byte) uint32 {
 // RawJSONFromResult extracts the raw JSON bytes pointed to by result.
 // input must be the json bytes that were used to generate result
 func RawJSONFromResult(result gjson.Result, input []byte) (RawJSON []byte) {
-   // This is lifted from gjson README. Basically, result.Raw is a copy of
-   // the bytes we want, but its more efficient to take a slice.
-   // If Index is 0 then for some reason we can't extract it from the original
-   // JSON bytes.
-   if result.Index > 0 {
-       RawJSON = input[result.Index : result.Index+len(result.Raw)]
-   } else {
-       RawJSON = []byte(result.Raw)
-   }
+   RawJSON = []byte(result.Raw)

    return
 }
-- 
2.32.0

I unfortunately haven't yet been able to find a proper fix, but hopefully this can be used as a workaround in the short term?

All the best.

edwargix commented 2 years ago

Hi, I am experiencing an issue that looks to be the same as what you're facing:

time="2021-12-31T20:10:05Z" level=fatal msg="error syncing: ProcessResponse panicked! since= panic=runtime error: slice bounds out of range [:160] with capacity 152\ngoroutine 1 [running]:\nruntime/debug.Stack()\n\t/usr/lib/go/src/runtime/debug/stack.go:24 +0x65\nmaunium.net/go/mautrix.(*DefaultSyncer).ProcessResponse.func1()\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/sync.go:133 +0x66\npanic({0x8ba520, 0xc000400690})\n\t/usr/lib/go/src/runtime/panic.go:1038 +0x215\nmaunium.net/go/mautrix/crypto/canonicaljson.RawJSONFromResult(...)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:274\nmaunium.net/go/mautrix/crypto/canonicaljson.sortJSONObject.func1({0x3, {0xc000356869, 0x17}, {0xc00035686a, 0x15}, 0x0, 0x89, {0x0, 0x0, 0x0}}, ...)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:113 +0x2d4\ngithub.com/tidwall/gjson.Result.ForEach({0x5, {0xc000356868, 0x8a}, {0x0, 0x0}, 0x0, 0x88, {0x0, 0x0, 0x0}}, ...)\n\t/root/go/pkg/mod/github.com/tidwall/gjson@v1.12.1/gjson.go:293 +0x52c\nmaunium.net/go/mautrix/crypto/canonicaljson.sortJSONObject({0x5, {0xc000356868, 0x8a}, {0x0, 0x0}, 0x0, 0x88, {0x0, 0x0, 0x0}}, ...)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:110 +0x165\nmaunium.net/go/mautrix/crypto/canonicaljson.sortJSONValue({0x5, {0xc000356868, 0x8a}, {0x0, 0x0}, 0x0, 0x88, {0x0, 0x0, 0x0}}, ...)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:62 +0x289\nmaunium.net/go/mautrix/crypto/canonicaljson.sortJSONObject({0x5, {0xc0003567e0, 0x113}, {0x0, 0x0}, 0x0, 0x0, {0x0, 0x0, 0x0}}, ...)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:136 +0x5f3\nmaunium.net/go/mautrix/crypto/canonicaljson.sortJSONValue({0x5, {0xc0003567e0, 0x113}, {0x0, 0x0}, 0x0, 0x0, {0x0, 0x0, 0x0}}, ...)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:62 +0x289\nmaunium.net/go/mautrix/crypto/canonicaljson.SortJSON({0xc000356360, 0xc000258f00, 0x113}, {0xc0003565a0, 0x0, 0x113})\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:51 +0x23a\nmaunium.net/go/mautrix/crypto/canonicaljson.CanonicalJSONAssumeValid({0xc000356120, 0x113, 0x120})\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:42 +0x96\nmaunium.net/go/mautrix/crypto/olm.(*Utility).VerifySignatureJSON(0x50, {0x8bc0e0, 0xc0003920f0}, {0xc000400408, 0x15}, {0xc0004140f0, 0xa}, {0xc000424210, 0x2b})\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/olm/utility.go:146 +0x2c7\nmaunium.net/go/mautrix/crypto/olm.VerifySignatureJSON({0x8bc0e0, 0xc0003920f0}, {0xc000400408, 0x15}, {0xc0004140f0, 0xa}, {0xc000424210, 0x2b})\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/olm/utility.go:159 +0xe5\nmaunium.net/go/mautrix/crypto.(*OlmMachine).validateDevice(0x0, {0xc000400408, 0x2}, {0xc0004140f0, 0xa}, {{0xc0004003c0, 0x15}, {0xc0004140d0, 0xa}, {0xc0001ae880, ...}, ...}, ...)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/devicelist.go:165 +0x21d\nmaunium.net/go/mautrix/crypto.(*OlmMachine).fetchKeys(0xc0000fc300, {0xc0003dc520, 0x1, 0x1}, {0x0, 0x0}, 0x1)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/devicelist.go:75 +0xf2c\nmaunium.net/go/mautrix/crypto.(*OlmMachine).GetOrFetchDevice(0xc0000fc300, {0xc000437a10, 0x2b}, {0xc0003e03a0, 0xa})\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/machine.go:343 +0x108\nmaunium.net/go/mautrix/crypto.(*OlmMachine).DecryptMegolmEvent(0xc0000fc300, 0xc000202780)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/decryptmegolm.go:58 +0x457\nmain.main.func3(0x878d60, 0xc000202780)\n\t/main.go:70 +0x54\nmaunium.net/go/mautrix.(*DefaultSyncer).notifyListeners(0xc0000667d0, 0xc000296510, 0xc000202780)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/sync.go:203 +0xd7\nmaunium.net/go/mautrix.(*DefaultSyncer).processSyncEvent(0xc0000667d0, {0xc0000193b0, 0xc00018fcb0}, 0xc000202780, 0x22)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/sync.go:193 +0x105\nmaunium.net/go/mautrix.(*DefaultSyncer).processSyncEvents(0xc000159ab8, {0xc0000193b0, 0x21}, {0xc00017e200, 0x32, 0xc00010e540}, 0xc000108d00)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/sync.go:164 +0x4a\nmaunium.net/go/mautrix.(*DefaultSyncer).ProcessResponse(0xc0000667d0, 0xc0000ce000, {0x0, 0x0})\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/sync.go:148 +0x293\nmaunium.net/go/mautrix.(*Client).SyncWithContext(0xc0000c82a0, {0x96c470, 0xc00001c038})\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/client.go:284 +0x46f\nmaunium.net/go/mautrix.(*Client).Sync(...)\n\t/root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/client.go:225\nmain.main()\n\t/main.go:114 +0x10f9\n"

Here's the log message with actual newlines and tabs:

time="2021-12-31T20:10:05Z" level=fatal msg="error syncing: ProcessResponse panicked! since= panic=runtime error: slice bounds out of range [:160] with capacity 152
goroutine 1 [running]:
runtime/debug.Stack()
  /usr/lib/go/src/runtime/debug/stack.go:24 +0x65
maunium.net/go/mautrix.(*DefaultSyncer).ProcessResponse.func1()
  /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/sync.go:133 +0x66
panic({0x8ba520, 0xc000400690})
  /usr/lib/go/src/runtime/panic.go:1038 +0x215
maunium.net/go/mautrix/crypto/canonicaljson.RawJSONFromResult(...)
  /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:274
maunium.net/go/mautrix/crypto/canonicaljson.sortJSONObject.func1({0x3, {0xc000356869, 0x17}, {0xc00035686a, 0x15}, 0x0, 0x89, {0x0, 0x0, 0x0}}, ...)
  /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:113 +0x2d4
github.com/tidwall/gjson.Result.ForEach({0x5, {0xc000356868, 0x8a}, {0x0, 0x0}, 0x0, 0x88, {0x0, 0x0, 0x0}}, ...)
  /root/go/pkg/mod/github.com/tidwall/gjson@v1.12.1/gjson.go:293 +0x52c
maunium.net/go/mautrix/crypto/canonicaljson.sortJSONObject({0x5, {0xc000356868, 0x8a}, {0x0, 0x0}, 0x0, 0x88, {0x0, 0x0, 0x0}}, ...)
  /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:110 +0x165
maunium.net/go/mautrix/crypto/canonicaljson.sortJSONValue({0x5, {0xc000356868, 0x8a}, {0x0, 0x0}, 0x0, 0x88, {0x0, 0x0, 0x0}}, ...)
  /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:62 +0x289
maunium.net/go/mautrix/crypto/canonicaljson.sortJSONObject({0x5, {0xc0003567e0, 0x113}, {0x0, 0x0}, 0x0, 0x0, {0x0, 0x0, 0x0}}, ...)
  /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:136 +0x5f3
maunium.net/go/mautrix/crypto/canonicaljson.sortJSONValue({0x5, {0xc0003567e0, 0x113}, {0x0, 0x0}, 0x0, 0x0, {0x0, 0x0, 0x0}}, ...)
  /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:62 +0x289
maunium.net/go/mautrix/crypto/canonicaljson.SortJSON({0xc000356360, 0xc000258f00, 0x113}, {0xc0003565a0, 0x0, 0x113})
  /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:51 +0x23a
maunium.net/go/mautrix/crypto/canonicaljson.CanonicalJSONAssumeValid({0xc000356120, 0x113, 0x120})
  /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/canonicaljson/json.go:42 +0x96
maunium.net/go/mautrix/crypto/olm.(*Utility).VerifySignatureJSON(0x50, {0x8bc0e0, 0xc0003920f0}, {0xc000400408, 0x15}, {0xc0004140f0, 0xa}, {0xc000424210, 0x2b})
  /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/olm/utility.go:146 +0x2c7
maunium.net/go/mautrix/crypto/olm.VerifySignatureJSON({0x8bc0e0, 0xc0003920f0}, {0xc000400408, 0x15}, {0xc0004140f0, 0xa}, {0xc000424210, 0x2b})
  /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/olm/utility.go:159 +0xe5
maunium.net/go/mautrix/crypto.(*OlmMachine).validateDevice(0x0, {0xc000400408, 0x2}, {0xc0004140f0, 0xa}, {{0xc0004003c0, 0x15}, {0xc0004140d0, 0xa}, {0xc0001ae880, ...}, ...}, ...)
  /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/devicelist.go:165 +0x21d
maunium.net/go/mautrix/crypto.(*OlmMachine).fetchKeys(0xc0000fc300, {0xc0003dc520, 0x1, 0x1}, {0x0, 0x0}, 0x1)
  /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/devicelist.go:75 +0xf2c
maunium.net/go/mautrix/crypto.(*OlmMachine).GetOrFetchDevice(0xc0000fc300, {0xc000437a10, 0x2b}, {0xc0003e03a0, 0xa})
  /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/machine.go:343 +0x108
maunium.net/go/mautrix/crypto.(*OlmMachine).DecryptMegolmEvent(0xc0000fc300, 0xc000202780)
  /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/crypto/decryptmegolm.go:58 +0x457
main.main.func3(0x878d60, 0xc000202780)
  /main.go:70 +0x54
maunium.net/go/mautrix.(*DefaultSyncer).notifyListeners(0xc0000667d0, 0xc000296510, 0xc000202780)
  /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/sync.go:203 +0xd7
maunium.net/go/mautrix.(*DefaultSyncer).processSyncEvent(0xc0000667d0, {0xc0000193b0, 0xc00018fcb0}, 0xc000202780, 0x22)
  /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/sync.go:193 +0x105
maunium.net/go/mautrix.(*DefaultSyncer).processSyncEvents(0xc000159ab8, {0xc0000193b0, 0x21}, {0xc00017e200, 0x32, 0xc00010e540}, 0xc000108d00)
  /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/sync.go:164 +0x4a
maunium.net/go/mautrix.(*DefaultSyncer).ProcessResponse(0xc0000667d0, 0xc0000ce000, {0x0, 0x0})
  /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/sync.go:148 +0x293
maunium.net/go/mautrix.(*Client).SyncWithContext(0xc0000c82a0, {0x96c470, 0xc00001c038})
  /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/client.go:284 +0x46f
maunium.net/go/mautrix.(*Client).Sync(...)
  /root/go/pkg/mod/maunium.net/go/mautrix@v0.10.6/client.go:225
main.main()
  /main.go:114 +0x10f9
"

Also, although the output here was for mautrix-go 0.10.6, the issue is still happening in version 0.10.8 (the latest release). Unfortunately I didn't think to keep the logs for when I last hit the problem on mautrix-go 0.10.8.

rakshazi commented 2 years ago

I can provide logs for 0.10.8 if anybody need them, but they are pretty same

tulir commented 2 years ago

Looks like there's some sort of regression in gjson. I noticed while trying to update the version used in mautrix-go and reverted it back to the old version now.

I'm not sure why you were using the wrong version though.

rakshazi commented 2 years ago

Sorry for delay,

the issue fixed with new mautrix-go release, thank you!

edwargix commented 2 years ago

Looks like there's some sort of regression in gjson. I noticed while trying to update the version used in mautrix-go and reverted it back to the old version now.

I'm not sure why you were using the wrong version though.

Yeah this shouldn't have applied to us right?

I'm not sure how v0.10.9 fixes the issue since there's no change in the gjson version from v0.10.8: https://github.com/mautrix/go/compare/v0.10.8...v0.10.9

rakshazi commented 2 years ago

The updated gjson version was my issue

tulir commented 2 years ago

All mautrix-go releases have the correct gjson version, but both of your stacktraces had the wrong version. Using the correct gjson version (v1.10.2) will fix it

edwargix commented 2 years ago

All mautrix-go releases have the correct gjson version, but both of your stacktraces had the wrong version. Using the correct gjson version (v1.10.2) will fix it

Oh I see; I didn't even notice the v1.12.1 in my stacktrace! Like you, I'm also unsure why it was using that version, especially since my program doesn't use gjson directly (only through mautrix-go). There must be something go-get does with transitive dependency versioning that I don't know about.

Regardless, thanks for the help!

rakshazi commented 2 years ago

In my case it was go get -u - that flag updates minor and patch versions of dependencies (including indirect/transitive) automatically

edwargix commented 2 years ago

I submitted a bug report in gjson for this issue: https://github.com/tidwall/gjson/issues/263

edwargix commented 2 years ago

Fix here: https://github.com/mautrix/go/pull/62