Post-mortem : 3 timeouts MCP — IPAddressDeny + Cloudflare + NFS

Contexte

J’ai mis en production un Hugo MCP Server (FastAPI, 7 tools) qui me permet d’éditer arleo.eu depuis Claude.ai. Architecture : claude.ai → mcp-oauth-proxy NUC → hugo-mcp-proxy NUC → MCP server VM.

Pendant 2 semaines, les appels create_page et update_page timeoutaient régulièrement côté Claude.ai. Pas systématiquement — environ 1 appel sur 3. Difficile à reproduire, plus difficile encore à corréler.

Voici le post-mortem en 3 actes.

Acte 1 — Le faux coupable : OAuth expiry

Symptôme : create_page retourne 401 Unauthorized après ~10 minutes d’inactivité.

Hypothèse initiale : le token OAuth expire et n’est pas refresh.

Investigation : logs mcp-oauth-proxy côté NUC :

2026-05-03 14:23:11 INFO  Token validated for client xxxxx
2026-05-03 14:33:42 INFO  Token validated for client xxxxx
2026-05-03 14:44:18 WARN  Token expired, returning 401

L’expiry est bien réel. Fix : extension de la durée de vie des tokens à 1h, et implémentation du refresh côté mcp-oauth-proxy.

Test : 30 minutes d’inactivité, puis create_page → réponse en 200ms.

Sauf que le timeout original n’était pas une 401, c’était un timeout. Je n’avais pas regardé assez attentivement.

Acte 2 — Le vrai coupable : IPAddressDeny=any

Symptôme persistant : après le fix OAuth, create_page reste lent. Pas un 401, pas un 500. Juste 30 secondes de silence, puis timeout côté Claude.ai.

Hypothèse : le service VM Hugo MCP fait un appel externe (purge Cloudflare cache) qui est bloqué.

Investigation : j’avais durci le service hugo-mcp.service la veille avec IPAddressDeny=any + IPAddressAllow=127.0.0.0/8. Je voulais juste autoriser le loopback.

Le problème : le tool create_page fait requests.post('https://api.cloudflare.com/client/v4/zones/.../purge_cache') à la fin. Cloudflare n’est PAS dans le whitelist. Le syscall connect() ne timeout pas instantanément en mode IPAddressDeny — le kernel drop le paquet silencieusement, et requests attend son timeout par défaut de 30 secondes.

Fix :

[Service]
IPAddressDeny=any
IPAddressAllow=127.0.0.0/8
IPAddressAllow=192.168.122.1/32
IPAddressAllow=104.16.0.0/12
IPAddressAllow=2606:4700::/32

Test : create_page → 800ms.

Sauf que parfois, ça reste lent. Pas systématiquement.

Acte 3 — Le coupable final : timing instrumentation comme révélateur

Symptôme persistant : create_page peut prendre soit 800ms soit 12s, sans pattern visible.

J’ai ajouté de la timing instrumentation dans le MCP : à chaque tool call, je log les durées de chaque sous-opération.

import time

def create_page(...):
    t0 = time.time()
    write_md_file(...)
    t1 = time.time()
    
    subprocess.run(["hugo", "--minify"])
    t2 = time.time()
    
    purge_cloudflare(...)
    t3 = time.time()
    
    log.info(f"create_page write={t1-t0:.0f}ms build={t2-t1:.0f}ms purge={t3-t2:.0f}ms")

Logs après instrumentation :

create_page write=12ms  build=2400ms   purge=380ms
create_page write=14ms  build=2350ms   purge=380ms
create_page write=11ms  build=11800ms  purge=380ms   ← LENT
create_page write=13ms  build=2410ms   purge=380ms

Le coupable n’est pas purge_cloudflare. C’est hugo --minify qui prend parfois 12 secondes au lieu de 2.4s.

Investigation Hugo : Hugo lit tous les fichiers de content/, themes/, static/. Si l’un est sur NFS QNAP et que QNAP fait son backup quotidien à ce moment, les latences NFS explosent.

J’ai vérifié : la VM Hugo monte static/images/ (page bundles) sur NFS QNAP. Quand le QNAP fait sa backup quotidienne (6h du matin chez moi), les stat() sur les fichiers prennent ~500ms chacun au lieu de 1ms. × ~30 fichiers = 12 secondes.

Fix permanent :

1. Migrer static/images/ vers le disque local de la VM (plus de NFS pour Hugo)
2. Ajouter une alerte BetterStack si QNAP NFS dépasse 30 minutes de backup (ce qui indiquerait un vrai problème, pas juste les MAJ quotidiennes)

Résultat : create_page consistant à 800ms ± 100ms.

Lessons learned

1. La timing instrumentation est l’outil de diag numéro un

Sans log.info(timing=...) dans chaque sous-opération, j’aurais cherché des heures dans les logs de Cloudflare et OAuth. Une fois les durées séparées, le coupable est apparu en 30 secondes de lecture de log.

Règle : tout tool MCP qui dépasse 500ms en p99 doit avoir des time.time() autour de chaque sous-opération.

2. IPAddressDeny=any est une arme à double tranchant

Excellent pour la sécu (réduit la surface d’attaque réseau du service), mais piégeux : tout appel externe non whitelist devient un timeout silencieux. Toujours auditer tous les appels externes que le service fait avant d’activer cette directive.

Liste à auditer pour un service Python :

• API externes (Cloudflare, GitHub, AbuseIPDB…)
• DNS lookups (socket.gethostbyname)
• Appels webhooks de monitoring (BetterStack heartbeat)

3. NFS différent de filesystem local pour les outils CLI

Hugo, Git, et la plupart des outils CLI font des stat() répétés. NFS introduit une latence de ~1ms minimum par syscall. C’est invisible en temps normal, catastrophique pendant un backup ou un partage saturé.

Règle : tout ce qui est lu ou écrit pendant une opération critique (build, deploy, hot path) doit être sur disque local. NFS pour les archives, les médias rarement consultés, les backups.

4. La cascade des hypothèses fait perdre du temps

J’ai passé environ 1h sur OAuth (qui était un vrai bug, mais pas LE bug). Puis 2h sur IPAddressDeny (idem). Puis 30min sur NFS.

Si j’avais commencé par instrumenter les durées avant de formuler des hypothèses, le NFS aurait sauté aux yeux dès la première lecture de log.

Règle : avant de chercher la cause, mesurer où le temps est passé. Toujours.

Conclusion

3 bugs distincts, 3 fixes différents. Aucun n’aurait été suffisant seul. Le test de validation finale : 24h de fonctionnement avec create_page consistant à 800ms, indépendamment de l’heure ou de la charge QNAP.

L’instrumentation timing est restée en prod. Elle me sert maintenant pour un dashboard BetterStack qui affiche les p50/p95/p99 par tool. p99 actuel : 1.2s, ce qui inclut le rebuild Hugo. Acceptable pour une édition interactive.