September 2023 - dovecot

auth: Panic: file oauth2-request.c assertion failed
by Urban Loesch 05 Sep '23

05 Sep '23

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?s…", 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

1 1

DOvecot requires both IPv4 and IPV6 to start
by TWHG Technical 04 Sep '23

04 Sep '23

Hello, I hope this is the right place to start. Ubuntu server the default listener configuration in dovecot.conf uses both IP4 and IP6 on systems that have IP6 disabled dovecot will not start. Is it possible to set the default to: listen = * to only bind to IP4 for installation and initial start. Rather than listen = *, :: which tries to bind to a non existent IP6 stack. Or simply fallback to ip4 if ip6 is not available. Thank you

6 5

DOvecot requires both IPv4 and IPV6 to start
by TWHG Technical 04 Sep '23

04 Sep '23

IPV6 is disabled in the grub command line. So before the OS boots. So there is no IPV6 support in the system. Unless one enables it in the Grub bootloader. Cheers

1 0

DOvecot requires both IPv4 and IPV6 to start
by TWHG Technical 04 Sep '23

04 Sep '23

I have tried replying twice. We have IPV6 disabled for security reasons on all server builds. An installer script failed which is how we caught this issue. We can see it is due to the config line. A graceful fallback to IPV4 if the IPV6 stack is not available would seem to be an elegant solution that would make dovecot resilient in all circunstances. Cheers Spart

4 3

no such user but Thunderbird okeys it ?
by lejeczek 04 Sep '23

04 Sep '23

Hi guys. I'm having quite bizarre situation where Dovecot logs: ... pam_unix(dovecot:auth): check pass; user unknown pam_unix(dovecot:auth): authentication failure; logname= uid=0 euid=0 tty=dovecot ruser=dupa rhost=AA.BB.CC.DD imap-login: Login: user=<dupa>, method=PLAIN, rip=AA.BB.CC.DD, lip=AA.BB.CC.DD, mpid=1756629, TLS, session=<uV7OwIIEWsJdviSg>: ... but Thunderbird allows, is okey with such user & creates an account for it. I must be having my setup miss-configured - I'm hoping it's something obvious somebody could point me towards. many thanks, L.

2 5