sercom/tester.py

   1 # vim: set et sw=4 sts=4 encoding=utf-8 foldmethod=marker:
   2
   3 from sercom.model import Entrega, CasoDePrueba
   4 from sercom.model import TareaFuente, TareaPrueba, ComandoFuente, ComandoPrueba
   5 from zipfile import ZipFile, BadZipfile
   6 from cStringIO import StringIO
   7 from shutil import rmtree
   8 from datetime import datetime
   9 from os.path import join
  10 from turbogears import config
  11 import subprocess as sp
  12 import os, sys, pwd, grp
  13 import resource as rsrc
  14 import logging
  15
  16 log = logging.getLogger('sercom.tester')
  17
  18 error_interno = _(u'\n**Error interno al preparar la entrega.**')
  19
  20 class UserInfo(object): #{{{
  21     def __init__(self, user):
  22         try:
  23             info = pwd.getpwnam(user)
  24         except:
  25             info = pwd.get(int(user))
  26         self.user = info[0]
  27         self.uid = info[2]
  28         self.gid = info[3]
  29         self.name = info[4]
  30         self.home = info[5]
  31         self.shell = info[6]
  32         self.group = grp.getgrgid(self.gid)[0]
  33 #}}}
  34
  35 user_info = UserInfo(config.get('sercom.tester.user', 65534))
  36
  37 def check_call(*popenargs, **kwargs): #{{{ XXX Python 2.5 forward-compatibility
  38     """Run command with arguments.  Wait for command to complete.  If
  39     the exit code was zero then return, otherwise raise
  40     CalledProcessError.  The CalledProcessError object will have the
  41     return code in the returncode attribute.
  42     ret = call(*popenargs, **kwargs)
  43
  44     The arguments are the same as for the Popen constructor.  Example:
  45
  46     check_call(["ls", "-l"])
  47     """
  48     retcode = sp.call(*popenargs, **kwargs)
  49     cmd = kwargs.get("args")
  50     if cmd is None:
  51         cmd = popenargs[0]
  52     if retcode:
  53         raise sp.CalledProcessError(retcode, cmd)
  54     return retcode
  55 sp.check_call = check_call
  56 #}}}
  57
  58 #{{{ Excepciones
  59
  60 class CalledProcessError(Exception): #{{{ XXX Python 2.5 forward-compatibility
  61     """This exception is raised when a process run by check_call() returns
  62     a non-zero exit status.  The exit status will be stored in the
  63     returncode attribute."""
  64     def __init__(self, returncode, cmd):
  65         self.returncode = returncode
  66         self.cmd = cmd
  67     def __str__(self):
  68         return ("Command '%s' returned non-zero exit status %d"
  69             % (self.cmd, self.returncode))
  70 sp.CalledProcessError = CalledProcessError
  71 #}}}
  72
  73 class Error(StandardError): pass
  74
  75 class ExecutionFailure(Error, RuntimeError): #{{{
  76     def __init__(self, comando, tarea=None, caso_de_prueba=None):
  77         self.comando = comando
  78         self.tarea = tarea
  79         self.caso_de_prueba = caso_de_prueba
  80 #}}}
  81
  82 class RsyncError(Error, EnvironmentError): pass
  83
  84 #}}}
  85
  86 def unzip(bytes, default_dst='.', specific_dst=dict()): # {{{
  87     u"""Descomprime un buffer de datos en formato ZIP.
  88     Los archivos se descomprimen en default_dst a menos que exista una entrada
  89     en specific_dst cuya clave sea el nombre de archivo a descomprimir, en
  90     cuyo caso, se descomprime usando como destino el valor de dicha clave.
  91     """
  92     log.debug(_(u'Intentando descomprimir'))
  93     if bytes is None:
  94         return
  95     zfile = ZipFile(StringIO(bytes), 'r')
  96     for f in zfile.namelist():
  97         dst = join(specific_dst.get(f, default_dst), f)
  98         if f.endswith(os.sep):
  99             log.debug(_(u'Creando directorio "%s" en "%s"'), f, dst)
 100             os.mkdir(dst)
 101         else:
 102             log.debug(_(u'Descomprimiendo archivo "%s" en "%s"'), f, dst)
 103             file(dst, 'w').write(zfile.read(f))
 104     zfile.close()
 105 #}}}
 106
 107 class SecureProcess(object): #{{{
 108     default = dict(
 109         max_tiempo_cpu      = 120,
 110         max_memoria         = 16,
 111         max_tam_archivo     = 5,
 112         max_cant_archivos   = 5,
 113         max_cant_procesos   = 0,
 114         max_locks_memoria   = 0,
 115     )
 116     uid = config.get('sercom.tester.chroot.user', 65534)
 117     MB = 1048576
 118     # XXX probar! make de un solo archivo lleva nproc=100 y nofile=15
 119     def __init__(self, comando, chroot, cwd, close_stdin=False,
 120                  close_stdout=False, close_stderr=False):
 121         self.comando = comando
 122         self.chroot = chroot
 123         self.cwd = cwd
 124         self.close_stdin = close_stdin
 125         self.close_stdout = close_stdout
 126         self.close_stderr = close_stderr
 127         log.debug(_(u'Proceso segurizado: chroot=%s, cwd=%s, user=%s, cpu=%s, '
 128             u'as=%sMiB, fsize=%sMiB, nofile=%s, nproc=%s, memlock=%s'),
 129             self.chroot, self.cwd, self.uid, self.max_tiempo_cpu,
 130             self.max_memoria, self.max_tam_archivo, self.max_cant_archivos,
 131             self.max_cant_procesos, self.max_locks_memoria)
 132     def __getattr__(self, name):
 133         if getattr(self.comando, name) is not None:
 134             return getattr(self.comando, name)
 135         return config.get('sercom.tester.limits.' + name, self.default[name])
 136     def __call__(self):
 137         x2 = lambda x: (x, x)
 138         if self.close_stdin:
 139             os.close(0)
 140         if self.close_stdout:
 141             os.close(1)
 142         if self.close_stderr:
 143             os.close(2)
 144         os.chroot(self.chroot)
 145         os.chdir(self.cwd)
 146         uinfo = UserInfo(self.uid)
 147         os.setgid(uinfo.gid)
 148         os.setuid(uinfo.uid) # Somos mortales irreversiblemente
 149         rsrc.setrlimit(rsrc.RLIMIT_CPU, x2(self.max_tiempo_cpu))
 150         rsrc.setrlimit(rsrc.RLIMIT_AS, x2(self.max_memoria*self.MB))
 151         rsrc.setrlimit(rsrc.RLIMIT_FSIZE, x2(self.max_tam_archivo*self.MB)) # XXX calcular en base a archivos esperados?
 152         rsrc.setrlimit(rsrc.RLIMIT_NOFILE, x2(self.max_cant_archivos)) #XXX Obtener de archivos esperados?
 153         rsrc.setrlimit(rsrc.RLIMIT_NPROC, x2(self.max_cant_procesos))
 154         rsrc.setrlimit(rsrc.RLIMIT_MEMLOCK, x2(self.max_locks_memoria))
 155         rsrc.setrlimit(rsrc.RLIMIT_CORE, x2(0))
 156         # Tratamos de forzar un sync para que entre al sleep del padre FIXME
 157         import time
 158         time.sleep(0)
 159 #}}}
 160
 161 class Tester(object): #{{{
 162
 163     def __init__(self, name, path, home, queue): #{{{ y properties
 164         self.name = name
 165         self.path = path
 166         self.home = home
 167         self.queue = queue
 168         # Ahora somos mortales (oid mortales)
 169         log.debug(_(u'Cambiando usuario y grupo efectivos a %s:%s (%s:%s)'),
 170             user_info.user, user_info.group, user_info.uid, user_info.gid)
 171         os.setegid(user_info.gid)
 172         os.seteuid(user_info.uid)
 173
 174     @property
 175     def build_path(self):
 176         return join(self.chroot, self.home, 'build')
 177
 178     @property
 179     def test_path(self):
 180         return join(self.chroot, self.home, 'test')
 181
 182     @property
 183     def chroot(self):
 184         return join(self.path, 'chroot_' + self.name)
 185
 186     @property
 187     def orig_chroot(self):
 188         return join(self.path, 'chroot')
 189     #}}}
 190
 191     def run(self): #{{{
 192         entrega_id = self.queue.get() # blocking
 193         while entrega_id is not None:
 194             entrega = Entrega.get(entrega_id)
 195             log.debug(_(u'Nueva entrega para probar en tester %s: %s'),
 196                 self.name, entrega)
 197             self.test(entrega)
 198             log.debug(_(u'Fin de pruebas de: %s'), entrega)
 199             entrega_id = self.queue.get() # blocking
 200     #}}}
 201
 202     def test(self, entrega): #{{{
 203         log.debug(_(u'Tester.test(entrega=%s)'), entrega)
 204         entrega.inicio_tareas = datetime.now()
 205         try:
 206             try:
 207                 self.setup_chroot(entrega)
 208                 self.ejecutar_tareas_fuente(entrega)
 209                 self.ejecutar_tareas_prueba(entrega)
 210                 self.clean_chroot(entrega)
 211             except ExecutionFailure, e:
 212                 entrega.correcta = False
 213                 log.info(_(u'Entrega incorrecta: %s'), entrega)
 214             except Exception, e:
 215                 if isinstance(e, SystemExit): raise
 216                 entrega.observaciones += error_interno
 217                 log.exception(_('Hubo una excepcion inesperada'))
 218             except:
 219                 entrega.observaciones += error_interno
 220                 log.exception(_('Hubo una excepcion inesperada desconocida'))
 221             else:
 222                 entrega.correcta = True
 223                 log.debug(_(u'Entrega correcta: %s'), entrega)
 224         finally:
 225             entrega.fin_tareas = datetime.now()
 226     #}}}
 227
 228     def setup_chroot(self, entrega): #{{{ y clean_chroot()
 229         log.debug(_(u'Tester.setup_chroot(entrega=%s)'), entrega.shortrepr())
 230         rsync = ('rsync', '--stats', '--itemize-changes', '--human-readable',
 231             '--archive', '--acls', '--delete-during', '--force', # TODO config
 232             join(self.orig_chroot, ''), self.chroot)
 233         log.debug(_(u'Ejecutando como root: %s'), ' '.join(rsync))
 234         os.seteuid(0) # Dios! (para chroot)
 235         os.setegid(0)
 236         try:
 237             sp.check_call(rsync)
 238         finally:
 239             log.debug(_(u'Cambiando usuario y grupo efectivos a %s:%s (%s:%s)'),
 240                 user_info.user, user_info.group, user_info.uid, user_info.gid)
 241             os.setegid(user_info.gid) # Mortal de nuevo
 242             os.seteuid(user_info.uid)
 243         unzip(entrega.archivos, self.build_path)
 244
 245     def clean_chroot(self, entrega):
 246         log.debug(_(u'Tester.clean_chroot(entrega=%s)'), entrega.shortrepr())
 247         pass # Se limpia con el próximo rsync
 248     #}}}
 249
 250     def ejecutar_tareas_fuente(self, entrega): #{{{ y tareas_prueba
 251         log.debug(_(u'Tester.ejecutar_tareas_fuente(entrega=%s)'),
 252             entrega.shortrepr())
 253         tareas = [t for t in entrega.instancia.ejercicio.enunciado.tareas
 254                     if isinstance(t, TareaFuente)]
 255         for tarea in tareas:
 256             tarea.ejecutar(self.build_path, entrega)
 257
 258     def ejecutar_tareas_prueba(self, entrega):
 259         log.debug(_(u'Tester.ejecutar_tareas_prueba(entrega=%s)'),
 260             entrega.shortrepr())
 261         for caso in entrega.instancia.ejercicio.enunciado.casos_de_prueba:
 262             caso.ejecutar(self.test_path, entrega)
 263     #}}}
 264
 265 #}}}
 266
 267 def ejecutar_caso_de_prueba(self, path, entrega): #{{{
 268     log.debug(_(u'CasoDePrueba.ejecutar(path=%s, entrega=%s)'), path,
 269         entrega.shortrepr())
 270     tareas = [t for t in entrega.instancia.ejercicio.enunciado.tareas
 271                 if isinstance(t, TareaPrueba)]
 272     prueba = entrega.add_prueba(self)
 273     try:
 274         try:
 275             for tarea in tareas:
 276                 tarea.ejecutar(path, prueba)
 277         except ExecutionFailure, e:
 278             prueba.exito = False
 279             if self.rechazar_si_falla:
 280                 entrega.exito = False
 281             if self.terminar_si_falla:
 282                 raise ExecutionFailure(e.comando, e.tarea, self)
 283         else:
 284             prueba.exito = True
 285     finally:
 286         prueba.fin = datetime.now()
 287 CasoDePrueba.ejecutar = ejecutar_caso_de_prueba
 288 #}}}
 289
 290 def ejecutar_tarea_fuente(self, path, entrega): #{{{
 291     log.debug(_(u'TareaFuente.ejecutar(path=%s, entrega=%s)'), path,
 292         entrega.shortrepr())
 293     try:
 294         for cmd in self.comandos:
 295             cmd.ejecutar(path, entrega)
 296     except ExecutionFailure, e:
 297         if self.rechazar_si_falla:
 298             entrega.exito = False
 299         if self.terminar_si_falla:
 300             raise ExecutionFailure(e.comando, self)
 301 TareaFuente.ejecutar = ejecutar_tarea_fuente
 302 #}}}
 303
 304 def ejecutar_tarea_prueba(self, path, prueba): #{{{
 305     log.debug(_(u'TareaPrueba.ejecutar(path=%s, prueba=%s)'), path,
 306         prueba.shortrepr())
 307     try:
 308         for cmd in self.comandos:
 309             cmd.ejecutar(path, prueba)
 310     except ExecutionFailure, e:
 311         if self.rechazar_si_falla:
 312             prueba.exito = False
 313         if self.terminar_si_falla:
 314             raise ExecutionFailure(e.comando, self)
 315 TareaPrueba.ejecutar = ejecutar_tarea_prueba
 316 #}}}
 317
 318 def ejecutar_comando_fuente(self, path, entrega): #{{{
 319     log.debug(_(u'ComandoFuente.ejecutar(path=%s, entrega=%s)'), path,
 320         entrega.shortrepr())
 321     comando_ejecutado = entrega.add_comando_ejecutado(self)
 322     unzip(self.archivos_entrada, path, # TODO try/except
 323         dict(__stdin__='/tmp/sercom.tester.%s.stdin' % comando_ejecutado.id)) # TODO /var/run/sercom
 324     options = dict(
 325         close_fds=True,
 326         shell=True,
 327         preexec_fn=SecureProcess(self, 'var/chroot_pepe', '/home/sercom/build')
 328     )
 329     if os.path.exists('/tmp/sercom.tester.%s.stdin' % comando_ejecutado.id): # TODO
 330         options['stdin'] = file('/tmp/sercom.tester.%s.stdin' % comando_ejecutado.id, 'r') # TODO
 331     else:
 332         options['preexec_fn'].close_stdin = True
 333     a_guardar = set(self.archivos_a_guardar)
 334     if self.STDOUTERR in a_guardar:
 335         options['stdout'] = file('/tmp/sercom.tester.%s.stdouterr'
 336             % comando_ejecutado.id, 'w') #TODO /var/run/sercom?
 337         options['stderr'] = sp.STDOUT
 338     else:
 339         if self.STDOUT in a_guardar:
 340             options['stdout'] = file('/tmp/sercom.tester.%s.stdout'
 341                 % comando_ejecutado.id, 'w') #TODO /run/lib/sercom?
 342         else:
 343             options['preexec_fn'].close_stdout = True
 344         if self.STDERR in a_guardar:
 345             options['stderr'] = file('/tmp/sercom.tester.%s.stderr'
 346                 % comando_ejecutado.id, 'w') #TODO /var/run/sercom?
 347         else:
 348             options['preexec_fn'].close_stderr = True
 349     log.debug(_(u'Ejecutando como root: %s'), self.comando)
 350     os.seteuid(0) # Dios! (para chroot)
 351     os.setegid(0)
 352     try:
 353         try:
 354             proc = sp.Popen(self.comando, **options)
 355         finally:
 356             log.debug(_(u'Cambiando usuario y grupo efectivos a %s:%s (%s:%s)'),
 357                 user_info.user, user_info.group, user_info.uid, user_info.gid)
 358             os.setegid(user_info.gid) # Mortal de nuevo
 359             os.seteuid(user_info.uid)
 360     except Exception, e:
 361         if hasattr(e, 'child_traceback'):
 362             log.error(_(u'Error en el hijo: %s'), e.child_traceback)
 363         raise
 364     proc.wait() #TODO un sleep grande nos caga todo, ver sercom viejo
 365     if self.retorno != self.RET_ANY:
 366         if self.retorno == self.RET_FAIL:
 367             if proc.returncode == 0:
 368                 if self.rechazar_si_falla:
 369                     entrega.correcta = False
 370                 comando_ejecutado.exito = False
 371                 comando_ejecutado.observaciones += _(u'Se esperaba que el '
 372                     u'programa termine con un error (código de retorno '
 373                     u'distinto de 0) pero terminó bien (código de retorno '
 374                     u'0).\n')
 375                 log.debug(_(u'Se esperaba que el programa termine '
 376                     u'con un error (código de retorno distinto de 0) pero '
 377                     u'terminó bien (código de retorno 0).\n'))
 378         elif self.retorno != proc.returncode:
 379             if self.rechazar_si_falla:
 380                 entrega.correcta = False
 381             comando_ejecutado.exito = False
 382             if proc.returncode < 0:
 383                 comando_ejecutado.observaciones += _(u'Se esperaba terminar '
 384                     u'con un código de retorno %s pero se obtuvo una señal %s '
 385                     u'(%s).\n') % (self.retorno, -proc.returncode,
 386                         -proc.returncode) # TODO poner con texto
 387                 log.debug(_(u'Se esperaba terminar con un código '
 388                     u'de retorno %s pero se obtuvo una señal %s (%s).\n'),
 389                     self.retorno, -proc.returncode, -proc.returncode)
 390             else:
 391                 comando_ejecutado.observaciones += _(u'Se esperaba terminar '
 392                     u'con un código de retorno %s pero se obtuvo %s.\n') \
 393                     % (self.retorno, proc.returncode)
 394                 log.debug(_(u'Se esperaba terminar con un código de retorno '
 395                     u'%s pero se obtuvo %s.\n'), self.retorno, proc.returncode)
 396     if comando_ejecutado.exito is None:
 397         log.debug(_(u'Código de retorno OK'))
 398     comando_ejecutado.fin = datetime.now()
 399     if a_guardar:
 400         buffer = StringIO()
 401         zip = ZipFile(buffer, 'w')
 402         # Guardamos stdout/stderr
 403         if self.STDOUTERR in a_guardar:
 404             a_guardar.remove(self.STDOUTERR)
 405             zip.write('/tmp/sercom.tester.%s.stdouterr'
 406                 % comando_ejecutado.id, '__stdouterr__')
 407         else:
 408             if self.STDOUT in a_guardar:
 409                 a_guardar.remove(self.STDOUT)
 410                 zip.write('/tmp/sercom.tester.%s.stdout'
 411                     % comando_ejecutado.id, '__stdout__')
 412             if self.STDERR in a_guardar:
 413                 a_guardar.remove(self.STDERR)
 414                 zip.write('/tmp/sercom.tester.%s.stderr'
 415                     % comando_ejecutado.id, '__stderr__')
 416         # Guardamos otros
 417         for f in a_guardar:
 418             if not os.path.exists(join(path, f)):
 419                 if self.rechazar_si_falla:
 420                     entrega.correcta = False
 421                 comando_ejecutado.exito = False
 422                 comando_ejecutado.observaciones += _(u'Se esperaba un archivo '
 423                     u'"%s" pero no fue encontrado') % f
 424                 log.debug(_(u'Se esperaba un archivo "%s" pero no fue '
 425                     u'encontrado'), f)
 426             else:
 427                 zip.write(join(path, f), f)
 428         zip.close()
 429         comando_ejecutado.archivos_guardados = buffer.getvalue()
 430     if comando_ejecutado.exito is None:
 431         comando_ejecutado.exito = True
 432     elif self.terminar_si_falla:
 433         raise ExecutionFailure(self)
 434
 435 #    if no_anda_ejecucion: # TODO
 436 #        comando_ejecutado.exito = False
 437 #        comando_ejecutado.observaciones += 'No anduvo xxx' # TODO mas info
 438 #        if self.rechazar_si_falla:
 439 #            entrega.exito = False
 440 #        if self.terminar_si_falla: # TODO
 441 #            raise ExecutionFailure(self)
 442     # XXX ESTO EN REALIDAD EN COMANDOS FUENTE NO IRIA
 443     # XXX SOLO HABRÍA QUE CAPTURAR stdout/stderr
 444     # XXX PODRIA TENER ARCHIVOS DE SALIDA PERO SOLO PARA MOSTRAR COMO RESULTADO
 445 #    for archivo in self.archivos_salida:
 446 #        pass # TODO hacer diff
 447 #    if archivos_mal: # TODO
 448 #        comando_ejecutado.exito = False
 449 #        comando_ejecutado.observaciones += 'No anduvo xxx' # TODO mas info
 450 #        if self.rechazar_si_falla:
 451 #            entrega.exito = False
 452 #        if self.terminar_si_falla: # TODO
 453 #            raise ExecutionFailure(self)
 454 #    else:
 455 #        comando_ejecutado.exito = True
 456 #        comando_ejecutado.observaciones += 'xxx OK' # TODO
 457 ComandoFuente.ejecutar = ejecutar_comando_fuente
 458 #}}}
 459
 460 def ejecutar_comando_prueba(self, path, prueba): #{{{
 461     log.debug(_(u'ComandoPrueba.ejecutar(path=%s, prueba=%s)'), path,
 462         prueba.shortrepr())
 463     rmtree(path)
 464     os.mkdir(path)
 465     unzip(prueba.caso_de_prueba.archivos_entrada, path) # TODO try/except
 466     unzip(self.archivos_entrada, path) # TODO try/except
 467     comando_ejecutado = prueba.add_comando_ejecutado(self)
 468     # TODO ejecutar en chroot (path)
 469     comando_ejecutado.fin = datetime.now()
 470 #    if no_anda_ejecucion: # TODO
 471 #        comando_ejecutado.exito = False
 472 #        comando_ejecutado.observaciones += 'No anduvo xxx' # TODO
 473 #        if self.rechazar_si_falla:
 474 #            entrega.exito = False
 475 #        if self.terminar_si_falla: # TODO
 476 #            raise ExecutionFailure(self) # TODO info de error
 477 #    for archivo in self.archivos_salida:
 478 #        pass # TODO hacer diff
 479 #    if archivos_mal: # TODO
 480 #        comando_ejecutado.exito = False
 481 #        comando_ejecutado.observaciones += 'No anduvo xxx' # TODO
 482 #        if self.rechazar_si_falla:
 483 #            entrega.exito = False
 484 #        if self.terminar_si_falla: # TODO
 485 #            raise ExecutionFailure(comando=self) # TODO info de error
 486 #    else:
 487 #        comando_ejecutado.exito = True
 488 #        comando_ejecutado.observaciones += 'xxx OK' # TODO
 489     comando_ejecutado.exito = True
 490     comando_ejecutado.observaciones += 'xxx OK' # TODO
 491 ComandoPrueba.ejecutar = ejecutar_comando_prueba
 492 #}}}
 493