"Cada vez que cometo un error me parece descubrir una verdad que no conocía"
Maurice Maeterlinck
Hoy abordamos un aspecto crucial en todo buen desarrollo. El control de errores. Y es que, amigos, aunque se encuentren Uds. en el TOP 5 de los mejores programadores de su barrio, una cosa es segura, y es que no hay nada seguro, y que todo lo que pueda fallar, fallará.
Más importante que no cometer errores -al menos respecto al desarrollar software-, es controlarlos adecuadamente. Hay que convivir con el error como un elemento más de nuestros desarrollos, tratándolo con mimo y cautela, vigilándolo, corrigiéndolo, monitorizándolo...
Amigos, no oculten sus errores. ¡Expóngalos! ¡Enfréntense a ellos! Aquí el desarrollo de software y la vida vislumbran algunos paralelismos.
Pero centrémonos en el desarrollo. ¿Creen que si dejan su código bajo un try {} catch {} sin más, su código aparentará no fallar nunca? Ciertamente no habrá excepciones no controladas, pero sí funcionamientos inadecuados. Para mayores complicaciones, los comportamientos inadecuados nos pasarán inadvertidos, imposibilitando su corrección. Este sería el mayor de los errores.
Si bien es cierto que, a nuestros amados usuarios, que bastante tienen ya con lo que tienen, tampoco hemos de hacerles partícipes de cada una de las fallas de nuestras aplicaciones. De cara al usuario el tratamiento del error debe ser suave, diplomático... incluso pedagógico si me apuran. Pueden incluso abordarlo si se atreven, con sentido del humor. Siempre me acuerdo de una pantalla de error no controlado en YouTube, que decía algo así como: "una legión de monos fuertemente entrenados se dirigen en este momento a su domicilio para resolver la situación". Cuidado, que no todos somos Google.
Pero de cara al desarrollador el error ha de ser implacable. No debe ocultar nada. Cuanto más se sepa de él, mejor.
Perdónenme la introducción. Resulta que me divierte bastante el tema del error. Pero ya sí me voy a ir centrando en lo que nos ocupa.
Hoy vamos a incorporar la librería NLOG a nuestra plataforma. Hay tres librerías para .NET que tratan la trazabilidad y control de errores, que destacan bastante, y son ciertamente similares. Como siempre hago, les dejo una extensa y detallada publicación antes de empezar a fabricar código: michaelscodingspot.com/logging-in-dotnet
Describe las distintas técnicas de logging, destaca los aspectos cruciales de la trazabilidad y entra en los detalles y particularidades de las herramientas más usadas. Es francamente un artículo muy interesante y completo.
Como les digo, nosotros ya tomamos la decisión de incorporar NLOG. Su eficacia está sobradamente probada, y su documentación es detallada y abundante (nlog-project.org)
Instalamos la librería vía Nuget, y lo primero que hemos de hacer es configurar nuestros parámetros de trazabilidad, lo cual de algún modo supone definir nuestra estrategia. Con NLOG la configuración se puede hacer vía fichero de configuración o programáticamente. Nosotros usaremos el sistema tradicional de añadir estas configuraciones en el fichero app.config.
Primera aproximación con nLOG
<configSections> <section name="entityFramework" type="System.Data.Entity.Internal.ConfigFile.EntityFrameworkSection, EntityFramework, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089" requirePermission="false"/> <section name="nlog" type="NLog.Config.ConfigSectionHandler, NLog"/> </configSections> <entityFramework> <providers> <provider invariantName="System.Data.SqlClient" type="System.Data.Entity.SqlServer.SqlProviderServices, EntityFramework.SqlServer"/> </providers> </entityFramework> <nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" autoReload="true"> <variable name="ExceptionLayout" value="${machinename} | ${longdate} | ${level:upperCase=true} | ${message} | ${exception} | ${stacktrace:format=Raw} " /> <targets async="true"> <default-target-parameters xsi:type="File" keepFileOpen="false"/> <target name="logconsole" xsi:type="Console" /> <target name="logfile" xsi:type="File" fileName="logs/error_${shortdate}.txt" layout="${ExceptionLayout}" /> </targets> <rules> <logger name="*" minlevel="Info" writeTo="logconsole" /> <logger name="*" minlevel="Error" writeTo="logfile" /> </rules> </nlog>
La variable ExceptionLayout define el renderizado de nuestra traza error. Veremos esto con más detalle más adelante. Lo primero y más fundamental es definir los destinos de la información, que pueden ser distintos en función del nivel de la traza.
Los niveles que queramos establecer se definen mediante el tag <logger> y en este mismo tag definimos la salida o target. Para nuestra solución vamos a definir en un primer intento dos niveles de trazabilidad, la información, que nos será útil en labores de depuración de código, y cuyo output será la consola de Visual Studio; y la excepción o error, cuya información se volcará en un fichero de texto.
Vean otras características que usaremos en esta primera versión de nuestro control de errores:
- La variante async=true en el tag <targets> nos asegura que la escritura de la trazabilidad se realizará de forma asíncrona, aspecto este muy importante para que la repercusión en el rendimiento de nuestra aplicación sea mínima.
- La propiedad keepFileOpen=false nos evitará posibles problemas de concurrencia al fichero de errores y sus posible errores de acceso derivados.
Bien, pongamos a prueba esta configuración básica.
Para comenzar a probar el control de errores, así como la información para la depuración usaremos nuestro test1 (multithreading vs singlethreading). En el constructor de la clase de negocio donde implementaremos el control de errores hay que definir una variable estática de la siguiente manera:
private static readonly NLog.Logger _logger = NLog.LogManager.GetCurrentClassLogger();
Centrémonos en la función privada CalcFibo1, que se usa en el primero de los testcases, aquel que calcula 200 elementos de la serie fibo en 500 hilos simultáneos. Esto es, que monta 500 veces un hilo que llama a la función CalcFibo1:
Aquí estamos ya probando nuestros dos niveles de trazabilidad, un texto meramente informativo que nos mostrará el principio y fin de la ejecución del hilo por consola, y una entrada detallada en fichero de texto, en caso de error.
while (cont< 500) { Thread thfibo = new Thread(() => CalcFibo1(cont)); _lst_process_control.Add(new objects.process_control() { Estado = objects.process_control.enumEstadoProceso.Ejecutando, Hilo = thfibo }); thfibo.Start(); Thread.Sleep(55); cont++; }
private static void CalcFibo1(int index) { try { _logger.Info("Inicia cálculo serie Fibo - Index " + index.ToString()); if (index == 1) { int a = 1 - 1; int b = 1 / a; } FiboCalc.CalcFibo(200); _lst_process_control[index].Estado = objects.process_control.enumEstadoProceso.Finalizado; _logger.Info("Finaliza cálculo serie Fibo - Index " + index.ToString()); } catch (Exception ex) { _logger.Error(ex, " CalcFibo1 - Index " + index.ToString()); _lst_process_control[index].Estado = objects.process_control.enumEstadoProceso.Erroneo; } }
Aquí estamos ya probando nuestros dos niveles de trazabilidad, un texto meramente informativo que nos mostrará el principio y fin de la ejecución del hilo por consola, y una entrada detallada en fichero de texto, en caso de error.
Observen que he provocado intencionadamente un error para una de las 500 ejecuciones previstas.
Ejecutemos el test y comprobemos los resultados. Primero echemos un vistazo a la consola:
Todo ha salido como esperábamos. Nos informa del inicio y fin de la ejecución del hilo, identificando el número de operación. Esta capacidad es muy interesante en soluciones multi-hilo cuya depuración puede resultar engorrosa. Ahora tenemos que fijarnos en si el error provocado quedó reflejado en algún fichero de texto.
¡Muy bien! Hemos puesto al tanto al usuario de los ocurrido, y para el desarrollador hemos escrito una nueva línea en fichero de texto con el detalle de la excepción. Una sola línea nueva gracias ha que hemos tenido la delicadeza de añadirle un condicionante al error if (index == 1)
¿Qué información está volcando en el fichero de errores? Pues exactamente la que le hemos pedido que mostrase. Recuperemos el fichero de configuración de NLOG:
<variable name="ExceptionLayout" value="${machinename} | ${longdate} | ${level:upperCase=true} | ${message} | ${exception} | ${stacktrace:format=Raw} " />
Las posibilidades son muchísimas, concretamente todas éstas de tal suerte que pueden Uds. definir la información de su ficherito de errores a la medida de las necesidades concretas del proyecto. Sean selectivos y piensen detenidamente la información a volcar: ésta debe ser suficiente para la identificación y resolución de errores, debe ofrecer un contexto claro acerca del cómo, cuándo dónde y porque se produjo el error, pero a la par, no se deben poner en compromiso los sistemas de almacenamiento. Como siempre los programadores debemos enfrentarnos a estos divertidos sudokus.
Tengan presente que la práctica de no escribirlo todo en un mismo fichero, sino crear ficheros distintos por días, niveles, capas, meses, o cualquier otra división que se les ocurra, les ahorrará problemas que de producirse, podrían llegar a resultar desastrosos.
Asimismo pongan atención en no dejar trazas de depuración en entornos productivos. Esto también es aplicable del lado del cliente, si usa Ud por ejemplo javaScript o cualquier framework derivado. ¡¡ Please Stop Using console.log !!
Jugando con el error
Disponer de un caso de programación multi-hilo es maravilloso para escribir un artículo sobre control de errores. Mi experiencia me dice que son técnicas prolijas en errores insospechados.Provocamos un error dentro de un método con 500 ejecuciones simultáneas, pero solo en una de las 500 gracias a if (index == 1)
Supongamos que suprimimos esa condición. Vamos a introducir un poco de estressss al sistema, provocando una excepción en cada uno de los 500 hilos ejecutados, y por cada excepción escribiremos una línea logging en nuestro fichero de texto tipo errores, y un elemento en la colección de mensajes para el usuario, mensajes que serán leídos y mostrados periódicamente desde el front-end.
private static void CalcFibo1(int index) { try { _logger.Info("Inicia cálculo serie Fibo - Index " + index.ToString()); if (index == 1) { //error 1 object o2 = null; int i2 = (int)o2; } else { //error 2 int a = 0; int b = 1 / a; } FiboCalc.CalcFibo(200); _lst_process_control[index].Estado = objects.process_control.enumEstadoProceso.Finalizado; _logger.Info("Finaliza cálculo serie Fibo - Index " + index.ToString()); } //catch (InvalidCastException cast_ex) //{ // _logger.Error(cast_ex, " CalcFibo1 - Index " + index.ToString()); //} catch (Exception ex) { _testexec.SetMsg("Error INESPECÍFICO calculando la serie - Hilo nº " + index.ToString()); _logger.Error(ex, " CalcFibo1 - Index " + index.ToString()); _lst_process_control[index].Estado = objects.process_control.enumEstadoProceso.Erroneo; } }
El resultado es éste:
Otro error en la lista de los más buscados, que se recrudece con la programación multi-hilo, es la colección modificada, una lista de clases que simultáneamente añade nuevos elementos, y periódicamente va leyéndolos y modificándolos. Se nos da el caso en la gestión de los mensajes para el usuario. La lista de mensajes está definida en la clase test_exec, clase base de todos los test.
Las operaciones de lectura se producen en el formulario que ejecuta los test, en el contexto de un control Timer que se ejecuta cada x segundos, creo que lo tengo puesto en 6.
private void timerControl_Tick(object sender, EventArgs e) { List<test_types.mensajes> lstMensajes = new List<test_types.mensajes>(); test_exec execObject = (test_exec)_testobject.Execution.OBJ; _estadoProceso = execObject.Estado; try { lstMensajes = execObject.Mensajes.Where(msg => msg.leido == false).ToList(); } catch (InvalidOperationException ex_inv) { _logger.Warn("Colección modificada"); } catch (Exception ex) { _logger.Error(ex, "Error al leer los mensajes - timerControl_Tick "); } foreach (var msg in lstMensajes) { execObject.SetMsgLeido(msg.id); } Application.DoEvents(); if (_estadoProceso == test_types.enumEstadoProceso.Ejecutando) { foreach (var msg in lstMensajes) { ListViewItem lstIt = new ListViewItem(msg.mensaje); lstMonitor.Items.Add(lstIt); } lstMensajes.Clear(); } else if (_estadoProceso == test_types.enumEstadoProceso.Finalizado) { timerControl.Enabled = false; //última lectura de mensajes foreach (var msg in lstMensajes) { ListViewItem lstIt = new ListViewItem(msg.mensaje); lstMonitor.Items.Add(lstIt); } //volvemos a establecer el cursor por defecto _container.SetDefaultCursor(); this.Cursor = Cursors.Default; } }
Los nuevos elementos de la colección se van añadiendo en el trascurso de la ejecución de cualquier test, llamando a un método de la clase base llamado SetMsg
public void SetMsg(string Msg) { this.Mensajes.Add(new test_types.mensajes() { id = Guid.NewGuid(), mensaje = Msg, leido = false }); }
Mientras que, desde el Timer que lee los mensajes, llama al método SetMsgLeido una vez se confirma que el mensaje ha sido pintado en pantalla, marcándolo como leído.
public void SetMsgLeido(Guid id) { reintenta: try { this.Mensajes.Where(idx => idx.id == id).First().leido = true; } catch (InvalidOperationException ex_inv) { intentos_mensajes++; _logger.Warn(ex_inv, "Lista modificada - Intento " + intentos_mensajes.ToString()); Thread.Sleep(100); if (intentos_mensajes < 8539) { goto reintenta; } } }
Eventualmente la consulta execObject.Mensajes.Where, o bien el método SetMsgLeido me devuelven un error de lista modificada. Compruebo que no ocurre en todas las ejecuciones, ni mucho menos; de la 500 ejecuciones pueden fallar promedio una o ninguna, calculado a vuelapluma. Mas como hechos son amores, implemento un sistema de reintentos mediante control de errores, y añado una entrada al fichero log de Warnings.
La gestión de estos errores ha queda razonablemente bien: a nosotros desarrolladores nos da suficiente información para detectarlos y corregirlos; al usuario le informa de que algo ocurrió, e incluso nos hemos atrevido a programar con éxito reintentos para una operación y fallo muy concretos.
También con técnicas de gestión de excepciones se puede programar la verificación de reglas de negocio. Levanten sus propias excepciones y dejen volar su imaginación.
¿Cuánto penaliza el uso de NLOG?
Si buscamos referencias acerca de NLOG u otras librerías, encontramos que teóricamente el rendimiento está muy optimizado, amén de ser librerías de considerable éxito. Hemos usado recursos interesantes como la grabación asíncrona y a pesar de todo, ¿qué mejor que disponer de una plataforma de tests, para comprobar si una aseveración teórica tiene sustento en la práctica?Recuperamos nuestro test de referencia, test1 multithreading vs singlethreading, y añadamos un testcase. Lo llamaremos MultithreadingCaseWithErrors. Hace lo mismo que MultithreadingCase pero con un error provocado en cada uno de los hilos, como hemos venido haciendo. Vemos los resultados:
Desconcertante ¿no? Aparentemente, a pesar de la inclusión de las trazas, el rendimiento de nuestro testcase nuevo es ligeramente mejor. Para buscar una explicación a esta eventualidad vamos a incluir una propiedad orden en la entidad testcase, e invertiremos el orden de ejecución de los dos primeros testcases:
Dejaremos el juego en este punto. Diviértanse incluyendo más y más variables a la ecuación. Por mi parte concluyo que, independientemente de las pequeñas variabilidades que hemos observamos, podemos concluir que la inclusión de la librería NLOG ha afectado mínimamente al rendimiento de la plataforma, lo cual es una gran noticia, que nos da vía libre para seguir avanzando en el control de errores.
Esto significa que nuestra cobertura actual en materia de gestión de errores es mínima. O dicho de otra forma, nuestro código puede fallar descontroladamente en muchas otras secciones de la plataforma.
Vamos a avanzar implementando las siguientes acciones: por un lado en los métodos MultithreadingCase y MultithreadingCaseWithErrors (y paulatinamente lo iremos haciendo en todos los testcases de todos los test) vamos a cubrir el código con las cláusulas try { } catch { }. Fíjense que al final de la ejecución de cada testcase llamamos al método EndTestCase (implementado en la clase base).
Este método genera los mensajes para el usuario, y además graba los tiempos de ejecución en base de datos. De modo que vamos a trasladar nuestro error provocado a la capa de datos y comprobar el comportamiento de la ejecución.
Vean que en el fragor del desarrollo he ido dejando controles de error sin demasiada coherencia, ya que funcionan individual, no colectivamente. El error que se origina en el repositorio no deja traza, queda oculto, excepto porque el método devuelve un valor false. Si se activase el catch en el método insertExecution de la clase test_functions pasaría lo mismo y finalmente, el valor verdadero o falso llega al método EndTestCase, que lo ignora por completo. Tanto usuario como desarrollador quedan ignorantes de todo lo ocurrido.
Bien pues nos toca corregir este pequeño desastre animal. Optaremos por lo siguiente: la escritura del error en el fichero log la delegaremos a la unidad lógica test , en la capa de negocio, tanto en la clase base como en sus derivadas, según nos interese.
Obviaremos el control de errores en los dos métodos InsertExecution, el del repositorio y el de test_functions. Todos deben quedar recogidos por el control de errores en MultithreadingCase (y todos los demás testcases), o bien en test_exec (clase base), en este caso en el método EndTestCase. Además al llegar el valor false al método EndTestCase aprovecharemos para darle un poquito de información al usuario, máxime en este caso en que usuario y desarrollador son la misma persona. Así quedaría (en MultithreadingCase no hay cambios):
Tras algunos cambios en el layout de la excepción, obtengo el resultado deseado, la traza completa del error en el fichero y la información correcta para el usuario:
Daré esta estrategia como temporalmente definitiva, y la iré incorporando en todos los métodos de negocio. Como ven es divertido dar con la estrategia de control de errores que mejor se adecue a la necesidad de nuestras soluciones. Les animo pues, a descargar la plataforma de test y compartir con nosotros sus propios experimentos. Seguiremos en próximas publicaciones explorando las muchas posibilidades que nacen de la combinación de la librería NLOG con las técnicas de control de errores.
Disfruten y aprendan amigos míos
Cobertura del control de errores y excepciones elevadas
Hasta ahora hemos securizado el método CalcFibo1, contenido en la clase test1_multithreading_vs_singlethreading, que es invocado en hilos independientes del hilo principal.Esto significa que nuestra cobertura actual en materia de gestión de errores es mínima. O dicho de otra forma, nuestro código puede fallar descontroladamente en muchas otras secciones de la plataforma.
Vamos a avanzar implementando las siguientes acciones: por un lado en los métodos MultithreadingCase y MultithreadingCaseWithErrors (y paulatinamente lo iremos haciendo en todos los testcases de todos los test) vamos a cubrir el código con las cláusulas try { } catch { }. Fíjense que al final de la ejecución de cada testcase llamamos al método EndTestCase (implementado en la clase base).
Este método genera los mensajes para el usuario, y además graba los tiempos de ejecución en base de datos. De modo que vamos a trasladar nuestro error provocado a la capa de datos y comprobar el comportamiento de la ejecución.
public void MultithreadingCase(ref TestCasesDomain _test) { TestCaseExecutionsDomain _execution = new TestCaseExecutionsDomain() { idTestCase = _test.id }; try { //registra inicio _execution.dtBegin = DateTime.Now; InitTestCase(_test.Function, _execution.dtBegin); //500 hilos calculan la serie fibo int cont = 0; while (cont < 500) { Thread thfibo = new Thread(() => CalcFibo1(cont)); _lst_process_control.Add(new objects.process_control() { Estado = objects.process_control.enumEstadoProceso.Ejecutando, Hilo = thfibo }); thfibo.Start(); Thread.Sleep(55); cont++; } while (_lst_process_control.Exists(pc => pc.Estado == objects.process_control.enumEstadoProceso.Ejecutando)) { Thread.Sleep(55); } //registra fin _execution.dtEnd = DateTime.Now; EndTestCase(_test.Function, _execution); _lst_process_control.Clear(); } catch (Exception ex) { _testexec.SetMsg("Error ejecutando MultithreadingCase"); _logger.Error(ex, "Error ejecutando MultithreadingCase"); } }
public void EndTestCase(string casename, TestCaseExecutionsDomain _testexec) { SetMsg(casename + " Case finalizado a las " + _testexec.dtEnd); SetMsg(casename + " Case ejecutado en " + _testexec.Miliseconds + " milisegundos"); _testobject.InsertExecution(_testexec); }
public override bool InsertExecution(TestCaseExecutionsDomain _testCaseExec) { bool res; try { res = _datatestrepository.InsertExecution(_testCaseExec); } catch (Exception) { return false; } return res; }
public bool InsertExecution(TestCaseExecutionsDomain _TestCaseExec) { try { ExecutionsModel _testexecmodel = mapper.Map<ExecutionsModel>(_TestCaseExec); using (var db = new context.LabsContext(_str_cnx)) { db.Executions.Add(_testexecmodel); //error!!!! object o2 = null; int i2 = (int)o2; db.SaveChanges(); } } catch (Exception ex) { return false; } return true; }
Vean que en el fragor del desarrollo he ido dejando controles de error sin demasiada coherencia, ya que funcionan individual, no colectivamente. El error que se origina en el repositorio no deja traza, queda oculto, excepto porque el método devuelve un valor false. Si se activase el catch en el método insertExecution de la clase test_functions pasaría lo mismo y finalmente, el valor verdadero o falso llega al método EndTestCase, que lo ignora por completo. Tanto usuario como desarrollador quedan ignorantes de todo lo ocurrido.
Bien pues nos toca corregir este pequeño desastre animal. Optaremos por lo siguiente: la escritura del error en el fichero log la delegaremos a la unidad lógica test , en la capa de negocio, tanto en la clase base como en sus derivadas, según nos interese.
Obviaremos el control de errores en los dos métodos InsertExecution, el del repositorio y el de test_functions. Todos deben quedar recogidos por el control de errores en MultithreadingCase (y todos los demás testcases), o bien en test_exec (clase base), en este caso en el método EndTestCase. Además al llegar el valor false al método EndTestCase aprovecharemos para darle un poquito de información al usuario, máxime en este caso en que usuario y desarrollador son la misma persona. Así quedaría (en MultithreadingCase no hay cambios):
public void EndTestCase(string casename, TestCaseExecutionsDomain _testexec) { try { _testobject.InsertExecution(_testexec); } catch (Exception ex) { SetMsg("Ha habido un problema al grabar los resultados en BBDD. Revise el fichero de erores"); _logger.Error(ex, "Error en EndTestCase(" + casename + ")"); } finally { SetMsg(casename + " Case finalizado a las " + _testexec.dtEnd); SetMsg(casename + " Case ejecutado en " + _testexec.Miliseconds + " milisegundos"); } }
public override bool InsertExecution(TestCaseExecutionsDomain _testCaseExec) { bool res = _datatestrepository.InsertExecution(_testCaseExec); return res; }
public bool InsertExecution(TestCaseExecutionsDomain _TestCaseExec) { ExecutionsModel _testexecmodel = mapper.Map<ExecutionsModel>(_TestCaseExec); using (var db = new context.LabsContext(_str_cnx)) { db.Executions.Add(_testexecmodel); //error!!!! object o2 = null; int i2 = (int)o2; db.SaveChanges(); } return true; }
Tras algunos cambios en el layout de la excepción, obtengo el resultado deseado, la traza completa del error en el fichero y la información correcta para el usuario:
<variable name="ExceptionLayout" value="${machinename} | ${longdate} | ${level:upperCase=true} | ${message} | ${exception:format=ToString,Properties,Data} " />
Daré esta estrategia como temporalmente definitiva, y la iré incorporando en todos los métodos de negocio. Como ven es divertido dar con la estrategia de control de errores que mejor se adecue a la necesidad de nuestras soluciones. Les animo pues, a descargar la plataforma de test y compartir con nosotros sus propios experimentos. Seguiremos en próximas publicaciones explorando las muchas posibilidades que nacen de la combinación de la librería NLOG con las técnicas de control de errores.
Disfruten y aprendan amigos míos
Comentarios
Publicar un comentario