Failed to log in cyrus as admin0

garmout · February 13, 2013, 10:18am

Bonjour,

J’ai deux installations de Bluemind sur deux serveurs, un serveur de test et un serveur de production. J’utilise Ubuntu 12.04.1 sur les deux installations, j’ai suivi la même procédure.

L’installation sur le serveur de test est parfaite.

L’installation sur le serveur de production est problématique, j’ai du recommencer à plusieurs reprises pour terminer l’installation. Au passage, je note qu’il faut attendre un bon moment entre chaque étape de l’installation, certain service java étant redémarré, l’installation se bloque si l’on va trop vite, le service java n’étant pas encore disponible.

Ici n’est pas mon problème, j’ai beau recommencer l’installation, je termine toujours par des erreurs de création et d’authentification du user admin0 sur IMAP.

Je réinstalle bluemind de la manière suivante :
apt-get remove --purge bm-full cyrus* postgre* nginx* postfix* apache2*
apt-get autoremove --purge

je purge aussi tous les fichiers restants de ces packages

apt-get install bm-full

Il n’y a rien a faire j’ai toujours des erreurs avec admin0.

Lors de l’installation de Bluemind j’ai l’erreur suivante dans /var/log/bm-tomcat/bm-java.log :
2013-02-12 21:27:40,268 n.b.s.s.HostDomainAdminTask ERROR - error creating user
net.bluemind.core.api.fault.ServerFault: Failed to log in cyrus as admin0
at net.bluemind.core.client.impl.AbstractClientImpl.checkServerError(AbstractClientImpl.java:279) ~[net.bluemind.core.client_1.0.0.b7878.jar:na]
at net.bluemind.core.client.user.UserClient.create(UserClient.java:104) ~[net.bluemind.core.client_1.0.0.b7878.jar:na]
at net.bluemind.sw.server.HostDomainAdminTask.run(HostDomainAdminTask.java:150) ~[HostDomainAdminTask.class:na]
at java.lang.Thread.run(Thread.java:679) [na:1.6.0_24]

Finalement l’installation se termine et j’arrive à me connecter à l’interface adminconsole avec l’utilisateur admin0. Par contre lorsque j’essaye de créer un nouveau utilisateur, j’obtiens l’erreur suivante dans /var/log/bm/core.log :
2013-02-13 09:51:10,654 n.b.c.u.UserBindingImpl ERROR - Failed to log in cyrus as admin0
2013-02-13 09:51:10,657 n.b.c.s.SyncServlet ERROR - sending ServerFault: Failed to log in cyrus as admin0
net.bluemind.core.api.fault.ServerFault: Failed to log in cyrus as admin0
at net.bluemind.system.cyrus.CyrusSystemHook.mailboxCreated(CyrusSystemHook.java:303) ~[na:na]
at net.bluemind.system.cyrus.CyrusSystemHook.onUserCreated(CyrusSystemHook.java:144) ~[na:na]

Il me semble que la création du user d’admin cyrus “admin0” ne c’est systématiquement pas bien passé et donc m’empêche de créé de nouveau compte.

J’ai essayé de me connecter en local en utilisant la commande :
cyradm -u admin0 localhost

Cela fonctionne sur le dev mais pas sur la prod. Aussi sur le dev, je peux voir dans les logs /var/log/bm/core.log les entrées suivantes :
2013-02-13 09:30:24,076 n.b.c.s.a.i.AuthenticationRegistry INFO - Validate password using service net.bluemind.core.server.auth.impl.DatabaseAuthenticationService: YES in 4ms.
2013-02-13 09:30:24,087 n.b.c.s.SyncServlet INFO - handler responded to login/validate in 27ms.

Je n’est rien en production. Donc j’ai comme l’impression que cyrus est configuré pour pointer sur bm-core en back afin de valider l’authentification et cela ne fonctionne pas en prod.

J’aimerai savoir si vous avez une méthode pour recréé le user admin0 par ligne de commande dans imap ?

Y’a t’il un fichier particulier lié a cette authentification que je dois absolument regarder ou supprimer lors d’une réinstallation ? Je supprime déja beaucoup de répertoire dont tous les bm- mais aussi /var/lib/cyrus/ et /var/spool/cyrus/

Pouvez vous sinon, m’expliquer brièvement le mécanisme d’authentification entre cyrus et bluemind. Je chercherai ensuite la solution par moi même que je partagerai.

C’est dommage mais dans l’immédiat, il m’est impossible de réinstaller Linux

Merci beaucoup d’avance.

nico.dumont · February 13, 2013, 10:41am

Tu peux déjà regarder dans /etc/imapd.conf
Tu doit normalement avoir une ligne “admins: admin0” et “lmtp_admins: admin0”

Toony · February 13, 2013, 10:44am

Arrêtez Cyrus et vérifiez qu’il est bien stoppé:

# /etc/init.d/cyrus-imapd stop
# ps auwx|grep cyrus

Vérifiez que vous n’avez plus de processus cyrmaster. Sinon tuez-le, et re-démarrez Cyrus.

L’authentification auprès de Cyrus se fait via la service ysnp. On a donc: cyrus->ysnp->bm-core.

Si la procédure précédente ne suffit pas, pouvez-vous nous fournir les logs /var/log/mail.log et /var/log/ysnp/ysnp.log.

Dans tous les cas, il sera mieux de refaire l’installation:

# bmctl stop
# su - postgres
$ dropdb bj
$ exit
# bmctl start

puis de vous connecter à l’URL: http://monserveur/setup

tcataldo · February 13, 2013, 10:45am

Pour cette erreur:

[quote]Lors de l’installation de Bluemind j’ai l’erreur suivante dans /var/log/bm-tomcat/bm-java.log :
2013-02-12 21:27:40,268 n.b.s.s.HostDomainAdminTask ERROR - error creating user
net.bluemind.core.api.fault.ServerFault: Failed to log in cyrus as admin0
at net.bluemind.core.client.impl.AbstractClientImpl.checkServerError(AbstractClientImpl.java:279) ~[net.bluemind.core.client_1.0.0.b7878.jar:na]
at net.bluemind.core.client.user.UserClient.create(UserClient.java:104) ~[net.bluemind.core.client_1.0.0.b7878.jar:na]
at net.bluemind.sw.server.HostDomainAdminTask.run(HostDomainAdminTask.java:150) ~[HostDomainAdminTask.class:na]
[/quote]

le fichier de log interressant serait /var/log/bm-locator/locator.log.

Nous avons 2 tickets internes pour cette erreur :

l’un se produit quand 6+[nb coeurs du serveurs]*6 >= 100
l’autre est une histoire de temps de réponse de locator > 5sec sous certaines conditions

garmout · February 13, 2013, 11:40am

Bonjour,

Merci pour votre aide, j’ai trouvé la solution par vos commentaires.

Un classique : sur mon serveur de prod le /tmp est monté noexec. Lors de l’installation, plusieurs scripts sont copiés dans /tmp et exécutés. J’ai une erreur sur l’installation de cyrus notament. En repassant celui-ci en exec, l’install de cyrus se passe correctement. Pour info, cela concerne aussi ssl-cert et postgresql-common. Il est possible que vos scripts utilisent aussi /tmp … C’est peut-être un prérequis ?

Après une réinstallation complète, j’arrive maintenant à me connecter sur imap et créer des comptes.

A noter que je suis aussi assujetti au problème des 5000, je ne sais pas quel est l’impact, j’ai vu passer ce log une seule fois en fin d’installation :
==> /var/log/ysnp/ysnp.log <==
2013-02-13 11:23:25,438 n.b.y.i.SaslauthdProtocol INFO - Attempting login: admin0 service: imap realm:
2013-02-13 11:24:29,035 n.b.l.c.LocatorClient ERROR - java.util.concurrent.TimeoutException: No response received after 5000
java.util.concurrent.ExecutionException: java.util.concurrent.TimeoutException: No response received after 5000
at com.ning.http.client.providers.netty.NettyResponseFuture.abort(NettyResponseFuture.java:297) ~[na:na]
at com.ning.http.client.providers.netty.NettyAsyncHttpProvider.abort(NettyAsyncHttpProvider.java:1321) ~[na:na]
at com.ning.http.client.providers.netty.NettyAsyncHttpProvider.access$700(NettyAsyncHttpProvider.java:137) ~[na:na]
at com.ning.http.client.providers.netty.NettyAsyncHttpProvider$ReaperFuture.run(NettyAsyncHttpProvider.java:1804) ~[na:na]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) ~[na:1.6.0_24]
at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351) ~[na:1.6.0_24]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178) ~[na:1.6.0_24]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165) ~[na:1.6.0_24]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267) ~[na:1.6.0_24]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) ~[na:1.6.0_24]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) ~[na:1.6.0_24]
at java.lang.Thread.run(Thread.java:679) ~[na:1.6.0_24]
Caused by: java.util.concurrent.TimeoutException: No response received after 5000
… 9 common frames omitted
2013-02-13 11:24:29,036 n.b.y.b.i.CoreCredentialValidator WARN - bm/core not found for admin0
2013-02-13 11:24:29,038 n.b.y.i.ValidationPolicy WARN - all 1 validator(s) rejected admin0 in 63599ms.

Merci pour votre aide.

tcataldo · February 13, 2013, 8:49pm

Le /tmp en noexec je note pour de futurs problèmes d’installation qu’on n’arrive pas à reproduire

Ton log de locator m’interesse toujours, tu est dans le cas de notre second ticket (https://forge.blue-mind.net/redmine/issues/3801 pour les bluemind). Pas trop de secrets dedans, juste une stack trace identique à la tienne sur une prod client.

Pour notre client le problème survenait lors d’une opération massive (resynchro avec annuaire LDAP) et au traitement d’une des modifs on a eu ça. Mon diagnostic initial penchait sur un temps de réponse réellement >5sec côté locator mais comme toi tu a ça à un moment de l’installation où le service locator est peu stressé j’aimerai (in)valider mon diagnostic.

Il me faudrait le log de locator autour des heures de l’install qui n’a pas marché complètement, et un cat /proc/cpuinfo si possible.

garmout · February 13, 2013, 11:17pm

Voici les logs.

Dans mon cas, pas d’opération massive, car il s’agit bien de la phase d’installation.

Je pense fortement que l’erreur vient du fait que Locator n’était pas encore totalement démarré lors de la tentative accèsd’Ysnp.

Voici le log de Locator associé :
2013-02-13 11:19:56,151 n.b.l.LocatorService INFO - Starting BM Locator…
2013-02-13 11:19:56,167 o.m.log INFO - Logging to Logger[org.mortbay.log] via org.mortbay.log.Slf4jLog
2013-02-13 11:19:56,243 o.m.log INFO - jetty-6.1.x
2013-02-13 11:20:59,674 o.m.log INFO - Started SslSocketConnector@0.0.0.0:8084
2013-02-13 11:20:59,724 n.b.l.LocatorService INFO - Accepting SSL queries on port 8084
2013-02-13 11:21:30,214 n.b.l.LocatorService INFO - Starting BM Locator…
2013-02-13 11:21:30,233 o.m.log INFO - Logging to Logger[org.mortbay.log] via org.mortbay.log.Slf4jLog
2013-02-13 11:21:30,372 o.m.log INFO - jetty-6.1.x
2013-02-13 11:22:33,909 o.m.log INFO - Started SslSocketConnector@0.0.0.0:8084
2013-02-13 11:22:33,950 n.b.l.LocatorService INFO - Accepting SSL queries on port 8084
2013-02-13 11:22:39,756 n.b.p.BMPoolActivator INFO - Starting BM connection pool…
2013-02-13 11:22:39,759 n.b.p.BMPoolActivator INFO - dbtype from bm.ini is PGSQL
2013-02-13 11:22:39,762 n.b.u.RunnableExtensionLoader INFO - net.bluemind.jdbc.oracle.provider.OracleConnectionFactory loaded.
2013-02-13 11:22:39,763 n.b.u.RunnableExtensionLoader INFO - net.bluemind.jdbc.pgsql.provider.PgSQLConnectionFactory loaded.
2013-02-13 11:22:39,763 n.b.u.RunnableExtensionLoader INFO - Loaded 2 implementors of net.bluemind.pool.jdbcdriver
2013-02-13 11:22:39,824 n.b.p.x.PoolActivator INFO - Pool bundle started.
2013-02-13 11:22:39,909 n.b.p.x.i.DataSource INFO - Starting pool…(jdbc:postgresql://XXX.XXX.XXX.XXX/bj)
2013-02-13 11:22:39,911 n.b.p.x.i.ConnectionPool INFO - Creating Physical connection…
2013-02-13 11:22:39,955 n.b.p.x.i.ConnectionPool INFO - Physical connection established.
2013-02-13 11:22:39,955 n.b.p.x.i.ConnectionPool INFO - Creating Physical connection…
2013-02-13 11:22:39,962 n.b.p.x.i.ConnectionPool INFO - Physical connection established.
2013-02-13 11:22:39,962 n.b.p.x.i.ConnectionPool INFO - Creating Physical connection…
2013-02-13 11:22:39,969 n.b.p.x.i.ConnectionPool INFO - Physical connection established.
2013-02-13 11:22:39,969 n.b.p.x.i.ConnectionPool INFO - Creating Physical connection…
2013-02-13 11:22:39,976 n.b.p.x.i.ConnectionPool INFO - Physical connection established.
2013-02-13 11:22:39,976 n.b.p.x.i.ConnectionPool INFO - Creating Physical connection…
2013-02-13 11:22:39,983 n.b.p.x.i.ConnectionPool INFO - Physical connection established.
2013-02-13 11:22:39,983 n.b.p.x.i.ConnectionPool INFO - Creating Physical connection…
2013-02-13 11:22:39,990 n.b.p.x.i.ConnectionPool INFO - Physical connection established.
2013-02-13 11:22:39,990 n.b.p.x.i.ConnectionPool INFO - Pool State after start is 0 used out of 6 connections
2013-02-13 11:22:39,990 n.b.p.x.i.PingThread INFO - created with 6 JDBC connections.
2013-02-13 11:22:40,029 n.b.l.HostLocationServlet ERROR - Could not find bm/mq for admin0@global.virt
2013-02-13 11:22:40,030 n.b.l.HostLocationServlet ERROR - Could not find bm/mq for admin0@global.virt
2013-02-13 11:22:53,573 n.b.l.HostLocationServlet ERROR - Could not find bm/core for admin0@global.virt
2013-02-13 11:23:25,080 n.b.l.HostLocationServlet INFO - query: /location/host/solr/contact/fake@bluemind.test.org => returned 1 IP(s) address(es) XXX.XXX.XXX.XXX ]
2013-02-13 11:23:25,089 n.b.l.HostLocationServlet INFO - query: /location/host/solr/event/fake@bluemind.test.org => returned 1 IP(s) address(es) XXX.XXX.XXX.XXX ]
2013-02-13 11:23:25,101 n.b.l.HostLocationServlet INFO - query: /location/host/solr/contact/fake@bluemind.test.org => returned 1 IP(s) address(es) XXX.XXX.XXX.XXX ]
2013-02-13 11:23:25,106 n.b.l.HostLocationServlet INFO - query: /location/host/solr/event/fake@bluemind.test.org => returned 1 IP(s) address(es) XXX.XXX.XXX.XXX ]
2013-02-13 11:23:25,214 n.b.l.HostLocationServlet INFO - query: /location/host/solr/contact/fake@bluemind.test.org => returned 1 IP(s) address(es) XXX.XXX.XXX.XXX ]
2013-02-13 11:23:25,222 n.b.l.HostLocationServlet INFO - query: /location/host/solr/event/fake@bluemind.test.org => returned 1 IP(s) address(es) XXX.XXX.XXX.XXX ]
2013-02-13 11:25:33,707 n.b.l.HostLocationServlet INFO - query: /location/host/bm/mq/admin0@global.virt => returned 1 IP(s) address(es) XXX.XXX.XXX.XXX ]
2013-02-13 11:25:35,819 n.b.l.HostLocationServlet INFO - query: /location/host/bm/core/admin0@global.virt => returned 1 IP(s) address(es) XXX.XXX.XXX.XXX ]
2013-02-13 11:25:36,893 n.b.l.HostLocationServlet INFO - query: /location/host/bm/core/admin0@global.virt => returned 1 IP(s) address(es) XXX.XXX.XXX.XXX ]
2013-02-13 11:26:07,024 n.b.l.HostLocationServlet INFO - query: /location/host/bm/mq/admin0@global.virt => returned 1 IP(s) address(es) XXX.XXX.XXX.XXX ]
2013-02-13 11:27:10,833 n.b.l.HostLocationServlet INFO - query: /location/host/bm/ac/admin0@global.virt => returned 1 IP(s) address(es) XXX.XXX.XXX.XXX ]
2013-02-13 11:27:16,212 n.b.l.HostLocationServlet INFO - query: /location/host/bm/core/admin0@global.virt => returned 1 IP(s) address(es) XXX.XXX.XXX.XXX ]
2013-02-13 11:27:17,970 n.b.l.HostLocationServlet INFO - query: /location/host/bm/core/admin0@global.virt => returned 1 IP(s) address(es) XXX.XXX.XXX.XXX ]
2013-02-13 11:27:18,025 n.b.l.HostLocationServlet INFO - query: /location/host/bm/core/admin0@global.virt => returned 1 IP(s) address(es) XXX.XXX.XXX.XXX ]
2013-02-13 11:27:46,738 n.b.l.HostLocationServlet INFO - query: /location/host/solr/contact/fake@bluemind.test.org => returned 1 IP(s) address(es) XXX.XXX.XXX.XXX ]
2013-02-13 11:27:46,742 n.b.l.HostLocationServlet INFO - query: /location/host/solr/event/fake@bluemind.test.org => returned 1 IP(s) address(es) XXX.XXX.XXX.XXX ]

Le log de ysnp.log :
2013-02-13 11:23:13,512 n.b.y.YSNPDaemon INFO - YSNP daemon starting
2013-02-13 11:23:13,701 n.b.y.YSNPConfiguration WARN - /etc/ysnp/ysnp.conf file not found. using default settings
2013-02-13 11:23:13,702 n.b.y.YSNPDaemon INFO - UNIX socket will be created on /var/run/saslauthd/mux
2013-02-13 11:23:13,796 n.b.y.u.RunnableExtensionLoader INFO - CoreCredentialValidatorFactory loaded.
2013-02-13 11:23:13,796 n.b.y.u.RunnableExtensionLoader INFO - Loaded 1 implementors of net.bluemind.ysnp.credentialvalidatorfactory
2013-02-13 11:23:13,881 n.b.y.i.AuthChainBuilder INFO - Starting main loop
2013-02-13 11:23:25,438 n.b.y.i.SaslauthdProtocol INFO - Attempting login: admin0 service: imap realm:
2013-02-13 11:24:29,035 n.b.l.c.LocatorClient ERROR - java.util.concurrent.TimeoutException: No response received after 5000
java.util.concurrent.ExecutionException: java.util.concurrent.TimeoutException: No response received after 5000
at com.ning.http.client.providers.netty.NettyResponseFuture.abort(NettyResponseFuture.java:297) ~[na:na]
at com.ning.http.client.providers.netty.NettyAsyncHttpProvider.abort(NettyAsyncHttpProvider.java:1321) ~[na:na]
at com.ning.http.client.providers.netty.NettyAsyncHttpProvider.access$700(NettyAsyncHttpProvider.java:137) ~[na:na]
at com.ning.http.client.providers.netty.NettyAsyncHttpProvider$ReaperFuture.run(NettyAsyncHttpProvider.java:1804) ~[na:na]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) ~[na:1.6.0_24]
at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351) ~[na:1.6.0_24]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178) ~[na:1.6.0_24]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165) ~[na:1.6.0_24]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267) ~[na:1.6.0_24]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) ~[na:1.6.0_24]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) ~[na:1.6.0_24]
at java.lang.Thread.run(Thread.java:679) ~[na:1.6.0_24]
Caused by: java.util.concurrent.TimeoutException: No response received after 5000
… 9 common frames omitted
2013-02-13 11:24:29,036 n.b.y.b.i.CoreCredentialValidator WARN - bm/core not found for admin0

Le /proc/cpuinfo :
processor : 0
vendor_id : GenuineIntel
cpu family : 6
model : 44
model name : Intel(R) Xeon(R) CPU L5640 @ 2.27GHz
stepping : 2
microcode : 0x5
cpu MHz : 2266.774
cache size : 12288 KB
physical id : 0
siblings : 2
core id : 0
cpu cores : 1
apicid : 0
initial apicid : 5
fpu : yes
fpu_exception : yes
cpuid level : 11
wp : yes
flags : fpu de tsc msr pae cx8 sep cmov pat clflush mmx fxsr sse sse2 ss ht syscall nx lm constant_tsc rep_good nopl aperfmperf pni ssse3 cx16 pcid sse4_1 sse4_2 popcnt hypervisor lahf_lm arat dts
bogomips : 4533.54
clflush size : 64
cache_alignment : 64
address sizes : 40 bits physical, 48 bits virtual
power management:

processor : 1
vendor_id : GenuineIntel
cpu family : 6
model : 44
model name : Intel(R) Xeon(R) CPU L5640 @ 2.27GHz
stepping : 2
microcode : 0x5
cpu MHz : 2266.774
cache size : 12288 KB
physical id : 0
siblings : 2
core id : 0
cpu cores : 1
apicid : 0
initial apicid : 5
fpu : yes
fpu_exception : yes
cpuid level : 11
wp : yes
flags : fpu de tsc msr pae cx8 sep cmov pat clflush mmx fxsr sse sse2 ss ht syscall nx lm constant_tsc rep_good nopl aperfmperf pni ssse3 cx16 pcid sse4_1 sse4_2 popcnt hypervisor lahf_lm arat dts
bogomips : 4533.54
clflush size : 64
cache_alignment : 64
address sizes : 40 bits physical, 48 bits virtual
power management: