jueves, 16 de enero de 2014

Depurar código administrado en entorno de producción.

Tienes un programa que sólo falla (lanzando una fea excepción) en el entorno de producción y eso es una putada. Por fortuna podemos mirar que esta pasando gracias a depurador de windows WinDgb.exe y un programita muy chulo de microsft que se llama Debug Diagnostic Tool 2.0. (DebugDiag)



Este es el programa que falla:
  Sub Main()

    Console.Read
    metodoQuePeta()

  End Sub
  
  Private Sub metodoQuePeta()
    Dim cadenaInterna As String = "cadena erronea"
    if cadenaInterna = "cadena erronea" then
      Throw New System.NotImplementedException("La cadena de caracteres esta mal y no puedo procesarla")
    end if
  End Sub

Básicamente consiste en lanzar DebugDiag en producción asociado al proceso que lanza la excepción y dejarlo correr. DebugDiag se encargará de capturar la excepción sin entrometerse demasiado y generar un Dump del estado del proceso en ese momento y su memoria.

Una vez generado ese Dump, debemos cargarlo en el depurador de windows con la opción "Open Crash Dump".

Cuando el depurador carga el Dump debemos agregar al depurador la extension que "entiende" el código administrado. Esta extensión es SOS Debugging Extension. Esto se hace con la instrucción ".loadby sos mscorwks".

Con la extension cargada ya podemos listar los hilos de código administrado que estaban corriendo en ese momento en el proceso con la instrucción "!treads"

0:000> !threads
ThreadCount: 2
UnstartedThread: 0
BackgroundThread: 1
PendingThread: 0
DeadThread: 0
Hosted Runtime: no           
  0    1 10d0 00000000003436c0      6020 Enabled  00000000027daa80:00000000027dbfd0 000000000033ac10     0 STA System.NotImplementedException (00000000027da7b8)
   2    2 1508 000000000034b600      b220 Enabled  0000000000000000:0000000000000000 000000000033ac10     0 MTA (Finalizer)

Podemos ver 2 hilos administrados (0 y 2). Vemos como el hilo 0 es el que ha lanzado la excepción en nuestro programa. (NotImplementedException), así que cambiamos el entrono de ejecución del depurador al hilo 0 con la instrucción "~0s" e inspeccionamos el volcado de pila con "!CLRStack".

0:000> !CLRStack
OS Thread Id: 0x10d0 (0)
Child-SP         RetAddr          Call Site
000000000014e960 000007ff00190174 Prototipos.Module1.metodoQuePeta()
000000000014e9b0 000007fef863d432 Prototipos.Module1.Main()

Así que el "metodoQuePeta" es el que está lanzando la excepción y este método es llamado por la funcion Main. Ya es algo, aun así estaría bien saber que nos cuenta la excepción para recabar más información.

Con el comando "!dso" (dump stack objects) podemos ver los objetos administrados que estaban relacionados en ese momento en el contexto de la pila.

0:000> !dso
OS Thread Id: 0x10d0 (0)
RSP/REG                  Object                      Name
000000000014e798 00000000027da7b8 System.NotImplementedException
000000000014e7b0 00000000027da7b8 System.NotImplementedException
000000000014e7d0 00000000027da7b8 System.NotImplementedException
000000000014e8a0 00000000027da7b8 System.NotImplementedException
000000000014e960 00000000027da7b8 System.NotImplementedException
000000000014e968 00000000027da840 System.String
000000000014e980 00000000027d9098 System.String
000000000014e990 00000000027da7b8 System.NotImplementedException
000000000014e9b0 00000000027d9df8 System.IO.TextReader+SyncTextReader
000000000014e9d0 00000000027d9098 System.String
Aquí tenemos la excepción y alguna cadena. Vamos a inspeccionar la excepción y ver su mensaje a ver que nos cuenta. Esto se hace con el comando "!do" (dump object) y el identificador del objeto.

0:000> !do 00000000027da7b8
Name: System.NotImplementedException
MethodTable: 000007fef80b3870
EEClass: 000007fef75c1568
Size: 136(0x88) bytes
 (C:\Windows\assembly\GAC_64\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
000007fef78d7d90  40000b5        8        System.String  0 instance 0000000000000000 _className
000007fef78d6138  40000b6       10 ...ection.MethodBase  0 instance 0000000000000000 _exceptionMethod
000007fef78d7d90  40000b7       18        System.String  0 instance 0000000000000000 _exceptionMethodString
000007fef78d7d90  40000b8       20        System.String  0 instance 00000000027da940 _message
000007fef78cf3b0  40000b9       28 ...tions.IDictionary  0 instance 0000000000000000 _data
000007fef78d8058  40000ba       30     System.Exception  0 instance 0000000000000000 _innerException
000007fef78d7d90  40000bb       38        System.String  0 instance 0000000000000000 _helpURL
000007fef78d7680  40000bc       40        System.Object  0 instance 00000000027daa08 _stackTrace
000007fef78d7d90  40000bd       48        System.String  0 instance 0000000000000000 _stackTraceString
000007fef78d7d90  40000be       50        System.String  0 instance 0000000000000000 _remoteStackTraceString
000007fef78df000  40000bf       70         System.Int32  1 instance                0 _remoteStackIndex
000007fef78d7680  40000c0       58        System.Object  0 instance 0000000000000000 _dynamicMethods
000007fef78df000  40000c1       74         System.Int32  1 instance      -2147467263 _HResult
000007fef78d7d90  40000c2       60        System.String  0 instance 0000000000000000 _source
000007fef78da798  40000c3       68        System.IntPtr  1 instance                0 _xptrs
000007fef78df000  40000c4       78         System.Int32  1 instance       -532459699 _xcode
Vemos los atributos de la clase excepción y entre ellos la cadena con el mensaje (_message). Inspeccionemos el mensaje de nuevo con el comando "!do" y el valor del atributo.

!do 00000000027da940
Name: System.String
MethodTable: 000007fef78d7d90
EEClass: 000007fef74de560
Size: 124(0x7c) bytes
 (C:\Windows\assembly\GAC_64\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
String: La cadena de caracteres esta mal y no puedo procesarlaFields:
              MT    Field   Offset                 Type VT     Attr            Value Name
000007fef78df000  4000096        8         System.Int32  1 instance               50 m_arrayLength
000007fef78df000  4000097        c         System.Int32  1 instance               49 m_stringLength
000007fef78d97d8  4000098       10          System.Char  1 instance               4e m_firstChar
000007fef78d7d90  4000099       20        System.String  0   shared           static Empty
                                 >> Domain:Value  000000000033ac10:0000000002731308 <<
000007fef78d9688  400009a       28        System.Char[]  0   shared           static WhitespaceChars
                                 >> Domain:Value  000000000033ac10:0000000002731ba0 <<
La excepción nos dice que hay una cadena que no podemos procesar. Como se supone que sabemos lo que hace nuestro método (tenemos el código fuente) ya tenemos toda la información para arreglarlo... bueno todavía no, estaría bien saber qué tiene la cadena para ponerla en desarrollo y reproducir el error.

Examinemos las cadenas hasta encontrar la que sabemos que ha hecho que falle el método.
0:000> !do 00000000027d9098
Name: System.String
MethodTable: 000007fef78d7d90
EEClass: 000007fef74de560
Size: 48(0x30) bytes
 (C:\Windows\assembly\GAC_64\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
String: cadena erronea
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
000007fef78df000  4000096        8         System.Int32  1 instance               12 m_arrayLength
000007fef78df000  4000097        c         System.Int32  1 instance               11 m_stringLength
000007fef78d97d8  4000098       10          System.Char  1 instance               62 m_firstChar
000007fef78d7d90  4000099       20        System.String  0   shared           static Empty
                                 >> Domain:Value  000000000033ac10:0000000002731308 <<
000007fef78d9688  400009a       28        System.Char[]  0   shared           static WhitespaceChars
                                 >> Domain:Value  000000000033ac10:0000000002731ba0 <<

Y aquí lo tenemos, esta es la variable de nuestro código que debe procesar el método. La cadena contiene un valor (cadena erronea) que hace que el método falle. Cogemos ese valor, lo ponemos en desarrollo, depuramos con el código fuente, lo arreglamos y preparamos la build 2.0 libre de bugs.

Happy debugging!!!!

1 comentario:

  1. Se me olvido poner en el post que es recomendable disponer de los archivos de informacion de depuracion (.pdb) de .NET de microsoft y de nuestro programa y configurar en el depurador de windows la ruta de estos archivos.

    ResponderEliminar