auth-worker service failed since recent MariaDB upgrade

[Stephan Bosch]

Op 20/01/2019 om 15:30 schreef Bogomil Vasilev via dovecot:
> Hello Aki,
>
> This patch seems to have done the trick - hopefully it works fine and 
> doesn't mask the problem.
> From the patch content, I see that it's from 4th of December.
> Is there a reason why this hasn't made it yet into upstream?

It is still being tested in QA (other stuff came first). It is 
internally tracked as DOV-2826, which merged to master.

> Did you come across this bug on your own and patch it temporarily?

Bug was seen earlier here: 
https://www.dovecot.org/pipermail/dovecot/2018-November/113627.html

Regards,

Stephan.

> Best regards,
>
> ---
> BOGOMIL VASILEV
> For contacts, use this e-mail. My GPG key is 646F3ABF6E457336
> Website: HTTPS://WWW.SMIRKY.NET/
>
> On 2019-01-20 15:11, Aki Tuomi wrote:
>
>> Can you try if 
>> https://github.com/dovecot/core/commit/3c5101ffdd2a8115e03ed7180d53578765dea4c9.patch 
>> helps?
>>
>> Aki
>> On 20 January 2019 at 15:05 Bogomil Vasilev via dovecot < 
>> dovecot at dovecot.org> wrote:
>>
>> Hello,
>>
>> I rebuilt mariadb and dovecot with debug symbols.
>> The backtrace is this:
>>
>> Program terminated with signal SIGABRT, Aborted.
>> #0 0x00007fb040e0cd7f in raise () from /usr/lib/libc.so.6
>> (gdb) bt full
>> #0 0x00007fb040e0cd7f in raise () from /usr/lib/libc.so.6
>> No symbol table info available.
>> #1 0x00007fb040df7672 in abort () from /usr/lib/libc.so.6
>> No symbol table info available.
>> #2 0x00007fb040e4f878 in __libc_message () from /usr/lib/libc.so.6
>> No symbol table info available.
>> #3 0x00007fb040e5618a in malloc_printerr () from /usr/lib/libc.so.6
>> No symbol table info available.
>> #4 0x00007fb040e57b27 in _int_free () from /usr/lib/libc.so.6
>> No symbol table info available.
>> #5 0x00007fb04114db89 in mysql_close (mysql=0x5592728448e0) at
>> /usr/src/debug/mariadb-10.3.12/libmariadb/libmariadb/mariadb_lib.c:1940
>> p = <optimized out>
>> #6 mysql_close (mysql=0x5592728448e0) at
>> /usr/src/debug/mariadb-10.3.12/libmariadb/libmariadb/mariadb_lib.c:1913
>> p = <optimized out>
>> #7 0x00005592724e2dac in driver_sqlpool_disconnect (_db=0x559272843be0)
>> at driver-sqlpool.c:590
>> conn__foreach_end = 0x559272844090
>> db = 0x559272843be0
>> conn = 0x559272844080
>> #8 0x00005592724d78fc in db_sql_unref (_conn=0x55927283b5e8) at
>> db-sql.c:128
>> conn = 0x559272843818
>> #9 0x00005592724cf89c in userdb_deinit (userdb=0x55927283b5c0) at
>> userdb.c:191
>> idx = 0
>> __func__ = "userdb_deinit"
>> #10 0x00005592724afbb9 in auth_deinit (auth=0x55927283b320) at
>> auth.c:335
>> passdb = <optimized out>
>> userdb = 0x55927283b4e0
>> passdb = <optimized out>
>> userdb = <optimized out>
>> #11 auths_deinit () at auth.c:433
>> auth__foreach_end = 0x559272842e18
>> auth = 0x559272842e10
>> #12 0x00005592724ae664 in main_deinit () at main.c:271
>> l = <optimized out>
>> l = <optimized out>
>> l_end = <optimized out>
>> #13 main (argc=<optimized out>, argv=<optimized out>) at main.c:398
>> c = <optimized out>
>> (gdb)
>>
>> My `dovecot -n` output is this:
>>
>> 0 « root » /home/smirky/stuff/ABS/dovecot # dovecot -n
>> # 2.3.4 (0ecbaf23d): /etc/dovecot/dovecot.conf
>> # Pigeonhole version 0.5.4 (60b0f48d)
>> # OS: Linux 5.0.0-rc2-mainline x86_64 Arch Linux
>> # Hostname: archy
>> dict {
>> quotadict = mysql:/etc/dovecot/dovecot-dict-sql.conf.ext
>> }
>> mail_home = /home/vmail/%d/%u
>> mail_location = maildir:~
>> mail_plugins = quota
>> managesieve_notify_capability = mailto
>> managesieve_sieve_capability = fileinto reject envelope
>> encoded-character vacation subaddress comparator-i;ascii-numeric
>> relational regex imap4flags copy include variables body enotify
>> environment mailbox date i
>> ndex ihave duplicate mime foreverypart extracttext imapsieve
>> vnd.dovecot.imapsieve
>> namespace inbox {
>> inbox = yes
>> location =
>> mailbox Drafts {
>> auto = create
>> special_use = \Drafts
>> }
>> mailbox Sent {
>> auto = subscribe
>> special_use = \Sent
>> }
>> mailbox "Sent Messages" {
>> auto = no
>> special_use = \Sent
>> }
>> mailbox Spam {
>> auto = subscribe
>> special_use = \Junk
>> }
>> mailbox Trash {
>> auto = subscribe
>> special_use = \Trash
>> }
>> prefix =
>> }
>> passdb {
>> args = /etc/dovecot/dovecot-sql.conf
>> driver = sql
>> }
>> plugin {
>> imapsieve_mailbox1_before = file:/etc/dovecot/sieve/report-spam.sieve
>> imapsieve_mailbox1_causes = COPY
>> imapsieve_mailbox1_name = Spam
>> imapsieve_mailbox2_before = file:/etc/dovecot/sieve/report-ham.sieve
>> imapsieve_mailbox2_causes = COPY
>> imapsieve_mailbox2_from = Junk
>> imapsieve_mailbox2_name = *
>> quota = dict:User quota::proxy::quotadict
>> quota_rule2 = Trash:storage=+10%%
>> quota_warning = storage=95%% quota-warning 95 %u
>> quota_warning2 = storage=80%% quota-warning 80 %u
>> quota_warning3 = -storage=100%% quota-warning below 100 %u
>> sieve_before = /etc/dovecot/sieve/filter.sieve
>> sieve_global_extensions = +vnd.dovecot.pipe
>> sieve_pipe_bin_dir = /etc/dovecot/sieve
>> sieve_plugins = sieve_imapsieve sieve_extprograms
>> }
>> protocols = imap pop3 sieve
>> service auth-worker {
>> unix_listener auth-worker {
>> group = vmail
>> mode = 0666
>> user = vmail
>> }
>> }
>> service auth {
>> unix_listener /var/spool/postfix/private/auth {
>> group = postfix
>> mode = 0660
>> user = postfix
>> }
>> user = root
>> }
>> service dict {
>> unix_listener dict {
>> group = vmail
>> mode = 0660
>> user = vmail
>> }
>> user = root
>> }
>> service imap-login {
>> inet_listener imap {
>> address = 127.0.0.1
>> }
>> }
>> service managesieve-login {
>> inet_listener sieve {
>> port = 4190
>> }
>> }
>> service pop3-login {
>> inet_listener pop3 {
>> address = 127.0.0.1
>> }
>> }
>> service quota-warning {
>> executable = script /usr/local/bin/quota-warning.sh
>> unix_listener quota-warning {
>> group = vmail
>> mode = 0660
>> user = vmail
>> }
>> user = vmail
>> }
>> service stats {
>> unix_listener stats-reader {
>> group = vmail
>> mode = 0660
>> user = vmail
>> }
>> unix_listener stats-writer {
>> group = vmail
>> mode = 0660
>> user = vmail
>> }
>> }
>> ssl_cert = </etc/letsencrypt/live/smirky.net/fullchain.pem
>> ssl_dh = # hidden, use -P to show it
>> ssl_key = # hidden, use -P to show it
>> userdb {
>> args = /etc/dovecot/dovecot-sql.conf
>> driver = sql
>> }
>> protocol pop3 {
>> mail_plugins = quota
>> pop3_client_workarounds = outlook-no-nuls oe-ns-eoh
>> pop3_uidl_format = %08Xu%08Xv
>> }
>> protocol lda {
>> mail_plugins = quota
>> postmaster_address = postmaster at smirky.net
>> }
>> protocol imap {
>> mail_max_userip_connections = 20
>> mail_plugin_dir = /usr/lib/dovecot/modules
>> mail_plugins = quota imap_quota imap_sieve
>> }
>>
>> ---
>> BOGOMIL VASILEV
>> For contacts, use this e-mail. My GPG key is 646F3ABF6E457336
>> Website: HTTPS://WWW.SMIRKY.NET/
>>
>> On 2019-01-20 13:22, Stephan Bosch wrote:
>>
>> Op 20/01/2019 om 10:50 schreef Bogomil Vasilev via dovecot:
>>
>> Hello,
>>
>> I have started having issues with auth-worker. Dovecot version:
>>
>> 0 « root » ~ # dovecot --version
>> 2.3.4 (0ecbaf23d)
>> 0 « root » ~ # pacman -Q dovecot
>> dovecot 2.3.4-2
>>
>> OS: Arch Linux
>>
>> From /var/log/mail.log:
>>
>> Jan 20 11:31:29 archy dovecot[23070]: auth-worker: Fatal: master:
>> service(auth-worker): child 9885 killed with signal 6 (core not dumped
>> - https://dovecot.org/bugreport.html#coredumps - set
>> /proc/sys/fs/suid_dum
>> pable to 2)
>>
>> From dmesg:
>>
>> [42113.729398] auth[8134]: segfault at 5579d8e1c8e0 ip
>> 00005579d8e1c8e0 sp 00007ffd44ab0df8 error 15
>> [42113.729406] Code: 00 00 00 00 00 00 00 00 00 00 80 00 00 00 00 00
>> 00 00 21 00 00 00 00 00 00 00 02 00 00 00 00 00 00 00 20 7a af 07 e3
>> 7f 00 00 <40> f4 b5 07 e3 7f 00 00 31 a0 00 00 00 00 00 00 e0 9f df d8
>> 79
>> 55
>>
>> This started happening on January 18th, after I upgraded Dovecot from
>> "2.3.4-1" to "2.3.4-2".
>> The package was rebuilt from our package maintainer due to bumping
>> MariaDB from 10.1.x to 10.3.x.
>> Before that, I did not have any issues at all.
>> However, I don't see any impact from this error too, at least not for
>> now.
>> I made a coredump as the error suggests and I'm pasting it here, as
>> per the bugreport rules:
>>
>> 0 « root » ~ # gdb /usr/lib/dovecot/auth /home/smirky/dovecot.dump
>> GNU gdb (GDB) 8.2.1
>> Copyright (C) 2018 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-pc-linux-gnu".
>> Type "show configuration" for configuration details.
>> For bug reporting instructions, please see:
>> < ">http://www.gnu.org/software/gdb/bugs/>.
>> Find the GDB manual and other documentation resources online at:
>> < ">http://www.gnu.org/software/gdb/documentation/>.
>>
>> For help, type "help".
>> Type "apropos word" to search for commands related to "word"...
>> Reading symbols from /usr/lib/dovecot/auth...(no debugging symbols
>> found)...done.
>> [New LWP 9549]
>> [Thread debugging using libthread_db enabled]
>> Using host libthread_db library "/usr/lib/libthread_db.so.1".
>> Core was generated by `dovecot/auth -w'.
>> Program terminated with signal SIGABRT, Aborted.
>> #0 0x00007fe1bb8ead7f in raise () from /usr/lib/libc.so.6
>> (gdb) bt full
>> #0 0x00007fe1bb8ead7f in raise () from /usr/lib/libc.so.6
>> No symbol table info available.
>> #1 0x00007fe1bb8d5672 in abort () from /usr/lib/libc.so.6
>> No symbol table info available.
>> #2 0x00007fe1bb92d878 in __libc_message () from /usr/lib/libc.so.6
>> No symbol table info available.
>> #3 0x00007fe1bb93418a in malloc_printerr () from /usr/lib/libc.so.6
>> No symbol table info available.
>> #4 0x00007fe1bb935b27 in _int_free () from /usr/lib/libc.so.6
>> No symbol table info available.
>> #5 0x00007fe1bbc2bb89 in mysql_close () from /usr/lib/libmariadb.so.3
>> No symbol table info available.
>> #6 0x0000563481946dac in ?? ()
>> No symbol table info available.
>> #7 0x000056348193b8fc in db_sql_unref ()
>> No symbol table info available.
>> #8 0x000056348193389c in userdb_deinit ()
>> No symbol table info available.
>> #9 0x0000563481913bb9 in auths_deinit ()
>> No symbol table info available.
>> #10 0x0000563481912664 in main ()
>> No symbol table info available.
>> (gdb)
>>
>> The way I see it, indeed it is highly-likely to be related to the
>> MariaDB version bump,
>> but I cannot be entirely sure if it's not a bug in Dovecot, discovered
>> by this bump.
>> Please let me know if you need any other info, related to my setup.
>> It is very hard to be sure. Dovecot could be using the MariaDB API
>> wrong (e.g., calling mysql_close() more than once) causing it to call
>> abort().
>>
>> You should install debug symbols for Dovecot and perhaps also MariaDB
>> to obtain a useful gdb backtrace. Now, it has no symbol table for any
>> of the function calls.
>>
>> In most cases is useful to also provide your configuration (output from
>> `dovecot -n`).
>>
>> Regards,
>>
>> Stephan.
>
> ---
> Aki Tuomi