En tant que développeur, nous sommes parfois confrontés à de « drôles de bugs », pas vraiment critiques mais difficilement explicables, souvent induits par la complexité d’un système qui doit gérer des systèmes hétérogènes et de très multiples cas de figure. Voici l’histoire un peu longue d’un problème bénin qui fut une sorte de « fil rouge » pendant les derniers mois, jusqu’à que l’on puisse enfin récemment mettre le doigt sur sa cause.
Chez plusieurs clients, la ligne suivante réapparaissait à plusieurs reprises dans le journal des défaillances système, de manière assez aléatoire et uniquement sur certaines sauvegardes :
Backup write error for backup #XXX : cannot delete file #YYYYY created inside the same transaction.
Ce message correspond à une situation qui ne devrait jamais survenir au moment de la validation d’une sauvegarde : la demande de suppression d’un fichier venant d’être créé au sein de la même opération. Il n’y a aucune raison qu’un fichier venant d’être sauvegardé soit immédiatement détruit avant même que la modification de la sauvegarde soit validée… sinon l’envoi du fichier serait purement et simplement inutile ! Un peu comme si le facteur venait sonner chez vous pour vous livrer un colis, puis le reprenait sous son bras en partant…
Une telle erreur n’est pas critique puisque dans ce cas UltraBackup annule la suppression des fichiers ajoutés et les conserve dans sa base de données. Néanmoins, il est toujours extrêmement dérangeant de constater qu’une situation improbable sur le papier peut, ne serait-ce qu’une seule fois, se produire en production. En tant que développeur, je trouve que cela affecte directement le « capital de confiance » associé à notre code – comme si telle une créature autonome il décidait de reconquérir sa liberté et d’agir sciemment contre son cahier des charges. Une sensation suffisamment désagréable pour motiver sérieusement la recherche de la cause d’un tel comportement !
Première stratégie : incriminer l’agent client et vérifier que cette suppression ne serait pas réalisée à sa demande, pour des raisons qu’il jugerait légitime. Ce dernier étant pleinement multi-threadé, deux fils d’exécution auraient en théorie pu entrer en conflit décisionnel sur le sort d’un même fichier, et envoyer au serveur des ordres contradictoires. Cette solution a vite été exclue, d’une part car les threads utilisent des systèmes de synchronisation pour coordonner leur travail, d’autre par car nous avons pu déterminer que toutes les requêtes de suppression envoyées au serveur étaient pleinement cohérentes et concernaient des fichiers réellement effacés du disque du client.
Seconde stratégie : chercher côté serveur ce qui pourrait provoquer un tel comportement. Nous avons soigneusement passé en revue les requêtes SQL exécutées lors de la validation des sauvegardes pour vérifier qu’elles ne comportaient pas d’erreurs susceptibles de produire un tel dysfonctionnement, sans succès. Nous avons donc fini par mettre de côté ce bug en attendant une idée ou une intuition qui pourrait nous guider vers une nouvelle piste.
Alors que je venais de trouver une nouvelle fois ce message dans la console d’administration d’un client, j’ai par hasard consulté l’historique des modifications apportées à la sauvegarde mentionnée par le texte d’erreur et constaté avec stupeur que la console affichait une date de dernière exécution antérieure à la précédente date d’exécution. Comme si la dernière date d’exécution était enregistrée le « 1 er Juin à 20h 40 », et l’avant dernière date d’exécution le « 1er Juin à 22h 40 » ! Puisque jusqu’à preuve du contraire le temps ne recule pas, on se trouvait bien dans une situation où les règles de suppression des anciennes versions pouvaient conduire à supprimer indûment des fichiers vus comme obsolètes alors qu’ils venaient d’être ajoutés sur le serveur.
Mais pourquoi UltraBackup utilisait-t-il la date du poste client, même si elle n’était pas valide ? En fait, la réponse tient à des raisons historiques. Depuis la première version d’UltraBackup, la base de données gérait deux référentiels de date : le référentiel client et le référentiel serveur. De nombreuses dates d’exécution étaient dupliquées, et chacun des champs stockait respectivement la date GMT vue du serveur (horloge serveur) et vue du poste client (horloge cliente). Cela permettait de gérer de manière transparente les cas où l’horloge d’un poste client était par erreur décalée de quelques minutes ou de quelques heures par rapport au serveur de sauvegarde. Toutes les dates d’exécution affichées dans son gestionnaire de sauvegarde restaient cohérentes avec son heure système, quel que soit son éventuel décalage avec l’heure serveur. Et si l’utilisateur voulait restaurer sa sauvegarde à une heure donnée, les fichiers obtenus seraient précisément ceux sauvegardés à la date choisie par le client, en tenant compte de l’erreur de date de son poste. Implication immédiate : les opérations de suppression des anciennes versions étaient réalisées dans le contexte du référentiel client, en supposant que le décalage d’horloge entre le client et le serveur soit à peu près constant et que la première ne puisse pas revenir dans le passé.
Mais évidemment, ce qui n’est pas explicitement interdit peut arriver, et arrive. Et fait réfléchir sur l’idée de conserver un tel système, alors que la très grande majorité des postes sous Windows utilisent un serveur de temps Internet et sont automatiquement synchronisés, rendant peu probable un décalage d’horloge significatif entre le client et le serveur. Par conséquent, nous avons décidé de supprimer ce double référentiel dans la version 5 puisqu’il était plus susceptible de complexifier le traitement des informations et d’introduire des erreurs que de gérer une situation peu fréquente et dans tous les cas anormale.
Désormais, on considère le serveur comme la seule entité sûre : c’est son horloge qui est systématiquement utilisée lorsque des dates d’exécution doivent être enregistrées dans la base de données. Une nouvelle alerte a été créée et est automatiquement activée pour les nouveaux utilisateurs créés avec la version 5 : l’alerte de désynchronisation de l’horloge cliente :
Cette alerte est déclenchée lorsque l’heure GMT du poste client diffère d’un certain nombre de minutes avec l’heure GMT serveur. Cette durée peut être configurée dans le fichier de configuration serveur et est initialisée par défaut à 15 minutes :
MaxUsersSysClockTimeShift=15
Lorsque celle-ci est déclenchée, mieux vaut passer sur le poste client réinitialiser la date et l’heure à une valeur correcte… Reste à déterminer pourquoi sur les quelques postes qui généraient l’erreur l’horloge système pouvait retourner dans le passé, mais ça, c’est une autre histoire !