Hi,
I'm running a postfix smtp relay server on which users are getting authenticated trough sasl via the dovecot authentication service. This works
without problems.
Recently I extended my configuration to authenticate users with the PLAIN
mechanism against Azure AD B2C with oauth2 in the future.
Important to mention is that currently no users are stored in Azure B2C. I only prepared the hole configuration and authentiucation falls back to
mysql database.
Now sometimes I get the error below in my logs (not permanently):
...
Dec 7 11:36:49 relay-out1 dovecot: auth: Panic: file oauth2-request.c: line 201 (oauth2_request_start): assertion failed:
(oauth2_valid_token(input->token))
Dec 7 11:36:49 relay-out1 dovecot: auth: Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0(backtrace_append+0x3d) [0x7f399402e62d] ->
/usr/lib/dovecot/libdovecot.so.0(backtrace_get+0x1e) [0x7f399402e74e] -> /usr/lib/dovecot/libdovecot.so.0(+0x1006eb) [0x7f399403b6eb] ->
/usr/lib/dovecot/libdovecot.so.0(+0x100781) [0x7f399403b781] -> /usr/lib/dovecot/libdovecot.so.0(+0x54b7c) [0x7f3993f8fb7c] ->
/usr/lib/dovecot/libdovecot.so.0(+0x4605a) [0x7f3993f8105a] -> /usr/lib/dovecot/libdovecot.so.0(oauth2_passwd_grant_start+0xfa) [0x7f3993f9870a] ->
dovecot/auth(db_oauth2_lookup+0x2ca) [0x560d0804368a] -> dovecot/auth(auth_request_default_verify_plain_continue+0x2d6) [0x560d08026436] ->
dovecot/auth(auth_policy_check+0x2b) [0x560d0802071b] -> dovecot/auth(+0x29f72) [0x560d0802ff72] ->
dovecot/auth(auth_request_handler_auth_continue+0xf7) [0x560d0802a197] -> dovecot/auth(+0x16c62) [0x560d0801cc62] ->
/usr/lib/dovecot/libdovecot.so.0(io_loop_call_io+0x69) [0x7f3994051c29] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0x131)
[0x7f3994053251] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x4c) [0x7f3994051ccc] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x40)
[0x7f3994051e50] -> /usr/lib/dovecot/libdovecot.so.0(master_service_run+0x13) [0x7f3993fc4df3] -> dovecot/auth(main+0x415) [0x560d0801abf5] ->
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xeb) [0x7f3993cee09b] -> dovecot/auth(_start+0x2a) [0x560d0801ad8a]
...
After the error above postfix says the connection to the authentication server
was lost:
...
Dec 7 11:36:49 relay-out1 rolrelayout1/smtpd[1655601]: warning: domain.com[12.12.12.12]: SASL LOGIN authentication failed: Connection lost to
authentication server
...
I was able to make a core dump.
...
# gdb /usr/lib/dovecot/auth core.auth.1654357.1670409409
GNU gdb (Debian 8.2.1-2+b3) 8.2.1
...
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /usr/lib/dovecot/auth...Reading symbols from
/usr/lib/debug/.build-id/bc/f14ed9cc2dda3ee9565fbd7ccd835460008438.debug...done.
done.
[New LWP 1654357]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `dovecot/auth'.
Program terminated with signal SIGABRT, Aborted.
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
50 ../sysdeps/unix/sysv/linux/raise.c: Datei oder Verzeichnis nicht
gefunden.
(gdb) bt full
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
set = {__val = {0, 1415, 1416, 94613970086496, 10, 139885273538955, 155, 139885273347109, 140724590457408, 118, 206158430224,
140724590457744, 140724590457536, 16888407779496842752, 94613970086472, 139885273131758}}
pid = <optimized out>
tid = <optimized out>
ret = <optimized out>
#1 0x00007f3993cec535 in __GI_abort () at abort.c:79
save_stage = 1
act = {__sigaction_handler = {sa_handler = 0x73f, sa_sigaction = 0x73f}, sa_mask = {__val = {1024, 18446744073709551615, 94613971926672,
94613971631792, 139885273108347, 94613970084312, 139885273090236, 94613970084312,
16888407779496842752, 94613970084288, 139885273346402, 140724590457744, 94613970084312, 140724590457744, 139885273346761,
94613970084312}}, sa_flags = -1811749030, sa_restorer = 0x5}
sigs = {__val = {32, 0 <repeats 15 times>}}
#2 0x00007f3993f8feaf in default_fatal_finish (status=0, type=LOG_TYPE_PANIC)
at failures.c:465
backtrace = 0x560d0813e220 "/usr/lib/dovecot/libdovecot.so.0(backtrace_append+0x3d) [0x7f399402e62d] ->
/usr/lib/dovecot/libdovecot.so.0(backtrace_get+0x1e) [0x7f399402e74e] -> /usr/lib/dovecot/libdovecot.so.0(+0x1006eb) [0x7f39"...
backtrace = <optimized out>
recursed = 0
#3 fatal_handler_real (ctx=<optimized out>, format=<optimized out>,
args=<optimized out>) at failures.c:477
status = 0
#4 0x00007f399403b781 in i_internal_fatal_handler (ctx=<optimized out>,
format=<optimized out>, args=<optimized out>) at failures.c:879
No locals.
#5 0x00007f3993f8fb7c in i_panic (format=format@entry=0x7f399407a0e8 "file %s: line
%d (%s): assertion failed: (%s)") at failures.c:530
ctx = {type = LOG_TYPE_PANIC, exit_status = 0, timestamp = 0x0,
timestamp_usecs = 0, log_prefix = 0x0, log_prefix_type_pos = 0}
args = {{gp_offset = 40, fp_offset = 48, overflow_arg_area =
0x7ffcff39b4e0, reg_save_area = 0x7ffcff39b420}}
#6 0x00007f3993f8105a in oauth2_request_start (set=0x560d08176150, input=0x7ffcff39b5d0, callback=0x560d08042b50 <db_oauth2_lookup_passwd_grant>,
context=0x560d082ffe90, p=0x560d082b7eb0, method=0x7f399407a2c6 "POST",
url=0x560d08178480 "https://xxx.b2clogin.com/xxx.onmicrosoft.com/B2C_1_ropc/oauth2/v2.0/token?scope=xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx";,
payload=0x560d082b7ed8, add_auth_bearer=false) at oauth2-request.c:201
__func__ = "oauth2_request_start"
pool = <optimized out>
req = <optimized out>
#7 0x00007f3993f9870a in oauth2_passwd_grant_start (set=set@entry=0x560d08176150, input=input@entry=0x7ffcff39b5d0, username=0x560d082ffe38
"user.name", password=0x560d082ffe48 "",
callback=callback@entry=0x560d08042b50 <db_oauth2_lookup_passwd_grant>,
context=context@entry=0x560d082ffe90) at oauth2-request.c:351
pool = 0x560d082b7eb0
payload = 0x560d082b7ed8
#8 0x0000560d0804368a in db_oauth2_lookup (db=0x560d08176060, req=0x560d082ffe90, token=<optimized out>, request=0x560d082ffba8,
callback=0x560d080370b0 <oauth2_verify_plain_continue>, context=0x560d082ffba8) at db-oauth2.c:862
input = {token = 0x560d082ffe48 "", service = 0x560d082ffe20 "smtp", local_ip = {family = 2, u = {ip6 = {__in6_u = {__u6_addr8 =
"\303\376\374\322", '\000' <repeats 11 times>, __u6_addr16 = {65219, 54012, 0, 0, 0, 0, 0, 0},
__u6_addr32 = {3539795651, 0, 0, 0}}}, ip4 = {s_addr = 3539795651}}}, real_local_ip = {family = 2, u = {ip6 = {__in6_u =
{__u6_addr8 = "\303\376\374\322", '\000' <repeats 11 times>, __u6_addr16 = {65219, 54012, 0, 0,
0, 0, 0, 0}, __u6_addr32 = {3539795651, 0, 0, 0}}}, ip4 = {s_addr = 3539795651}}}, remote_ip = {family = 2, u = {ip6 = {__in6_u =
{__u6_addr8 = "*\300\070\226", '\000' <repeats 11 times>, __u6_addr16 = {49194, 38456,
0, 0, 0, 0, 0, 0}, __u6_addr32 = {2520301610, 0, 0, 0}}}, ip4 = {s_addr = 2520301610}}}, real_remote_ip = {family = 2, u = {ip6 =
{__in6_u = {__u6_addr8 = "*\300\070\226", '\000' <repeats 11 times>, __u6_addr16 = {
49194, 38456, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {2520301610, 0, 0, 0}}}, ip4 = {s_addr = 2520301610}}}, local_port = 0,
real_local_port = 0, remote_port = 0, real_remote_port = 0}
__func__ = "db_oauth2_lookup"
#9 0x0000560d08026436 in auth_request_default_verify_plain_continue (request=0x560d082ffba8, callback=0x560d0803e6f0 <plain_verify_callback>) at
auth-request.c:1123
passdb = 0x560d0814da40
result = 22029
cache_key = <optimized out>
error = 0x560d082ffe38 "user.name"
password = 0x560d082ffe48 ""
__func__ = "auth_request_default_verify_plain_continue"
#10 0x0000560d0802071b in auth_policy_check (request=<optimized out>, password=<optimized out>, cb=<optimized out>, context=<optimized out>) at
auth-policy.c:575
pool = <optimized out>
ctx = <optimized out>
#11 0x0000560d0802ff72 in mech_plain_auth_continue (request=0x560d082ffba8,
data=0x560d0813d368 "user.name", data_size=30) at mech-plain.c:58
authid = <optimized out>
authenid = 0x560d0813d377 "user.name"
error = 0x560d0813d320 "h\323\023\b\rV"
pass = 0x560d0813d388 ""
i = <optimized out>
len = <optimized out>
count = 2
#12 0x0000560d0802a197 in auth_request_handler_auth_continue (handler=0x560d082d1ae8, args=args@entry=0x560d08268e96
"21\tdGhvbWFzLmZlcnJhcmkAdGhvbWFzLmZlcnJhcmkA") at auth-request-handler.c:738
request = 0x560d082ffba8
data = 0x560d08268e99 "dGhvbWFzLmZlcnJhcmkAdGhvbWFzLmZlcnJhcmkA"
data_len = 40
buf = 0x560d0813d320
id = 21
#13 0x0000560d0801cc62 in auth_client_handle_line (line=0x560d08268e91 "CONT\t21\tdGhvbWFzLmZlcnJhcmkAdGhvbWFzLmZlcnJhcmkA", conn=0x560d08276d30) at
auth-client-connection.c:228
No locals.
#14 auth_client_input (conn=<optimized out>) at auth-client-connection.c:311
_data_stack_cur_id = 3
line = <optimized out>
ret = <optimized out>
#15 0x00007f3994051c29 in io_loop_call_io (io=0x560d0826f240) at ioloop.c:737
ioloop = 0x560d08145f80
t_id = 2
__func__ = "io_loop_call_io"
#16 0x00007f3994053251 in io_loop_handler_run_internal
(ioloop=ioloop@entry=0x560d08145f80) at ioloop-epoll.c:222
ctx = 0x560d08148600
events = <optimized out>
event = 0x560d08148680
list = 0x560d082ae620
io = <optimized out>
tv = {tv_sec = 0, tv_usec = 315566}
events_count = <optimized out>
msecs = <optimized out>
ret = <optimized out>
i = 0
j = <optimized out>
call = <optimized out>
__func__ = "io_loop_handler_run_internal"
#17 0x00007f3994051ccc in io_loop_handler_run (ioloop=0x560d08145f80) at
ioloop.c:789
__func__ = "io_loop_handler_run"
#18 0x00007f3994051e50 in io_loop_run (ioloop=0x560d08145f80) at ioloop.c:762
__func__ = "io_loop_run"
#19 0x00007f3993fc4df3 in master_service_run (service=0x560d08145dd0,
callback=<optimized out>) at master-service.c:869
No locals.
#20 0x0000560d0801abf5 in main (argc=<optimized out>, argv=<optimized out>) at
main.c:393
c = <optimized out>
...
And "doveconf -n":
...
# 2.3.19.1 (9b53102964): /etc/dovecot/dovecot.conf
# OS: Linux 5.10.0-18-amd64 x86_64 Debian 10.13
# Hostname: relay-out1.domain.com
auth_cache_negative_ttl = 0
auth_cache_size = 40 M
auth_cache_ttl = 30 days
auth_mechanisms = plain login
auth_username_chars =
abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ01234567890.-_%@
auth_username_translation = %@
auth_verbose = yes
auth_verbose_passwords = plain
auth_worker_max_count = 100
disable_plaintext_auth = no
namespace inbox {
inbox = yes
location =
mailbox Drafts {
special_use = \Drafts
}
mailbox Junk {
special_use = \Junk
}
mailbox Sent {
special_use = \Sent
}
mailbox "Sent Messages" {
special_use = \Sent
}
mailbox Trash {
special_use = \Trash
}
prefix =
}
passdb {
args = /etc/dovecot/dovecot-oauth2.plain.conf.ext
driver = oauth2
mechanisms = plain login
}
passdb {
args = /etc/dovecot/dovecot-sql-account.conf
driver = sql
}
service auth {
unix_listener /var/spool/postfix/private/auth {
group = postfix
mode = 0660
user = postfix
}
}
userdb {
args = /etc/dovecot/dovecot-sql-account.conf
driver = sql
}
...
System OS is Debian 10, Dovecot installed from dovecot repository.
Many thanks
Urban
