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

26 Jul 2016 · *.*


      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@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 [0x7f8cf8c5d3aa] ->
dovecot/auth 1 wait, 0 passdb, 0 userdb [0x7f8cf8c6a14f] ->
dovecot/auth 1 wait, 0 passdb, 0 userdb [0x7f8cf8c5cf2b] ->
dovecot/auth 1 wait, 0 passdb, 0
userdb [0x7f8cf8c5d033]
-> dovecot/auth 1 wait, 0 passdb, 0
userdb [0x7f8cf8c6d902] -> dovecot/auth
1 wait, 0 passdb, 0 userdb [0x7f8cf8c6e106] -> dovecot/auth
1 wait, 0 passdb, 0 userdb [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 [0x7f8cf8c52be1] ->
/lib64/libc.so.6(__libc_start_main+0xf5) [0x7f8cf7b1fb15] ->
dovecot/auth 1 wait, 0 passdb, 0 userdb [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@domain.com,192.168.10.9,<fJJWaYA4GOXa1753>): unknown user

passwd-file(username@domain.com,192.168.10.9,<fJJWaYA4GOXa1753>):

trying the next passdb
Jul 26 02:10:58 auth: Info:

unknown user  - trying the next passdb
Jul 26 02:10:58 pop3-login: Info: proxy(username@domain.com): started
proxying to mailstore03.service.int.oss-core.com:110:
user=username@domain.com, method=DIGEST-MD5, rip=192.168.10.9,
lip=203.134.11.19, session=<fJJWaYA4GOXa1753>,
orig_user=username@domain.com
Jul 26 02:10:58 pop3-login: Info: proxy(username@domain.com):
disconnecting 192.168.10.9 (Disconnected by server(0s idle, in=139,
out=4767)): user=username@domain.com, method=DIGEST-MD5,
rip=192.168.10.9, lip=203.134.11.19, session=<fJJWaYA4GOXa1753>,
orig_user=username@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@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@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 }}
#2  0x00007f8cf8597526 in default_fatal_finish (type=<optimized out>,
status=status@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@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@entry=0x7f8cf935bb30,
scheme=scheme@entry=0x7f8cf8c8024d "LANMAN",
callback=callback@entry=0x7f8cf8c6a000 ) 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@entry=0x0,
size=size@entry=0, request=request@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 

__FUNCTION__ = "auth_request_lookup_credentials_callback"
#9  0x00007f8cf8c6d902 in passdb_handle_credentials
(result=result@entry=PASSDB_RESULT_USER_UNKNOWN, password=<optimized 
out>, scheme=scheme@entry=0x0, callback=0x7f8cf8c5cfc0
,
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@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@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@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 [0x7f197c44715a]
-> dovecot/auth 1 wait, 0 passdb, 0 userdb
[0x7f197c453f8f] -> dovecot/auth 1 wait, 0 passdb, 0
userdb [0x7f197c446d2b] -> dovecot/auth 1 wait, 0 passdb,
0 userdb [0x7f197c4
46e28] -> dovecot/auth 1 wait, 0 passdb, 0
userdb [0x7f197c457742] ->
dovecot/auth 1 wait, 0 passdb, 0 userdb [0x7f197c457f06]
-> dovecot/auth 1
wait, 0 passdb, 0 userdb [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 [0x7f197c43cbe1] ->
/lib64/libc.so.6(__libc_start_main+0xf5)
[0x7f197b30ab15] -> dovecot/auth 1 wait, 0 passdb, 0 userdb
[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

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

Leon Kyneur