August 2023 - dovecot

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

28 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

Bug - doveadm backup out-of-memory kill/crash when no separators set
by James Harrison 26 Aug '23

26 Aug '23

Hi, I hit a fun issue with doveadm when migrating from dovecot 2.2.36 (1f10bfa63) to 2.3.19.1 (9b53102964) (CentOS 7 to Debian 12). When running doveadm -v -D backup -R -u "user@name" tcp:localhost:1234, I found that the first sync would always work, but subsequent runs of the command would cause doveadm to reach a subfolder (Archives/2008 in the example below) and then silently mmap() increasing powers of 2 before the OOM killer finally got it. Deleting the source folder caused it to remain stuck on the same folder, but for the deletion event. I switched memory overcommit off to force a crash, and got a gdb backtrace: #0 __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at ./nptl/pthread_kill.c:44 #1 0x00007ffff786bd9f in __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78 #2 0x00007ffff781cf32 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26 #3 0x00007ffff7807472 in __GI_abort () at ./stdlib/abort.c:79 #4 0x00007ffff7b4ffae in default_fatal_finish (status=0, type=LOG_TYPE_PANIC) at ../lib/failures.c:465 #5 fatal_handler_real (ctx=<optimized out>, format=<optimized out>, args=<optimized out>) at ../lib/failures.c:477 #6 0x00007ffff7bfa081 in default_fatal_handler (ctx=<optimized out>, format=<optimized out>, args=<optimized out>) at ../lib/failures.c:485 #7 0x00007ffff7b5017c in i_panic (format=0x7ffff7c5d748 "data stack: Out of memory when allocating %zu bytes") at ../lib/failures.c:530 #8 0x00007ffff7b4f67f in mem_block_alloc (min_size=min_size@entry=16) at ../lib/data-stack.c:386 #9 0x00007ffff7bf8b60 in t_malloc_real (size=<optimized out>, permanent=<optimized out>) at ../lib/data-stack.c:492 #10 0x00007ffff7c348f1 in t_strdup_until (start=start@entry=0x55555565f440, end=end@entry=0x55555565f448) at ../lib/strfuncs.c:270 #11 0x00005555555adc62 in convert_name_to_remote_sep (name=0x55555565f440 "Archives/2008", tree=0x55555564e188) at dsync/dsync-mailbox-tree.c:270 #12 dsync_mailbox_tree_build_name128_remotesep_hash (tree=0x55555564e188) at dsync/dsync-mailbox-tree.c:315 #13 dsync_mailbox_tree_find_delete (tree=0x55555564e188, del=0x5555556469f0) at dsync/dsync-mailbox-tree.c:405 #14 0x00005555555a4195 in dsync_brain_mailbox_tree_add_delete (tree=0x55555564e188, other_tree=0x55555564f5f8, other_del=0x5555556469f0, node_r=0x7fffffffe350, status_r=0x7fffffffe348) at dsync/dsync-brain-mailbox-tree.c:504 #15 0x00005555555a44cd in dsync_brain_recv_mailbox_tree_deletes (brain=0x55555564b2d8) at dsync/dsync-brain-mailbox-tree.c:590 #16 0x00005555555a5365 in dsync_brain_run_real (brain=brain@entry=0x55555564b2d8, changed_r=changed_r@entry=0x7fffffffe453) at dsync/dsync-brain.c:709 #17 0x00005555555a59f9 in dsync_brain_run (changed_r=0x7fffffffe453, brain=0x55555564b2d8) at dsync/dsync-brain.c:752 #18 dsync_brain_run (changed_r=0x7fffffffe453, brain=0x55555564b2d8) at dsync/dsync-brain.c:740 #19 dsync_brain_run_io (context=<optimized out>) at dsync/dsync-brain.c:113 #20 dsync_brain_run_io (context=0x55555564b2d8) at dsync/dsync-brain.c:100 #21 0x00005555555b23df in dsync_ibc_stream_input (ibc=0x555555646720) at dsync/dsync-ibc-stream.c:232 #22 0x00007ffff7c11cd9 in io_loop_call_io (io=0x5555556418f0) at ../lib/ioloop.c:737 #23 0x00007ffff7c13aa2 in io_loop_handler_run_internal (ioloop=ioloop@entry=0x55555560bf40) at ../lib/ioloop-epoll.c:222 #24 0x00007ffff7c13b50 in io_loop_handler_run (ioloop=ioloop@entry=0x55555560bf40) at ../lib/ioloop.c:789 #25 0x00007ffff7c13d10 in io_loop_run (ioloop=0x55555560bf40) at ../lib/ioloop.c:762 #26 0x000055555558b22e in cmd_dsync_run_remote (user=0x555555637248) at ./src/doveadm/doveadm-dsync.c:543 #27 cmd_dsync_run (_ctx=0x55555561f288, user=0x555555637248) at ./src/doveadm/doveadm-dsync.c:750 #28 0x000055555558bd12 in doveadm_mail_next_user (ctx=0x55555561f288, error_r=0x7fffffffe818) at ./src/doveadm/doveadm-mail.c:464 #29 0x000055555558cf45 in doveadm_mail_cmd_exec (wildcard_user=0x0, ctx=0x55555561f288) at ./src/doveadm/doveadm-mail.c:659 #30 doveadm_cmd_ver2_to_mail_cmd_wrapper (cctx=0x7fffffffe970) at ./src/doveadm/doveadm-mail.c:988 #31 0x0000555555597622 in doveadm_cmd_run_ver2 (argc=5, argv=0x55555560ba38, cctx=cctx@entry=0x7fffffffe970) at ./src/doveadm/doveadm-cmd.c:465 #32 0x0000555555597697 in doveadm_cmd_try_run_ver2 (cmd_name=<optimized out>, argc=<optimized out>, argv=<optimized out>, cctx=0x7fffffffe970) at ./src/doveadm/doveadm-cmd.c:363 #33 0x000055555557919a in main (argc=<optimized out>, argv=<optimized out>) at ./src/doveadm/doveadm.c:361 Neither server had a separator set in the inbox namespace. Having identified the convert_name_to_remote_sep function as the likely trigger point I set the separator to / on both ends, and doveadm backup now runs without issue. Can provide config if helpful but I think probably irrelevant to this one - the namespace config is the default other than the separator item. May be worth mentioning that having the separator set can avoid this condition in the doveadm backup docs - this took me a while to figure out! -- Cheers, James Harrison

2 1

Stop Logging to Syslog
by Asai 25 Aug '23

25 Aug '23

Greetings, My logging config is as follows: # doveadm log find Debug: /var/log/dovecot-debug.log Info: /var/log/dovecot.log Warning: /var/log/dovecot.log Error: /var/log/dovecot.log Fatal: /var/log/dovecot.log However, I'm still getting logs in /var/log/messages which I don't want. I've looked into /etc/rsyslog.conf for clues, but can't find anything that would point to Dovecot logging to /var/log/messages. Can anyone point me in the right direction here? Thank you, Asai

2 1

libdovecot-storage.so.0.0.0 [.] maildir_filename_base_hash with high cpu load
by habi li 25 Aug '23

25 Aug '23

[image: image.png] we find the libdovecot-storage.so cpu so high ,can you help me

3 2

sievec: Misleading error message
by Horst Prote 25 Aug '23

25 Aug '23

Hi, in a sieve script I just made a syntax error and got this error message on calling sievec: error: the else command must follow an if or elseif command. My first thougth was "Are you kidding me!" as I used "elseif". But then I realized that the correct syntax is "elsif". So I think that error message should be corrected to error: the else command must follow an if or elsif command. Thanks, Horst

3 2

Re: Question about namespaces
by Peter Wienemann 22 Aug '23

22 Aug '23

Hi J, On 21.08.23 21:08, J Doe wrote: > My current dovecot.conf is rather basic when it comes to namespaces - I > have one private namespace per user: > > namespace inbox { > type = private > separator = / > inbox = yes > hidden = no > list = yes > subscriptions = yes > } > > I have some users who connect via more than one client - for instance, > some use Apple Mail in addition to Roundcube. I have noticed that > different mail clients sometimes create similar mailboxes, such as Trash > and Deleted Items. I would like the same mailboxes across any client, > so I am wondering if there is a way in Dovecot to specify the folders > and have the *client* not create them. For instance, a config in > dovecot.conf that specifies a Trash folder and the mail clients cannot > create "Deleted Items", etc. in addition to this. > > Is this possible ? this can be done using the settings in https://github.com/dovecot/core/blob/main/doc/example-config/conf.d/15-mail… Best regards, Peter

2 1

dovecot 2.4 issue with openssl >= 3.0.8
by Michal Hlavinka 21 Aug '23

21 Aug '23

Hi, I've started testing main git branch and found an issue with openssl 3. Test suite fails: test_load_v1_key ........................................... : ok test-crypto.c:445: Assert failed: ret == TRUE test-crypto.c:446: Assert failed: error == NULL Panic: file dcrypt-openssl3.c: line 2917 (dcrypt_openssl_public_key_type): assertion failed: (key != NULL && key->key != NULL) Error: Raw backtrace: test-crypto(+0x5af01) [0x55951b667f01] -> test-crypto(backtrace_get+0x2f) [0x55951b66877f] -> test-crypto(+0x31291) [0x55951b63e291] -> test-crypto(+0x312d5) [0x55951b63e2d5] -> test-crypto(+0x16025) [0x55951b623025] -> libdcrypt_openssl.so(+0x70ff) [0x7f5a995b60ff] -> test-crypto(+0x2a17b) [0x55951b63717b] -> test-crypto(+0x3055d) [0x55951b63d55d] -> test-crypto(test_run+0x6c) [0x55951b63d61c] -> test-crypto(main+0x4e) [0x55951b62b66e] -> libc.so.6(+0x27b4a) [0x7f5a995eeb4a] -> libc.so.6(__libc_start_main+0x8b) [0x7f5a995eec0b] -> test-crypto(_start+0x25) [0x55951b62b7e5] The issue is caused by change in openssl >= 3.0.8 in lib-dcryt/dcrypt-openssl3.c method ec_key_get_pub_point_hex(...) in old version (for openssl 1.x) it uses compressed format: EC_POINT_point2hex(g, p, POINT_CONVERSION_COMPRESSED, NULL); in openssl3 version it uses EVP_PKEY_get_octet_string_param(pkey, OSSL_PKEY_PARAM_PUB_KEY, buf, sizeof(buf), &len); but key is created in dcrypt_evp_pkey_from_point(...) with OSSL_PKEY_PARAM_EC_POINT_CONVERSION_FORMAT, "uncompressed" this was working in openssl pre 3.0.8 as compression format was ignored when dumping data and used always compressed format. From https://www.openssl.org/docs/man3.0/man7/EVP_KEYMGMT-EC.html """ Before OpenSSL 3.0.8, the implementation of providers included with OpenSSL always opted for an encoding in compressed format, unconditionally. Since OpenSSL 3.0.8, the implementation has been changed to honor the OSSL_PKEY_PARAM_EC_POINT_CONVERSION_FORMAT parameter, if set, or to default to uncompressed format.""" I don't see simple way how to force compressed format just for dumping data without effecting the key itself. Method that can be used with compression format argument is EC_POINT_point2hex but it requires quite lengthy extraction of EC_POINT first. I've tried this for testing with: static const char *ec_key_get_pub_point_hex(const EVP_PKEY *pkey) { if (!EVP_PKEY_is_a(pkey, "EC")) return NULL; size_t len; EVP_PKEY_get_utf8_string_param(pkey, OSSL_PKEY_PARAM_GROUP_NAME, NULL, 0, &len); buffer_t *parambuf = t_buffer_create(len+1); EVP_PKEY_get_utf8_string_param(pkey, OSSL_PKEY_PARAM_GROUP_NAME, (char *)parambuf->data, len+1, &len); int nid = OBJ_txt2nid(parambuf->data); EVP_PKEY_get_octet_string_param(pkey, OSSL_PKEY_PARAM_PUB_KEY, NULL, 0, &len); parambuf = t_buffer_create(len+1); EVP_PKEY_get_octet_string_param(pkey, OSSL_PKEY_PARAM_PUB_KEY, (unsigned char *)parambuf->data, len+1, &len); EC_GROUP *ec_grp = EC_GROUP_new_by_curve_name(nid); if (ec_grp == NULL) return NULL; EC_POINT *point = EC_POINT_new(ec_grp); if (point == NULL) { EC_GROUP_free(ec_grp); return NULL; } if (!EC_POINT_oct2point(ec_grp, point, parambuf->data, len, NULL)) return NULL; char *ret = EC_POINT_point2hex(ec_grp, point, POINT_CONVERSION_COMPRESSED, NULL); EC_GROUP_free(ec_grp); EC_POINT_free(point); return ret; } and it fixed the issue, but there may be an easier way how to achieve that. Cheers Michal Hlavinka

3 6

Question about namespaces
by J Doe 21 Aug '23

21 Aug '23

Hello, I have a question regarding namespaces. My current dovecot.conf is rather basic when it comes to namespaces - I have one private namespace per user: namespace inbox { type = private separator = / inbox = yes hidden = no list = yes subscriptions = yes } I have some users who connect via more than one client - for instance, some use Apple Mail in addition to Roundcube. I have noticed that different mail clients sometimes create similar mailboxes, such as Trash and Deleted Items. I would like the same mailboxes across any client, so I am wondering if there is a way in Dovecot to specify the folders and have the *client* not create them. For instance, a config in dovecot.conf that specifies a Trash folder and the mail clients cannot create "Deleted Items", etc. in addition to this. Is this possible ? Thanks, - J

1 0

Backing up m(d)box - rsync?
by donotspam＠fastmail.fm 19 Aug '23

19 Aug '23

Hello, I manage a small number of email accounts for a voluntary organisation on a shared hosting platform. $ dovecot --version 2.3.13 (89f716dc2) I would like to keep automated local backups, but do not have access to doveadm. I have seen a couple of forum posts where users have have suggested that using rsync to backup m(d)box folders can corrupt dovecot's indexes, but there is no further explanation, and this is apparently not a problem for maildir. Our host seems to use mdbox. Does doveadm provide some sort of transaction/locking mechanism to prevent consistency problems? Others seem to recommend using tar but I don't see what difference that should make. Given that cpanel backups (provided as tar.gz archives of the home directory) include mail/ and seem to be copies of the filesystem at a particular time (though not true "snapshots" as such), aren't these just as "safe" as an rsync-ed backup? Can anyone confirm/deny/shed any light on the issue(s), if indeed any? Many thanks, Gareth

5 7