Fix: Increase anchor API timeout and improve error handling

**Motivations:**
- Anchor API requests were timing out with "This operation was aborted" errors
- Multiple simultaneous anchor requests can wait for mutex, causing delays
- Slow Bitcoin RPC calls can exceed the 120s timeout

**Root causes:**
- Timeout of 120s was too short when multiple anchors are in progress (mutex wait)
- Slow Bitcoin RPC operations (listunspent, createrawtransaction, sign, send) can take longer than 120s
- Insufficient logging made it difficult to diagnose timeout vs connection closure

**Correctifs:**
- Increased ANCHOR_API_TIMEOUT_MS from 120000 (120s) to 180000 (180s) to handle mutex waits and slow RPC calls
- Added start time tracking to measure elapsed time for all operations
- Enhanced logging with:
  - Log at request start with url, documentUid, hash (truncated), timeoutMs
  - Log on success with txid and elapsedMs
  - Log on abort with elapsedMs, timeoutMs, errorName, errorCode
  - Log on failure with elapsedMs, errorName, errorCode
- Improved error message to include elapsed time: "timeout or connection closed after Xs"
- Added timeout-specific log when timeout is reached (before abort)

**Evolutions:**
- Better observability with elapsed time in all logs
- More detailed error information (errorName, errorCode) for diagnosis
- Timeout log helps distinguish timeout from early connection closure

**Pages affectées:**
- api-filigrane/src/routes/watermark.js: Increased timeout, added timing and enhanced logging
- fixKnowledge/api-filigrane-anchor-request-aborted.md: Updated documentation with new timeout (180s), improved logging details, and mutex wait explanation
This commit is contained in:
ncantu 2026-01-28 11:29:58 +01:00
parent 9291eab9d5
commit 37446c8483
2 changed files with 180 additions and 9 deletions

View File

@ -12,10 +12,16 @@ import { scanBuffer } from '../clamav.js';
export const watermarkRouter = express.Router();
/** Timeout pour l'appel à l'API d'ancrage (ms). L'ancrage Bitcoin peut prendre du temps (RPC, broadcast, mutex). */
const ANCHOR_API_TIMEOUT_MS = 180000; // 3 minutes (augmenté de 120s à 180s pour gérer les cas de mutex et RPC lents)
/**
* Fonction utilitaire pour appeler l'API d'ancrage
* Utilise un AbortController pour timeout explicite ; sans quoi un proxy peut fermer la connexion et lever "This operation was aborted".
*/
async function callAnchorAPI(hash, apiKey, documentUid) {
const startTime = Date.now();
// Toujours utiliser l'URL publique HTTPS, même en interne
let anchorApiUrl = process.env.ANCHOR_API_URL;
@ -43,18 +49,84 @@ async function callAnchorAPI(hash, apiKey, documentUid) {
body.documentUid = documentUid;
}
logger.info('Starting anchor API request', {
url,
documentUid: documentUid ?? null,
hash: hash.substring(0, 16) + '...',
timeoutMs: ANCHOR_API_TIMEOUT_MS,
});
const controller = new AbortController();
const timeoutId = setTimeout(() => {
const elapsed = Date.now() - startTime;
logger.error('Anchor API request timeout reached', {
url,
documentUid: documentUid ?? null,
elapsedMs: elapsed,
timeoutMs: ANCHOR_API_TIMEOUT_MS,
});
controller.abort();
}, ANCHOR_API_TIMEOUT_MS);
try {
const response = await fetch(url, {
method: 'POST',
headers,
body: JSON.stringify(body),
signal: controller.signal,
});
clearTimeout(timeoutId);
const elapsed = Date.now() - startTime;
if (!response.ok) {
const error = await response.json();
throw new Error(error.message || error.error || 'Failed to anchor document');
const errorBody = await response.json().catch(() => ({}));
const message = errorBody.message ?? errorBody.error ?? 'Failed to anchor document';
logger.error('Anchor API returned error status', {
status: response.status,
message,
documentUid: documentUid ?? null,
elapsedMs: elapsed,
});
throw new Error(message);
}
return await response.json();
const result = await response.json();
logger.info('Anchor API request succeeded', {
url,
documentUid: documentUid ?? null,
txid: result.txid ?? null,
elapsedMs: elapsed,
});
return result;
} catch (err) {
clearTimeout(timeoutId);
const elapsed = Date.now() - startTime;
const isAborted = err.name === 'AbortError' || (err.message && err.message.includes('aborted'));
if (isAborted) {
logger.error('Anchor API request aborted (timeout or connection closed)', {
url,
documentUid: documentUid ?? null,
message: err.message,
elapsedMs: elapsed,
timeoutMs: ANCHOR_API_TIMEOUT_MS,
errorName: err.name,
errorCode: err.code,
});
throw new Error(
`Anchor API request aborted: timeout or connection closed after ${Math.round(elapsed / 1000)}s. Check anchorage availability and proxy read timeout (e.g. ${Math.round(ANCHOR_API_TIMEOUT_MS / 1000)}s).`
);
}
logger.error('Anchor API request failed', {
url,
documentUid: documentUid ?? null,
message: err.message,
elapsedMs: elapsed,
errorName: err.name,
errorCode: err.code,
});
throw err;
}
}
/**

View File

@ -0,0 +1,99 @@
# Fix: Anchor API request failed (BLOQUANT) "This operation was aborted"
**Auteur** : Équipe 4NK
**Date** : 2026-01-28
**Version** : 1.0
## Problème identifié
Lors du traitement de documents (filigrane + ancrage), lappel à lAPI dancrage échoue avec une erreur de type :
- `Anchor API request failed (BLOQUANT): This operation was aborted.`
- `[FileProcessingService] ÉCHEC ANCRAGE BITCOIN pour document <uuid>`
- Le document nest pas créé car lancrage est bloquant.
### Symptômes
- Erreur systématique ou intermittente sur lancrage.
- Message natif : `This operation was aborted` (DOMException lorsque la requête HTTP est interrompue).
- Les messages « FileProcessingService », « Anchor API request failed (BLOQUANT) », « ÉCHEC ANCRAGE BITCOIN » sont émis par le client (frontend ou service appelant la chaîne filigrane → ancrage), pas par ce dépôt.
## Cause racine
La requête HTTP envoyée par **api-filigrane** vers lAPI dancrage (`https://anchorage.certificator.4nkweb.com/api/anchor/document`) est **interrompue** avant davoir reçu une réponse. Causes possibles :
1. **Timeout côté proxy (nginx / reverse proxy)**
Si `proxy_read_timeout` (ou équivalent) est trop court, le proxy ferme la connexion pendant que lancrage est encore en cours (RPC Bitcoin, construction tx, broadcast). La fermeture de la connexion provoque labort du `fetch()` côté api-filigrane → « This operation was aborted ».
2. **Absence de timeout explicite côté api-filigrane**
Le `fetch()` vers lAPI dancrage navait ni `AbortSignal` ni timeout. En cas de fermeture de connexion (proxy, réseau, serveur anchorage), Node renvoie une erreur dabort sans message explicite sur la cause (timeout proxy vs indisponibilité anchorage).
3. **Durée réelle de lancrage**
`api-anchorage` exécute : lecture DB UTXOs, mutex, RPC bitcoind (listunspent, createrawtransaction, sign, send). Sous charge ou latence RPC, la réponse peut dépasser 3060 s, ce qui dépasse souvent les timeouts proxy par défaut.
4. **Attente du mutex**
Si plusieurs ancrages sont en cours simultanément, les requêtes doivent attendre le mutex pour accéder aux UTXOs. Cette attente peut faire dépasser le timeout de 120s, surtout si les opérations RPC Bitcoin sont lentes.
## Correctifs appliqués
### 1. Timeout et gestion derreur dans api-filigrane (`callAnchorAPI`)
**Fichier** : `api-filigrane/src/routes/watermark.js`
- **Timeout explicite** : `AbortController` avec un timeout de 120 s (`ANCHOR_API_TIMEOUT_MS = 120000`) pour lappel à lAPI dancrage. Évite dattendre indéfiniment et permet de distinguer un vrai timeout dune simple fermeture de connexion.
- **Gestion des aborts** :
Si lerreur est de type abort (`AbortError` ou message contenant « aborted »), on log et on relance une erreur explicite :
`Anchor API request aborted: timeout or connection closed. Check anchorage availability and proxy read timeout (e.g. 120s).`
- **Logs** :
En cas dabort ou déchec, log avec `url`, `documentUid` et `message` pour le diagnostic (disponibilité anchorage, timeouts proxy).
### 2. Recommandation infrastructure (proxy)
Pour que lancrage ne soit pas coupé par le proxy :
- **Nginx** (ou équivalent) devant `api-anchorage` :
`proxy_read_timeout` et `proxy_connect_timeout` ≥ 180 s pour les routes dancrage (au minimum `POST /api/anchor/document`). Le timeout nginx doit être supérieur ou égal au timeout côté api-filigrane (180s).
- Exemple (à adapter au bloc `location` concerné) :
```nginx
proxy_read_timeout 180s;
proxy_connect_timeout 75s;
proxy_send_timeout 180s;
```
## Modifications
**Fichiers modifiés**
- `api-filigrane/src/routes/watermark.js` :
- Constante `ANCHOR_API_TIMEOUT_MS` augmentée de 120000 (120s) à 180000 (180s)
- `AbortController` + timeout sur le `fetch`
- Gestion des aborts avec temps écoulé dans le message d'erreur
- Logs améliorés avec temps de début, temps écoulé, détails d'erreur (`errorName`, `errorCode`)
- Log au début de la requête, en cas de succès, d'abort et d'échec
**Fichiers créés**
- `fixKnowledge/api-filigrane-anchor-request-aborted.md` : cette documentation.
## Modalités de déploiement
1. **Déployer la nouvelle version de api-filigrane** (contenant le timeout 180 s et la gestion derreur améliorée).
2. **Vérifier / ajuster le reverse proxy** devant api-anchorage :
- Timeouts ≥ 180 s pour les requêtes vers lAPI dancrage (le timeout nginx doit être supérieur ou égal au timeout côté api-filigrane).
3. **Redémarrer api-filigrane** après déploiement.
4. **Tester** : soumettre un document (filigrane + ancrage) et vérifier les logs api-filigrane en cas déchec (message « Anchor API request aborted » ou « Anchor API request failed » avec url/documentUid/elapsedMs).
## Modalités danalyse
- **Logs api-filigrane** :
Rechercher `Anchor API request aborted` ou `Anchor API request failed` avec lURL, le `documentUid` et le `elapsedMs` pour savoir si léchec est lié au timeout 180s ou à une fermeture de connexion avant (proxy, réseau). Le `elapsedMs` indique le temps écoulé avant labort, ce qui permet de distinguer un timeout (≈180s) dune fermeture de connexion précoce.
- **Logs api-anchorage** :
Vérifier que les requêtes `POST /api/anchor/document` arrivent bien et si elles sont longues (RPC, mutex). Si les requêtes napparaissent pas ou sont coupées après X secondes, augmenter les timeouts proxy. Vérifier aussi les logs de mutex pour voir sil y a des attentes longues.
- **Logs proxy (nginx)** :
En cas de fermeture de connexion côté proxy, les logs nginx (erreur, timeout) indiquent si la coupure vient du proxy. Vérifier que `proxy_read_timeout` est ≥ 180s.
## Références
- Message derreur utilisateur : `Anchor API request failed (BLOQUANT): This operation was aborted.`
- Erreur native : `DOMException` / « This operation was aborted » lorsque `fetch()` est interrompu (connexion fermée ou `AbortController.abort()`).
- Documentation existante : `fixKnowledge/api-anchorage-401-error.md`, `fixKnowledge/api-anchorage-too-long-mempool-chain.md`.