- dovecot - dovecot.org

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

06 Sep '23

I think we are off topic. We have a network policy that until such time as we have fully implemented the same security we have on our IPV4 network we simply do not allow IPV6 as it is another attack vector we are not fully upto speed on. So we block all IPV6 at the perimeter and on all switches, firewalls and routers. So if you connect to our network with a device no IP6 is configured and only IPV4 is allowed. We will get there! But that is not this issue. The issue is that dovecot is assuming that IPV6 is there and crashes out if it's not. Hacking the config to only listen on IP4 solves the problem but not while installing from standard repos to install the currently supported version. Cheers Spart

9 13

Dovecot with Postfix "no SASL authentication mechanisms"
by mangawilly＠gmail.com 05 Sep '23

05 Sep '23

Hi. Can someone help me please check what is wrong with my config? postfix is saying "no SASL authentication mechanisms" and I'm using dovecot. From what I read so far, it is related to my dovecot settings. Here are the details of my config http://paste.debian.net/1290864/

9 16

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

Dovecot director and backend on same server
by Michael Cassaniti 29 Aug '23

29 Aug '23

Hi, I'm attempting to run both the director and the backend under the same configuration on the same server. When I run doveadm director map I don't get any output. I have a shared file system between servers and clients can access any server. I was running without a director in front and seeing index corruption so I'm now attempting to use a director. I enabled additional logging for now but that didn't explain much. Dovecot version: 2.3.20 (80a5ac675d) on Alpine Linux v3.18.2 Dovecot configuration (doveconf -n) with some bits removed. # Pigeonhole version 0.5.19 (4eae2f79) # OS: Linux 6.1.43-0-lts x86_64 # Hostname: <REDACTED> auth_debug = yes auth_socket_path = director-userdb director_mail_servers = 192.168.252.2 192.168.252.3 192.168.252.4 192.168.252.5 192.168.252.20 director_servers = 192.168.252.2 192.168.252.3 192.168.252.4 192.168.252.5 192.168.252.20 imap_hibernate_timeout = 5 secs log_debug = events=* login_trusted_networks = 192.168.252.0/24 mail_debug = yes mail_fsync = always mail_gid = vmail mail_location = maildir:~/Maildir:LAYOUT=fs mail_nfs_index = yes mail_nfs_storage = yes mail_plugins = acl quota mail_uid = vmail 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 index ihave duplicate mime foreverypart extracttext imapsieve vnd.dovecot.imapsieve mmap_disable = yes namespace inbox { inbox = yes location = mailbox Bin { auto = subscribe autoexpunge = 30 days special_use = \Trash } mailbox Drafts { auto = subscribe special_use = \Drafts } mailbox Sent { auto = subscribe special_use = \Sent } mailbox Spam { auto = subscribe autoexpunge = 30 days special_use = \Junk } prefix = } passdb { args = /etc/dovecot/dovecot-sql.conf.ext driver = sql } plugin { acl = vfile quota = maildir:quota quota_rule = *:storage=5G quota_rule2 = Bin:ignore quota_rule3 = Spam:ignore sieve = file: ~/sieve;active=~/dovecot.sieve sieve_plugins = sieve_imapsieve } protocols = imap lmtp sieve service auth { unix_listener /var/spool/postfix/private/auth { group = postfix mode = 0660 user = postfix } } service director { fifo_listener login/proxy-notify { mode = 0600 user = $default_login_user } inet_listener { port = 9090 } unix_listener director-admin { mode = 0600 } unix_listener director-userdb { mode = 0600 } unix_listener login/director { mode = 0666 } } service imap-login { executable = imap-login director } service imap { user = vmail } service ipc { unix_listener ipc { user = dovecot } } service lmtp { unix_listener /var/spool/postfix/private/dovecot-lmtp { group = postfix mode = 0600 user = postfix } user = vmail } service managesieve-login { executable = managesieve-login director inet_listener sieve { port = 4190 } } ssl = required ssl_cert = </etc/letsencrypt/live/<REDACTED>/fullchain.pem ssl_cipher_list = HIGH:!SSLv3:!aNULL ssl_key = # hidden, use -P to show it userdb { args = /etc/dovecot/dovecot-sql.conf.ext driver = sql } protocol lmtp { mail_plugins = acl quota sieve } protocol imap { mail_plugins = acl quota imap_acl imap_quota imap_sieve imap_zlib } Regards, Michael Cassaniti

1 0

[bug] dovecot passes zero byte input stream when passing email with .eml attachment to apache tika parser, causes 'SEVERE' error
by pgnd 29 Aug '23

29 Aug '23

revisiting a prior, never resolved issue tika 2.4.1 'Text extraction failed' errors when dovecot+fts 2.3.19.1 passes embedded *.eml (message/rfc822) files ; org.apache.tika.parser.mail.RFC822Parser or dovecot ? https://dovecot.org/list/dovecot/2022-August/125085.html i now run dovecot --version 2.3.20 (80a5ac675d) with dovecot23_fts_flatcurve built 20230812 from git.HEAD on lsb_release -rd Description: Fedora release 38 (Thirty Eight) Release: 38 apache/tika 2.8.0 runs on another box dovecot passes mail to tika, via config fts_tika = http://192.0.2.20:9998/tika/ indexing & search work with simple mail passed, and with attachments ... except with .eml attachments. sending this message (plain txt email, with .eml as attachment) Content-Type: multipart/mixed; boundary="------------O6z0p865JVYqnvxPyzc0aSLA" Message-ID: <0b7f5053-05b5-4b4f-8c7e-4a640b79a5f4(a)fastmail.fm> Date: Sat, 12 Aug 2023 19:37:44 -0400 MIME-Version: 1.0 User-Agent: Mozilla Thunderbird Reply-To: sender(a)example1.com From: sender <sender(a)example1.com> Content-Language: en-US To: recipient(a)example2.com Subject: tika test This is a multi-part message in MIME format. --------------O6z0p865JVYqnvxPyzc0aSLA Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 8bit Â tika test --------------O6z0p865JVYqnvxPyzc0aSLA Content-Type: message/rfc822; name="t2.eml" Content-Disposition: attachment; filename="t2.eml" Content-Transfer-Encoding: 8bit Message-ID: <89e5914a-e928-422d-824f-5b4e90170cd7(a)fastmail.fm> Date: Sat, 12 Aug 2023 14:32:48 -0400 MIME-Version: 1.0 User-Agent: Mozilla Thunderbird Reply-To: sender(a)example1.com From: sender <sender(a)example1.com> Content-Language: en-US To: recipient(a)example2.com Subject: t2 Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 8bit Â t2 --------------O6z0p865JVYqnvxPyzc0aSLA-- from an off-site server to local postfix+dovecot instance tika & dovecot logs, journalctl -f -u tika Aug 12 19:52:36 svr04tika[2035]: INFO [qtp1472012329-175] 19:52:36,918 org.apache.tika.server.core.TikaLoggingFilter Request URI: http://192.0.2.20:9998/tika/ Aug 12 19:52:36 svr04tika[2035]: INFO [qtp1472012329-175] 19:52:36,918 org.apache.tika.server.core.resource.TikaResource /tika (message/rfc822) Aug 12 19:52:36 svr04tika[2035]: WARN [qtp1472012329-175] 19:52:36,918 org.apache.tika.server.core.resource.TikaResource tika/: Text extraction failed (t2.eml) Aug 12 19:52:36 svr04tika[2035]: org.apache.tika.exception.ZeroByteFileException: InputStream must have > 0 bytes Aug 12 19:52:36 svr04tika[2035]: at org.apache.tika.parser.AutoDetectParser.parse(AutoDetectParser.java:185) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.apache.tika.parser.ParserDecorator.parse(ParserDecorator.java:152) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.apache.tika.parser.DigestingParser.parse(DigestingParser.java:57) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.apache.tika.server.core.resource.TikaResource.parse(TikaResource.java:357) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.apache.tika.server.core.resource.TikaResource.lambda$produceText$1(TikaResource.java:507) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.apache.cxf.jaxrs.provider.BinaryDataProvider.writeTo(BinaryDataProvider.java:177) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.apache.cxf.jaxrs.utils.JAXRSUtils.writeMessageBody(JAXRSUtils.java:1651) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.serializeMessage(JAXRSOutInterceptor.java:249) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.processResponse(JAXRSOutInterceptor.java:122) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.handleMessage(JAXRSOutInterceptor.java:84) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:307) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.apache.cxf.interceptor.OutgoingChainInterceptor.handleMessage(OutgoingChainInterceptor.java:90) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:307) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:265) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.apache.cxf.transport.http_jetty.JettyHTTPDestination.doService(JettyHTTPDestination.java:247) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.apache.cxf.transport.http_jetty.JettyHTTPHandler.handle(JettyHTTPHandler.java:79) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1440) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:190) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1355) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:191) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) ~[tika-server-standard-2.8.0.jar:2.8.0] Aug 12 19:52:36 svr04tika[2035]: at java.lang.Thread.run(Thread.java:1623) [?:?] Aug 12 19:52:36 svr04tika[2035]: Aug 12, 2023 7:52:36 PM org.apache.cxf.jaxrs.utils.JAXRSUtils logMessageHandlerProblem Aug 12 19:52:36 svr04tika[2035]: SEVERE: Problem with writing the data, class org.apache.tika.server.core.resource.TikaResource$$Lambda$387/0x00000008012a9300, ContentType: text/plain tail -f /var/log/dovecot/*log | grep http-client 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: host 192.0.2.20: Host created 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: host 192.0.2.20: Host session created 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: peer 192.0.2.20:9998 (shared): Peer created 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: peer 192.0.2.20:9998: Peer pool created 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: peer 192.0.2.20:9998: Peer created 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: queue http://192.0.2.20:9998: Setting up connection to 192.0.2.20:9998 (1 requests pending) 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: peer 192.0.2.20:9998: Linked queue http://192.0.2.20:9998 (1 queues linked) 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: queue http://192.0.2.20:9998: Started new connection to 192.0.2.20:9998 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: request [Req1: PUT http://192.0.2.20/tika/] Submitted (requests left=1) 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: request [Req1: PUT http://192.0.2.20/tika/] Waiting for request to finish 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: peer 192.0.2.20:9998: Creating 1 new connections to handle requests (already 0 usable, connecting to 0, closing 0) 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: peer 192.0.2.20:9998: Making new connection 1 of 1 (0 connections exist, 0 pending) 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: conn 192.0.2.20:9998 [1]: Connecting 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: conn 192.0.2.20:9998 [1]: Waiting for connect (fd=28) to finish for max 0 msecs 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: conn 192.0.2.20:9998 [1]: HTTP connection created (1 parallel connections exist) 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: conn 192.0.2.20:9998 [1]: Client connected (fd=28) 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: conn 192.0.2.20:9998 [1]: Connected 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: conn 192.0.2.20:9998 [1]: Ready for requests 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: peer 192.0.2.20:9998: Successfully connected (1 connections exist, 0 pending) 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: peer 192.0.2.20:9998: Successfully connected (1 connections exist, 0 pending) 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: peer 192.0.2.20:9998: Using 1 idle connections to handle 1 requests (1 total connections ready) 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: queue http://192.0.2.20:9998: Connection to peer 192.0.2.20:9998 claimed request [Req1: PUT http://192.0.2.20:9998/tika/] 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: conn 192.0.2.20:9998 [1]: Claimed request [Req1: PUT http://192.0.2.20:9998/tika/] 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: request [Req1: PUT http://192.0.2.20/tika/] Sent header 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: peer 192.0.2.20:9998: No more requests to service for this peer (1 connections exist, 0 pending) 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: conn 192.0.2.20:9998 [1]: Got 422 response for request [Req1: PUT http://192.0.2.20:9998/tika/] Unprocessable Entity (took 3 ms + 106 ms in queue) 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: request [Req1: PUT http://192.0.2.20/tika/] Finished 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: queue http://192.0.2.20:9998: Dropping request [Req1: PUT http://192.0.2.20:9998/tika/] 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: host 192.0.2.20: Host is idle (timeout = 100 msecs) 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: request [Req1: PUT http://192.0.2.20/tika/] Free (requests left=1) 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: peer 192.0.2.20:9998: No requests to service for this peer (1 connections exist, 0 pending) 2023-08-12 19:52:36 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: conn 192.0.2.20:9998 [1]: No more requests queued; going idle (timeout = 100 msecs) 2023-08-12 19:52:37 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: host 192.0.2.20: Idle host timed out 2023-08-12 19:52:37 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: host 192.0.2.20: Host destroy 2023-08-12 19:52:37 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: host 192.0.2.20: Host session destroy 2023-08-12 19:52:37 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: queue http://192.0.2.20:9998: Destroy 2023-08-12 19:52:37 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: peer 192.0.2.20:9998: Unlinked queue http://192.0.2.20:9998 (0 queues linked) 2023-08-12 19:52:37 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: conn 192.0.2.20:9998 [1]: Idle connection timed out 2023-08-12 19:52:37 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: conn 192.0.2.20:9998 [1]: Connection close 2023-08-12 19:52:37 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: conn 192.0.2.20:9998 [1]: Connection disconnect 2023-08-12 19:52:37 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: conn 192.0.2.20:9998 [1]: Disconnected: Connection closed (fd=28) 2023-08-12 19:52:37 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: conn 192.0.2.20:9998 [1]: Detached peer 2023-08-12 19:52:37 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: peer 192.0.2.20:9998: Lost a connection (0 queues linked, 0 connections left, 0 connections pending, 0 requests pending, 0 requests urgent) 2023-08-12 19:52:37 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: conn 192.0.2.20:9998 [1]: Connection destroy 2023-08-12 19:52:37 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: peer 192.0.2.20:9998: Dropping peer now 2023-08-12 19:52:37 indexer-worker(recipient(a)example2.com)<lrVsHUQb2GR1dgAA+IOfAw:xKZLMEQb2GR3dgAA+IOfAw>: Debug: http-client: peer 192.0.2.20:9998: Peer close unclear 2 me whether this is a bug in dovecot or in tika, or a matter of (mis)config. ?? _______________________________________________ dovecot mailing list -- dovecot(a)dovecot.org To unsubscribe send an email to dovecot-leave(a)dovecot.org

2 3

Dovecot, mail_crypt, global keys, permissions
by David Mehler 28 Aug '23

28 Aug '23

Hello, I'm using Dovecot v2.3 with the mail_crypt plugin and global keys. I am seeing this error immediately after imap login then after this error imap logs out. I'm hoping this is a simple permissions problem and the key can not be read rather than an underlying configuration issue. I do not know what this UID 5395 refers to. 2023-08-11T04:14:14.539308-04:00 hostname dovecot: imap(username(a)domain.org)<492738><zO4WTKECnvRoDWll>: Error: Mailbox INBOX: UID=5395: read() failed: read(/var/mail/mailboxes/domain.org/username/mail/mailboxes/INBOX/dbox-Mail… failed: Private key not available: mailbox_attribute_get(INBOX, /priv/vendor/vendor.dovecot/pvt/crypt/privkeys/e9f195fe9fd1953d08e815ba6fda9b6c5ae1ed692c9adade2f958c322552cbb0) failed: Mailbox attributes not enabled (FETCH BODY[HEADER]) #ls -ld crypt drwxr-xr-x 2 root root 4096 Jul 25 08:52 crypt/ # cd crypt #ls -l * -r-------- 1 root root 241 Jul 25 15:43 master.key -rw-r--r-- 1 root root 178 Jul 25 15:43 master.pub Thanks. Dave.

2 5