# FIX 2026-08-31 — El cron horario WAV→MP3 truncaba las grabaciones de las llamadas en curso **Fecha**: 2026-08-31 **Reporte**: 30-08, revisando las grabaciones de una llamante (caso Briseida, tarotista CAMILA 375) David detecta grabaciones cortadas. Ejemplo: uniqueid `1788080316.5620787`, llamada de 10:58:36 a 11:16:19 (CEL, 1063 s; CDR 172 s + 890 s) y el MP3 dura **139 s**: se corta justo a las 11:00:55, la hora a la que el cron lo convirtió. **Estado**: RESUELTO (fix aplicado 13:41) y verificado en producción con el ciclo real de las 14:00 (5 WAV en uso omitidos, 0 grabaciones truncadas) y de las 15:00 (ver "Pruebas"). --- ## Alcance real: no eran 7 llamadas, eran ~90 al día Comparando la duración de cada fichero (ffprobe/soxi) con el intervalo CHAN_START→CHAN_END del CEL de su uniqueid, para todos los ficheros > 100 KB del directorio de grabaciones: | Ventana (mtime del fichero) | Ficheros | Truncados (> 15 s de menos) | Con > 5 min perdidos | |----------------------------------|---------:|----------------------------:|---------------------:| | 30-08 (día del reporte) | 708 | **90** (todos con mtime en el minuto :00–:02 → cron) | 64 | | 31-08 00:00 → 13:41 (pre-fix) | 437 | **46** (todos en :00–:02) | 30 | | 31-08 desde 13:41 (post-fix) | 42 | **0** | 0 | Peores casos del 30-08: `1788123595.5634599` 114 s de 5401; `1788119494.5632522` 592 s de 3703; `1788108606.5628530` 665 s de 3727. El cron existe desde el "FIX 2026-01-21" (comentario del crontab), así que **toda llamada que estuviera en curso a una hora en punto desde enero ha perdido el resto de su grabación**. Lo perdido no se puede recuperar (ver "Causa raíz"). Nota metodológica: una diferencia de −4…−9 s en llamadas cortas es normal y NO es truncado: el handler `h` ([cuelgue]) hace `StopMixMonitor()` y luego ejecuta el AGI (~4 s) antes de que salga CHAN_END; además los ficheros salen ~1,5 % más largos que el intervalo CEL (reloj de MixMonitor). Por eso el umbral útil es 15 s. ## Causa raíz (dos bugs en el mismo script) Script: `/usr/local/bin/convert-pending-wavs.sh`, crontab de root `0 * * * *` (log `/var/log/asterisk/wav_conversion_cron.log`), y duplicado a las 04:00 en `/etc/cron.d/asterisk-wav-maintenance`. 1. **Convertía y borraba WAV abiertos.** Recorría TODOS los `*.wav` de `/mnt/volume_fra1_01/asterisk-spool/monitor/`, los pasaba por ffmpeg y hacía `rm` del WAV. MixMonitor mantiene el WAV abierto y escribiendo durante toda la llamada: ffmpeg lee lo grabado hasta ese instante (MP3 truncado) y el `rm` desenlaza el fichero → MixMonitor sigue escribiendo en un inodo sin nombre y el resto del audio desaparece al colgar. Evidencia: `[2026-08-30 11:00:55] Convertido y eliminado: .../1788080316.5620787.wav → ....mp3 (2.2MiB → 458KiB)` con CHAN_END del canal a las 11:16:19. 2,2 MiB de WAV slin 8 kHz/16 bit = 139 s, lo que dura el MP3. 2. **ffmpeg se comía el stdin del bucle** (bug preexistente). El bucle es `while read -d '' wav_file; do ... done < <(find ... -print0)`; ffmpeg sin `/dev/null || date +%s) + if fuser -s "$wav_file" 2>/dev/null || [ $(( $(date +%s) - wav_mtime )) -lt 180 ]; then + log_message "OMITIDO (en uso): $wav_file" + ((OMITIDOS++)) + continue + fi + # Obtener tamaño del WAV @@ -79,7 +96,9 @@ - if /usr/bin/ffmpeg -y -i "$wav_file" -codec:a libmp3lame -qscale:a 2 "$mp3_file" > /dev/null 2>&1; then + # FIX 2026-08-31b: /dev/null 2>&1; then @@ -126,6 +145,7 @@ log_message "Errores: $ERRORS" +log_message "Omitidos (en uso): $OMITIDOS" ``` Un WAV omitido no se pierde: cuando la llamada cuelga lo convierte el camino de cuelgue (`hangup_processor.py` → `convert_all_to_mp3.sh `) o, si ese no salta, el siguiente ciclo horario (ya cerrado y con mtime > 3 min). `fuser` en el entorno del cron: el crontab de root no fija `PATH` → cron usa `/usr/bin:/bin`, y `fuser` está en `/usr/bin/fuser` (= `/bin/fuser`). Los dos criterios han saltado de verdad en el ciclo de las 14:00: `1788174301.5646510.wav` estaba abierto (fuser) y `1788176071.5646894.wav` se había cerrado 15 s antes (mtime < 180 s). ## Pruebas **13:41, ejecución manual** tras aplicar el parche (con `test_abierto_20260831.wav` mantenido abierto por un proceso y `test_reciente_20260831.wav` recién creado, ambos borrados después): 180 WAV, 8 omitidos (5 llamadas reales + los 2 de prueba + 1 recién cerrada), 8 convertidos, 0 rutas recortadas. **14:00, ciclo real del cron** (`wav_conversion_cron.log.1`, rotado a las 14:17): ``` [2026-08-31 14:00:27] OMITIDO (en uso): .../1788174301.5646510.wav [2026-08-31 14:00:27] OMITIDO (en uso): .../1788176071.5646894.wav [2026-08-31 14:00:39] OMITIDO (en uso): .../1788176642.5647068.wav [2026-08-31 14:00:40] OMITIDO (en uso): .../1788176621.5647040.wav [2026-08-31 14:00:40] OMITIDO (en uso): .../1788177599.5647185.wav [2026-08-31 14:00:59] Total archivos WAV: 178 / Convertidos: 9 / Errores: 164 / Omitidos (en uso): 5 ``` Los 164 "errores" son los WAV de solo cabecera (44–2284 bytes, "MP3 generado muy pequeño"); la limpieza de WAV vacíos se hizo después de ese ciclo. 0 líneas con ruta recortada desde las 13:41 (`grep 'ffmpeg falló para: ' | grep -vc 'para: /mnt/'` = 0). **Verificación de no-truncado** de los 5 omitidos (CEL en hora Madrid; duración fichero con ffprobe/soxi): | uniqueid (fichero) | Llamada (CEL CHAN_START→CHAN_END) | CDR duration/billsec | Fichero | Resultado | |------------------------|-----------------------------------|----------------------|--------------------|-----------| | 1788174301.5646510 | 13:05:02→14:05:37 = 3635 s | 3625 / 3624 | mp3 3688 s (convertido al colgar, auto_convert.log 14:05:28) | completo | | 1788176071.5646894 | 13:34:32→13:59:45 = 1513 s | 33+1479 | wav 1539 s (cerrado 15 s antes del ciclo; lo convierte el siguiente) | completo | | 1788176621.5647040 | 13:43:42→14:02:31 = 1129 s | 23+1092 | mp3 1140 s (convertido al colgar 14:02:27) | completo | | 1788176642.5647068 (*) | 13:44:03→14:02:27 = 1104 s | 3 (NO ANSWER, otro canal) | wav 1120 s | completo | | 1788177599.5647185 | 13:59:59→14:30:14 = 1815 s | 67+1747 | wav 1847 s | completo (empezó 1 s antes del ciclo; antes del fix se habría quedado en ~40 s) | | **Contraste 30-08** 1788080316.5620787 | 10:58:36→11:16:19 = 1063 s | 172+890 | mp3 **139 s** | TRUNCADA por el cron 11:00:55 | (*) `1788176642.5647068` es el `GLOBAL(CALL_ID)` (TEMP_ID tras la transferencia) de la misma llamada que `1788176621.5647040`: el fichero se nombra con CALL_ID, no con el uniqueid del canal grabado. Controles convertidos en ese mismo ciclo (llamadas ya cerradas): `1788176562.5647025` mp3 895 s vs CEL 876 s; `1788175721.5646809` 844 s vs 831 s. Y el barrido global post-fix: 42 ficheros, 0 truncados. **15:00, ciclo real** (segundo ciclo con el fix): `Total archivos WAV: 37 / Convertidos: 22 / Errores: 15 / Omitidos (en uso): 0`, 0 rutas recortadas. Convirtió ya cerrados los tres WAV que había omitido a las 14:00 (`1788176071.5646894` → mp3 1539 s, `1788176642.5647068` → 1120 s, `1788177599.5647185` → 1847 s: las mismas duraciones que tenían los WAV, nada perdido). Los 15 errores son los WAV de solo cabecera que quedan (ver "Pendientes"). ## Camino de conversión al colgar (no tocado, verificado) `call_system/processors/hangup_processor.py:760` → `SYSTEM /var/lib/asterisk/convert_all_to_mp3.sh ` (log `/var/log/asterisk/auto_convert.log`). El script hace glob `${CALL_ID}*.wav` (solo `CALL_ID.wav` y `CALL_ID_2.wav` de esa llamada) y se ejecuta dentro del handler `h` de `[cuelgue]` (`extensions_dslp_hangup_handlers.conf`), que hace `StopMixMonitor()` como segunda prioridad, antes del AGI. Comprobación con datos: 787 conversiones por este camino desde el 30-08 00:00, **0** con hora de conversión anterior al último evento CEL de su linkedid. Riesgos residuales: - El glob es prefijo sin separador (`1788178871.5647340*` también casaría con `1788178871.56473400.wav`): imposible en la práctica (los seq de un mismo segundo son consecutivos). - Este camino NO salta en todas las llamadas (hoy `1788176071.5646894` y `1788177599.5647185` no tienen entrada en auto_convert.log). Por eso el cron horario es la red de seguridad y tenía que quedar bien. ## Higiene (misma sesión) - 149 WAV vacíos borrados. Copia: `/root/test_cron_wav_20260831/wav_vacios_20260831.tar.gz` + listado `wav_vacios_20260831.txt`. - `/etc/logrotate.d/asterisk-wav-conversion` creado (weekly, rotate 4, compress, copytruncate) y rotación forzada: `wav_conversion_cron.log.1` = 435 MB acumulados desde enero. - `/etc/cron.d/asterisk-wav-maintenance`: línea de las 04:00 comentada (duplicado del crontab horario). Backup `/root/test_cron_wav_20260831/asterisk-wav-maintenance.bak_20260831`. ## Rollback - Script (NO recomendado: vuelve el truncado): `cp /usr/local/bin/convert-pending-wavs.sh.bak_abiertos_20260831 /usr/local/bin/convert-pending-wavs.sh` - cron.d: `cp /root/test_cron_wav_20260831/asterisk-wav-maintenance.bak_20260831 /etc/cron.d/asterisk-wav-maintenance` - logrotate: `rm /etc/logrotate.d/asterisk-wav-conversion` - WAV vacíos: `tar tzf /root/test_cron_wav_20260831/wav_vacios_20260831.tar.gz` para ver las rutas y `tar xzf ... -C /` (no aportan nada: solo cabecera RIFF). ## Verificación futura ```bash # Cada ciclo debe mostrar "Omitidos (en uso): N" (N = llamadas en curso a esa hora) y 0 truncados grep -h 'OMITIDO (en uso)\|Omitidos\|Convertidos\|Errores' /var/log/asterisk/wav_conversion_cron.log | tail -20 grep 'ffmpeg falló para: ' /var/log/asterisk/wav_conversion_cron.log | grep -vc 'para: /mnt/' # debe ser 0 # Detector de truncados de un día (fichero vs CEL), umbral 15 s: cd /mnt/volume_fra1_01/asterisk-spool/monitor for f in $(find . -maxdepth 1 -name '*.mp3' -size +100k -newermt "$(date +%F) 00:00"); do u=$(basename ${f%.mp3}); u=${u%_2} d=$(ffprobe -v error -show_entries format=duration -of csv=p=0 $f); d=${d%.*} span=$(echo "SELECT UNIX_TIMESTAMP(MAX(eventtime))-UNIX_TIMESTAMP(MIN(eventtime)) FROM cel WHERE uniqueid='$u'" | isql asterisk -b) [ -n "$span" ] && [ $((d - span)) -lt -15 ] && echo "TRUNCADO $f fichero=${d}s cel=${span}s" done ``` ## Pendientes / hallazgos no tocados - **logrotate.d roto**: `/etc/logrotate.d/asterisk` y 5 ficheros más los descarta logrotate entero por "duplicate log entry" contra `aggressive-rotation` → esos logs de Asterisk no rotan por esa vía. - **PCI**: las grabaciones contienen números de tarjeta dictados en claro (flujo VISA, ficheros `*_2.wav` y la grabación del cliente) y los MP3 se sirven desde el panel. Fuera del alcance de este fix; hay que decidir qué hacer (no grabar el tramo de tarjeta, o cifrar/limitar acceso). - Las grabaciones truncadas antes del 31-08 13:41 (~90/día desde enero) no son recuperables. - Quedan ~12 WAV de solo cabecera (44–2284 bytes, llamadas sin bridge) que el cron reintenta cada hora y anota como "MP3 generado muy pequeño". Inofensivo; `convert_all_to_mp3.sh` los borra si pasan por su uniqueid, el cron no. - El camino de conversión al colgar no se dispara en todas las llamadas (ver arriba); no investigado.