Pour cet article, nous allons nous intéresser à un cas peu commun.
Une erreur passée inaperçue pendant plusieurs mois car visée par aucune règle ou moniteur se reproduisait très régulièrement, aléatoirement sur l’un ou l’autre des Management Servers :
Evénement 26319, An exception was thrown while processing GetObjectsFromReader for session ID uuid:2f0f5bab-011d-4002-98d1-4c500cc449a2;id=103303.
Exception message : A transport-level error has occurred when receiving results from the server. (provider TCP Provider, error 0 – The specified network name is no longer available).
La partie “provider TCP Provider, error 0 – The specified network name is no longer available” fait immanquablement penser à une erreur SQL, et le fait que la source de l’événement soit OpsMgr SDK Service est un indice supplémentaire en ce sens.
Une verification dans le journal d’événements Applications du serveur SQL de la base OperationsManager montre qu’effectivement, un événement 7886 est présent pour chaque événement 26319 sur les Management Servers :
A read operation on a large objects failed while sending data to the client. A common cause for this is if the application is running in READ UNCOMMITTED isolation level. This connection will be terminated.
« Une cause courante pour cette erreur est si le niveau d’isolation est READ UNCOMMITED »… Vérifions donc cela dans la base OperationsManager, à l’aide de la commande DBCC USEROPTIONS :
Manifestement, ce n’est pas le cas, elle est bien en committed…
Je me tourne donc vers mon moteur de recherche préféré, qui une fois n’est pas coutume ne m’aide qu’assez peu. Un lien retient cependant mon attention : https://scomblog.wordpress.com/2012/02/29/469/.
La plupart des informations abordées dans cet article n’ont rien à voir avec le cas qui nous intéresse aujourd’hui, mais le dernier point est des plus intéressant (malgré sa syntaxe assez douloureuse) : il nous apprend que cette erreur peut se produire lorsque une lecture d’une alerte dans la base de données survient au même moment que la mise à jour de cette même alerte (cas d’une alerte dont le RepeatCount s’incrémente), ce qui provoque un conflit.
Le cas de figure le plus évident serait donc celui d’une console SCOM ouverte sur une alerte qui s’incrémente très régulièrement lorsqu’un rafraîchissement de la console survient au moment de la mise à jour de l’alerte en base. En plus, cet environnement a effectivement quelques alertes dont le RepeatCount est élevé (plusieurs dizaines de milliers).
Sauf qu’après une petite enquête auprès des utilisateurs, aucun ne semble avoir de problème récurrent avec la console (popup d’erreur, déconnexions…) qui devraient pourtant se produire lorsque l’incident survient.
Pour en avoir le cœur net, une trace SQL est prise avec l’aide du support Microsoft. Elle révèle que les requêtes qui provoquent le problème sont toutes semblables à ceci :
Cette requête récupère les détails d’une alerte (source, description etc) ; elle est donc parfaitement légitime et il est normal d’en rencontrer un grand nombre. Elle cadre d’ailleurs avec l’explication préalablement analysée.
Un détail attire cependant mon attention : ici, la requête est effectuée pour TOUTES les alertes présentes dans l’environnement, puisque la variable @Id0, supposée contenir l’ID de l’alerte à récupérer, contient ici le caractère %, autrement dit le « joker » du langage SQL !
Il s’agit donc d’une requête particulièrement lourde, et qui n’a pas réellement de raison d’être effectuée par une utilisation normale de la console.
Peut-être est-il alors possible de retrouver par quel compte utilisateur cette requête est déclenchée ? Cela nous aiderait à comprendre comment elle survient…
Revenons donc à notre événement sur le Management Server SCOM. Ce n’est pas très lisible, mais il nous indique quelle session a rencontré le problème via l’information id=. Il s’agit donc ici de la session 103303.
En descendant un peu dans le journal d’événement, il doit normalement exister un événement 26328 qui correspond à la création de cette session et qui contient le compte l’ayant créé :
Voilà qui est intéressant ! Dans cet environnement, tous les utilisateurs se connectent avec leur compte nominal personnel. Le compte « SCOM2012_admin » n’est utilisé que pour l’exécution de scripts qui font appel à SCOM.
Il n’y a ici pas de moyen technique permettant de savoir quel est ce script ni à partir d’où il est exécuté, mais une bonne connaissance de l’environnement m’a permis d’avoir des soupçons sur un script en particulier qui s’exécutait très régulièrement et effectuait des traitements sur les alertes.
Une analyse du script a révélé qu’il exécutait le cmdlet Get-SCOMAlert | Where {blabla}, c’est-à-dire qu’il récupérait l’intégralité des alertes avec toutes leurs propriétés puis les filtrait à l’aide de la clause Where ; ce qui correspond parfaitement à ce qu’indiquait la trace SQL : nous tenons manifestement notre coupable !
Et la correction est en plus assez simple : il suffit de réaliser le filtrage dans la requête, ce qui a pour conséquence de l’alléger considérablement, en modifiant le cmdlet de la sorte : Get-SCOMAlert –Criteria {blablabla}.
Suite à cette modification, l’événement ne s’est plus reproduit et, pour ne rien gâcher, le serveur qui exécutait le script a vu son occupation CPU et RAM diminuer fortement :)