thr3ads.net - dovecot - [2.2.25 auth issue] auth-request.c: line 1049 (auth_request_lookup_credentials): assertion failed: (request->credentials

If this information is useful, please help other people find it:
Share via:

Alexey Asemov (Alex/AT)

2016-Jul-09 07:55 UTC

[2.2.25 auth issue] auth-request.c: line 1049 (auth_request_lookup_credentials): assertion failed: (request->credentials_scheme == scheme)

Hello,

Since updating to 2.2.25, we do have the following issue (seems to be 
related to the new auth policy code):

Jul  9 00:00:14 LXmail01 dovecot: auth-worker(6558): 
sql(user at domain.org,*.*.*.*,<wjpa7SY3nNFR8yTo>): unknown user
Jul  9 00:00:14 LXmail01 dovecot: auth: Panic: file auth-request.c: line 
1049 (auth_request_lookup_credentials): assertion failed: 
(request->credentials_scheme == scheme)
Jul  9 00:00:14 LXmail01 dovecot: auth: Error: Raw backtrace: 
/usr/lib64/dovecot/libdovecot.so.0(+0x8d57e) [0x7f197bd8157e] -> 
/usr/lib64/dovecot/libdovecot.so.0(+0x8d65e) [0x7f197bd8165e] ->
  /usr/lib64/dovecot/libdovecot.so.0(i_fatal+0) [0x7f197bd201f6] -> 
dovecot/auth [1 wait, 0 passdb, 0 userdb](+0x1a15a) [0x7f197c44715a] -> 
dovecot/auth [1 wait, 0 passdb, 0 userdb](+0x26f8f)
[0x7f197c453f8f] -> dovecot/auth [1 wait, 0 passdb, 0 userdb](+0x19d2b) 
[0x7f197c446d2b] -> dovecot/auth [1 wait, 0 passdb, 0 
userdb](auth_request_lookup_credentials_callback+0x68) [0x7f197c4
46e28] -> dovecot/auth [1 wait, 0 passdb, 0 
userdb](passdb_handle_credentials+0x92) [0x7f197c457742] -> dovecot/auth 
[1 wait, 0 passdb, 0 userdb](+0x2af06) [0x7f197c457f06] -> dovecot/auth [1
  wait, 0 passdb, 0 userdb](+0x2065a) [0x7f197c44d65a] -> 
/usr/lib64/dovecot/libdovecot.so.0(io_loop_call_io+0x4c) 
[0x7f197bd94edc] -> 
/usr/lib64/dovecot/libdovecot.so.0(io_loop_handler_run_in
ternal+0xff) [0x7f197bd9633f] -> 
/usr/lib64/dovecot/libdovecot.so.0(io_loop_handler_run+0x25) 
[0x7f197bd94f65] -> /usr/lib64/dovecot/libdovecot.so.0(io_loop_run+0x38) 
[0x7f197bd95118] -> /usr
/lib64/dovecot/libdovecot.so.0(master_service_run+0x13) [0x7f197bd26663] 
-> dovecot/auth [1 wait, 0 passdb, 0 userdb](main+0x3a1) 
[0x7f197c43cbe1] -> /lib64/libc.so.6(__libc_start_main+0xf5)
[0x7f197b30ab15] -> dovecot/auth [1 wait, 0 passdb, 0 userdb](+0xfdd1) 
[0x7f197c43cdd1]
Jul  9 00:00:14 LXmail01 dovecot: auth: Fatal: master: service(auth): 
child 6555 killed with signal 6 (core dumps disabled)
Jul  9 00:00:14 LXmail01 dovecot: pop3-login: Warning: Auth connection 
closed with 1 pending requests (max 1 secs, pid=8133, EOF)

Environment is MySQL passdb/userdb, we are using plain scheme as default 
and password_noscheme field. In 2.2.24 and below auth worked without 
scratch. Reverting all policy-related commits in 2.2.25 fixes this, but 
I have not dug the details.

KR,

Alex

Aki Tuomi

2016-Jul-11 05:22 UTC

head link

[2.2.25 auth issue] auth-request.c: line 1049 (auth_request_lookup_credentials): assertion failed: (request->credentials_scheme == scheme)

On 09.07.2016 10:55, Alexey Asemov (Alex/AT) wrote:> Hello,
>
> Since updating to 2.2.25, we do have the following issue (seems to be
> related to the new auth policy code):
>
> Jul  9 00:00:14 LXmail01 dovecot: auth-worker(6558):
> sql(user at domain.org,*.*.*.*,<wjpa7SY3nNFR8yTo>): unknown user
> Jul  9 00:00:14 LXmail01 dovecot: auth: Panic: file auth-request.c:
> line 1049 (auth_request_lookup_credentials): assertion failed:
> (request->credentials_scheme == scheme)
> Jul  9 00:00:14 LXmail01 dovecot: auth: Error: Raw backtrace:
> /usr/lib64/dovecot/libdovecot.so.0(+0x8d57e) [0x7f197bd8157e] ->
> /usr/lib64/dovecot/libdovecot.so.0(+0x8d65e) [0x7f197bd8165e] ->
>  /usr/lib64/dovecot/libdovecot.so.0(i_fatal+0) [0x7f197bd201f6] ->
> dovecot/auth [1 wait, 0 passdb, 0 userdb](+0x1a15a) [0x7f197c44715a]
> -> dovecot/auth [1 wait, 0 passdb, 0 userdb](+0x26f8f)
> [0x7f197c453f8f] -> dovecot/auth [1 wait, 0 passdb, 0
> userdb](+0x19d2b) [0x7f197c446d2b] -> dovecot/auth [1 wait, 0 passdb,
> 0 userdb](auth_request_lookup_credentials_callback+0x68) [0x7f197c4
> 46e28] -> dovecot/auth [1 wait, 0 passdb, 0
> userdb](passdb_handle_credentials+0x92) [0x7f197c457742] ->
> dovecot/auth [1 wait, 0 passdb, 0 userdb](+0x2af06) [0x7f197c457f06]
> -> dovecot/auth [1
>  wait, 0 passdb, 0 userdb](+0x2065a) [0x7f197c44d65a] ->
> /usr/lib64/dovecot/libdovecot.so.0(io_loop_call_io+0x4c)
> [0x7f197bd94edc] ->
> /usr/lib64/dovecot/libdovecot.so.0(io_loop_handler_run_in
> ternal+0xff) [0x7f197bd9633f] ->
> /usr/lib64/dovecot/libdovecot.so.0(io_loop_handler_run+0x25)
> [0x7f197bd94f65] ->
> /usr/lib64/dovecot/libdovecot.so.0(io_loop_run+0x38) [0x7f197bd95118]
> -> /usr
> /lib64/dovecot/libdovecot.so.0(master_service_run+0x13)
> [0x7f197bd26663] -> dovecot/auth [1 wait, 0 passdb, 0
> userdb](main+0x3a1) [0x7f197c43cbe1] ->
> /lib64/libc.so.6(__libc_start_main+0xf5)
> [0x7f197b30ab15] -> dovecot/auth [1 wait, 0 passdb, 0 userdb](+0xfdd1)
> [0x7f197c43cdd1]
> Jul  9 00:00:14 LXmail01 dovecot: auth: Fatal: master: service(auth):
> child 6555 killed with signal 6 (core dumps disabled)
> Jul  9 00:00:14 LXmail01 dovecot: pop3-login: Warning: Auth connection
> closed with 1 pending requests (max 1 secs, pid=8133, EOF)
>
> Environment is MySQL passdb/userdb, we are using plain scheme as
> default and password_noscheme field. In 2.2.24 and below auth worked
> without scratch. Reverting all policy-related commits in 2.2.25 fixes
> this, but I have not dug the details.
>
> KR,
>
> Alex
Hi!

Could you provide your doveconf -n so we could debug this?

Aki

Leon Kyneur

2016-Jul-26 02:30 UTC

head link

[2.2.25 auth issue] auth-request.c: line 1049 (auth_request_lookup_credentials): assertion failed: (request->credentials_scheme == scheme)

I am also seeing this error since updating to 2.2.25. I do believe it's 
only occurring on CRAM-MD5, DIGEST-MD5 and NLTM auth.

# dovecot --version
2.2.25 (7be1766)

Jul 26 02:10:57 auth-worker(11499): Info: 
ldap(username,192.168.10.9,<fJJWaYA4GOXa1753>): unknown user - trying 
the next passdb
Jul 26 02:10:57 auth-worker(11499): Info: 
ldap(username at notallocated.com.au,192.168.10.9,<fJJWaYA4GOXa1753>): 
unknown user
Jul 26 02:10:57 auth: Panic: file auth-request.c: line 1069 
(auth_request_lookup_credentials): assertion failed: 
(request->credentials_scheme == scheme)
Jul 26 02:10:57 auth: Error: Raw backtrace: 
/usr/lib64/dovecot/libdovecot.so.0(+0x8d52e) [0x7f8cf859752e] -> 
/usr/lib64/dovecot/libdovecot.so.0(+0x8d60e) [0x7f8cf859760e] -> 
/usr/lib64/dovecot/libdovecot.so.0(i_fatal+0) [0x7f8cf85361b6] -> 
dovecot/auth [1 wait, 0 passdb, 0 userdb](+0x1a3aa) [0x7f8cf8c5d3aa] -> 
dovecot/auth [1 wait, 0 passdb, 0 userdb](+0x2714f) [0x7f8cf8c6a14f] -> 
dovecot/auth [1 wait, 0 passdb, 0 userdb](+0x19f2b) [0x7f8cf8c5cf2b] -> 
dovecot/auth [1 wait, 0 passdb, 0 
userdb](auth_request_lookup_credentials_callback+0x73) [0x7f8cf8c5d033] 
-> dovecot/auth [1 wait, 0 passdb, 0 
userdb](passdb_handle_credentials+0x92) [0x7f8cf8c6d902] -> dovecot/auth 
[1 wait, 0 passdb, 0 userdb](+0x2b106) [0x7f8cf8c6e106] -> dovecot/auth 
[1 wait, 0 passdb, 0 userdb](+0x2081a) [0x7f8cf8c6381a] -> 
/usr/lib64/dovecot/libdovecot.so.0(io_loop_call_io+0x4c) 
[0x7f8cf85aae8c] -> 
/usr/lib64/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0xff) 
[0x7f8cf85ac2ef] -> 
/usr/lib64/dovecot/libdovecot.so.0(io_loop_handler_run+0x25) 
[0x7f8cf85aaf15] -> /usr/lib64/dovecot/libdovecot.so.0(io_loop_run+0x38) 
[0x7f8cf85ab0c8] -> 
/usr/lib64/dovecot/libdovecot.so.0(master_service_run+0x13) 
[0x7f8cf853c613] -> dovecot/auth [1 wait, 0 passdb, 0 
userdb](main+0x3a1) [0x7f8cf8c52be1] -> 
/lib64/libc.so.6(__libc_start_main+0xf5) [0x7f8cf7b1fb15] -> 
dovecot/auth [1 wait, 0 passdb, 0 userdb](+0xfdd1) [0x7f8cf8c52dd1]
Jul 26 02:10:57 auth: Fatal: master: service(auth): child 11496 killed 
with signal 6 (core dumped)
Jul 26 02:10:57 pop3-login: Warning: Auth connection closed with 1 
pending requests (max 0 secs, pid=11488, EOF)
Jul 26 02:10:58 auth-worker(11505): Info: 
ldap(username at domain.com,192.168.10.9,<fJJWaYA4GOXa1753>): unknown user
- trying the next passdb
Jul 26 02:10:58 auth: Info: 
passwd-file(username at domain.com,192.168.10.9,<fJJWaYA4GOXa1753>): 
unknown user  - trying the next passdb
Jul 26 02:10:58 pop3-login: Info: proxy(username at domain.com): started 
proxying to mailstore03.service.int.oss-core.com:110: 
user=<username at domain.com>, method=DIGEST-MD5, rip=192.168.10.9, 
lip=203.134.11.19, session=<fJJWaYA4GOXa1753>, 
orig_user=<username at domain.com>
Jul 26 02:10:58 pop3-login: Info: proxy(username at domain.com): 
disconnecting 192.168.10.9 (Disconnected by server(0s idle, in=139, 
out=4767)): user=<username at domain.com>, method=DIGEST-MD5, 
rip=192.168.10.9, lip=203.134.11.19, session=<fJJWaYA4GOXa1753>, 
orig_user=<username at domain.com>


# gdb /usr/libexec/dovecot/auth 
core-auth-sig6-user97-group97-pid11496-time1469499057
GNU gdb (GDB) Red Hat Enterprise Linux 7.6.1-80.el7
Copyright (C) 2013 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later 
<http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show
copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /usr/libexec/dovecot/auth...Reading symbols from 
/usr/lib/debug/usr/libexec/dovecot/auth.debug...done.
done.
[New LWP 11496]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `dovecot/auth'.
Program terminated with signal 6, Aborted.
#0  0x00007f8cf7b335f7 in __GI_raise (sig=sig at entry=6) at 
../nptl/sysdeps/unix/sysv/linux/raise.c:56
56      return INLINE_SYSCALL (tgkill, 3, pid, selftid, sig);
(gdb) bt full
#0  0x00007f8cf7b335f7 in __GI_raise (sig=sig at entry=6) at 
../nptl/sysdeps/unix/sysv/linux/raise.c:56
         resultvar = 0
         pid = 11496
         selftid = 11496
#1  0x00007f8cf7b34ce8 in __GI_abort () at abort.c:90
         save_stage = 2
         act = {__sigaction_handler = {sa_handler = 0x1, sa_sigaction = 
0x1}, sa_mask = {__val = {31457280, 140727725664896, 140727725664888, 
140243452896936, 140243438753907, 140243445984576, 140243452896936, 513, 
6889173324748996864,
               140727725665136, 140243438919218, 140243452896936, 
140727725665024, 0, 140243438919321, 140243452896936}}, sa_flags = 
-128374774, sa_restorer = 0x7ffdba192b01}
         sigs = {__val = {32, 0 <repeats 15 times>}}
#2  0x00007f8cf8597526 in default_fatal_finish (type=<optimized out>, 
status=status at entry=0) at failures.c:201
         backtrace = 0x7f8cf93126e0 
"/usr/lib64/dovecot/libdovecot.so.0(+0x8d52e) [0x7f8cf859752e] -> 
/usr/lib64/dovecot/libdovecot.so.0(+0x8d60e) [0x7f8cf859760e] -> 
/usr/lib64/dovecot/libdovecot.so.0(i_fatal+0) [0x7f8cf85361b6] ->
dove"...
#3  0x00007f8cf859760e in i_internal_fatal_handler (ctx=0x7ffdba192b50, 
format=<optimized out>, args=<optimized out>) at failures.c:670
         status = 0
#4  0x00007f8cf85361b6 in i_panic (format=format at entry=0x7f8cf8c7ad40 
"file %s: line %d (%s): assertion failed: (%s)") at failures.c:275
         ctx = {type = LOG_TYPE_PANIC, exit_status = 0, timestamp = 0x0, 
timestamp_usecs = 0}
         args = {{gp_offset = 40, fp_offset = 48, overflow_arg_area = 
0x7ffdba192c50, reg_save_area = 0x7ffdba192b90}}
#5  0x00007f8cf8c5d3aa in auth_request_lookup_credentials 
(request=request at entry=0x7f8cf935bb30, 
scheme=scheme at entry=0x7f8cf8c8024d "LANMAN", 
callback=callback at entry=0x7f8cf8c6a000 <lm_credentials_callback>) at 
auth-request.c:1069
         ctx = <optimized out>
         __FUNCTION__ = "auth_request_lookup_credentials"
#6  0x00007f8cf8c6a14f in ntlm_credentials_callback (result=<optimized 
out>, credentials=<optimized out>, size=<optimized out>, 
auth_request=0x7f8cf935bb30) at mech-ntlm.c:171
         request = 0x7f8cf935bb30
#7  0x00007f8cf8c5cf2b in auth_request_lookup_credentials_finish 
(result=PASSDB_RESULT_USER_UNKNOWN, credentials=credentials at entry=0x0, 
size=size at entry=0, request=request at entry=0x7f8cf935bb30) at 
auth-request.c:1012
No locals.
#8  0x00007f8cf8c5d033 in auth_request_lookup_credentials_callback 
(result=PASSDB_RESULT_USER_UNKNOWN, credentials=0x0, size=0, 
request=0x7f8cf935bb30) at auth-request.c:1054
         passdb = <optimized out>
         cache_cred = 0x7f8cf9312657 ""
         cache_scheme = 0xfffffffffffffffd <Address 0xfffffffffffffffd 
out of bounds>
         __FUNCTION__ = "auth_request_lookup_credentials_callback"
#9  0x00007f8cf8c6d902 in passdb_handle_credentials 
(result=result at entry=PASSDB_RESULT_USER_UNKNOWN, password=<optimized 
out>, scheme=scheme at entry=0x0, callback=0x7f8cf8c5cfc0 
<auth_request_lookup_credentials_callback>,
     auth_request=0x7f8cf935bb30) at passdb.c:144
         credentials = 0x0
         size = 0
#10 0x00007f8cf8c6e106 in lookup_credentials_callback (reply=<optimized 
out>, context=<optimized out>) at passdb-blocking.c:119
         request = 0x7f8cf935bb30
         result = PASSDB_RESULT_USER_UNKNOWN
         password = 0x0
         scheme = 0x0
#11 0x00007f8cf8c6381a in auth_worker_request_handle 
(request=0x7f8cf936f9c0, request=0x7f8cf936f9c0, line=0x7f8cf936bac3 
"FAIL\t-3", conn=0x7f8cf934def0) at auth-worker-server.c:303
No locals.
#12 worker_input (conn=0x7f8cf934def0) at auth-worker-server.c:403
         line = 0x7f8cf936bac2 "\tFAIL\t-3"
         id_str = <optimized out>
         id = 5
#13 0x00007f8cf85aae8c in io_loop_call_io (io=0x7f8cf935b520) at 
ioloop.c:564
         ioloop = 0x7f8cf93197f0
         t_id = 2
         __FUNCTION__ = "io_loop_call_io"
#14 0x00007f8cf85ac2ef in io_loop_handler_run_internal 
(ioloop=ioloop at entry=0x7f8cf93197f0) at ioloop-epoll.c:220
         ctx = 0x7f8cf9329960
         events = <optimized out>
         list = 0x7f8cf935b580
         io = <optimized out>
         tv = {tv_sec = 59, tv_usec = 999487}
         events_count = <optimized out>
         msecs = <optimized out>
         ret = 1
         i = 0
         call = <optimized out>
         __FUNCTION__ = "io_loop_handler_run_internal"
#15 0x00007f8cf85aaf15 in io_loop_handler_run 
(ioloop=ioloop at entry=0x7f8cf93197f0) at ioloop.c:612
No locals.
#16 0x00007f8cf85ab0c8 in io_loop_run (ioloop=0x7f8cf93197f0) at 
ioloop.c:588
         __FUNCTION__ = "io_loop_run"
#17 0x00007f8cf853c613 in master_service_run (service=0x7f8cf9319690, 
callback=<optimized out>) at master-service.c:640
No locals.
#18 0x00007f8cf8c52be1 in main (argc=1, argv=0x7f8cf9319390) at main.c:400
         c = <optimized out>



On 09/07/16 15:55, Alexey Asemov (Alex/AT) wrote:> Hello,
>
> Since updating to 2.2.25, we do have the following issue (seems to be 
> related to the new auth policy code):
>
> Jul  9 00:00:14 LXmail01 dovecot: auth-worker(6558): 
> sql(user at domain.org,*.*.*.*,<wjpa7SY3nNFR8yTo>): unknown user
> Jul  9 00:00:14 LXmail01 dovecot: auth: Panic: file auth-request.c: 
> line 1049 (auth_request_lookup_credentials): assertion failed: 
> (request->credentials_scheme == scheme)
> Jul  9 00:00:14 LXmail01 dovecot: auth: Error: Raw backtrace: 
> /usr/lib64/dovecot/libdovecot.so.0(+0x8d57e) [0x7f197bd8157e] -> 
> /usr/lib64/dovecot/libdovecot.so.0(+0x8d65e) [0x7f197bd8165e] ->
>  /usr/lib64/dovecot/libdovecot.so.0(i_fatal+0) [0x7f197bd201f6] -> 
> dovecot/auth [1 wait, 0 passdb, 0 userdb](+0x1a15a) [0x7f197c44715a] 
> -> dovecot/auth [1 wait, 0 passdb, 0 userdb](+0x26f8f)
> [0x7f197c453f8f] -> dovecot/auth [1 wait, 0 passdb, 0 
> userdb](+0x19d2b) [0x7f197c446d2b] -> dovecot/auth [1 wait, 0 passdb, 
> 0 userdb](auth_request_lookup_credentials_callback+0x68) [0x7f197c4
> 46e28] -> dovecot/auth [1 wait, 0 passdb, 0 
> userdb](passdb_handle_credentials+0x92) [0x7f197c457742] -> 
> dovecot/auth [1 wait, 0 passdb, 0 userdb](+0x2af06) [0x7f197c457f06] 
> -> dovecot/auth [1
>  wait, 0 passdb, 0 userdb](+0x2065a) [0x7f197c44d65a] -> 
> /usr/lib64/dovecot/libdovecot.so.0(io_loop_call_io+0x4c) 
> [0x7f197bd94edc] -> 
> /usr/lib64/dovecot/libdovecot.so.0(io_loop_handler_run_in
> ternal+0xff) [0x7f197bd9633f] -> 
> /usr/lib64/dovecot/libdovecot.so.0(io_loop_handler_run+0x25) 
> [0x7f197bd94f65] -> 
> /usr/lib64/dovecot/libdovecot.so.0(io_loop_run+0x38) [0x7f197bd95118] 
> -> /usr
> /lib64/dovecot/libdovecot.so.0(master_service_run+0x13) 
> [0x7f197bd26663] -> dovecot/auth [1 wait, 0 passdb, 0 
> userdb](main+0x3a1) [0x7f197c43cbe1] -> 
> /lib64/libc.so.6(__libc_start_main+0xf5)
> [0x7f197b30ab15] -> dovecot/auth [1 wait, 0 passdb, 0 userdb](+0xfdd1) 
> [0x7f197c43cdd1]
> Jul  9 00:00:14 LXmail01 dovecot: auth: Fatal: master: service(auth): 
> child 6555 killed with signal 6 (core dumps disabled)
> Jul  9 00:00:14 LXmail01 dovecot: pop3-login: Warning: Auth connection 
> closed with 1 pending requests (max 1 secs, pid=8133, EOF)
>
> Environment is MySQL passdb/userdb, we are using plain scheme as 
> default and password_noscheme field. In 2.2.24 and below auth worked 
> without scratch. Reverting all policy-related commits in 2.2.25 fixes 
> this, but I have not dug the details.
>
> KR,
>
> Alex

dovecot - Jul 2016 - [2.2.25 auth issue] auth-request.c: line 1049 (auth_request_lookup_credentials): assertion failed: (request->credentials_scheme == scheme)

[2.2.25 auth issue] auth-request.c: line 1049 (auth_request_lookup_credentials): assertion failed: (request->credentials_scheme == scheme)

[2.2.25 auth issue] auth-request.c: line 1049 (auth_request_lookup_credentials): assertion failed: (request->credentials_scheme == scheme)

[2.2.25 auth issue] auth-request.c: line 1049 (auth_request_lookup_credentials): assertion failed: (request->credentials_scheme == scheme)