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): pass
  76
  77 class RsyncError(Error, EnvironmentError): pass
  78
  79 #}}}
  80
  81 def unzip(bytes, default_dst='.', specific_dst=dict()): # {{{
  82     u"""Descomprime un buffer de datos en formato ZIP.
  83     Los archivos se descomprimen en default_dst a menos que exista una entrada
  84     en specific_dst cuya clave sea el nombre de archivo a descomprimir, en
  85     cuyo caso, se descomprime usando como destino el valor de dicha clave.
  86     """
  87     log.debug(_(u'Intentando descomprimir'))
  88     if bytes is None:
  89         return
  90     zfile = ZipFile(StringIO(bytes), 'r')
  91     for f in zfile.namelist():
  92         dst = join(specific_dst.get(f, default_dst), f)
  93         if f.endswith(os.sep):
  94             log.debug(_(u'Creando directorio "%s" en "%s"'), f, dst)
  95             os.mkdir(dst)
  96         else:
  97             log.debug(_(u'Descomprimiendo archivo "%s" en "%s"'), f, dst)
  98             file(dst, 'w').write(zfile.read(f))
  99     zfile.close()
 100 #}}}
 101
 102 class SecureProcess(object): #{{{
 103     default = dict(
 104         max_tiempo_cpu      = 120,
 105         max_memoria         = 16,
 106         max_tam_archivo     = 5,
 107         max_cant_archivos   = 5,
 108         max_cant_procesos   = 0,
 109         max_locks_memoria   = 0,
 110     )
 111     uid = config.get('sercom.tester.chroot.user', 65534)
 112     MB = 1048576
 113     # XXX probar! make de un solo archivo lleva nproc=100 y nofile=15
 114     def __init__(self, comando, chroot, cwd, close_stdin=False,
 115                  close_stdout=False, close_stderr=False):
 116         self.comando = comando
 117         self.chroot = chroot
 118         self.cwd = cwd
 119         self.close_stdin = close_stdin
 120         self.close_stdout = close_stdout
 121         self.close_stderr = close_stderr
 122         log.debug(_(u'Proceso segurizado: chroot=%s, cwd=%s, user=%s, cpu=%s, '
 123             u'as=%sMiB, fsize=%sMiB, nofile=%s, nproc=%s, memlock=%s'),
 124             self.chroot, self.cwd, self.uid, self.max_tiempo_cpu,
 125             self.max_memoria, self.max_tam_archivo, self.max_cant_archivos,
 126             self.max_cant_procesos, self.max_locks_memoria)
 127     def __getattr__(self, name):
 128         if getattr(self.comando, name) is not None:
 129             return getattr(self.comando, name)
 130         return config.get('sercom.tester.limits.' + name, self.default[name])
 131     def __call__(self):
 132         x2 = lambda x: (x, x)
 133         if self.close_stdin:
 134             os.close(0)
 135         if self.close_stdout:
 136             os.close(1)
 137         if self.close_stderr:
 138             os.close(2)
 139         os.chroot(self.chroot)
 140         os.chdir(self.cwd)
 141         uinfo = UserInfo(self.uid)
 142         os.setgid(uinfo.gid)
 143         os.setuid(uinfo.uid) # Somos mortales irreversiblemente
 144         rsrc.setrlimit(rsrc.RLIMIT_CPU, x2(self.max_tiempo_cpu))
 145         rsrc.setrlimit(rsrc.RLIMIT_AS, x2(self.max_memoria*self.MB))
 146         rsrc.setrlimit(rsrc.RLIMIT_FSIZE, x2(self.max_tam_archivo*self.MB)) # XXX calcular en base a archivos esperados?
 147         rsrc.setrlimit(rsrc.RLIMIT_NOFILE, x2(self.max_cant_archivos)) #XXX Obtener de archivos esperados?
 148         rsrc.setrlimit(rsrc.RLIMIT_NPROC, x2(self.max_cant_procesos))
 149         rsrc.setrlimit(rsrc.RLIMIT_MEMLOCK, x2(self.max_locks_memoria))
 150         rsrc.setrlimit(rsrc.RLIMIT_CORE, x2(0))
 151         # Tratamos de forzar un sync para que entre al sleep del padre FIXME
 152         import time
 153         time.sleep(0)
 154 #}}}
 155
 156 class Tester(object): #{{{
 157
 158     def __init__(self, name, path, home, queue): #{{{ y properties
 159         self.name = name
 160         self.path = path
 161         self.home = home
 162         self.queue = queue
 163         # Ahora somos mortales (oid mortales)
 164         log.debug(_(u'Cambiando usuario y grupo efectivos a %s:%s (%s:%s)'),
 165             user_info.user, user_info.group, user_info.uid, user_info.gid)
 166         os.setegid(user_info.gid)
 167         os.seteuid(user_info.uid)
 168
 169     @property
 170     def build_path(self):
 171         return join(self.chroot, self.home, 'build')
 172
 173     @property
 174     def test_path(self):
 175         return join(self.chroot, self.home, 'test')
 176
 177     @property
 178     def chroot(self):
 179         return join(self.path, 'chroot_' + self.name)
 180
 181     @property
 182     def orig_chroot(self):
 183         return join(self.path, 'chroot')
 184     #}}}
 185
 186     def run(self): #{{{
 187         entrega_id = self.queue.get() # blocking
 188         while entrega_id is not None:
 189             entrega = Entrega.get(entrega_id)
 190             log.debug(_(u'Nueva entrega para probar en tester %s: %s'),
 191                 self.name, entrega)
 192             self.test(entrega)
 193             log.debug(_(u'Fin de pruebas de: %s'), entrega)
 194             entrega_id = self.queue.get() # blocking
 195     #}}}
 196
 197     def test(self, entrega): #{{{
 198         log.debug(_(u'Tester.test(entrega=%s)'), entrega)
 199         entrega.inicio_tareas = datetime.now()
 200         try:
 201             try:
 202                 self.setup_chroot(entrega)
 203                 self.ejecutar_tareas_fuente(entrega)
 204                 self.ejecutar_tareas_prueba(entrega)
 205                 self.clean_chroot(entrega)
 206             except ExecutionFailure, e:
 207                 entrega.correcta = False
 208                 log.info(_(u'Entrega incorrecta: %s'), entrega)
 209             except Exception, e:
 210                 if isinstance(e, SystemExit): raise
 211                 entrega.observaciones += error_interno
 212                 log.exception(_('Hubo una excepcion inesperada'))
 213             except:
 214                 entrega.observaciones += error_interno
 215                 log.exception(_('Hubo una excepcion inesperada desconocida'))
 216             else:
 217                 entrega.correcta = True
 218                 log.debug(_(u'Entrega correcta: %s'), entrega)
 219         finally:
 220             entrega.fin_tareas = datetime.now()
 221     #}}}
 222
 223     def setup_chroot(self, entrega): #{{{ y clean_chroot()
 224         log.debug(_(u'Tester.setup_chroot(entrega=%s)'), entrega.shortrepr())
 225         rsync = ('rsync', '--stats', '--itemize-changes', '--human-readable',
 226             '--archive', '--acls', '--delete-during', '--force', # TODO config
 227             join(self.orig_chroot, ''), self.chroot)
 228         log.debug(_(u'Ejecutando como root: %s'), ' '.join(rsync))
 229         os.seteuid(0) # Dios! (para chroot)
 230         os.setegid(0)
 231         try:
 232             sp.check_call(rsync)
 233         finally:
 234             log.debug(_(u'Cambiando usuario y grupo efectivos a %s:%s (%s:%s)'),
 235                 user_info.user, user_info.group, user_info.uid, user_info.gid)
 236             os.setegid(user_info.gid) # Mortal de nuevo
 237             os.seteuid(user_info.uid)
 238         unzip(entrega.archivos, self.build_path)
 239
 240     def clean_chroot(self, entrega):
 241         log.debug(_(u'Tester.clean_chroot(entrega=%s)'), entrega.shortrepr())
 242         pass # Se limpia con el próximo rsync
 243     #}}}
 244
 245     def ejecutar_tareas_fuente(self, entrega): #{{{ y tareas_prueba
 246         log.debug(_(u'Tester.ejecutar_tareas_fuente(entrega=%s)'),
 247             entrega.shortrepr())
 248         tareas = [t for t in entrega.instancia.ejercicio.enunciado.tareas
 249                     if isinstance(t, TareaFuente)]
 250         for tarea in tareas:
 251             tarea.ejecutar(self.build_path, entrega)
 252
 253     def ejecutar_tareas_prueba(self, entrega):
 254         log.debug(_(u'Tester.ejecutar_tareas_prueba(entrega=%s)'),
 255             entrega.shortrepr())
 256         for caso in entrega.instancia.ejercicio.enunciado.casos_de_prueba:
 257             caso.ejecutar(self.test_path, entrega)
 258     #}}}
 259
 260 #}}}
 261
 262 def ejecutar_caso_de_prueba(self, path, entrega): #{{{
 263     log.debug(_(u'CasoDePrueba.ejecutar(path=%s, entrega=%s)'), path,
 264         entrega.shortrepr())
 265     tareas = [t for t in entrega.instancia.ejercicio.enunciado.tareas
 266                 if isinstance(t, TareaPrueba)]
 267     prueba = entrega.add_prueba(self)
 268     try:
 269         try:
 270             for tarea in tareas:
 271                 tarea.ejecutar(path, prueba)
 272         except ExecutionFailure, e:
 273             prueba.exito = False
 274             if self.rechazar_si_falla:
 275                 entrega.exito = False
 276             if self.terminar_si_falla:
 277                 raise ExecutionError(e.comando, e.tarea, prueba)
 278         else:
 279             prueba.exito = True
 280     finally:
 281         prueba.fin = datetime.now()
 282 CasoDePrueba.ejecutar = ejecutar_caso_de_prueba
 283 #}}}
 284
 285 def ejecutar_tarea_fuente(self, path, entrega): #{{{
 286     log.debug(_(u'TareaFuente.ejecutar(path=%s, entrega=%s)'), path,
 287         entrega.shortrepr())
 288     try:
 289         for cmd in self.comandos:
 290             cmd.ejecutar(path, entrega)
 291     except ExecutionFailure, e:
 292         if self.rechazar_si_falla:
 293             entrega.exito = False
 294         if self.terminar_si_falla:
 295             raise ExecutionError(e.comando, tarea)
 296 TareaFuente.ejecutar = ejecutar_tarea_fuente
 297 #}}}
 298
 299 def ejecutar_tarea_prueba(self, path, prueba): #{{{
 300     log.debug(_(u'TareaPrueba.ejecutar(path=%s, prueba=%s)'), path,
 301         prueba.shortrepr())
 302     try:
 303         for cmd in self.comandos:
 304             cmd.ejecutar(path, prueba)
 305     except ExecutionFailure, e:
 306         if self.rechazar_si_falla:
 307             prueba.exito = False
 308         if self.terminar_si_falla:
 309             raise ExecutionError(e.comando, tarea)
 310 TareaPrueba.ejecutar = ejecutar_tarea_prueba
 311 #}}}
 312
 313 def ejecutar_comando_fuente(self, path, entrega): #{{{
 314     log.debug(_(u'ComandoFuente.ejecutar(path=%s, entrega=%s)'), path,
 315         entrega.shortrepr())
 316     comando_ejecutado = entrega.add_comando_ejecutado(self)
 317     unzip(self.archivos_entrada, path, # TODO try/except
 318         dict(__stdin__='/tmp/sercom.tester.%s.stdin' % comando_ejecutado.id)) # TODO /var/run/sercom
 319     options = dict(
 320         close_fds=True,
 321         shell=True,
 322         preexec_fn=SecureProcess(self, 'var/chroot_pepe', '/home/sercom/build')
 323     )
 324     if os.path.exists('/tmp/sercom.tester.%s.stdin' % comando_ejecutado.id): # TODO
 325         options['stdin'] = file('/tmp/sercom.tester.%s.stdin' % comando_ejecutado.id, 'r') # TODO
 326     else:
 327         options['preexec_fn'].close_stdin = True
 328     if self.guardar_stdouterr:
 329         options['stdout'] = file('/tmp/sercom.tester.%s.stdouterr'
 330             % comando_ejecutado.id, 'w') #TODO /var/run/sercom?
 331         options['stderr'] = sp.STDOUT
 332     else:
 333         if self.guardar_stdout:
 334             options['stdout'] = file('/tmp/sercom.tester.%s.stdout'
 335                 % comando_ejecutado.id, 'w') #TODO /run/lib/sercom?
 336         else:
 337             options['preexec_fn'].close_stdout = True
 338         if self.guardar_stderr:
 339             options['stderr'] = file('/tmp/sercom.tester.%s.stderr'
 340                 % comando_ejecutado.id, 'w') #TODO /var/run/sercom?
 341         else:
 342             options['preexec_fn'].close_stderr = True
 343     log.debug(_(u'Ejecutando como root: %s'), self.comando)
 344     os.seteuid(0) # Dios! (para chroot)
 345     os.setegid(0)
 346     try:
 347         try:
 348             proc = sp.Popen(self.comando, **options)
 349         finally:
 350             log.debug(_(u'Cambiando usuario y grupo efectivos a %s:%s (%s:%s)'),
 351                 user_info.user, user_info.group, user_info.uid, user_info.gid)
 352             os.setegid(user_info.gid) # Mortal de nuevo
 353             os.seteuid(user_info.uid)
 354     except Exception, e:
 355         if hasattr(e, 'child_traceback'):
 356             log.error(_(u'Error en el hijo: %s'), e.child_traceback)
 357         raise
 358     proc.wait() #TODO un sleep grande nos caga todo, ver sercom viejo
 359     if self.retorno != self.RET_ANY:
 360         if self.retorno == self.RET_FAIL:
 361             if proc.returncode == 0:
 362                 comando_ejecutado.exito = False
 363                 comando_ejecutado.observaciones += _(u'Se esperaba que el '
 364                     u'programa termine con un error (código de retorno '
 365                     u'distinto de 0) pero terminó bien (código de retorno '
 366                     u'0).\n')
 367                 log.debug(_(u'Se esperaba que el programa termine '
 368                     u'con un error (código de retorno distinto de 0) pero '
 369                     u'terminó bien (código de retorno 0).\n'))
 370         elif self.retorno != proc.returncode:
 371             comando_ejecutado.exito = False
 372             if proc.returncode < 0:
 373                 comando_ejecutado.observaciones += _(u'Se esperaba terminar '
 374                     u'con un código de retorno %s pero se obtuvo una señal %s '
 375                     u'(%s).\n') % (self.retorno, -proc.returncode,
 376                         -proc.returncode) # TODO poner con texto
 377                 log.debug(_(u'Se esperaba terminar con un código '
 378                     u'de retorno %s pero se obtuvo una señal %s (%s).\n'),
 379                     self.retorno, -proc.returncode, -proc.returncode)
 380             else:
 381                 comando_ejecutado.observaciones += _(u'Se esperaba terminar '
 382                     u'con un código de retorno %s pero se obtuvo %s.\n') \
 383                     % (self.retorno, proc.returncode)
 384                 log.debug(_(u'Se esperaba terminar con un código de retorno '
 385                     u'%s pero se obtuvo %s.\n'), self.retorno, proc.returncode)
 386     if comando_ejecutado.exito is None:
 387         log.debug(_(u'Código de retorno OK'))
 388     comando_ejecutado.fin = datetime.now()
 389     buffer = StringIO()
 390     zip = ZipFile(buffer, 'w')
 391     if self.guardar_stdouterr:
 392         zip.write('/tmp/sercom.tester.%s.stdouterr'
 393             % comando_ejecutado.id, '__stdouterr__')
 394     else:
 395         if self.guardar_stdout:
 396             azipwrite('/tmp/sercom.tester.%s.stdout'
 397                 % comando_ejecutado.id, '__stdout__')
 398         if self.guardar_stderr:
 399             zip.write('/tmp/sercom.tester.%s.stderr'
 400                 % comando_ejecutado.id, '__stderr__')
 401     zip.close()
 402     comando_ejecutado.archivos_guardados = buffer.getvalue()
 403
 404 #    if no_anda_ejecucion: # TODO
 405 #        comando_ejecutado.exito = False
 406 #        comando_ejecutado.observaciones += 'No anduvo xxx' # TODO mas info
 407 #        if self.rechazar_si_falla:
 408 #            entrega.exito = False
 409 #        if self.terminar_si_falla: # TODO
 410 #            raise ExecutionFailure(self)
 411     # XXX ESTO EN REALIDAD EN COMANDOS FUENTE NO IRIA
 412     # XXX SOLO HABRÍA QUE CAPTURAR stdout/stderr
 413     # XXX PODRIA TENER ARCHIVOS DE SALIDA PERO SOLO PARA MOSTRAR COMO RESULTADO
 414 #    for archivo in self.archivos_salida:
 415 #        pass # TODO hacer diff
 416 #    if archivos_mal: # TODO
 417 #        comando_ejecutado.exito = False
 418 #        comando_ejecutado.observaciones += 'No anduvo xxx' # TODO mas info
 419 #        if self.rechazar_si_falla:
 420 #            entrega.exito = False
 421 #        if self.terminar_si_falla: # TODO
 422 #            raise ExecutionFailure(self)
 423 #    else:
 424 #        comando_ejecutado.exito = True
 425 #        comando_ejecutado.observaciones += 'xxx OK' # TODO
 426     comando_ejecutado.exito = True
 427     comando_ejecutado.observaciones += 'xxx OK' # TODO
 428 ComandoFuente.ejecutar = ejecutar_comando_fuente
 429 #}}}
 430
 431 def ejecutar_comando_prueba(self, path, prueba): #{{{
 432     log.debug(_(u'ComandoPrueba.ejecutar(path=%s, prueba=%s)'), path,
 433         prueba.shortrepr())
 434     rmtree(path)
 435     os.mkdir(path)
 436     unzip(prueba.caso_de_prueba.archivos_entrada, path) # TODO try/except
 437     unzip(self.archivos_entrada, path) # TODO try/except
 438     comando_ejecutado = prueba.add_comando_ejecutado(self)
 439     # TODO ejecutar en chroot (path)
 440     comando_ejecutado.fin = datetime.now()
 441 #    if no_anda_ejecucion: # TODO
 442 #        comando_ejecutado.exito = False
 443 #        comando_ejecutado.observaciones += 'No anduvo xxx' # TODO
 444 #        if self.rechazar_si_falla:
 445 #            entrega.exito = False
 446 #        if self.terminar_si_falla: # TODO
 447 #            raise ExecutionFailure(self) # TODO info de error
 448 #    for archivo in self.archivos_salida:
 449 #        pass # TODO hacer diff
 450 #    if archivos_mal: # TODO
 451 #        comando_ejecutado.exito = False
 452 #        comando_ejecutado.observaciones += 'No anduvo xxx' # TODO
 453 #        if self.rechazar_si_falla:
 454 #            entrega.exito = False
 455 #        if self.terminar_si_falla: # TODO
 456 #            raise ExecutionFailure(comando=self) # TODO info de error
 457 #    else:
 458 #        comando_ejecutado.exito = True
 459 #        comando_ejecutado.observaciones += 'xxx OK' # TODO
 460     comando_ejecutado.exito = True
 461     comando_ejecutado.observaciones += 'xxx OK' # TODO
 462 ComandoPrueba.ejecutar = ejecutar_comando_prueba
 463 #}}}
 464