computer bug Rhodidiou ! Ca y est, je suis de mauvaise humeur... Alors que je commençais tout juste à me dire que Java ca pouvais être pas mal de temps en temps, voilà que je perd deux heures sur un problème à la con !

Je m'explique.

Aujourd'hui, mon serveur Alfresco arrive en production. Jolie petite machine sous Debian avec Tomcat dessus et tout et tout. Il démarre, le gars dans le datacenter m'annonce fébrilement qu'il a branché le cable, je test et hop je vois ma page s'ouvrir. La magie du moment m'émeut, alors empli de confiance je tente la page de login d'alfresco share. Et là, tout s'enchaine !

Java a la particularité de savoir vous insulter longuement et goulument dans un langage que vous ne comprendrez de toute façon jamais. Genre "j'ai pas pu ouvrir le fichier alors je te fait un dump complet des tes 4 GO de mémoires dans syslog". Sympa, mais pas pour le diagnostic. Alors tout bon sysadmin qui a déjà eu affaire à java sais qu'une trace de jvm c'est encore plus désagréable à contempler qu'un tableau de Joan Mitchell...

Celle qui m'agressait cette après-midi s'appelait, de son petit nom :

15:07:05,510 INFO  [org.alfresco.config.JndiPropertiesFactoryBean] Loading properties file from class path resource [alf
resco/repository.properties]                                                                                            
15:07:05,514 INFO  [org.alfresco.config.JndiPropertiesFactoryBean] Loading properties file from class path resource [alf
resco/domain/transaction.properties]                                                                                    
15:07:05,514 INFO  [org.alfresco.config.JndiPropertiesFactoryBean] Loading properties file from URL [file:/var/lib/tomca
t6/shared/classes/alfresco-global.properties]                                                                           
15:07:06,309 INFO  [org.alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resou
rce [alfresco/alfresco-shared.properties]                                                                               
15:07:10,794 WARN  [org.hibernate.cfg.SettingsFactory] Could not obtain connection metadata                             
org.apache.commons.dbcp.SQLNestedException: Cannot create PoolableConnectionFactory (Communications link failure        
                                                                                                                        
The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the
 server.)                                                                                                               
        at org.apache.commons.dbcp.BasicDataSource.createDataSource(BasicDataSource.java:1225)                          
        at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880)                              
        at org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.getConnection(LocalDataSourceConnectionP
rovider.java:81)                                                                                                        
        at org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:84)                                     
        at org.hibernate.cfg.Configuration.buildSettings(Configuration.java:2073)                                       
        at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:1298)                                 
        at org.springframework.orm.hibernate3.LocalSessionFactoryBean.newSessionFactory(LocalSessionFactoryBean.java:805
)                                                                                                                       
        at org.springframework.orm.hibernate3.LocalSessionFactoryBean.buildSessionFactory(LocalSessionFactoryBean.java:7
45)                                                                                                                     
        at org.springframework.orm.hibernate3.AbstractSessionFactoryBean.afterPropertiesSet(AbstractSessionFactoryBean.j
ava:134)                                                                                                                
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowi
reCapableBeanFactory.java:1203)                                                                                         
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireC
apableBeanFactory.java:1172)                                                                                            
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapab
leBeanFactory.java:427)                                                                                                 
        at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:249)      
        at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegis
try.java:155)                                                                                                           
        at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:246)          
        at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:160)          
        at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveReference(BeanDefinitionValueRes
olver.java:267)

et ça continue pendant des kilomètres... Faut savoir que, là dedans, ya une seule info intéressante, c'est ça :

Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

Bon... Donc Tomcat se ramasse en douze façon Nikolay Davydenko en quart de finale d'un tournoi du grand Chelem. Reste à savoir pourquoi. Mon serveur tomcat est bien lancé, netstat -taupen|grep mysql me le montre bien en LISTEN sur 127.0.0.1.. donc j'en fait quoi moi, de ma tartine ?

Reste les grands moyen, obligé d'installé un tcpdump sur un serveur de prod tout propre... m'enfin bon, c'est ça ou l'aller-retour sur l'A86. Alors je branche mon port en écoute façon

tcpdump -w trace_tomcat_mysql.pcap -s 16436 -Svni lo tcp and port 3306

Et voilà qu'il me retourne le truc suivant :

wireshark tomcat

Faut cliquer sur l'image, sinon vous allez vous faire mal aux yeux. Bref, ce qu'il me dit mon wireshark, c'est que le Tomcat il essai de se connecter au Mysql en IPv6... Pourquoi il fait ça ? J'en sais rien... Est-ce qu'il le faisait déjà avant et que c'est coté MySQL que quelque chose à changé ? J'en sais rien. Ce qui est sur, c'est que MySQL ne bind pas son port en IPv6. Donc ça peut pas marcher...

2 heures de galères....

Ouaip, deux heures, ca explique le coté un peu nerveux du billet. Entre les redémarrages de tomcat en changeant les paramètres, les tentatives de modification du port coté MySQL, j'ai même pensé à un problème de security policy de Debian... niveau noeud aux cerveaux, on fait pas mieux.

Alors je vous fait pas attendre plus longtemps, le problème c'est apparemment une mise à jour de cette $%*££ù* de JVM qui fait privilégie maintenant les requêtes en IPv6 sur IPv4. Me demandez pas quel est l'@&%ù** qui a décidé ça sans prévenir personne, mais dans le genre belle bêtise, elle est pas mal.

Bref, ça se corrige en rajoutant le paramètre suivant dans les JAVA_OPTS du fichier /etc/default/tomcat6:

-Djava.net.preferIPv4Stack=true

Redémarrage fébrile du Tomcat.

Le regard figé sur mon tail -f /var/log/tomcat6/alfresco.log

Pas de message bizarre, cela marcherait-il ?

YES ! La page de login !!!!

Voilà, c'était 3615 mylife dans la catégorie mésaventures de sysadmin.