Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Panic/fatal during imap operation #262

Open
mwyvr opened this issue Dec 13, 2024 · 3 comments
Open

Panic/fatal during imap operation #262

mwyvr opened this issue Dec 13, 2024 · 3 comments

Comments

@mwyvr
Copy link

mwyvr commented Dec 13, 2024 •
edited
Loading

Environment: FreeBSD 14.2-RELEASE (also occurred on 14.1-RELEASE p6)

./mox version
v0.0.14-0.20241110222017-3d4cd0043094
go1.23.4 freebsd/amd64

Since moving my mox installation from Linux to FreeBSD a couple weeks ago I've been noting non-fatal panics in mox logs relating to IMAP error: invalid memory address or nil pointer dereference" pkg=imapserver cmd="uid fetch"; the system has continued to function. I don't recall seeing these non-fatal panics before but don't have logs to verify.

Over the past week the mox daemon has been killed by fatal SIGSEGV panics a number of times; they are preceded by an IMAP connection(s) that don't make it to fetch.

While I've not seen these panics on Linux; the change in platforms may be a red herring or related to moving the data. I did a backup, verifydata, backup again, etc, prior to firing up the system on the new platform.

First, a typical non-fatal panic:

Dec 13 01:25:57 bugs mox[9062]: l=error m="imap command panic" err="runtime error: invalid memory address or nil pointer dereference" pkg=imapserver cmd="uid fetch" duration=4.667367ms cid=193aca2e1cf delta=331.617703ms [email protected]
Dec 13 01:25:57 bugs mox[9062]: l=error m="unhandled panic" err="runtime error: invalid memory address or nil pointer dereference" pkg=imapserver cid=193aca2e1cf delta="994.971µs" [email protected]
Dec 13 01:25:57 bugs mox[9062]: goroutine 22090 [running]:
Dec 13 01:25:57 bugs mox[9062]: runtime/debug.Stack()
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/src/go/src/runtime/debug/stack.go:26 +0x5e
Dec 13 01:25:57 bugs mox[9062]: runtime/debug.PrintStack()
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/src/go/src/runtime/debug/stack.go:18 +0x13
Dec 13 01:25:57 bugs mox[9062]: github.com/mjl-/mox/imapserver.serve.func2()
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/imapserver/server.go:707 +0x2c5
Dec 13 01:25:57 bugs mox[9062]: panic({0xf93b80?, 0x1b0fd50?})
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/src/go/src/runtime/panic.go:785 +0x132
Dec 13 01:25:57 bugs mox[9062]: github.com/mjl-/mox/imapserver.(*conn).command.func1()
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/imapserver/server.go:846 +0xce5
Dec 13 01:25:57 bugs mox[9062]: panic({0xf93b80?, 0x1b0fd50?})
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/src/go/src/runtime/panic.go:785 +0x132
Dec 13 01:25:57 bugs mox[9062]: github.com/mjl-/mox/imapserver.(*fetchCmd).process.func1()
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/imapserver/fetch.go:324 +0x32d
Dec 13 01:25:57 bugs mox[9062]: panic({0xf93b80?, 0x1b0fd50?})
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/src/go/src/runtime/panic.go:785 +0x132
Dec 13 01:25:57 bugs mox[9062]: github.com/mjl-/bstore.(*Query[...]).finish(0x12e3200, 0x86c8a2c40)
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/query.go:324 +0x18b
Dec 13 01:25:57 bugs mox[9062]: panic({0xf93b80?, 0x1b0fd50?})
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/src/go/src/runtime/panic.go:785 +0x132
Dec 13 01:25:57 bugs mox[9062]: internal/abi.(*Type).Kind(...)
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/src/go/src/internal/abi/type.go:189
Dec 13 01:25:57 bugs mox[9062]: reflect.Value.typeSlow({0x0?, 0x0?, 0x86c8a2c40?})
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/src/go/src/reflect/value.go:2698 +0x2f
Dec 13 01:25:57 bugs mox[9062]: reflect.Value.Type(...)
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/src/go/src/reflect/value.go:2682
Dec 13 01:25:57 bugs mox[9062]: github.com/mjl-/bstore.packIndexKey({0x0?, 0x0?, 0x415425?})
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/keys.go:269 +0x5b
Dec 13 01:25:57 bugs mox[9062]: github.com/mjl-/bstore.packIndexKeys({0x86c91b400, 0x1, 0xee7236?}, {0x0, 0x0, 0x0?})
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/keys.go:239 +0xa9
Dec 13 01:25:57 bugs mox[9062]: github.com/mjl-/bstore.(*Query[...]).selectPlan(0x12e3200)
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/plan.go:132 +0x1238
Dec 13 01:25:57 bugs mox[9062]: github.com/mjl-/bstore.(*Query[...]).nextKey(_, _, _)
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/query.go:371 +0x90
Dec 13 01:25:57 bugs mox[9062]: github.com/mjl-/bstore.(*Query[...]).Get(_)
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/query.go:963 +0x1b6
Dec 13 01:25:57 bugs mox[9062]: github.com/mjl-/mox/imapserver.(*fetchCmd).xensureMessage(0x86c91d880)
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/imapserver/fetch.go:280 +0x147
Dec 13 01:25:57 bugs mox[9062]: github.com/mjl-/mox/imapserver.(*fetchCmd).process(0x86c91d880, {0x86c7da180, 0x2, 0xfffffffffffffffc?})
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/imapserver/fetch.go:359 +0x785
Dec 13 01:25:57 bugs mox[9062]: github.com/mjl-/mox/imapserver.(*conn).cmdxFetch.func2(0x86c6cdb80)
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/imapserver/fetch.go:237 +0xcaa
Dec 13 01:25:57 bugs mox[9062]: github.com/mjl-/mox/imapserver.(*conn).xdbwrite.func1(0x86c91d6d0?)
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/imapserver/server.go:400 +0x17
Dec 13 01:25:57 bugs mox[9062]: github.com/mjl-/bstore.(*DB).Write.func1(0x86cc380e0)
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/store.go:653 +0xde
Dec 13 01:25:57 bugs mox[9062]: go.etcd.io/bbolt.(*DB).Update(0x10bdf23?, 0x86c91d750)
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/go/pkg/mod/go.etcd.io/[email protected]/db.go:886 +0x6f
Dec 13 01:25:57 bugs mox[9062]: github.com/mjl-/bstore.(*DB).Write(0x86c88ca00, {0x12caa68, 0x1b72a40}, 0x86c91d7c8)
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/store.go:649 +0xef
Dec 13 01:25:57 bugs mox[9062]: github.com/mjl-/mox/imapserver.(*conn).xdbwrite(0x86ce51260?, 0x36c0d83c0101?)
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/imapserver/server.go:399 +0x45
Dec 13 01:25:57 bugs mox[9062]: github.com/mjl-/mox/imapserver.(*conn).cmdxFetch(0x86c889b80, 0x1, {0x86cc28600, 0x1}, {0x86cc28602, 0x9}, 0x86ce51260)
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/imapserver/fetch.go:140 +0x42e
Dec 13 01:25:57 bugs mox[9062]: github.com/mjl-/mox/imapserver.(*conn).cmdUIDFetch(0xf80fe0?, {0x86cc28600?, 0x86cc2ea70?}, {0x86cc28602?, 0xa?}, 0x86ce50a80?)
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/imapserver/server.go:3242 +0x31
Dec 13 01:25:57 bugs mox[9062]: github.com/mjl-/mox/imapserver.(*conn).command(0x86c889b80)
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/imapserver/server.go:883 +0x33a
Dec 13 01:25:57 bugs mox[9062]: github.com/mjl-/mox/imapserver.serve({0x86c5c1321, 0x6}, 0x193aca2e1cf, 0x86c5c5180, {0x12d04f8, 0x86c005188}, 0x1, 0x0)
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/imapserver/server.go:748 +0x1230
Dec 13 01:25:57 bugs mox[9062]: created by github.com/mjl-/mox/imapserver.listen1.func1 in goroutine 122
Dec 13 01:25:57 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/imapserver/server.go:371 +0x2d7

And then a fatal SIGSEGV panic; this is preceded by two IMAP connections; this happens to be my device, and I have two mail accounts serviced by this mox instance:

Dec 13 05:30:24 bugs mox[9062]: l=info m="client id" pkg=imapserver params="map[AGUID:yTbzx2+mmBaECxCfUGPRFQlRmqY= name:com.google.android.gm os:android os-version:15; AP4A.241205.01
3 vendor:Google x-android-device-model:Pixel 7 x-android-mobile-net-operator:ROGERS]" cid=193aca2e444 delta=106.703494ms
Dec 13 05:30:24 bugs mox[9062]: l=info m="client id" pkg=imapserver params="map[AGUID:X8HC56yvKVamrXjr9zE4Q3K5xwI= name:com.google.android.gm os:android os-version:15; AP4A.241205.01
3 vendor:Google x-android-device-model:Pixel 7 x-android-mobile-net-operator:ROGERS]" cid=193aca2e445 delta=105.715804ms
Dec 13 05:30:24 bugs mox[9062]: unexpected fault address 0x10400010117
Dec 13 05:30:24 bugs mox[9062]: fatal error: fault
Dec 13 05:30:24 bugs mox[9062]: [signal SIGSEGV: segmentation violation code=0x1 addr=0x10400010117 pc=0x4e51d5]
Dec 13 05:30:24 bugs mox[9062]: 
Dec 13 05:30:24 bugs mox[9062]: goroutine 23201 gp=0x86c8da540 m=6 mp=0x86c369c08 [running]:
Dec 13 05:30:24 bugs mox[9062]: runtime.throw({0x10be7ba?, 0x86cc61a90?})
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/src/go/src/runtime/panic.go:1067 +0x48 fp=0x86cc61a10 sp=0x86cc619e0 pc=0x473c48
Dec 13 05:30:24 bugs mox[9062]: runtime.sigpanic()
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/src/go/src/runtime/signal_unix.go:931 +0x285 fp=0x86cc61a70 sp=0x86cc61a10 pc=0x475ac5
Dec 13 05:30:24 bugs mox[9062]: reflect.Zero({0x12d7cb0?, 0x10400010100?})
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/src/go/src/reflect/value.go:3278 +0x35 fp=0x86cc61aa0 sp=0x86cc61a70 pc=0x4e51d5
Dec 13 05:30:24 bugs mox[9062]: github.com/mjl-/bstore.typeVersion.parse({0x7, 0x2, 0x0, {0x86cd38a08, 0x3d, 0x43}, 0x86c2ed890, 0x86c2e0720, {0xeda049, 0x7}, ...}, ...)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/parse.go:169 +0x31f fp=0x86cc61d30 sp=0x86cc61aa0 pc=0x5865ff
Dec 13 05:30:24 bugs mox[9062]: github.com/mjl-/bstore.storeType.parse({{0xeda049, 0x7}, {0x12d7cb0, 0x10b9a80}, 0x86cae2510, 0x86c2ede90}, {0x10b9a80?, 0x86c8b8908?, 0x410965?}, {0x87e273038, ...})
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/parse.go:119 +0x2b8 fp=0x86cc61f30 sp=0x86cc61d30 pc=0x585bf8
Dec 13 05:30:24 bugs mox[9062]: github.com/mjl-/bstore.storeType.parseFull({{0xeda049, 0x7}, {0x12d7cb0, 0x10b9a80}, 0x86cae2510, 0x86c2ede90}, {0x10b9a80?, 0x86c8b8908?, 0x52e2d8?}, {0x87b99c718, ...}, ...)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/parse.go:143 +0x105 fp=0x86cc61fb8 sp=0x86cc61f30 pc=0x586245
Dec 13 05:30:24 bugs mox[9062]: github.com/mjl-/bstore.(*pair[...]).Value(_, _)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/query.go:162 +0x265 fp=0x86cc622e0 sp=0x86cc61fb8 pc=0xa9c765
Dec 13 05:30:24 bugs mox[9062]: github.com/mjl-/bstore.(*exec[...]).checkFilter(0x12d8380, 0x86cc63f80)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/exec.go:452 +0x230 fp=0x86cc63760 sp=0x86cc622e0 pc=0xa98f50
Dec 13 05:30:24 bugs mox[9062]: github.com/mjl-/bstore.(*exec[...]).nextKey(_, _, _)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/exec.go:376 +0x1990 fp=0x86cc64360 sp=0x86cc63760 pc=0xa9b9b0
Dec 13 05:30:24 bugs mox[9062]: github.com/mjl-/bstore.(*Query[...]).nextKey(_, _, _)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/query.go:380 +0x145 fp=0x86cc64810 sp=0x86cc64360 pc=0xa94085
Dec 13 05:30:24 bugs mox[9062]: github.com/mjl-/bstore.(*Query[...]).foreachKey(0x12e3200, 0x0, 0x1, 0x86cc64f88)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/query.go:399 +0xc5 fp=0x86cc64f18 sp=0x86cc64810 pc=0xa93ba5
Dec 13 05:30:24 bugs mox[9062]: github.com/mjl-/bstore.(*Query[...]).ForEach(0x12e3200, 0x86c621258)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/query.go:1243 +0x159 fp=0x86cc64fc8 sp=0x86cc64f18 pc=0xa8ae19
Dec 13 05:30:24 bugs mox[9062]: github.com/mjl-/mox/imapserver.(*conn).cmdSelectExamine.func1.1(0x86c64dcc0)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/imapserver/server.go:2034 +0x245 fp=0x86cc652a8 sp=0x86cc64fc8 pc=0xe26c05
Dec 13 05:30:24 bugs mox[9062]: github.com/mjl-/mox/imapserver.(*conn).xdbread.func1(0x5?)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/imapserver/server.go:408 +0x17 fp=0x86cc652c0 sp=0x86cc652a8 pc=0xe15cd7
Dec 13 05:30:24 bugs mox[9062]: github.com/mjl-/bstore.(*DB).Read.func1(0x86d1750a0)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/store.go:634 +0xde fp=0x86cc65338 sp=0x86cc652c0 pc=0x59ca1e
Dec 13 05:30:24 bugs mox[9062]: go.etcd.io/bbolt.(*DB).View(0xe3957c?, 0x86c6213e0)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/go.etcd.io/[email protected]/db.go:917 +0x6c fp=0x86cc653a0 sp=0x86cc65338 pc=0x566f6c
Dec 13 05:30:24 bugs mox[9062]: github.com/mjl-/bstore.(*DB).Read(0x86cb08140, {0x12caa68, 0x1b72a40}, 0x86c621458)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/store.go:630 +0xef fp=0x86cc65420 sp=0x86cc653a0 pc=0x59c8af
Dec 13 05:30:24 bugs mox[9062]: github.com/mjl-/mox/imapserver.(*conn).xdbread(0x10bd116?, 0x2?)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/imapserver/server.go:407 +0x45 fp=0x86cc65478 sp=0x86cc65420 pc=0xe15c85
Dec 13 05:30:24 bugs mox[9062]: github.com/mjl-/mox/imapserver.(*conn).cmdSelectExamine.func1()
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/imapserver/server.go:2025 +0x7b fp=0x86cc654d8 sp=0x86cc65478 pc=0xe2699b
Dec 13 05:30:24 bugs mox[9062]: github.com/mjl-/mox/store.(*Account).WithRLock(0x86cc8f890?, 0x1000?)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/store/account.go:1380 +0x7e fp=0x86cc65520 sp=0x86cc654d8 pc=0xa6635e
Dec 13 05:30:24 bugs mox[9062]: github.com/mjl-/mox/imapserver.(*conn).cmdSelectExamine(0x86cd6da20, 0x1, {0x86cc8f800, 0x1}, {0x86c19c268?, 0x86c16cc88?}, 0x86cd2b020)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/imapserver/server.go:2024 +0x917 fp=0x86cc65ad0 sp=0x86cc65520 pc=0xe24df7
Dec 13 05:30:24 bugs mox[9062]: github.com/mjl-/mox/imapserver.(*conn).cmdSelect(0xf80fe0?, {0x86cc8f800?, 0x86cc8f830?}, {0x86cc8f802?, 0xa?}, 0x86c8a7140?)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/imapserver/server.go:1933 +0x31 fp=0x86cc65b18 sp=0x86cc65ad0 pc=0xe24411
Dec 13 05:30:24 bugs mox[9062]: github.com/mjl-/mox/imapserver.(*conn).command(0x86cd6da20)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/imapserver/server.go:883 +0x33a fp=0x86cc65c08 sp=0x86cc65b18 pc=0xe1935a
Dec 13 05:30:24 bugs mox[9062]: github.com/mjl-/mox/imapserver.serve({0x86c5c1321, 0x6}, 0x193aca2e445, 0x86c5c5180, {0x12d04f8, 0x86c6b2388}, 0x1, 0x0)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/imapserver/server.go:748 +0x1230 fp=0x86cc65f98 sp=0x86cc65c08 pc=0xe18690
Dec 13 05:30:24 bugs mox[9062]: github.com/mjl-/mox/imapserver.listen1.func1.gowrap1()
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/imapserver/server.go:371 +0x3e fp=0x86cc65fe0 sp=0x86cc65f98 pc=0xe15abe
Dec 13 05:30:24 bugs mox[9062]: runtime.goexit({})
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/src/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0x86cc65fe8 sp=0x86cc65fe0 pc=0x47bda1
Dec 13 05:30:24 bugs mox[9062]: created by github.com/mjl-/mox/imapserver.listen1.func1 in goroutine 122
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/imapserver/server.go:371 +0x2d7
Dec 13 05:30:24 bugs mox[9062]: 
Dec 13 05:30:24 bugs mox[9062]: goroutine 1 gp=0x86c0061c0 m=nil [chan receive, 5474 minutes]:
Dec 13 05:30:24 bugs mox[9062]: runtime.gopark(0x994005?, 0xfb20c0?, 0x1?, 0xea?, 0x86c621868?)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/src/go/src/runtime/proc.go:424 +0xce fp=0x86c0e77d8 sp=0x86c0e77b8 pc=0x473d6e
Dec 13 05:30:24 bugs mox[9062]: runtime.chanrecv(0x86c51f8f0, 0x86c621d00, 0x1)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/src/go/src/runtime/chan.go:639 +0x41c fp=0x86c0e7850 sp=0x86c0e77d8 pc=0x409d5c
Dec 13 05:30:24 bugs mox[9062]: runtime.chanrecv1(0x86c51f8f0?, 0x86c621d10?)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/src/go/src/runtime/chan.go:489 +0x12 fp=0x86c0e7878 sp=0x86c0e7850 pc=0x409912
Dec 13 05:30:24 bugs mox[9062]: main.cmdServe(0x86c19ce10)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/serve_unix.go:414 +0x1245 fp=0x86c0e7d68 sp=0x86c0e7878 pc=0xeb4165
Dec 13 05:30:24 bugs mox[9062]: main.main()
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/go/pkg/mod/github.com/mjl-/[email protected]/main.go:520 +0xce6 fp=0x86c0e7f50 sp=0x86c0e7d68 pc=0xe820e6
Dec 13 05:30:24 bugs mox[9062]: runtime.main()
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/src/go/src/runtime/proc.go:272 +0x28b fp=0x86c0e7fe0 sp=0x86c0e7f50 pc=0x43e1cb
Dec 13 05:30:24 bugs mox[9062]: runtime.goexit({})
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/src/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0x86c0e7fe8 sp=0x86c0e7fe0 pc=0x47bda1
Dec 13 05:30:24 bugs mox[9062]: 
Dec 13 05:30:24 bugs mox[9062]: goroutine 2 gp=0x86c006700 m=nil [force gc (idle), 5 minutes]:
Dec 13 05:30:24 bugs mox[9062]: runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/src/go/src/runtime/proc.go:424 +0xce fp=0x86c05afa8 sp=0x86c05af88 pc=0x473d6e
Dec 13 05:30:24 bugs mox[9062]: runtime.goparkunlock(...)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/src/go/src/runtime/proc.go:430
Dec 13 05:30:24 bugs mox[9062]: runtime.forcegchelper()
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/src/go/src/runtime/proc.go:337 +0xa5 fp=0x86c05afe0 sp=0x86c05afa8 pc=0x43e505
Dec 13 05:30:24 bugs mox[9062]: runtime.goexit({})
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/src/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0x86c05afe8 sp=0x86c05afe0 pc=0x47bda1
Dec 13 05:30:24 bugs mox[9062]: created by runtime.init.7 in goroutine 1
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/src/go/src/runtime/proc.go:325 +0x1a
Dec 13 05:30:24 bugs mox[9062]: 
Dec 13 05:30:24 bugs mox[9062]: goroutine 3 gp=0x86c006c40 m=nil [runnable]:
Dec 13 05:30:24 bugs mox[9062]: runtime.goschedIfBusy()
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/src/go/src/runtime/proc.go:376 +0x28 fp=0x86c05b780 sp=0x86c05b768 pc=0x43e5a8
Dec 13 05:30:24 bugs mox[9062]: runtime.bgsweep(0x86c03a080)
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/src/go/src/runtime/mgcsweep.go:301 +0x14f fp=0x86c05b7c8 sp=0x86c05b780 pc=0x42670f
Dec 13 05:30:24 bugs mox[9062]: runtime.gcenable.gowrap1()
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/src/go/src/runtime/mgc.go:204 +0x25 fp=0x86c05b7e0 sp=0x86c05b7c8 pc=0x41ae65
Dec 13 05:30:24 bugs mox[9062]: runtime.goexit({})
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/src/go/src/runtime/asm_amd64.s:1700 +0x1 fp=0x86c05b7e8 sp=0x86c05b7e0 pc=0x47bda1
Dec 13 05:30:24 bugs mox[9062]: created by runtime.gcenable in goroutine 1
Dec 13 05:30:24 bugs mox[9062]:         /home/mw/src/go/src/runtime/mgc.go:204 +0x66
... followed by > 100 goroutines
@mwyvr
Copy link
Author

mwyvr commented Dec 13, 2024 •
edited
Loading

I'm starting to wonder if it is platform specific, as I'm seeing inconsistent behaviour building mox on the server and on my workstation. Related to that, I note the following:

golang/go#35777
https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=270247

Building with GODEBUG=asyncpreemptoff=1 is successful on the problematic server. I'm going to try running that binary and observe.

Edit: No issues observed yet when running code built with that flag.

Further investigation shows there may, in fact, be an issue with Go in certain virtualized environments, first noted in 2020. Furthermore, as the issue affects a number of non-trivial Go applications I've tested, not just mox, and affects go install of go itself -- and all of these only on a FreeBSD virtual machine, not on Linux VMs or Linux or FreeBSD baremetal, it now seems clear that mox isn't the issue.

I think you can close this or at least ignore it for now; I'm pursuing this with the Go and FreeBSD projects; will update this with any final conclusions or resolution.

@mjl-
Copy link
Owner

mjl- commented Dec 15, 2024

Hi @mwyvr, thanks for reporting and looking into this closer. Will be interesting to learn the cause of this, and which kinds of applications trigger this.

@mwyvr
Copy link
Author

mwyvr commented Dec 17, 2024

An update: this is not a mox issue and can be closed, but as running mox on a VM is likely a common deployment strategy, others may run into this.

The issue relates to this report on the Go project: golang/go#46272

Digging into the details, it has become clear the issue isn't specific to Go, either.

golang/go#69255 (comment)

A FreeBSD project contributor wrote a C program that fails memcmp tests on Vultr's VM infrastructure when running a FreeBSD guest. It does not fail on FreeBSD running on bare metal, nor on another commercial FreeBSD VMs running on typical KVM/QEMU platform.

From the Go discussion:

suspect the fault comes down to aarch64 only having 47 or 39 bits of address space while the x86_64 GC assume 48 bits. Under linux-user emulation we are limited by the host address space. However I do note 48 was chosen for all arches so I wonder ...

A Reddit comment points to a possible configuration choice that Vultr, a fairly sizable commercial VM provider, may have made.

On the latest several generations of Xeons, and some EPYCs, there's a BIOS flag for adjusting bit depth in relation to (checks notes, is too early to recall from memory, may have additional cognition online later today.. only had four hours of sleep)... uuuh... it's almost always a Microsoft issue in root cause analysis.

Regardless of what happens with FreeBSD on Vultr, I'm going to move my mox instance to the other FreeBSD provider late today and run it for a few days; will update with results.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@mjl- @mwyvr