etm-powersync-energy-plugin-etm/docs/upstream/RAPPORT_nymea_logger_sigsegv.md

SIGSEGV dans Logger::log — déréférencement d'un journaliseur ABSENT

À remonter à nymea. Rédigé le 2026-08-31, symbolisé et conclu le 2026-09-05. Le vidage est conservé (voir « Pièces »).

L'hypothèse initiale — durée de vie du Logger vis-à-vis des événements postés — est TOMBÉE. Ce n'est pas un usage après libération. C'est un pointeur nul déréférencé, et la garde qui devait l'empêcher interroge un ensemble différent de celui qu'elle protège. Le correctif est d'une ligne.

Conclusion, en une phrase

ThingManagerImplementation::executeAction() connecte une lambda à ThingActionInfo::finished qui écrit un journal d'action via m_actionLoggers.value(clé)->log(...). QHash::value() rend nullptr sur une clé absente, et le résultat est déréférencé sans contrôle. La garde utilisée — thing->loggedActionTypeIds().contains(actionType.id()) — porte sur la liste du Thing, pas sur la table des journaliseurs ; les deux divergent au retrait d'un Thing, et c'est là que ça casse.

Ce qui est ÉTABLI

Symbolisé avec libnymea1-dbgsym et libnymea-core-dbgsym en 1.15.2+202606191336~trixie1 — la version exacte du plantage, identifiants de build vérifiés (libnymea.so.1 : 3696e684…, libnymea-core.so.1 : b50a1ae5…).

trame	résolution
#0 libnymea.so.1 + 0x14ea24	Logger::log(QStringList const&, QVariantMap const&) — libnymea/logging/logger.cpp:55
#1 libnymea-core.so.1 + 0x1edae6	ThingManagerImplementation::executeAction(Action const&)::{lambda()#1}::operator()() const

Et le registre tranche la nature du défaut : rdi = 0x0 au moment du signal. Dans l'ABI SysV AMD64, rdi porte le premier argument, donc this pour une méthode non statique. Logger::log a été appelée sur un pointeur nul. Un usage après libération donnerait une adresse quelconque, pas zéro.

Le corps de Logger::log tient en une instruction — m_engine->logEvent(this, tags, values) — donc la lecture de m_engine à l'offset d'un this nul produit le SIGSEGV.

Le mécanisme

// thingmanagerimplementation.cpp — executeAction()
connect(info, &ThingActionInfo::finished, this, [=](){
    if (thing->loggedActionTypeIds().contains(actionType.id())) {      // ← garde
        ...
        m_actionLoggers.value(thing->id().toString() + "-" + actionType.name())->log({}, {...});
    }                                              // ↑ rend nullptr si la clé est absente
});

void ThingManagerImplementation::unregisterActionLogger(Thing *thing, const ActionTypeId &id) {
    ...
    m_actionLoggers.remove(name);      // la TABLE est vidée
}

Au retrait d'un Thing, la boucle foreach (actionTypeId : thing->loggedActionTypeIds()) unregisterActionLogger(...) vide la table. La liste loggedActionTypeIds() du Thing, elle, n'est pas touchée : c'est une propriété du Thing, pas de la table.

La connexion est établie avec this (le ThingManager) pour contexte, pas avec le Thing ni avec l'info. Un finished déjà posté survit donc au retrait du Thing. Quand la lambda s'exécute :

1. la garde consulte loggedActionTypeIds() → vraie, la liste est intacte ;
2. m_actionLoggers.value(clé) → nullptr, l'entrée a été retirée ;
3. nullptr->log(...) → SIGSEGV.

La garde et la table ne parlent pas du même objet. C'est ce qui rend le défaut invisible à la relecture : le code a une garde, elle a l'air de protéger l'accès qui suit, et elle n'a aucun rapport avec lui.

Pourquoi la reproductibilité est FAIBLE, et pourquoi ce n'est pas rassurant

Observé une fois sur une exécution de suite de tests en tâche de fond ; non reproduit en trois séquences identiques ni en exécution isolée (48/48, code 0). La fenêtre exige qu'une action soit encore en vol au moment où son Thing est retiré — ce qu'un démontage de suite de tests produit naturellement, et qu'une exécution tranquille ne produit presque jamais.

Ce n'est pas limité aux tests. Toute suppression de Thing pendant qu'une action est en cours ouvre la même fenêtre, sur une installation de production. Une action longue — une borne de recharge qui négocie, un appareil Modbus lent — l'élargit.

Correctif proposé

Le minimum, une ligne, sans changement de conception :

Logger *logger = m_actionLoggers.value(thing->id().toString() + "-" + actionType.name());
if (logger)
    logger->log({}, {...});

Mieux, et c'est la vraie leçon : faire porter la garde sur la table qu'on va indexer (m_actionLoggers.contains(clé)) plutôt que sur une liste qui lui ressemble. Les mêmes deux lignes existent pour m_stateLoggers et m_eventLoggers — à vérifier de la même façon.

Le Logger lui-même n'est pas en cause : sa durée de vie est correcte. C'est son ABSENCE de la table qui n'est pas testée.

Environnement

libnymea1 / libnymea-core	1.15.2+202606191336~trixie1
Qt	6.8.2+dfsg-9+deb13u2
Système	Debian 13 (trixie), x86_64
Binaire	suite de tests charging du plugin énergie ETM

Réserve de lecture

La symbolisation vient des symboles 1.15.2, donc les noms et les lignes sont ceux de la version qui a planté. En revanche, le code cité ci-dessus est lu dans l'arbre 1.16.0 (seule source disponible localement). Les deux symboles résolus s'y retrouvent à l'identique, et Logger::log y fait toujours trois lignes — mais la formulation exacte du correctif est à vérifier contre 1.15.2 par quelqu'un qui a la branche.

Pièces

• Vidage : coredumpctl du 2026-08-31 07:06:01 CEST, PID 115071, 2,7 Mio compressés (77 Mio décompressés), conservé.
• Symbolisation reproductible sans installer quoi que ce soit, et sans privilèges :

V=1.15.2+202606191336~trixie1
apt-get download libnymea1-dbgsym=$V libnymea-core-dbgsym=$V
for d in *.deb; do dpkg-deb -x "$d" root/; done
addr2line -f -C -e root/usr/lib/debug/.build-id/36/96e684….debug 0x14ea24   # → Logger::log
addr2line -f -C -e root/usr/lib/debug/.build-id/b5/0a1ae5….debug 0x1edae6   # → la lambda
gdb -batch -q --core=<core> -ex "info all-registers rdi"                    # → rdi = 0x0

gdb ne peut PAS produire de pile complète ici : le binaire de test et le plugin ont été reconstruits depuis le plantage, donc leurs identifiants de build ne correspondent plus au vidage. La résolution par offset dans les bibliothèques, elle, reste valide — leurs identifiants correspondent, et c'est tout ce dont la conclusion a besoin.

Second point, MESURÉ : le coût d'un qCInfo, et une chaîne construite pour rien

Ouvert sur l'hypothèse que la journalisation volerait du temps à la boucle de décision. La mesure ne la soutient pas — et deux prémisses étaient fausses. On le consigne quand même, parce qu'il en reste un défaut réel, petit et chiffré.

Ce qui était faux dans l'hypothèse

1. qCInfo ne passe PAS par le LogEngine. Il va au gestionnaire de messages (nymeaLogMessageHandler), qui écrit sur stdout avec fflush par ligne. Le chemin Logger::log() → LogEngine::logEvent() est celui des états et actions journalisés, déclenché par des changements d'état, pas par les traces de code. Deux chemins, deux coûts.
2. Le LogEngine de la cible ne fait pas d'I/O synchrone. C'est LogEngineInfluxDB : logEvent() empile dans m_writeQueue et QNetworkAccessManager::post() part en asynchrone. Rien n'y bloque le thread appelant. (Le .sqlite cité plus haut est celui du harnais de test.)

Ce qui est mesuré, sur la cible

Banc croisé arm64, lié à libnymea, gestionnaire de nymea installé, stdout sur la socket journald — les conditions de nymead. Raspberry Pi Zero 2 W, 5 000 lignes par essai, trois essais.

condition	coût par ligne
catégorie ACTIVE, stdout → journald	69,4 µs (68,6 / 68,9 / 76,5)
catégorie ACTIVE, stdout → /dev/null	61,9 µs (61,7 / 62,3 / 61,7)
catégorie ÉTEINTE	0,0045 µs

L'I/O n'est pas le coût : 8 µs sur 70. Le reste est du formatage, dans le thread appelant. Et l'extinction de catégorie court-circuite avant tout formatage — c'est gratuit, Qt fait ce qu'il faut.

Rapporté au cycle : la boucle d'arbitrage tourne à 60 s exactement, pour ~30 lignes par cycle (915 lignes sur 30 min relevées au journal). Soit 2,1 ms par cycle de 60 s — 0,0035 %. Pour atteindre 1 % du cycle, il faudrait ~8 600 lignes par cycle, soit 143 lignes par seconde soutenues.

Conclusion : la journalisation ne vole pas de temps à la boucle de décision sur cette cible. Ce n'était pas un argument pour ce rapport, et l'y mettre sans mesurer l'aurait affaibli.

Le défaut qui reste, lui, est réel

nymeaLogMessageHandler construit messageString — dont QDateTime::currentDateTime().toString("yyyy.MM.dd hh:mm:ss.zzz") — pour chaque message, alors que cette chaîne ne sert que si un fichier journal est ouvert :

QMutexLocker locker(&s_loggerMutex);
if (s_logFile.isOpen()) {           // ← seul usage de messageString
    QTextStream textStream(&s_logFile);
    textStream << messageString << '\n';
}

Mesuré isolément sur la même cible : 28,0 µs par appel (31,9 / 27,9 / 27,9), soit 40 % du coût d'une ligne. Et nymead tourne sans fichier journal dans le service livré (ExecStart=/usr/bin/nymead -n, aucun descripteur .log ouvert) : ces 28 µs sont jetés à chaque message, sur toutes les installations en configuration par défaut.

Correctif : ne construire messageString que sous if (s_logFile.isOpen()). Le switch sert déjà à deux fins — écrire sur stdout et fabriquer la chaîne ; seule la seconde est conditionnelle.

Ce n'est pas une urgence : 28 µs × 30 lignes = 0,8 ms par cycle de 60 s. C'est signalé parce que c'est gratuit à corriger et que le coût est payé par tout le monde, tout le temps.

Ce qui est demandé

1. Confirmer le correctif contre la branche 1.15.x, et vérifier les deux tables jumelles (m_stateLoggers, m_eventLoggers).
2. Décider si la connexion doit prendre thing ou info pour contexte plutôt que this — ce qui fermerait la fenêtre au lieu de la rendre inoffensive.
3. Indépendant du plantage : conditionner la construction de messageString à s_logFile.isOpen() dans nymeaLogMessageHandler — 28 µs par message rendus à toute installation sans fichier journal, soit la configuration livrée.