--- title: "Post-mortem : 3 timeouts MCP — IPAddressDeny + Cloudflare + NFS" description: "3 timeouts successifs sur create_page côté Claude.ai : OAuth expiry, IPAddressDeny sans whitelist Cloudflare, NFS QNAP saturaté par les backups. La timing instrumentation comme outil de diag." url: "https://www.arleo.eu/posts/postmortem-mcp-timeouts-cloudflare/" language: "fr" datePublished: "2026-05-09T12:44:44+02:00" dateModified: "2026-05-15T23:51:25+02:00" tags: ["postmortem","mcp","cloudflare","systemd","debug","homelab"] categories: ["post-mortems"] contentSignal: "ai-train=no, search=yes, ai-input=yes" --- # Post-mortem : 3 timeouts MCP — IPAddressDeny + Cloudflare + NFS 3 timeouts successifs sur create_page côté Claude.ai : OAuth expiry, IPAddressDeny sans whitelist Cloudflare, NFS QNAP saturaté par les backups. La timing instrumentation comme outil de diag. ## 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`. {{< mermaid-svg hash="564532ac" >}} 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** : ```ini [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. ```python 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. ## Tags - postmortem - mcp - cloudflare - systemd - debug - homelab ## Categories - post-mortems