Últimos Cambios
Blog personal: El hilo del laberinto
|
|
|
Últimos Cambios |
|
Blog personal: El hilo del laberinto
|
|
|
Última Actualización: 7 de octubre de 2012
Durante años, en la web corporativa, hemos tenido este problema: de vez en cuando, la web corporativa se bloquea. Es decir, deja de responder y los navegadores reciben (tras unos largos segundos de espera) un mensaje de "timeout" del Apache, diciendo que el ZOPE que hay detrás no responde. No ocurre todos los días, pero cuando ocurre es siempre más o menos en la misma ventana horaria y, lo que es peor, el problema se resuelve solo tras unos minutos, una hora como mucho.
Dado que el problema es esporádico, ocurre de madrugada y se resuelve solo al cabo de unos minutos, investigarlo era complicado y de relativamente baja prioridad. Y así estuvimos durante años.
Hasta que me tocó las narices, claro.
El problema fundamental era enterarse de que la web estaba caída, conectarse por la noche y estudiar el problema mientras está ocurriendo. La ventana es muy corta, menos de una hora. En varios intentos el problema se solucionó por si solo mientras estaba mirando, dejándome con un palmo de narices. Pero esta experiencia me aportó información adicional, como que si el ZOPE se bloqueaba una noche, se bloquearía entre las doce y la una de la madrugada, y se resolvería automáticamente a la una de la madrugada. 100% consistente.
Lo más evidente, y más teniendo en cuenta el perfil de nuestra web corporativa, era suponer que estábamos recibiendo un ataque de denegación de servicio, pero en los logs no se veía nada y la consistencia en los horarios durante años resultaba poco creíble.
Los hechos eran los siguientes:
La siguiente suposición es que que hay un proceso periódico que está causando problemas. Algún cron, la copia de seguridad diaria, etc. Pero el consumo de CPU se centra en el ZOPE, y no hay nada más que esté ejecutándose, relevante.
¿Qué está haciendo el ZOPE en ese momento?. Depurar un programa en un lenguaje interpretado desde el exterior, sin su colaboración, es muy difícil. Herramientas como "gdb" están pensadas para depurar un programa en C, pero aquí lo que está en C es el intérprete, no vemos directamente el código python que se está ejecutando. Además, dado que el problema se resuelve solo en una hora o menos, es difícil profundizar en el análisis de las estructuras internas del intérprete de python a tiempo.
Pero este sistema está funcionando bajo Solaris, y tenemos acceso a unas cuantas herramientas interesante, como "dtrace" o "gcore".
"gcore" es una herramienta Solaris que permite generar un "core dump" de un proceso en ejecución, sin interrumpir su funcionamiento. La ventaja de analizar ese "core dump" es que captura exactamente el estado de python/ZOPE y podemos analizar sus tripas sin que nos afecte que el proceso se recupere solo a los 5 minutos.
Una vez que tenemos ese "core dump", podemos analizarlo con GDB. Hay un "python-gdb" que son extensiones de GDB para analizar las tripas del intérprete de forma simple, pero yo no las tenía para python 2.4 (que es la versión que usa mi ZOPE) y, además, estoy muy famirializado con el intérprete de python, ya que soy "core developer" del proyecto desde 2008. Así que tirando del hilo, siguiendo punteros, listas enlazadas y "frames", determino que los cuatro hilos de ZOPE están bloqueados en el mismo producto ZOPE: COREBlog. Más que eso, están bloqueados, los cuarto, en la misma rutina. El fragmento de código relevante es el siguiente (fichero "utility.py"):
def get_tomorrow(int_date):
#return 'tomorrow' of int_date
return get_relative_int_date(int_date,24*60*60)
def get_yesterday_t(year,month,day):
#return 'yesterday' of int_date
return get_relative_int_date_t(year,month,day,-(24*60*60+10))
def get_tomorrow_t(year,month,day):
#return 'tomorrow' of int_date
return get_relative_int_date_t(year,month,day,24*60*60+10)
def get_relative_int_date(int_date,delta):
#return relative int_date using 'delta'
t = list(localtime(time()))
t[0] = int_date / 10000
t[1] = (int_date / 100) % 100
t[2] = int_date % 100
s = mktime(t) + delta
return sec_to_date_int(s)
def get_relative_int_date_t(year,month,day,delta):
#return relative int_date using 'delta'
t = list(localtime(time()))
t[0] = year
t[1] = month
t[2] = day
s = mktime(t) + delta
tt = localtime(s)
return tt[0],tt[1],tt[2]
Este código es bastante evidente. Básicamente te permite moverte por el día anterior/siguiente, a partir de una fecha dada. Esto se usa, por ejemplo, para mostrar los históricos de COREBlog. Para ello, sumamos o restamos 24 horas a la fecha actual. Por ejemplo, si queremos mostrar el histórico de un mes, lo que se hace es empezar en el día uno de dicho mes e ir avanzando de 24 en 24 horas, hasta que cambiamos de mes y ahí paramos.
Pero esta lógica es incorrecta. ¿Por qué?.
Pensadlo un momento...
Pensadlo un poquito más...
¿Ya lo tienes?
El código supone que todos los días tienen 24 horas... y eso no es cierto. En concreto, dejando los "leap seconds" al margen, buena parte del planeta cambia su horario en la primavera/otoño, el famoso cambio horario. Tenemos un día que dura 23 horas y otro que dura 25 horas. Argg!. Si estamos en el día que dura 25 horas, avanzamos 24 horas, seguimos en el mismo día, y si la lógica es terminar el bucle cuando cambiamos de mes, estaremos en un bucle infinito, clavados en el mismo día.
Dado que la web está siendo escaneada constantemente por "crawlers" (léase, Google y cientos más), entre otras cosas revisando los archivos del blog, este problema ocurre en cualquier época del año, no solo cuando cambiamos de horario. Así, si una visita entra en el histórico de octubre (cambio de horario en España, con día de 25 horas), ese hilo ZOPE se quedará bloqueado. No pasa nada, esa conexión dará "timeout", pero otras conexiones se servirán con otros hilos ZOPE... a menos que entren varias peticiones para Octubre y se vayan bloqueando hilos poco a poco, hasta que no queda ninguno disponible para servir la web.
¿Por qué esto solo ocurre en una ventana de tiempo determinada, y se resuelve solo? La clave está en "tt = localtime(s)".
Una vez que el problema está claro, la solución también. De hecho la implementación correcta es mucho más sencilla que la original. El parche:
--- COREBlog.py.old 2009-10-23 18:43:41.565628000 +0200
+++ COREBlog.py 2010-07-07 22:30:24.214367407 +0200
@@ -64,7 +64,7 @@
from ObjectBase import Comment,Trackback
from Category import Category
from AuthBridge import AuthBridge
-from utility import r2i,sec_to_date_int,day_to_date_int,get_yesterday,get_tomorrow, \
+from utility import r2i,get_yesterday,get_tomorrow, \
get_yesterday_t,get_tomorrow_t, \
remove_html,validate_html,getNewID,make_unique, \
call_addentry_hook, \
--- utility.py.old 2010-07-07 22:15:46.402459595 +0200
+++ utility.py 2010-07-07 22:36:02.409476632 +0200
@@ -40,6 +40,9 @@
from stripogram import html2safehtml
+import datetime
+delta_dia = datetime.timedelta(1)
+
__doc__="""Zope Blog Product 'COREBlog:utility'
$Id: utility.py,v 1.6 2005/04/30 09:30:06 ats_shib Exp $"""
@@ -65,61 +68,33 @@
except:
return default
-def sec_to_date_int(second = 0):
- #make calendar_date(int,like 20031123) from second
- if second == 0:
- second = time()
- t = localtime(second)
- int_date = t[0]*10000 + t[1]*100 + t[2]
- return int_date
-
-
-def day_to_date_int(year,month,day):
- #make calendar_date(int,like 20031123) from year,month,day
- int_date = year*10000 + month*100 + day
- return int_date
-
-
def get_yesterday(int_date):
#return 'yesterday' of int_date
- return get_relative_int_date(int_date,-24*60*60)
+ return get_relative_int_date(int_date, -delta_dia)
def get_tomorrow(int_date):
#return 'tomorrow' of int_date
- return get_relative_int_date(int_date,24*60*60)
+ return get_relative_int_date(int_date, delta_dia)
def get_yesterday_t(year,month,day):
- #return 'yesterday' of int_date
- return get_relative_int_date_t(year,month,day,-(24*60*60+10))
-
+ d = datetime.date(year, month, day)-delta_dia
+ return d.year, d.month, d.day
def get_tomorrow_t(year,month,day):
- #return 'tomorrow' of int_date
- return get_relative_int_date_t(year,month,day,24*60*60+10)
-
+ d = datetime.date(year, month, day)+delta_dia
+ return d.year, d.month, d.day
def get_relative_int_date(int_date,delta):
#return relative int_date using 'delta'
- t = list(localtime(time()))
- t[0] = int_date / 10000
- t[1] = (int_date / 100) % 100
- t[2] = int_date % 100
- s = mktime(t) + delta
- return sec_to_date_int(s)
+ year = int_date // 10000
+ month = (int_date // 100) % 100
+ day = int_date % 100
+ d = datetime.date(year, month, day)+delta
+ return d.year*10000+d.month*100+d.day
-def get_relative_int_date_t(year,month,day,delta):
- #return relative int_date using 'delta'
- t = list(localtime(time()))
- t[0] = year
- t[1] = month
- t[2] = day
- s = mktime(t) + delta
- tt = localtime(s)
- return tt[0],tt[1],tt[2]
-
#field validation/sanitize
def remove_html(s):
Aquí utilizo la librería "datetime" para manipular las fechas de forma segura. Si tenemos una librería en la stdlib para ésto, ¡usémosla!.
COREBlog es un producto de blogs para Zope, escrita por un japonés. Está abandonada en 2006. Viendo la última versión del código, sigue teniendo este problema. Me sorprende que este problema no se haya solucionado oficialmente, porque debería afectar a TODO el mundo en zonas horarias con cambio horario anual, que es buena parte del planeta y la mayoría de los países occidentales. En fin...
El problema lo investigué y solucioné el 7 de julio de 2010.
Más información sobre los OpenBadges
Donación BitCoin: 19niBN42ac2pqDQFx6GJZxry2JQSFvwAfS
