Solr planter sans raison

BlueMind - FR Discussions
1

Bonjour,

Mon serveur vient de ce planter sans raison apparante
J’ai des message d’erreur etrange dans core.log

2013-05-17 12:59:34,686 n.b.c.s.SyncServlet INFO - handler responded to calendar/getPendingEventCount in 1ms.
2013-05-17 12:59:35,794 e.a.b.f.Fail2BanAuthentification INFO - First attempt for i.dumont@anasta.eu
2013-05-17 12:59:35,794 n.b.c.s.a.i.AuthenticationRegistry INFO - Validate password using service eu.anasta.bm.fail2ban.Fail2BanAuthentification: UNKNOWN in 0ms.
2013-05-17 12:59:35,795 n.b.c.s.a.i.AuthenticationRegistry INFO - Validate password using service net.bluemind.core.server.auth.impl.DatabaseAuthenticationService: YES in 1ms.
2013-05-17 12:59:35,796 n.b.c.s.SyncServlet INFO - handler responded to login/validate in 2ms.
2013-05-17 12:59:35,955 e.a.b.f.Fail2BanAuthentification INFO - First attempt for i.dumont@anasta.eu
2013-05-17 12:59:35,955 n.b.c.s.a.i.AuthenticationRegistry INFO - Validate password using service eu.anasta.bm.fail2ban.Fail2BanAuthentification: UNKNOWN in 0ms.
2013-05-17 12:59:35,956 n.b.c.s.a.i.AuthenticationRegistry INFO - Validate password using service net.bluemind.core.server.auth.impl.DatabaseAuthenticationService: YES in 1ms.
2013-05-17 12:59:35,957 n.b.c.s.SyncServlet INFO - handler responded to login/validate in 2ms.
2013-05-17 12:59:36,073 n.b.c.s.SyncServlet INFO - handler responded to calendar/getPendingEventCount in 1ms.
2013-05-17 12:59:36,185 e.a.b.f.Fail2BanAuthentification INFO - First attempt for i.dumont@anasta.eu
2013-05-17 12:59:36,185 n.b.c.s.a.i.AuthenticationRegistry INFO - Validate password using service eu.anasta.bm.fail2ban.Fail2BanAuthentification: UNKNOWN in 1ms.
2013-05-17 12:59:36,185 n.b.c.s.a.i.AuthenticationRegistry INFO - Validate password using service net.bluemind.core.server.auth.impl.DatabaseAuthenticationService: YES in 0ms.
2013-05-17 12:59:36,186 n.b.c.s.SyncServlet INFO - handler responded to login/validate in 1ms.
2013-05-17 12:59:38,115 n.b.c.s.SyncServlet INFO - handler responded to calendar/getPendingEventCount in 1ms.
2013-05-17 12:59:38,216 n.b.c.UserManagement INFO - Accepting token as password for d.thibeaux@anasta.eu in ysnp
2013-05-17 12:59:38,216 n.b.c.s.SyncServlet INFO - handler responded to login/validate in 0ms.
2013-05-17 12:59:38,673 n.b.c.s.SyncServlet INFO - handler responded to calendar/getPendingEventCount in 1ms.
2013-05-17 12:59:40,859 n.b.c.s.SyncServlet INFO - handler responded to calendar/getPendingEventCount in 1ms.
2013-05-17 12:59:42,298 n.b.c.s.EventIndexer ERROR - Internal Server Error

Internal Server Error

request: http://0.0.0.0:8080/solr/event/update/javabin
org.apache.solr.common.SolrException: Internal Server Error

Internal Server Error

request: http://0.0.0.0:8080/solr/event/update/javabin
        at org.apache.solr.client.solrj.impl.CommonsHttpSolrServer.request(CommonsHttpSolrServer.java:432) ~[apache-solr-solrj-3.5.0.jar:3.5.0 1204988 - simon - 2011-11-22 14:54:39]
        at org.apache.solr.client.solrj.impl.CommonsHttpSolrServer.request(CommonsHttpSolrServer.java:246) ~[apache-solr-solrj-3.5.0.jar:3.5.0 1204988 - simon - 2011-11-22 14:54:39]
        at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:105) ~[apache-solr-solrj-3.5.0.jar:3.5.0 1204988 - simon - 2011-11-22 14:54:39]
        at org.apache.solr.client.solrj.SolrServer.commit(SolrServer.java:178) ~[apache-solr-solrj-3.5.0.jar:3.5.0 1204988 - simon - 2011-11-22 14:54:39]
        at org.apache.solr.client.solrj.SolrServer.commit(SolrServer.java:154) ~[apache-solr-solrj-3.5.0.jar:3.5.0 1204988 - simon - 2011-11-22 14:54:39]
        at net.bluemind.core.solr.EventIndexer.doIndex(EventIndexer.java:73) [net.bluemind.core_1.0.0.b8734.jar:na]
        at net.bluemind.core.solr.EventIndexer.run(EventIndexer.java:64) [net.bluemind.core_1.0.0.b8734.jar:na]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441) [na:1.6.0_26]
        at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) [na:1.6.0_26]
        at java.util.concurrent.FutureTask.run(FutureTask.java:138) [na:1.6.0_26]
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [na:1.6.0_26]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [na:1.6.0_26]
        at java.lang.Thread.run(Thread.java:662) [na:1.6.0_26]


2013-05-17 12:59:43,671 n.b.c.s.SyncServlet INFO - handler responded to calendar/getPendingEventCount in 1ms.
2013-05-17 12:59:44,325 n.b.c.s.SyncServlet INFO - handler responded to calendar/getPendingEventCount in 1ms.
2013-05-17 12:59:46,109 n.b.c.UserManagement INFO - Accepting token as password for n.dumont@anasta.eu in bm-hps-ping
2013-05-17 12:59:46,109 n.b.c.s.SyncServlet INFO - handler responded to login/doLogin in 0ms.
2013-05-17 12:59:46,132 n.b.c.s.SyncServlet INFO - handler responded to calendar/getPendingEventCount in 2ms.
2013-05-17 12:59:46,206 n.b.c.UserManagement INFO - Accepting token as password for n.dumont@anasta.eu in ysnp
2013-05-17 12:59:46,206 n.b.c.s.SyncServlet INFO - handler responded to login/validate in 0ms.
2013-05-17 12:59:47,255 n.b.c.s.EventIndexer INFO - [1120] indexed in SOLR
2013-05-17 12:59:47,697 n.b.c.s.EventIndexer INFO - [1250] indexed in SOLR
2013-05-17 12:59:48,319 n.b.c.s.SyncServlet INFO - handler responded to calendar/getPendingEventCount in 1ms.
2013-05-17 12:59:48,803 n.b.c.UserManagement INFO - Accepting token as password for n.laruelle@anasta.eu in bm-hps-ping
2013-05-17 12:59:48,803 n.b.c.s.SyncServlet INFO - handler responded to login/doLogin in 0ms.
2013-05-17 12:59:48,824 n.b.c.s.SyncServlet INFO - handler responded to calendar/getPendingEventCount in 1ms.
2013-05-17 12:59:49,040 n.b.h.m.MailBindingImpl INFO - at.user: mc.verbelen@anasta.eu
...]
2013-05-17 13:01:40,164 n.b.c.s.EventIndexer ERROR - Internal Server Error

Internal Server Error

request: http://0.0.0.0:8080/solr/event/update/javabin?wt=javabin&version=2
org.apache.solr.common.SolrException: Internal Server Error

Internal Server Error

request: http://0.0.0.0:8080/solr/event/update/javabin?wt=javabin&version=2
        at org.apache.solr.client.solrj.impl.CommonsHttpSolrServer.request(CommonsHttpSolrServer.java:432) ~[apache-solr-solrj-3.5.0.jar:3.5.0 1204988 - simon - 2011-11-22 14:54:39]
        at org.apache.solr.client.solrj.impl.CommonsHttpSolrServer.request(CommonsHttpSolrServer.java:246) ~[apache-solr-solrj-3.5.0.jar:3.5.0 1204988 - simon - 2011-11-22 14:54:39]
        at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:105) ~[apache-solr-solrj-3.5.0.jar:3.5.0 1204988 - simon - 2011-11-22 14:54:39]
        at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:121) ~[apache-solr-solrj-3.5.0.jar:3.5.0 1204988 - simon - 2011-11-22 14:54:39]
        at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:106) ~[apache-solr-solrj-3.5.0.jar:3.5.0 1204988 - simon - 2011-11-22 14:54:39]
        at net.bluemind.core.solr.EventIndexer.doIndex(EventIndexer.java:72) [net.bluemind.core_1.0.0.b8734.jar:na]
        at net.bluemind.core.solr.EventIndexer.run(EventIndexer.java:64) [net.bluemind.core_1.0.0.b8734.jar:na]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441) [na:1.6.0_26]
        at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) [na:1.6.0_26]
        at java.util.concurrent.FutureTask.run(FutureTask.java:138) [na:1.6.0_26]
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [na:1.6.0_26]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [na:1.6.0_26]
        at java.lang.Thread.run(Thread.java:662) [na:1.6.0_26]
2013-05-17 13:01:40,164 n.b.c.s.EventIndexer ERROR - Internal Server Error

Internal Server Error

request: http://0.0.0.0:8080/solr/event/update/javabin?wt=javabin&version=2
org.apache.solr.common.SolrException: Internal Server Error

Internal Server Error

request: http://0.0.0.0:8080/solr/event/update/javabin?wt=javabin&version=2
        at org.apache.solr.client.solrj.impl.CommonsHttpSolrServer.request(CommonsHttpSolrServer.java:432) ~[apache-solr-solrj-3.5.0.jar:3.5.0 1204988 - simon - 2011-11-22 14:54:39]
        at org.apache.solr.client.solrj.impl.CommonsHttpSolrServer.request(CommonsHttpSolrServer.java:246) ~[apache-solr-solrj-3.5.0.jar:3.5.0 1204988 - simon - 2011-11-22 14:54:39]
        at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:105) ~[apache-solr-solrj-3.5.0.jar:3.5.0 1204988 - simon - 2011-11-22 14:54:39]
        at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:121) ~[apache-solr-solrj-3.5.0.jar:3.5.0 1204988 - simon - 2011-11-22 14:54:39]
        at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:106) ~[apache-solr-solrj-3.5.0.jar:3.5.0 1204988 - simon - 2011-11-22 14:54:39]
        at net.bluemind.core.solr.EventIndexer.doIndex(EventIndexer.java:72) [net.bluemind.core_1.0.0.b8734.jar:na]
        at net.bluemind.core.solr.EventIndexer.run(EventIndexer.java:64) [net.bluemind.core_1.0.0.b8734.jar:na]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441) [na:1.6.0_26]
        at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) [na:1.6.0_26]
        at java.util.concurrent.FutureTask.run(FutureTask.java:138) [na:1.6.0_26]
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [na:1.6.0_26]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [na:1.6.0_26]
        at java.lang.Thread.run(Thread.java:662) [na:1.6.0_26]
...]

J’ai volontairement remplacer mon IP par 0.0.0.0

2

Ce problème est peut être du a un autre bug que j’ai eu aujourd’hui est expliquer ici: https://forge.blue-mind.net/redmine/issues/4631 avec tout les log.

3

Hi,

Un fichier *.hprof est il présent dans /tmp ?

J’ai lutté avec des problèmes du genre cette semaine et solr est rarement en faute.

Tu a fait pas mal côté code/contributions bluemind. Si tu n’a pas de hprof dans ton /tmp pourrais tu tester un re-index de tes données solr.

Plusieurs façons de faire ça, mais si tu a notre git passer par docs/client-api/samples/scala/reindex.scala est surement la façon la plus simple de le faire.

Tu aptitude install scala
Tu copie tout le répertoire docs/client-api/sample/scala dans ta vm/serveur :
scp -r scala/ root@:
ssh
cd scala
wget http://pkg.blue-mind.net/2/precise/main/bluemind-client-api-8921.zip
unzip bluemind-client-api-8921.zip
./reindex.scala

4

J’ai bien un fichier nommé java_pid1319.hprof dans /tmp.
Ce fichier fait presque 300M.
Es ce que je doit tout de même essayer de re-indexer ? (je suis toujours e version 1.10 pour le moment)

5

Pas forcément besoin de ré-indexer. C’est un dump mémoire automatique qui se produit lors d’un out of memory.

J’analyse ces fichiers avec yourkit (http://yourkit.com). Pourrais tu le compresser et le mettre en ligne quelque part pour que je puisse savoir ce qui a consommé trop de mémoire et voir s’il s’agit d’un bug ?

Pour augmenter la mémoire allouée au tomcat bluemind, tu peux créer un fichier /etc/bm/tomcat_conf.ini avec le contenu suivant :

MEM=512

Ca nous sert à passer un -Xmx plus important à la JVM du tomcat.

6

voila le fichier : http://www.anasta.eu/transfert/hprof.zip

7

Ton OutOfMemory est lié à un problème de synchro calendrier sur un de tes utilisateurs.

Lors du plantage, tu a plusieurs requêtes de synchros d’agenda identiques ce qui est anormal puisque le calendrier n’envoie jamais 2 fois la même chose en temps normal.

Si je prend 2 requêtes faites au tomcat parmis celle qui font 1.2meg (et donc qui consomment bcp de mémoire) :

http://forum.blue-mind.net/screens/forum-388/requests.png

Je regarde les données envoyées et les 2 concernent le même calendrier, avec la même date de dernière synchro.

La première requête :

http://forum.blue-mind.net/screens/forum-388/hashmap_1.png

La seconde :

http://forum.blue-mind.net/screens/forum-388/hashmap_2.png

Autre requête mais calendrier et date de dernière synchro identique.

Dans les 670k de données json qui tentent d’être envoyés au serveur (et qui ne passent pas), les participants aux rendez vous sont :

5 “email”: “c.mulkens@xxx”,
401 “email”: “d.thibeaux@xxx”,
2 “email”: “i.dumont@xxx”,
1 “email”: “jean_micheldaune@xxx”,
21 “email”: “m.dumont@xxx”,
1 “email”: “m.strens@xxx”,
1 “email”: “mc.verbelen@xxx”,
4 “email”: “n.dumont@xxx”,
12 “email”: “n.laruelle@xxx”,
3 “email”: “pj.laborne@xxx”,
1 “email”: “s.kopowitsch@xxx”,
3 “email”: “z.grandjean@xxx”,

(j’ai les données json exactes si ça peut t’aider à comprendre ce qui c’est passé, mais elles contiennent trop d’infos personnelles pour être postées sur le forum)

401 fois, d.thibeaux participe donc je dirai que c’est sa synchro qu’il faudrait regarder. Tu a aussi probablement une stacktrace soit côté core, soit côté bm-java.log qui devrait aider à comprendre pourquoi les données sont refusées par le serveur.

Je trouve aussi étrange que son navigateur envoie autant de données d’un coup en modification. L’utilisateur est peut être repassé “on line” après une assez longue période d’utilisation en mode déconnecté ?

8

Heeeeeuuu … :s
J’avoue que la je suis un peux perdu.
C’est très étrange il n’y a jamais eu de rendez-vous entre ces personne (et pas de raison d’en avoir un). Je vois pas trop ce que je pourrai vérifié de mon coter. sa me semble bien lier au bug 4631 alors … (y a tout les core.log de la journée)
pour bm-java.log : www.anasta.eu/transfert/bm-java.zip

Normalement personne n’utilise le mode déconnecter chez nous et surement pas pour créer 401 événement . l’utilisateur en question n’a que 539 événement dans son calendrier.

9

Ok vu, en fait le problème est côté m.dumont (le calendrier 4) qui envoie en modification au serveur beaucoup d’events, dont 401 appartenant au calendrier 10 (d.thibeaux) sur lequel il n’a pas les droits.

2013-05-17 12:28:00,010 n.b.c.c.CalendarBindingImpl INFO - doSync.update of id 771
2013-05-17 12:28:00,010 n.b.c.c.CalendarBindingImpl INFO -    [SearchAndFill] em: d.thibeaux@xxx t: user id: 10
2013-05-17 12:28:00,018 n.b.c.c.CalendarSanityCheckHome WARN - No domain specified in CalendarInfo
2013-05-17 12:28:00,018 n.b.c.c.CalendarSanityCheckHome INFO - BJR50, check access right: user #4, calendar #10
2013-05-17 12:28:00,079 n.b.c.c.CalendarBindingImpl INFO - [m.dumont] Calendar : m.dumont cannot modify event[ISABELLE  : voir pour THYSSEN] because not owner or no write right on owner d.thibeaux. Only participation will be changed
2013-05-17 12:28:00,079 n.b.c.c.CalendarHome INFO - should modify event with title ISABELLE  : voir pour THYSSEN date: Mon Nov 05 15:00:00 GMT 2012 id: 771 onlyUpdateMyself: true, updateAttendees: true
2013-05-17 12:28:00,118 n.b.c.c.EventChangeImportance INFO - Event modification is minor (BJR 75)
2013-05-17 12:28:00,120 n.b.c.c.CalendarHome INFO - event update will remove all eventException for event 771.
2013-05-17 12:28:00,127 n.b.c.s.SolrHelper INFO - [event 771] scheduled for solr indexing

On cherche, j’ai mis d’autres camarades dans la boucle. Je comprend ton out of memory, mais pourquoi ton javascript envoie tout ça, c’est plus trop mon domaine de compétences.

10

Bonjour,

Un bug ( et créer dans la forge ) à été en effet détecté au niveau de l’application calendrier avec certains navigateurs.
Pourriez-vous m’indiquer le navigateur utilisé par m.dumont ?

Le contournement le plus simple pour le moment est de lui demander de réinitialiser ses données local (via les préférences).

11

Google Chrome.

je n’ai plus eu le problème depuis le restart du serveur (bmctl restart).