Mise en production de BM: Erreur DBERROR... cyrusdb error

tikok974 · April 18, 2017, 1:51pm

Bonjour,

J’ai migré notre plateforme Zarafa vers Bluemind. Notre nouvelle plateforme Bluemind est actuellement en version 3.5.4.1 et est hébergé sur une VM de type KVM tournant sous Debian 8.1 (RAM 10Go, 4 CPU).

J’ai remarqué cette erreur dans le log “/var/log/mail.err”…uniquement qu’à certains moment !

Apr 18 04:01:00 chloris cyrus/tls_prune[18361]: DBERROR: opening /var/lib/cyrus/tls_sessions.db: cyrusdb error
Apr 18 11:14:45 chloris cyrus/imap[28083]: Fatal error: Mailbox has been (re)moved
Apr 18 12:49:01 chloris cyrus/master[9098]: process 9111 exited, signaled to death by 3
Apr 18 12:49:01 chloris cyrus/notify[9110]: recvfrom failed: Interrupted system call
Apr 18 12:49:52 chloris cyrus/master[2177]: setrlimit: Unable to set file descriptors limit to -1: Operation not permitted
Apr 18 12:49:52 chloris cyrus/master[2177]: retrying with 65536 (current max)
Apr 18 12:49:52 chloris cyrus/tls_prune[2204]: DBERROR: opening /var/lib/cyrus/tls_sessions.db: cyrusdb error
Apr 18 12:49:52 chloris cyrus/master[2177]: process 2204 exited, status 1

Que puis-je faire pour y remédier ?

Merci.

aaujon · May 4, 2017, 8:16am

Bonjour,

L’erreur sur tls_prune est normale car BlueMind n’utilise pas le caching des sessions TLS via cyrus.
Les autres erreurs sont ‘normales’ aussi le setrlimit sur -1 ne fonctionne pas mais BlueMind utilise un fallback dans ce cas là

tikok974 · May 4, 2017, 1:08pm

Salut Arnaud,
Merci pour ta réponse.
Cependant on voit aussi ci-dessus l’erreur:

...
...
Apr 18 11:14:45 chloris cyrus/imap[28083]: Fatal error: Mailbox has been (re)moved
...
...

Est-ce que cela pourrai être lié au problème de dossier et synchro EAS que j’ai mentionné aussi ICI ?

Merci.

aaujon · May 4, 2017, 1:11pm

C’est possible, il faudrait voir d’où vient la requête avec les logs de bm-ips

tikok974 · May 4, 2017, 1:58pm

Re,

Il aurait fallut que je vérifie le log “/var/log/bm-ips/ips.log” le 18 Avril dernier.

Cependant, depuis 04H00 ce matin, je n’ai eu que ça comme erreur dans “/var/log/mail.err”:

May  1 04:01:00 chloris cyrus/tls_prune[15261]: DBERROR: opening /var/lib/cyrus/tls_sessions.db: cyrusdb error
May  2 04:01:00 chloris cyrus/tls_prune[18613]: DBERROR: opening /var/lib/cyrus/tls_sessions.db: cyrusdb error
May  3 04:01:00 chloris cyrus/tls_prune[22052]: DBERROR: opening /var/lib/cyrus/tls_sessions.db: cyrusdb error
May  4 04:01:00 chloris cyrus/tls_prune[24791]: DBERROR: opening /var/lib/cyrus/tls_sessions.db: cyrusdb error

Par contre, dans “/var/log/bm-ips/ips.log” voilà ce que l’on peut voir:

...
...
2017-05-04 13:00:29,583 [vert.x-worker-thread-19] net.bluemind.ips.mbox.index.impl.FlagsChangeRunnable INFO - [sdupond@domain.tld][mbox.uid 31279EFF-69DC-45C1-AEFB-DC922AD055E9] folder lookup: imap://user/sdupond@domain.tld/Sent
2017-05-04 13:00:29,587 [vert.x-worker-thread-19] net.bluemind.index.mail.MailIndexService INFO - change flags in imap://user/sdupond@domain.tld/Sent 643:922
2017-05-04 13:00:29,587 [vert.x-worker-thread-19] net.bluemind.index.mail.MailIndexService INFO - Bulk START on index mailspool_alias_31279EFF-69DC-45C1-AEFB-DC922AD055E9
2017-05-04 13:00:29,589 [vert.x-worker-thread-19] net.bluemind.index.mail.MailIndexService INFO - Bulk END (0)
2017-05-04 13:00:29,589 [vert.x-worker-thread-19] net.bluemind.index.mail.MailIndexService INFO - updated emails 0
2017-05-04 13:00:29,589 [vert.x-worker-thread-19] net.bluemind.ips.mbox.index.impl.FlagsChangeRunnable INFO - Update time is 2ms.
2017-05-04 13:00:29,589 [vert.x-worker-thread-19] net.bluemind.ips.mbox.index.impl.FlagsChangeRunnable INFO - [sdupond@domain.tld][Sent] Reindexing done in 7ms.
2017-05-04 13:00:29,594 [vert.x-worker-thread-16] net.bluemind.ips.mbox.index.MailboxIndexUpdater INFO - [Sent] onMailsExpunged: '922'
2017-05-04 13:00:29,595 [vert.x-worker-thread-16] net.bluemind.ips.mbox.index.impl.UidExpungeRunnable INFO - [sdupond@domain.tld][mbox.uid 31279EFF-69DC-45C1-AEFB-DC922AD055E9] folder lookup: imap://user/sdupond@domain.tld/Sent
2017-05-04 13:00:29,598 [vert.x-worker-thread-16] net.bluemind.index.mail.MailIndexService INFO - expunge: imap://user/sdupond@domain.tld/Sent 922
2017-05-04 13:00:29,598 [vert.x-worker-thread-16] net.bluemind.index.mail.MailIndexService INFO - Bulk START on index mailspool_alias_31279EFF-69DC-45C1-AEFB-DC922AD055E9
2017-05-04 13:00:29,600 [vert.x-worker-thread-16] net.bluemind.index.mail.MailIndexService INFO - Bulk END (0)
2017-05-04 13:00:29,600 [vert.x-worker-thread-16] net.bluemind.index.mail.MailIndexService INFO - expunge imap://user/sdupond@domain.tld/Sent (922) : 0 deleted
2017-05-04 13:00:29,600 [vert.x-worker-thread-16] net.bluemind.ips.mbox.index.impl.UidExpungeRunnable INFO - [sdupond@domain.tld][Sent] Reindexing done in 6ms.
2017-05-04 13:00:29,641 [vert.x-worker-thread-7] net.bluemind.ips.mq.notify.impl.ForwardToMQ INFO - [sdupond@domain.tld] mail.added '"Classement /4-Demandes de renseignements" (\Seen) " 4-May-2017 14:59:00 +0200" {13615}'
2017-05-04 13:00:29,641 [vert.x-worker-thread-7] net.bluemind.ips.mbox.index.MailboxIndexUpdater INFO - [sdupond@domain.tld] onMailAdded: '"Classement /4-Demandes de renseignements" (\Seen) " 4-May-2017 14:59:00 +0200" {13615}' => 'OK
 [APPENDUID 1486970587 4355] Completed'
2017-05-04 13:00:29,641 [vert.x-worker-thread-7] net.bluemind.ips.mbox.index.MailboxIndexUpdater INFO - [sdupond@domain.tld] Classement /4-Demandes de renseignements new mail has uid 4355
2017-05-04 13:00:29,661 [vert.x-worker-thread-7] net.bluemind.ips.mbox.index.impl.IndexRunnable INFO - [sdupond@domain.tld][mbox.uid 31279EFF-69DC-45C1-AEFB-DC922AD055E9] folder lookup: imap://user/sdupond@domain.tld/Classement /4
-Demandes de renseignements
2017-05-04 13:00:29,688 [vert.x-worker-thread-7] net.bluemind.ips.mbox.index.impl.IndexRunnable ERROR - [mailbox:acls-31279EFF-69DC-45C1-AEFB-DC922AD055E9] folder with uri imap://user/sdupond@domain.tld/Classement /4-Demandes de rense
ignements not found.
net.bluemind.core.api.fault.ServerFault: [mailbox:acls-31279EFF-69DC-45C1-AEFB-DC922AD055E9] folder with uri imap://user/sdupond@domain.tld/Classement /4-Demandes de renseignements not found.
        at net.bluemind.core.rest.base.ClientProxyGenerator$2.invoke(ClientProxyGenerator.java:280) ~[net.bluemind.core.rest_3.1.21348.jar:na]
        at com.sun.proxy.$Proxy32.byContentUri(Unknown Source) ~[na:na]
        at net.bluemind.ips.mbox.index.impl.AbstractIndexOperation.getFolderItem(AbstractIndexOperation.java:89) [net.bluemind.ips.mbox.index_3.1.21348.jar:na]
        at net.bluemind.ips.mbox.index.impl.AbstractIndexOperation.getFolderItem(AbstractIndexOperation.java:80) [net.bluemind.ips.mbox.index_3.1.21348.jar:na]
        at net.bluemind.ips.mbox.index.impl.IndexRunnable.runOp(IndexRunnable.java:61) ~[net.bluemind.ips.mbox.index_3.1.21348.jar:na]
        at net.bluemind.ips.mbox.index.impl.AbstractIndexOperation.run(AbstractIndexOperation.java:69) [net.bluemind.ips.mbox.index_3.1.21348.jar:na]
        at net.bluemind.ips.mbox.index.MailboxIndexUpdater.onMailAdded(MailboxIndexUpdater.java:207) [net.bluemind.ips.mbox.index_3.1.21348.jar:na]
        at net.bluemind.ips.mbox.index.MailboxIndexUpdater.onCompleteCommand(MailboxIndexUpdater.java:83) [net.bluemind.ips.mbox.index_3.1.21348.jar:na]
        at net.bluemind.ips.vertx.impl.SessionListeners.notify(SessionListeners.java:66) [net.bluemind.ips.vertx_3.1.21348.jar:na]
        at net.bluemind.ips.vertx.impl.CompletedCommandManager.commandCompleted(CompletedCommandManager.java:122) [net.bluemind.ips.vertx_3.1.21348.jar:na]
        at net.bluemind.ips.vertx.impl.CompletedCommandManager.access$1(CompletedCommandManager.java:97) [net.bluemind.ips.vertx_3.1.21348.jar:na]
        at net.bluemind.ips.vertx.impl.CompletedCommandManager$2.handle(CompletedCommandManager.java:68) [net.bluemind.ips.vertx_3.1.21348.jar:na]
        at net.bluemind.ips.vertx.impl.CompletedCommandManager$2.handle(CompletedCommandManager.java:1) [net.bluemind.ips.vertx_3.1.21348.jar:na]
        at org.vertx.java.core.eventbus.impl.DefaultEventBus$11.run(DefaultEventBus.java:963) [io.vertx.core_2.1.6.bm4.jar:na]
        at org.vertx.java.core.impl.DefaultContext$3.run(DefaultContext.java:175) [io.vertx.core_2.1.6.bm4.jar:na]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_72]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_72]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_72]
Caused by: net.bluemind.core.api.fault.ServerFault: [mailbox:acls-31279EFF-69DC-45C1-AEFB-DC922AD055E9] folder with uri imap://user/sdupond@domain.tld/Classement /4-Demandes de renseignements not found.
        at net.bluemind.core.rest.base.codec.JsonObjectCodec.parseFault(JsonObjectCodec.java:113) ~[net.bluemind.core.rest_3.1.21348.jar:na]
        at net.bluemind.core.rest.base.codec.JsonObjectCodec$Response.decode(JsonObjectCodec.java:89) ~[net.bluemind.core.rest_3.1.21348.jar:na]
        at net.bluemind.core.rest.base.ClientProxyGenerator$MethodCallBuilder.parseResponse(ClientProxyGenerator.java:410) ~[net.bluemind.core.rest_3.1.21348.jar:na]
        at net.bluemind.core.rest.base.ClientProxyGenerator$EventMethodInvoker$1.success(ClientProxyGenerator.java:217) ~[net.bluemind.core.rest_3.1.21348.jar:na]
        at net.bluemind.core.rest.base.ClientProxyGenerator$EventMethodInvoker$1.success(ClientProxyGenerator.java:1) ~[net.bluemind.core.rest_3.1.21348.jar:na]
        at net.bluemind.core.rest.http.internal.AsyncCompletionHandler.onCompleted(AsyncCompletionHandler.java:101) ~[net.bluemind.core.rest.http_3.1.21348.jar:na]
        at com.ning.http.client.AsyncCompletionHandlerBase.onCompleted(AsyncCompletionHandlerBase.java:25) ~[com.ning.async-http-client_1.9.26.jar:na]
        at com.ning.http.client.AsyncCompletionHandler.onCompleted(AsyncCompletionHandler.java:55) ~[com.ning.async-http-client_1.9.26.jar:na]
        at com.ning.http.client.providers.netty.future.NettyResponseFuture.getContent(NettyResponseFuture.java:177) ~[com.ning.async-http-client_1.9.26.jar:na]
        at com.ning.http.client.providers.netty.future.NettyResponseFuture.done(NettyResponseFuture.java:214) ~[com.ning.async-http-client_1.9.26.jar:na]
        at com.ning.http.client.providers.netty.handler.HttpProtocol.finishUpdate(HttpProtocol.java:194) ~[com.ning.async-http-client_1.9.26.jar:na]
        at com.ning.http.client.providers.netty.handler.HttpProtocol.exitAfterHandlingBody(HttpProtocol.java:396) ~[com.ning.async-http-client_1.9.26.jar:na]
        at com.ning.http.client.providers.netty.handler.HttpProtocol.handleHttpResponse(HttpProtocol.java:423) ~[com.ning.async-http-client_1.9.26.jar:na]
        at com.ning.http.client.providers.netty.handler.HttpProtocol.handle(HttpProtocol.java:470) ~[com.ning.async-http-client_1.9.26.jar:na]
        at com.ning.http.client.providers.netty.handler.Processor.messageReceived(Processor.java:88) ~[com.ning.async-http-client_1.9.26.jar:na]
        at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.handler.stream.ChunkedWriteHandler.handleUpstream(ChunkedWriteHandler.java:142) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.handler.codec.http.HttpContentDecoder.messageReceived(HttpContentDecoder.java:108) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:296) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.handler.codec.frame.FrameDecoder.unfoldAndFireMessageReceived(FrameDecoder.java:459) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.handler.codec.replay.ReplayingDecoder.callDecode(ReplayingDecoder.java:536) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.handler.codec.replay.ReplayingDecoder.messageReceived(ReplayingDecoder.java:435) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.handler.codec.http.HttpClientCodec.handleUpstream(HttpClientCodec.java:92) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:559) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:88) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:108) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:337) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:89) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108) ~[org.jboss.netty_3.10.3.Final.jar:na]
        at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42) ~[na:na]
        ... 3 common frames omitted
2017-05-04 13:00:29,688 [vert.x-worker-thread-7] net.bluemind.ips.mbox.index.impl.IndexRunnable INFO - [sdupond@domain.tld][Classement /4-Demandes de renseignements] Reindexing done in 47ms.
...
...
2017-05-04 13:15:20,996 [vert.x-worker-thread-19] net.bluemind.ips.vertx.impl.CompletedCommandManager WARN - [lbernard@domain.tld] No notification for failure of 'SELECT "Trash/Concepteurs"' => NO Mailbox does not exist
2017-05-04 13:15:21,154 [vert.x-worker-thread-0] net.bluemind.ips.vertx.impl.CompletedCommandManager WARN - [lbernard@domain.tld] No notification for failure of 'SELECT "Trash/OUTILS-MATOS"' => NO Mailbox does not exist
2017-05-04 13:15:21,275 [vert.x-worker-thread-8] net.bluemind.ips.vertx.impl.CompletedCommandManager WARN - [lbernard@domain.tld] No notification for failure of 'SELECT "Trash/PARTENARIAT"' => NO Mailbox does not exist
2017-05-04 13:15:22,025 [vert.x-eventloop-thread-6] net.bluemind.ips.imap.dm.commands.append.AppendCP INFO - [lbernard@domain.tld] OUTLOOK Rejecting too big message (19299704bytes)
2017-05-04 13:15:22,025 [vert.x-eventloop-thread-6] net.bluemind.ips.vertx.impl.DataHandler WARN - [lbernard@domain.tld] Closing with hr4x NO message is too big
...
...

Mes questions:

1) Qu’est ce qui explique les erreurs Java provoquées sur certains dossiers…est-ce que c’est aussi lié au problème du chemin qu’il y a sur ces dossiers et qui est prévu d’être réglé dans la version 3.5.5 de BM ?

2) Est-ce que la réindexation que l’on peut voir juste après l’erreur Java règle le problème sur le dossier concerné ?

3) Qu’est ce qui explique l’erreur “OUTLOOK Rejecting too big message” ?

Merci.

aaujon · May 4, 2017, 2:13pm

Oui le problème est lié au chemin, la 3.5.5 va tout remettre d’aplomb, elle est prévu pour sortir dans la deuxième quinzaine de mai.
Non l’indexation du message échoue justement à cause du problème de chemin des dossiers
Cela veut tout simplement dire que le message dépasse la taille maximale configurée dans BM (ici le mail fait presque 20 Mo)

tikok974 · May 4, 2017, 2:36pm

Re,

OK pour “1)” et “2)”.
Par contre pour “3)”, je ne comprend pas…c’est à l’envoi ou à la réception que le problème se pose ?
Est-ce que l’utilisateur reçoit un message d’erreur à ce moment là dans Outlook ?

Nous avons mis effectivement dans BM une limite de 25 MiB. De plus, le service Fetchmail qui tourne sur le serveur BM est paramétré pour ne récupérer que des messages qui n’excèdent pas cette taille chez notre fournisseur de mail externe. Normalement, en réception dans la boîte BM de l’utilisateur, il n’y a pas de message supérieur à 25 MiB.
De plus, si l’utilisateur souhaite envoyer un e-mail plus gros que 25 MiB, il se voit proposer de mettre ces pièces jointes dans son espace sur BM et un lien de téléchargement sera créé dans son e-mail pour le(s) destinataires.
Est-ce que c’est à ce moment là, lorsque le connecteur BM propose de stocker le message en interne et créer un lien dans l’e-mail, que nous avons cette erreur dans le log bm-ips ?

Merci.

aaujon · May 4, 2017, 2:52pm

Le message rejeté arrive via IMAP, c’est donc un message que l’utilisateur sous Outlook essaye de stocker dans un de ses dossiers (Draft par exemple), cela peut arriver si l’utilisateur commence à écrire un mail avec des grosses pièces jointes puis décide ensuite de les détacher, pendant ce temps Outlook essaye d’enregistrer le mail dans le dossier Draft, ce qui n’est pas possible en raison de la taille. Une fois que l’utilisateur a détaché les PJ alors il n’y a plus d’erreurs.
Si le scénario n’est pas celui là, le plus simple serait d’essayer de reproduire le problème puis de créer un ticket avec les informations.

tikok974 · May 4, 2017, 2:55pm

Re,

OK…je vais checker et je te redis.

Merci beaucoup pour tes explications

tikok974 · July 3, 2017, 7:07am

Bonjour,

Je suis passé sur la dernière version de BM (3.5.5.1) et mon problème lié au chemin est résolu.

Merci à toute l’équipe pour votre travail.