Actions qui des fois passent et des fois non

BlueMind - FR Discussions
1

Bonjour,

j’ai un problème assez important. Dans l’interface d’administration quand j’essaie de faire des actions, j’ai un temps de chargement assez long (1 bonne grosse minute) et je reviens à la page d’accueil sans qu’il ne ce soit rien passé.

Par exemple j’essaie de partager un calendrier pour un utilisateur, je valide, ça met du temps je reviens à la page d’accueil et si je regarde ma modification n’a pas été prise en compte.
Idem sur la suppression d’un utilisateur, etc …

Comment analyser et résoudre ce problème.

Slts

2

Pour compléter voici le timeout nginx :

2014/01/08 10:01:22 [error] 15790#0: *44728 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 8*********8, server: mail-bm.domaine.com, request: "POST /adminconsole/adminconsole/userOps HTTP/1.1", upstream: "[http://127.0.0.1:8079/adminconsole/adminconsole/userOps](http://127.0.0.1:8079/adminconsole/adminconsole/userOps)", host: "mail-bm.domaine.com", referrer: "[https://mail-bm.makina-corpus.com/adminconsole/](https://mail-bm.makina-corpus.com/adminconsole/)"
3

Pouvez-vous nous fournir les logs /var/log/bm/core.log lorsqu’une opération provoque ce timeout ?

4

Est-ce que je peux faire un grep sur un événement particulier ? Sinon le core.log va être long

5

Voici le log pour le partage de l’agenda de formation@domaine.com :

2014-01-08 09:33:33,224 n.b.c.s.SyncServlet INFO - handler responded to calendar/doSync in 3ms.
2014-01-08 09:33:34,909 n.b.c.UserManagement INFO - Accepting token as password for admin0@global.virt in bm-hps-ping
2014-01-08 09:33:34,911 n.b.c.s.SyncServlet INFO - handler responded to login/validate in 2ms.
2014-01-08 09:33:34,940 n.b.s.c.UserSC INFO - max_quota check: 0
2014-01-08 09:33:34,941 n.b.c.u.UserHome INFO - update User with login: formation, id:101, entityId:1477
2014-01-08 09:33:34,945 n.b.c.c.ContactHome INFO - modifyC(Virtuel Formation Virtuel)
2014-01-08 09:33:34,945 n.b.c.c.ContactHome INFO - modify contact with id=101 entityId=1477
2014-01-08 09:33:34,951 n.b.c.s.SolrHelper INFO - [contact 101] scheduled for solr indexing
2014-01-08 09:33:34,957 n.b.i.i.ClientSupport INFO - Sending admin0 credentials to IMAP server.
2014-01-08 09:33:35,091 n.b.c.UserManagement INFO - Accepting token as password for admin0@global.virt in ysnp
2014-01-08 09:33:35,093 n.b.c.s.SyncServlet INFO - handler responded to login/validate in 2ms.
2014-01-08 09:33:35,095 n.b.s.c.CyrusSystemHook INFO - untouchable acl, box: user/formation@domaine.com c: formation@domaine.com a: lrswipkxtea
2014-01-08 09:33:35,095 n.b.s.c.CyrusSystemHook INFO - untouchable acl, box: user/formation@domaine.com c: admin0 a: lrswipkxtea
2014-01-08 09:33:35,098 n.b.n.c.SChNodeClient INFO - Opening stream on /etc/postfix/virtual_mailbox-flat...
2014-01-08 09:33:35,100 n.b.n.c.ScpReader INFO - Streaming virtual_mailbox-flat size: 1497...
2014-01-08 09:33:35,209 n.b.c.s.ContactIndexer INFO - [101] indexed in SOLR
2014-01-08 09:33:35,231 n.b.n.c.SchExecTask INFO - Run cmd /usr/sbin/postmap /etc/postfix/virtual_mailbox-flat
2014-01-08 09:33:44,187 n.b.c.UserManagement INFO - Accepting token as password for formation@domaine.com in bm-hps-ping
2014-01-08 09:33:44,189 n.b.c.s.SyncServlet INFO - handler responded to login/validate in 2ms.
2014-01-08 09:33:58,036 n.b.c.UserManagement INFO - Accepting token as password for formation@domaine.com in bm-hps-ping
2014-01-08 09:33:58,040 n.b.c.s.SyncServlet INFO - handler responded to login/validate in 3ms.
2014-01-08 09:33:59,246 n.b.i.i.ClientSupport INFO - Sending formation@domaine.com credentials to IMAP server.
2014-01-08 09:33:59,248 n.b.c.s.SyncServlet INFO - handler responded to mail/unreadMailCount in 7ms.
2014-01-08 09:33:59,278 n.b.c.s.SyncServlet INFO - handler responded to calendar/doSync in 3ms.
2014-01-08 09:34:00,025 n.b.c.j.i.JobBindingImpl INFO - getJobFromId net.bluemind.core.jobs.cleanup.JobExecutionsCleanJob
2014-01-08 09:34:00,027 n.b.c.j.i.JobHome INFO - Loaded 1 jobs from database.
2014-01-08 09:34:00,031 n.b.c.j.i.JobBindingImpl INFO - getJobFromId Vacation
2014-01-08 09:34:00,032 n.b.c.j.i.JobHome INFO - Loaded 1 jobs from database.
2014-01-08 09:34:00,033 n.b.c.j.i.Scheduler INFO - Finishing net.bluemind.core.jobs.cleanup.JobExecutionsCleanJob-global.virt-1389173640027
2014-01-08 09:34:00,033 n.b.c.j.i.Scheduler INFO - [net.bluemind.core.jobs.cleanup.JobExecutionsCleanJob-global.virt-1389173640027] progress is now 100%.
2014-01-08 09:34:00,033 n.b.c.j.i.ExecutionRecorder INFO - recording execution of net.bluemind.core.jobs.cleanup.JobExecutionsCleanJob-global.virt-1389173640027
2014-01-08 09:34:00,033 n.b.c.j.i.JobHome INFO - recording execution for net.bluemind.core.jobs.cleanup.JobExecutionsCleanJob-global.virt-1389173640027...
2014-01-08 09:34:00,034 n.b.c.j.i.JobHome INFO - run plan for net.bluemind.core.jobs.cleanup.JobExecutionsCleanJob@global.virt updated with last_run set to id 33678 (start: Wed Jan 08 09:34:00 GMT 2014)
2014-01-08 09:34:00,034 n.b.c.j.i.JobHome INFO - saving 7 entries...
2014-01-08 09:34:00,035 n.b.c.j.i.Scheduler INFO - [net.bluemind.core.jobs.cleanup.JobExecutionsCleanJob-global.virt-1389173640027] finished and recorded: SUCCESS, duration: 6ms.
2014-01-08 09:34:00,035 n.b.c.j.i.Scheduler INFO - Finishing net.bluemind.core.jobs.cleanup.JobExecutionsCleanJob-global.virt-1389173640027
2014-01-08 09:34:00,036 n.b.c.j.i.Scheduler INFO - Finishing Vacation-global.virt-1389173640032
2014-01-08 09:34:00,036 n.b.c.j.i.Scheduler INFO - [Vacation-global.virt-1389173640032] progress is now 100%.
2014-01-08 09:34:00,036 n.b.c.j.i.ExecutionRecorder INFO - recording execution of Vacation-global.virt-1389173640032
2014-01-08 09:34:00,036 n.b.c.j.i.JobHome INFO - recording execution for Vacation-global.virt-1389173640032...
2014-01-08 09:34:00,037 n.b.c.j.i.JobHome INFO - run plan for Vacation@global.virt updated with last_run set to id 33679 (start: Wed Jan 08 09:34:00 GMT 2014)
2014-01-08 09:34:00,037 n.b.c.j.i.JobHome INFO - saving 3 entries...
2014-01-08 09:34:00,038 n.b.c.j.i.Scheduler INFO - [Vacation-global.virt-1389173640032] finished and recorded: SUCCESS, duration: 4ms.
2014-01-08 09:34:00,038 n.b.c.j.i.JobBindingImpl INFO - getJobFromId EventAlert
2014-01-08 09:34:00,039 n.b.c.j.i.JobHome INFO - Loaded 1 jobs from database.
2014-01-08 09:34:00,042 n.b.c.j.i.JobBindingImpl INFO - getJobFromId net.bluemind.archive.core.ArchiveJob
2014-01-08 09:34:00,043 n.b.c.j.i.JobHome INFO - Loaded 1 jobs from database.
2014-01-08 09:34:00,043 n.b.c.j.i.JobRunner INFO - net.bluemind.archive.core.ArchiveJob@domaine.com: The fire from the sky still falls (launch date: Wed Jan 08 22:00:00 GMT 2014)
2014-01-08 09:34:00,046 n.b.c.j.i.JobBindingImpl INFO - getJobFromId net.bluemind.dataprotect.core.DataProtectJob
2014-01-08 09:34:00,047 n.b.c.j.i.JobHome INFO - Loaded 1 jobs from database.
2014-01-08 09:34:00,047 n.b.d.c.DataProtectJob INFO - not planned, last run was 1781secs ago.
2014-01-08 09:34:00,047 n.b.d.c.DataProtectJob INFO - less than one day ago, skipping execution.
2014-01-08 09:34:00,050 n.b.c.j.i.JobBindingImpl INFO - getJobFromId ImportLdapJob
2014-01-08 09:34:00,050 n.b.c.j.i.JobHome INFO - Loaded 1 jobs from database.
2014-01-08 09:34:00,051 n.b.c.j.i.JobRunner INFO - ImportLdapJob@domaine.com: The fire from the sky still falls (launch date: Wed Jan 08 09:35:00 GMT 2014)
2014-01-08 09:34:00,053 n.b.c.j.i.JobBindingImpl INFO - getJobFromId net.bluemind.core.jobs.quota.QuotaGatheringJob
2014-01-08 09:34:00,053 n.b.c.j.i.JobHome INFO - Loaded 0 jobs from database.
2014-01-08 09:34:00,054 n.b.c.j.q.QuotaGatheringJob INFO - not forced, last run was 1781secs ago.
2014-01-08 09:34:00,054 n.b.c.j.q.QuotaGatheringJob INFO - less than one day ago, skipping execution.
2014-01-08 09:34:00,185 n.b.c.j.i.Scheduler INFO - Finishing EventAlert-global.virt-1389173640039
2014-01-08 09:34:00,185 n.b.c.j.i.Scheduler INFO - [EventAlert-global.virt-1389173640039] progress is now 100%.
2014-01-08 09:34:03,159 n.b.i.i.ClientSupport INFO - Sending formation@domaine.com credentials to IMAP server.
2014-01-08 09:34:03,161 n.b.c.s.SyncServlet INFO - handler responded to mail/unreadMailCount in 6ms.
2014-01-08 09:34:03,255 n.b.c.s.SyncServlet INFO - handler responded to calendar/doSync in 9ms.
2014-01-08 09:34:06,037 n.b.c.j.i.ExecutionRecorder INFO - recording execution of EventAlert-global.virt-1389173640039
2014-01-08 09:34:06,038 n.b.c.j.i.JobHome INFO - recording execution for EventAlert-global.virt-1389173640039...
2014-01-08 09:34:06,041 n.b.c.j.i.JobHome INFO - run plan for EventAlert@global.virt updated with last_run set to id 33680 (start: Wed Jan 08 09:34:00 GMT 2014)
2014-01-08 09:34:06,042 n.b.c.j.i.JobHome INFO - saving 3 entries...
2014-01-08 09:34:06,046 n.b.c.j.i.Scheduler INFO - [EventAlert-global.virt-1389173640039] finished and recorded: SUCCESS, duration: 146ms.
2014-01-08 09:34:14,203 n.b.c.UserManagement INFO - Accepting token as password for formation@domaine.com in bm-hps-ping
2014-01-08 09:34:14,206 n.b.c.s.SyncServlet INFO - handler responded to login/validate in 3ms.
2014-01-08 09:34:29,296 n.b.c.s.SyncServlet INFO - handler responded to calendar/doSync in 5ms.
2014-01-08 09:34:33,045 n.b.c.UserManagement INFO - Accepting token as password for formation@domaine.com in bm-hps-ping
2014-01-08 09:34:33,047 n.b.c.s.SyncServlet INFO - handler responded to login/validate in 2ms.
2014-01-08 09:34:33,310 n.b.c.s.SyncServlet INFO - handler responded to calendar/doSync in 11ms.
2014-01-08 09:34:34,955 n.b.c.UserManagement INFO - Accepting token as password for admin0@global.virt in bm-hps-ping
2014-01-08 09:34:34,958 n.b.c.s.SyncServlet INFO - handler responded to login/validate in 2ms.
2014-01-08 09:34:35,799 n.b.c.s.SyncServlet INFO - handler responded to user/getUserFromId in 20ms.
2014-01-08 09:34:35,855 n.b.c.s.SyncServlet INFO - handler responded to system/findDomains in 2ms.
6

Y’a-t-il une action qui provoque ce timeout systématiquement ou est-ce aléatoire ?
Il faudrait les logs correspondant à un action lente de votre console d’admin ?

7

Justement c’est les logs lors d’une des actions lentes.

Actions sur lesquels j’ai ce problème :

  • suppression d’un utilisateur
  • partage d’un calendrier
  • retrait de la suspension d’un utilisateur
  • ajout d’un membre dans un groupe

En fait j’ai l’impression que ce sont toutes les actions qui concernent les utilisateurs et les groupes. A savoir que l’annuaire est basé sur un ldap je sais pas si ça influence

8

Est-il possible d’avoir accès en SSH à votre serveur ?

9

yes je rajoute les clés et envoi l’ip en privé