Python 3.13: zlib.error: Error -2 while flushing: inconsistent stream state

Tras actualizar a Python 3.13 y mod_wsgi, tal y como se describe en Problema actualizando mis servicios WSGI a Python 3.13, empecé a ver estos errores en el log:

Exception ignored in: <gzip on 0x7fd58e3c6fb0>
Traceback (most recent call last):
  File "/usr/local/lib/python3.13/gzip.py", line 373, in close
    fileobj.write(self.compress.flush())
zlib.error: Error -2 while flushing: inconsistent stream state

La excepción no parece tener ningún efecto práctico en el programa, pero muestra que hay un problema a resolver.

Lo primero que llama la atención es que el traceback no parece completo, no indica qué código está llamando a la función close(). Ese detalle junto al mensaje Exception ignored in: indica que se trata de una excepción asíncrona que ocurre en un destructor.

Para saber qué parte del código está generando esa excepción (de forma asíncrona), podemos modificar el código añadiendo esto al principio:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17

 import sys, inspect
 class GzipFile(gzip.GzipFile):
     def __init__(self, *args, **kwargs):
         creador = inspect.stack()[1]
         self._creador = (creador.filename, creador.function, creador.lineno)
         del creador
         return super().__init__(*args, **kwargs)

     def close(self):
         try:
             print("CLOSE", file=sys.stderr)
             return super().close()
         except Exception as exc:
             print(self._creador, file=sys.stderr)
             raise

 gzip.GzipFile = GzipFile

Este código sobrecarga la clase gzip.GzipFile con una versión propia que registra en qué línea de código se crea cada instancia de gzip.GzipFile y muestra esa información si ocurre una excepción en el método close().

La línea 1 importa módulos que utilizaremos en el nuevo código. En la línea 2 creamos una nueva clase que deriva de gzip.GzipFile. En su constructor (líneas 3-7) llamamos al constructor original, pero nos quedamos con los detalles del punto de código que ha llamado al constructor. Es decir, dónde se instancia la clase. Ojo a la línea 6, que evita que tengamos ciclos que impedirían que la recolección de basuras se hiciese pronto, rápido y bien.

Las líneas 9-15 sobrecargan el método close(). El nuevo código llama al método close() original, pero, si ocurre una excepción, utilizamos la información que almacenamos en el constructor para imprimir (línea 14) en qué línea de código se ha instanciado el objeto con el que ahora tenemos problemas. Tras hacer eso, volvemos a levantar la excepción original (línea 15).

Por último, la línea 17 reemplaza la clase gzip.GzipFile original, de forma que cuando el programa cree instancias nuevas, utilizará nuestro nuevo código.

Lanzando el código nuevo, ahora vemos lo siguiente:

('/home/buffy/clients_data.py', '_store_state', 99)
Exception ignored in: <gzip on 0x7fd5d4207550>
Traceback (most recent call last):
  File "/home/buffy/wsgi.py", line 19, in close
    return super().close()
  File "/usr/local/lib/python3.13/gzip.py", line 373, in close
    fileobj.write(self.compress.flush())
zlib.error: Error -2 while flushing: inconsistent stream state

Ahora vemos la excepción original, pero con el añadido de la primera línea: ('/home/buffy/clients_data.py', '_store_state', 99). Aquí vemos qué módulo, qué función y en qué línea de código se crea la instancia de gzip.GzipFile que nos está causando problemas. Lo más interesante es que comprobamos en los logs que siempre que salta la excepción, la instancia se ha creado siempre en el mismo sitio. Ya tenemos por dónde empezar.

El código responsable es el siguiente:

 92
 93
 94
 95
 96
 97
 98
 99
100
101
102
103
104
105
106
107
108

 def _store_state(self):
     try:
         fd = os.open(self._data_file + '.NEW',
                      os.O_WRONLY | os.O_CREAT, 0o640)

         with open(fd, 'wb') as f:
             f.write(bytes((0,)))  # VERSIÓN
             f = gzip.GzipFile(fileobj=f, mode='wb')
             with self.lock:
                 estado = self.tupla_estado(TS_inicial=self._ts_inicial,
                                            clientes=self._state)
                 self.cbor.dump(estado, f)
             f.flush(zlib_mode=zlib.Z_FINISH)
             os.fsync(f.fileno())
         os.rename(self._data_file + '.NEW', self._data_file)
     except Exception:
         pass

Vemos la creación de la instancia en la línea 99, pero no hay ningún close() en esa función. ¿Qué está pasando?. Existe un close() implícito en el destructor de la instancia creada en la línea 99, que se llamará cuando termine la función, ya que la instancia es local a la función y se destruye cuando la función termina.

¿Cuál es el problema?. Estudiando el código original de gzip.GzipFile vemos que su método close() llama también, lógicamente, al método flush() que nosotros ya llamamos en la línea 104 de nuestro código. ¿Es posible que sea un error llamar a flush() una vez que ya lo hemos llamado con el parámetro zlib.Z_FINISH?

Para comprobarlo escribo el siguiente programa, buscando reproducir el error:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12

 #!/usr/bin/env python3.13

 import io
 import gzip
 import zlib

 a = gzip.GzipFile(fileobj=io.BytesIO(), mode='wb')

 a.flush()
 a.flush()
 a.flush(zlib_mode=zlib.Z_FINISH)
 a.close()

El código es trivial de entender. La clave es la interacción entre las líneas 11 y 12. Ejecutamos el código y obtenemos lo siguiente:

Traceback (most recent call last):
  File "/tmp/ram/./j.py", line 12, in <module>
    a.close()
    ~~~~~~~^^
  File "/usr/local/lib/python3.13/gzip.py", line 373, in close
    fileobj.write(self.compress.flush())
                  ~~~~~~~~~~~~~~~~~~~^^
zlib.error: Error -2 while flushing: buffer error

¡Exactamente la misma excepción que estábamos buscando! Claro que en este caso lo generamos de forma explícita en la línea 12 de nuestro código, al hacer el close(). Si eliminamos esa línea y volvemos a ejecutar este código de prueba, obtenemos:

Exception ignored in: <gzip on 0x7fe9c51708b0>
Traceback (most recent call last):
  File "/usr/local/lib/python3.13/gzip.py", line 373, in close
zlib.error: Error -2 while flushing: buffer error

Exactamente lo que ha originado toda esta investigación: una excepción asíncrona e ignorada, pero cuya existencia se comunica a través de stderr.

Aunque es discutible que no se pueda hacer un flush() sobre un objeto de compresión de datos sobre el que ya hemos hecho un flush() final (podría simplemente ignorarse), el camino está claro: Queremos cerrar la instancia de compresión y asegurarnos de que acaba en el disco duro para asegurar su durabilidad. Podemos cambiar el código de esta manera:

 92
 93
 94
 95
 96
 97
 98
 99
100
101
102
103
104
105
106
107
108

 def _store_state(self):
     try:
         fd = os.open(self._data_file + '.NEW',
                      os.O_WRONLY | os.O_CREAT, 0o640)

         with open(fd, 'wb') as f:
             f.write(bytes((0,)))  # VERSIÓN
             f2 = gzip.GzipFile(fileobj=f, mode='wb')
             with self.lock:
                 estado = self.tupla_estado(TS_inicial=self._ts_inicial,
                                            clientes=self._state)
                 self.cbor.dump(estado, f2)
             f2.close()
             os.fsync(f.fileno())
         os.rename(self._data_file + '.NEW', self._data_file)
     except Exception:
         pass

Comparada con la versión anterior de esta rutina, aquí mantenemos el acceso a la instancia de los datos comprimidos utilizando f2 en vez de f en las líneas 99, 103 y 104. En vez de hacer un flush() en la línea 104, cerramos la instancia de gzip.GzipFile() que creamos en la línea 99. Esto ya realiza un flush() final implícito, así que el Sistema Operativo recibe el bloque de datos comprimido completo, que nos aseguramos de que esté en el disco duro de forma durable en la línea 105.

¿Qué ocurre cuando el método llega a su fin y se destruye la instancia gzip.GzipFile()?. Como esa instancia está marcada como closed, se entiende que ya se ha hecho flush() previamente y no hace falta hacer nada más.

¡Problema solucionado!