search

mjl- / mox

modern full-featured open source secure mail server for low-maintenance self-hosted email
https://www.xmox.nl
MIT License
3.7k stars 111 forks source link

Stack traces on recent re-install #238

Closed mwyvr closed 1 week ago

mwyvr commented 2 weeks ago

I recently moved my mox system to a new virtual machine and have been seeing stack traces in the logs since bringing it up. They appear to all be pkg=smtpserver related, and all are bogus connections. 

mox version
v0.0.12
go1.23.2 linux/amd64

mox is built and runs on a musl libc system; for a short period of time I had it running on 0.0.12 on a glibc system until moving it back this week. I've not seen these stack traces before.

Please let me know what I can do to assist.

None of the stack trace events appear to be associated with legitimate smtp connections. Here's a connection (cid=19302fb3e1f) that appears to have triggered the trace, or is coincidental with the debug trace:

2024-11-06 22:06:52 info mox[1241]: l=info m="new connection" pkg=smtpserver remote=94.141.120.188:34491 local=45.63.39.122:25 submission=false tls=false listener=public cid=19302fb3e1e delta="
71.14µs"
2024-11-06 22:06:52 info mox[1241]: l=info m="connection closed" pkg=smtpserver cid=19302fb3e1e delta=435.2978ms
2024-11-06 22:07:11 info mox[1241]: l=info m="new connection" pkg=smtpserver remote=77.85.243.55:38809 local=45.63.39.122:465 submission=true tls=true listener=public cid=19302fb3e1f delta="58.
495µs"
2024-11-06 22:07:16 info mox[1241]: goroutine 1021 [running]:
2024-11-06 22:07:16 info mox[1241]: runtime/debug.Stack()
2024-11-06 22:07:16 info mox[1241]:     /usr/lib/go/src/runtime/debug/stack.go:26 +0x5e
2024-11-06 22:07:16 info mox[1241]: runtime/debug.PrintStack()
2024-11-06 22:07:16 info mox[1241]:     /usr/lib/go/src/runtime/debug/stack.go:18 +0x13
2024-11-06 22:07:16 info mox[1241]: github.com/mjl-/mox/smtpserver.command.func1()
2024-11-06 22:07:16 info mox[1241]:     /home/mox/go/pkg/mod/github.com/mjl-/mox@v0.0.12/smtpserver/server.go:754 +0x18c
2024-11-06 22:07:16 info mox[1241]: panic({0x1055660?, 0xc000908a80?})
2024-11-06 22:07:16 info mox[1241]:     /usr/lib/go/src/runtime/panic.go:785 +0x132
2024-11-06 22:07:16 info mox[1241]: github.com/mjl-/mox/smtpserver.xcheckf({0x12c3f20, 0x1b0fd70}, {0x10d84fe?, 0x1b0fd60?}, {0x0?, 0x1?, 0x0?})
2024-11-06 22:07:16 info mox[1241]:     /home/mox/go/pkg/mod/github.com/mjl-/mox@v0.0.12/smtpserver/error.go:12 +0x17e
2024-11-06 22:07:16 info mox[1241]: github.com/mjl-/mox/smtpserver.(*conn).cmdAuth(0xc00087cfc8, 0xc000908a40)
2024-11-06 22:07:16 info mox[1241]:     /home/mox/go/pkg/mod/github.com/mjl-/mox@v0.0.12/smtpserver/server.go:1114 +0xe5b
2024-11-06 22:07:16 info mox[1241]: github.com/mjl-/mox/smtpserver.command(0xc00087cfc8)
2024-11-06 22:07:16 info mox[1241]:     /home/mox/go/pkg/mod/github.com/mjl-/mox@v0.0.12/smtpserver/server.go:802 +0x383
2024-11-06 22:07:16 info mox[1241]: github.com/mjl-/mox/smtpserver.serve({0xc0005c25b1, 0x6}, 0x19302fb3e1f, {{0xc0000ce18a?, 0x1?}, {0x0?, 0x0?}}, 0xc0005b41c0, {0x12d1838, 0xc000366008}, ...)
2024-11-06 22:07:16 info mox[1241]:     /home/mox/go/pkg/mod/github.com/mjl-/mox@v0.0.12/smtpserver/server.go:704 +0x1385
2024-11-06 22:07:16 info mox[1241]: created by github.com/mjl-/mox/smtpserver.listen1.func1 in goroutine 124
2024-11-06 22:07:16 info mox[1241]:     /home/mox/go/pkg/mod/github.com/mjl-/mox@v0.0.12/smtpserver/server.go:272 +0x45f
2024-11-06 22:07:16 info mox[1241]: l=info m="connection closed" err="read: EOF (io error)" pkg=smtpserver cid=19302fb3e1f delta=5.135998754s
mjl- commented 2 weeks ago

Hi @mwyvr, thanks for reporting. It's coming from https://github.com/mjl-/mox/blob/v0.0.12/smtpserver/server.go#L1114, the xcheckf() is seeing an "err" from store.OpenEmailAuth that is not nil and not store.ErrUnknownCredentials. I don't immediately see what it could be. The stack is being printed at https://github.com/mjl-/mox/blob/v0.0.12/smtpserver/server.go#L754, which is just a way to help debugging. A few lines above, an smtp response is written. Could you enable tracing on the smtp server? This can be enabled in mox.conf, or while the process is alive in the admin web interface. Next time such a stack trace is printed, we should see a descriptive error message. I'll add error logging to just above the stack printing too. I'm now preparing a v0.0.13 release, this won't be included yet though.

mwyvr commented 2 weeks ago

OK, Here's one stack dump with "trace" on, it appears to relate to cid=193041edbb7:

2024-11-07 02:16:19 info mox[1241]: l=info m="new connection" pkg=smtpserver remote=121.88.205.146:53073 local=45.63.39.122:465 submission=true tls=true listener=public cid=193041edbb7 delta="54.599µs"
2024-11-07 02:16:19 info mox[1241]: l=trace m="LS: 220 bugs.solutionroute.com ESMTP mox v0.0.12\r\n" pkg=smtpserver cid=193041edbb7 delta="36.122µs"
2024-11-07 02:16:22 info mox[1241]: l=trace m="RC: EHLO [127.0.0.1]\r\n" pkg=smtpserver cid=193041edbb7 delta=2.884074403s
2024-11-07 02:16:22 info mox[1241]: l=debug m="smtp command result" pkg=smtpserver kind=submission cmd=ehlo code=250 ecode= duration="20.44µs" cid=193041edbb7 delta="53.151µs"
2024-11-07 02:16:22 info mox[1241]: l=trace m="LS: 250-bugs.solutionroute.com\r\n250-PIPELINING\r\n250-SIZE 104857600\r\n250-REQUIRETLS\r\n250-AUTH SCRAM-SHA-256-PLUS SCRAM-SHA-256 SCRAM-SHA-1-PLUS SCRAM-SHA-1 CRAM-MD5 PLAIN LOGIN\r\n250-FUTURERELEASE 5184000 2025-01-06T02:16:22Z\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250-LIMITS RCPTMAX=1000\r\n250 SMTPUTF8\r\n" pkg=smtpserver cid=193041edbb7 delta="12.535µs"
2024-11-07 02:16:23 info mox[1241]: l=trace m="RC: AUTH LOGIN\r\n" pkg=smtpserver cid=193041edbb7 delta=849.912379ms
2024-11-07 02:16:23 info mox[1241]: l=trace m="LS: 334 VXNlcm5hbWU6\r\n" pkg=smtpserver cid=193041edbb7 delta="28.605µs"
2024-11-07 02:16:24 info mox[1241]: l=trace m="RC: cGhvdG9AbWlrZXdhdGtpbnMuY2E=\r\n" pkg=smtpserver cid=193041edbb7 delta=821.917947ms
2024-11-07 02:16:24 info mox[1241]: l=trace m="LS: 334 UGFzc3dvcmQ6\r\n" pkg=smtpserver cid=193041edbb7 delta="15.772µs"
2024-11-07 02:16:24 info mox[1241]: l=info m="new connection" pkg=smtpserver remote=94.141.120.188:2116 local=45.63.39.122:25 submission=false tls=false listener=public cid=193041edbba delta="41.246µs"
2024-11-07 02:16:24 info mox[1241]: l=trace m="LS: 220 bugs.solutionroute.com ESMTP mox v0.0.12\r\n" pkg=smtpserver cid=193041edbba delta="20.654µs"
2024-11-07 02:16:24 info mox[1241]: l=trace m="RC: EHLO User\r\n" pkg=smtpserver cid=193041edbba delta=140.759283ms
2024-11-07 02:16:24 info mox[1241]: l=debug m="smtp command result" pkg=smtpserver kind=smtp cmd=ehlo code=250 ecode= duration="15.938µs" cid=193041edbba delta="41.644µs"
2024-11-07 02:16:24 info mox[1241]: l=trace m="LS: 250-bugs.solutionroute.com\r\n250-PIPELINING\r\n250-SIZE 104857600\r\n250-STARTTLS\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250-LIMITS RCPTMAX=1000\r\n250 SMTPUTF8\r\n" pkg=smtpserver cid=193041edbba delta="10.527µs"
2024-11-07 02:16:24 info mox[1241]: l=trace m="RC: AUTH LOGIN\r\n" pkg=smtpserver cid=193041edbba delta=150.789071ms
2024-11-07 02:16:24 info mox[1241]: l=debug m="smtp command result" err="authentication only allowed on submission ports" pkg=smtpserver kind=smtp cmd=auth code=503 ecode=5.5.1 duration="23.836µs" cid=193041edbba delta="102.154µs"
2024-11-07 02:16:24 info mox[1241]: l=trace m="LS: 503 5.5.1 authentication only allowed on submission ports (8h0LkJj_GoMsZqce1WXO0g)\r\n" pkg=smtpserver cid=193041edbba delta="11.331µs"
2024-11-07 02:16:24 info mox[1241]: l=trace m="RC: QUIT\r\n" pkg=smtpserver cid=193041edbba delta=147.463371ms
2024-11-07 02:16:24 info mox[1241]: l=debug m="smtp command result" pkg=smtpserver kind=smtp cmd=quit code=221 ecode=2.0.0 duration="11.076µs" cid=193041edbba delta="34.94µs"
2024-11-07 02:16:24 info mox[1241]: l=trace m="LS: 221 2.0.0 okay thanks bye\r\n" pkg=smtpserver cid=193041edbba delta="9.708µs"
2024-11-07 02:16:24 info mox[1241]: l=info m="connection closed" pkg=smtpserver cid=193041edbba delta="69.718µs"
2024-11-07 02:16:25 info mox[1241]: l=traceauth m="RC: ***" pkg=smtpserver cid=193041edbb7 delta=1.042054949s
2024-11-07 02:16:25 info mox[1241]: l=debug m="smtp command result" err="verifying credentials: no such account" pkg=smtpserver kind=submission cmd=auth code=451 ecode=4.3.0 duration=1.864105972s cid=193041edbb7 delta="120.654µs"
2024-11-07 02:16:25 info mox[1241]: l=trace m="LS: 451 4.3.0 verifying credentials: no such account (OYlkSNj8U5g9wu6YXqh2rA)\r\n" pkg=smtpserver cid=193041edbb7 delta="11.945µs"
2024-11-07 02:16:25 info mox[1241]: goroutine 825 [running]:
2024-11-07 02:16:25 info mox[1241]: runtime/debug.Stack()
2024-11-07 02:16:25 info mox[1241]:     /usr/lib/go/src/runtime/debug/stack.go:26 +0x5e
2024-11-07 02:16:25 info mox[1241]: runtime/debug.PrintStack()
2024-11-07 02:16:25 info mox[1241]:     /usr/lib/go/src/runtime/debug/stack.go:18 +0x13
2024-11-07 02:16:25 info mox[1241]: github.com/mjl-/mox/smtpserver.command.func1()
2024-11-07 02:16:25 info mox[1241]:     /home/mox/go/pkg/mod/github.com/mjl-/mox@v0.0.12/smtpserver/server.go:754 +0x18c
2024-11-07 02:16:25 info mox[1241]: panic({0x1055660?, 0xc0002df940?})
2024-11-07 02:16:25 info mox[1241]:     /usr/lib/go/src/runtime/panic.go:785 +0x132
2024-11-07 02:16:25 info mox[1241]: github.com/mjl-/mox/smtpserver.xcheckf({0x12c3f20, 0x1b0fd70}, {0x10d84fe?, 0x1b0fd60?}, {0x0?, 0x0?, 0x13?})
2024-11-07 02:16:25 info mox[1241]:     /home/mox/go/pkg/mod/github.com/mjl-/mox@v0.0.12/smtpserver/error.go:12 +0x17e
2024-11-07 02:16:25 info mox[1241]: github.com/mjl-/mox/smtpserver.(*conn).cmdAuth(0xc0006dcb48, 0xc0002df1c0)
2024-11-07 02:16:25 info mox[1241]:     /home/mox/go/pkg/mod/github.com/mjl-/mox@v0.0.12/smtpserver/server.go:1163 +0x77b
2024-11-07 02:16:25 info mox[1241]: github.com/mjl-/mox/smtpserver.command(0xc0006dcb48)
2024-11-07 02:16:25 info mox[1241]:     /home/mox/go/pkg/mod/github.com/mjl-/mox@v0.0.12/smtpserver/server.go:802 +0x383
2024-11-07 02:16:25 info mox[1241]: github.com/mjl-/mox/smtpserver.serve({0xc0005aac61, 0x6}, 0x193041edbb7, {{0xc00056d80a?, 0x16?}, {0x0?, 0x0?}}, 0xc00059d6c0, {0x12d1838, 0xc0001a1888}, ...)
2024-11-07 02:16:25 info mox[1241]:     /home/mox/go/pkg/mod/github.com/mjl-/mox@v0.0.12/smtpserver/server.go:704 +0x1385
2024-11-07 02:16:25 info mox[1241]: created by github.com/mjl-/mox/smtpserver.listen1.func1 in goroutine 96
2024-11-07 02:16:25 info mox[1241]:     /home/mox/go/pkg/mod/github.com/mjl-/mox@v0.0.12/smtpserver/server.go:272 +0x45f
2024-11-07 02:16:25 info mox[1241]: l=info m="connection closed" err="read: EOF (io error)" pkg=smtpserver cid=193041edbb7 delta=594.028548ms
mwyvr commented 2 weeks ago

And another, same situation.

2024-11-07 03:51:01 info mox[1241]: l=info m="new connection" pkg=smtpserver remote=220.80.210.47:34984 local=45.63.39.122:465 submission=true tls=true listener=public cid=193041edcd1 delta="12
6.647µs"
2024-11-07 03:51:01 info mox[1241]: l=trace m="LS: 220 bugs.solutionroute.com ESMTP mox v0.0.12\r\n" pkg=smtpserver cid=193041edcd1 delta="105.901µs"
2024-11-07 03:51:03 info mox[1241]: l=trace m="RC: EHLO [127.0.0.1]\r\n" pkg=smtpserver cid=193041edcd1 delta=2.034792641s
2024-11-07 03:51:03 info mox[1241]: l=debug m="smtp command result" pkg=smtpserver kind=submission cmd=ehlo code=250 ecode= duration="20.929µs" cid=193041edcd1 delta="56.13µs"
2024-11-07 03:51:03 info mox[1241]: l=trace m="LS: 250-bugs.solutionroute.com\r\n250-PIPELINING\r\n250-SIZE 104857600\r\n250-REQUIRETLS\r\n250-AUTH SCRAM-SHA-256-PLUS SCRAM-SHA-256 SCRAM-SHA-1-
PLUS SCRAM-SHA-1 CRAM-MD5 PLAIN LOGIN\r\n250-FUTURERELEASE 5184000 2025-01-06T03:51:03Z\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250-LIMITS RCPTMAX=1000\r\n250 SMTPUTF8\r\n" pkg=smtpserver
 cid=193041edcd1 delta="12.914µs"
2024-11-07 03:51:04 info mox[1241]: l=trace m="RC: AUTH LOGIN\r\n" pkg=smtpserver cid=193041edcd1 delta=758.963032ms
2024-11-07 03:51:04 info mox[1241]: l=trace m="LS: 334 VXNlcm5hbWU6\r\n" pkg=smtpserver cid=193041edcd1 delta="25.34µs"
2024-11-07 03:51:04 info mox[1241]: l=trace m="RC: cGhvdG9AbWlrZXdhdGtpbnMuY2E=\r\n" pkg=smtpserver cid=193041edcd1 delta=677.94826ms
2024-11-07 03:51:04 info mox[1241]: l=trace m="LS: 334 UGFzc3dvcmQ6\r\n" pkg=smtpserver cid=193041edcd1 delta="22.117µs"
2024-11-07 03:51:05 info mox[1241]: l=traceauth m="RC: ***" pkg=smtpserver cid=193041edcd1 delta=668.540795ms
2024-11-07 03:51:05 info mox[1241]: l=debug m="smtp command result" err="verifying credentials: no such account" pkg=smtpserver kind=submission cmd=auth code=451 ecode=4.3.0 duration=1.34660208
4s cid=193041edcd1 delta="116.951µs"
2024-11-07 03:51:05 info mox[1241]: l=trace m="LS: 451 4.3.0 verifying credentials: no such account (muMGPGZC9SQ5NVf5WnrfWQ)\r\n" pkg=smtpserver cid=193041edcd1 delta="14.281µs"
2024-11-07 03:51:05 info mox[1241]: goroutine 2206 [running]:
2024-11-07 03:51:05 info mox[1241]: runtime/debug.Stack()
2024-11-07 03:51:05 info mox[1241]:     /usr/lib/go/src/runtime/debug/stack.go:26 +0x5e
2024-11-07 03:51:05 info mox[1241]: runtime/debug.PrintStack()
2024-11-07 03:51:05 info mox[1241]:     /usr/lib/go/src/runtime/debug/stack.go:18 +0x13
2024-11-07 03:51:05 info mox[1241]: github.com/mjl-/mox/smtpserver.command.func1()
2024-11-07 03:51:05 info mox[1241]:     /home/mox/go/pkg/mod/github.com/mjl-/mox@v0.0.12/smtpserver/server.go:754 +0x18c
2024-11-07 03:51:05 info mox[1241]: panic({0x1055660?, 0xc000a54080?})
2024-11-07 03:51:05 info mox[1241]:     /usr/lib/go/src/runtime/panic.go:785 +0x132
2024-11-07 03:51:05 info mox[1241]: github.com/mjl-/mox/smtpserver.xcheckf({0x12c3f20, 0x1b0fd70}, {0x10d84fe?, 0x1b0fd60?}, {0x0?, 0x0?, 0x13?})
2024-11-07 03:51:05 info mox[1241]:     /home/mox/go/pkg/mod/github.com/mjl-/mox@v0.0.12/smtpserver/error.go:12 +0x17e
2024-11-07 03:51:05 info mox[1241]: github.com/mjl-/mox/smtpserver.(*conn).cmdAuth(0xc0009b4488, 0xc000a54040)
2024-11-07 03:51:05 info mox[1241]:     /home/mox/go/pkg/mod/github.com/mjl-/mox@v0.0.12/smtpserver/server.go:1163 +0x77b
2024-11-07 03:51:05 info mox[1241]: github.com/mjl-/mox/smtpserver.command(0xc0009b4488)
2024-11-07 03:51:05 info mox[1241]:     /home/mox/go/pkg/mod/github.com/mjl-/mox@v0.0.12/smtpserver/server.go:802 +0x383
2024-11-07 03:51:05 info mox[1241]: github.com/mjl-/mox/smtpserver.serve({0xc0005aac61, 0x6}, 0x193041edcd1, {{0xc00056d80a?, 0x16?}, {0x0?, 0x0?}}, 0xc00059d6c0, {0x12d1838, 0xc00014c388}, ...
)
2024-11-07 03:51:05 info mox[1241]:     /home/mox/go/pkg/mod/github.com/mjl-/mox@v0.0.12/smtpserver/server.go:704 +0x1385
2024-11-07 03:51:05 info mox[1241]: created by github.com/mjl-/mox/smtpserver.listen1.func1 in goroutine 96
2024-11-07 03:51:05 info mox[1241]:     /home/mox/go/pkg/mod/github.com/mjl-/mox@v0.0.12/smtpserver/server.go:272 +0x45f
2024-11-07 03:51:06 info mox[1241]: l=info m="connection closed" err="read: EOF (io error)" pkg=smtpserver cid=193041edcd1 delta=538.611099ms
mwyvr commented 2 weeks ago

I've backed up/verified/etc and am now running v0.0.13, but still seeing the issue, same pattern.

All are bogus validation attempts from bad actors (what else is new).

mjl- commented 2 weeks ago

Thanks. Is the address photo@ (from the login attempt) an alias by any chance? If so, I can see how these stack traces are happening. The commit above should fix that case.

The "no such account" is from https://www.xmox.nl/xr/v0.0.13/store/account.go.html#L882. https://www.xmox.nl/xr/v0.0.13/store/account.go.html#L2264 would be called with empty account name, which it gets from... https://www.xmox.nl/xr/v0.0.13/mox-/lookup.go.html#L77 after https://www.xmox.nl/xr/v0.0.13/mox-/lookup.go.html#L66 didn't pass because of allowAlias while ok was true.

See https://www.xmox.nl/b/#3d4cd004309469fb1fddbf3f89afc5ab111823ac for a binary for this commit.

mwyvr commented 2 weeks ago

Hi Mechiel,

Yes, that is an alias.

I've put the 0.14 beta code on with logging on trace; these failed "alias" auths are no longer causing the store.OpenEmailAuth()/xcheckf() failure, thanks.

Incidentally, this feels like new behaviour for submissions; I have always had hundreds of failed auth attempts on imap, including for that alias.

Thank you for looking into this! Michael

mjl- commented 1 week ago

Incidentally, this feels like new behaviour for submissions; I have always had hundreds of failed auth attempts on imap, including for that alias.

I do remember a recent change around error handling during login attempts, so it may indeed be recent.

Thank you for looking into this!

Happy to help, thanks for reporting!

Closing the issue now, feel free to reopen if it somehow turns up again.