Mientras leía el
Radar de Tecnología ThoughtWorks , me encontré con la técnica de "
Registro separado por solicitud ". En
Confirmit hacemos un amplio uso del registro, y me preguntaba cómo se podría implementar esta funcionalidad.
Descripción del problema
Veamos qué está en juego. Supongamos que tenemos un servicio web. En algún momento, comienza a fallar en los servidores de producción, pero solo para algunas solicitudes. Por ejemplo, los bloqueos ocurren solo para un usuario específico. O solo en un punto de acceso separado ... Necesitamos encontrar una razón. En este caso, la tala viene en nuestra ayuda.
Podemos insertar suficientes instrucciones de registro en nuestro código para comprender la causa del problema. Estas instrucciones generalmente hacen coincidir su mensaje con un cierto nivel de registro (Depuración, Información, Advertencia, ...). Además, el registro en sí también tiene su propio nivel. Todos los mensajes con niveles superiores al nivel de registro se registrarán en el almacenamiento de registro (archivo, base de datos, ...). Si el nivel del mensaje es inferior al nivel de registro, el mensaje simplemente se descartará.
Cuando nuestra aplicación funciona bien, queremos ver la menor cantidad posible de entradas de registro para que su tamaño siga siendo pequeño. Al mismo tiempo, si la aplicación falla, queremos que el registro tenga suficientes entradas para que podamos entender la causa del problema. La dificultad aquí es que generalmente establecemos un nivel de registro para todos los registradores en nuestra aplicación. Si todo está en orden, mantenemos este nivel alto (por ejemplo, Advertencia). Si necesitamos buscar la causa de la falla, la instalamos a continuación (por ejemplo, Depuración).
Un nivel de registro por aplicación
Cuando establecemos el nivel de registro en la aplicación bajo, nuestros almacenes de registros se llenan de una gran cantidad de mensajes. Estos mensajes provienen de diferentes solicitudes y se mezclan entre sí, ya que las solicitudes se pueden servir simultáneamente. Esto lleva a una serie de problemas potenciales:
- ¿Cómo separar los mensajes de solicitudes problemáticas de los mensajes de otras solicitudes?
- Las solicitudes que no provocan bloqueos aún pasan su tiempo escribiendo en el repositorio de registros, aunque estos mensajes nunca se utilizarán.
- Los mensajes de solicitudes exitosas ocuparán espacio en los repositorios de registros, aunque estos mensajes nunca se utilizarán.
Honestamente, estas dificultades no son insuperables. Para separar los mensajes de solicitudes "buenas" de los mensajes de solicitudes "malas", puede usar la
identificación de correlación . Todos los sistemas modernos de procesamiento de registros permiten filtrar registros por diversos criterios, incluido esto.
El rendimiento tampoco suele ser un problema importante. Los sistemas de registro admiten la grabación asincrónica, por lo que el efecto del registro masivo generalmente no es perjudicial.
Y el espacio en disco ahora es relativamente barato, por lo que almacenar muchos registros no es un problema. Especialmente si podemos eliminar registros antiguos de vez en cuando.
Sin embargo, ¿podemos mejorar este sistema? ¿Podemos establecer un nivel de registro separado para cada solicitud, dependiendo de ciertas condiciones? Me gustaría considerar este problema aquí.
Nivel de registro separado para cada solicitud
Permítanme establecer los requisitos para la solución que implementaré. Debe haber una manera de establecer un nivel de registro separado para cada solicitud. Debe haber una forma flexible de especificar las condiciones que determinan la elección de este nivel para una solicitud en particular. Y debería ser posible cambiar estas condiciones durante la ejecución del programa sin la necesidad de reiniciarlo.
Entonces, la tarea está establecida. Empecemos
Crearé un servicio web simple basado en .NET Core. Tendrá un solo controlador:
[Route("api/[controller]")] [ApiController] public class ValuesController : ControllerBase { ...
Discutiremos la implementación de la propiedad
Logger más adelante. Para esta aplicación,
usaré la biblioteca
log4net para iniciar sesión. Esta biblioteca ofrece una oportunidad interesante. Estoy hablando de
herencia de nivel . En resumen, si en la configuración de esta biblioteca usted dice que el registro con el nombre
X debe tener el nivel de registro de
Información , esto significa que todos los registros con nombres que comienzan con
X. (por ejemplo,
XY ,
XZ ,
XAB ) heredarán este mismo nivel.
De aquí viene la idea original. Para cada solicitud, determinaré de alguna manera el nivel requerido de registro. Luego crearé un nuevo registro con nombre en la configuración de
log4net . Este registro tendrá el nivel de registro requerido. Después de eso, todos los objetos de registro creados como parte de la solicitud actual deben tener nombres que comiencen con el nombre de este nuevo registro creado por mí. El único problema aquí es que
log4net nunca elimina los registros. Una vez creados, existen durante toda la vida de la aplicación. Por esta razón, inicialmente creo un registro para cada posible nivel de registro:
<?xml version="1.0" encoding="utf-8" ?> <log4net> <appender name="Console" type="log4net.Appender.ConsoleAppender"> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%5level [%thread] (%file:%line) - %message%newline" /> </layout> </appender> <appender name="RollingFile" type="log4net.Appender.RollingFileAppender"> <file value="RequestLoggingLog.log" /> <appendToFile value="true" /> <maximumFileSize value="100KB" /> <maxSizeRollBackups value="2" /> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%level %thread %logger - %message%newline" /> </layout> </appender> <root> <level value="WARN" /> <appender-ref ref="Console" /> <appender-ref ref="RollingFile" /> </root> <logger name="EdlinSoftware.Log.Error"> <level value="ERROR" /> </logger> <logger name="EdlinSoftware.Log.Warning"> <level value="WARN" /> </logger> <logger name="EdlinSoftware.Log.Info"> <level value="INFO" /> </logger> <logger name="EdlinSoftware.Log.Debug"> <level value="DEBUG" /> </logger> </log4net>
Ahora tengo varios registros con los nombres
EdlinSoftware.Log.XXXX . Estos nombres servirán como prefijos de los nombres de registro utilizados en las consultas. Para evitar colisiones entre solicitudes, almacenaré el prefijo calculado para esta solicitud en una instancia
AsyncLocal . El valor de este objeto se establecerá en el nuevo middleware OWIN:
app.Use(async (context, next) => { try { LogSupport.LogNamePrefix.Value = await LogSupport.GetLogNamePrefix(context); await next(); } finally { LogSupport.LogNamePrefix.Value = null; } });
Cuando se establece este valor, es muy fácil crear registradores con el prefijo de nombre deseado:
public static class LogSupport { public static readonly AsyncLocal<string> LogNamePrefix = new AsyncLocal<string>(); public static ILog GetLogger(string name) { return GetLoggerWithPrefixedName(name); } public static ILog GetLogger(Type type) { return GetLoggerWithPrefixedName(type.FullName); } private static ILog GetLoggerWithPrefixedName(string name) { if (!string.IsNullOrWhiteSpace(LogNamePrefix.Value)) { name = $"{LogNamePrefix.Value}.{name}"; } return LogManager.GetLogger(typeof(LogSupport).Assembly, name); } .... }
Ahora está claro cómo obtener una instancia de registrador en nuestro controlador:
[Route("api/[controller]")] [ApiController] public class ValuesController : ControllerBase { private ILog _logger; private ILog Logger { get => _logger ?? (_logger = LogSupport.GetLogger(typeof(ValuesController))); } .... }
Queda por hacer solo una cosa: de alguna manera establecer las reglas por las cuales elegimos el nivel de registro para cada solicitud. Este debería ser un mecanismo bastante flexible. La idea básica es usar secuencias de comandos de C #.
Crearé un archivo
LogLevelRules.json , donde
definiré un conjunto de pares de "regla - nivel de registro":
[ { "logLevel": "Debug", "ruleCode": "context.Request.Path.Value == \"/api/values/1\"" }, { "logLevel": "Debug", "ruleCode": "context.Request.Path.Value == \"/api/values/3\"" } ]
Aquí
logLevel es el nivel deseado de registro, y
ruleCode es un código C # que devuelve un valor booleano para la solicitud dada. La aplicación ejecutará los códigos de regla uno por uno. La primera regla, cuyo código devuelve verdadero, se usará para establecer el nivel apropiado de registro. Si todas las reglas devuelven falso, se utilizará el nivel predeterminado.
Para crear delegados a partir de una representación en cadena de reglas, se
utiliza la clase
CSharpScript :
public class Globals { public HttpContext context; } internal class LogLevelRulesCompiler { public IReadOnlyList<LogLevelRule> Compile(IReadOnlyList<LogLevelRuleDescription> levelRuleDescriptions) { var result = new List<LogLevelRule>(); foreach (var levelRuleDescription in levelRuleDescriptions ?? new LogLevelRuleDescription[0]) { var script = CSharpScript.Create<bool>(levelRuleDescription.RuleCode, globalsType: typeof(Globals)); ScriptRunner<bool> runner = script.CreateDelegate(); result.Add(new LogLevelRule(levelRuleDescription.LogLevel, runner)); } return result; } } internal sealed class LogLevelRule { public string LogLevel { get; } public ScriptRunner<bool> Rule { get; } public LogLevelRule(string logLevel, ScriptRunner<bool> rule) { LogLevel = logLevel ?? throw new ArgumentNullException(nameof(logLevel)); Rule = rule ?? throw new ArgumentNullException(nameof(rule)); } }
Aquí, el método
Compile obtiene una lista de objetos leídos del archivo
LogLevelRules.json . Crea un delegado de
corredor para cada regla.
Esta lista de delegados se puede guardar:
LogSupport.LogLevelSetters = new LogLevelRulesCompiler().Compile( new LogLevelRulesFileReader().ReadFile("LogLevelRules.json") );
y usado en el futuro:
public static class LogSupport { internal static IReadOnlyList<LogLevelRule> LogLevelSetters = new LogLevelRule[0]; ... public static async Task<string> GetLogNamePrefix(HttpContext context) { var globals = new Globals { context = context }; string result = null; foreach (var logLevelSetter in LogLevelSetters) { if (await logLevelSetter.Rule(globals)) { result = $"EdlinSoftware.Log.{logLevelSetter.LogLevel}"; break; } } return result; } }
Por lo tanto, cuando se inicia la aplicación, leemos
LogLevelRules.json , convertimos su contenido a la lista de delegados utilizando la clase
CSharpScript y
guardamos esta lista en el campo
LogSupport.LogLevelSetters . Luego, para cada solicitud, ejecutamos delegados de esta lista para obtener el nivel de registro.
Lo único que queda por hacer es realizar un seguimiento de los cambios en el archivo
LogLevelRules.json . Si queremos establecer el nivel de registro para algunas consultas, agregamos una nueva regla a este archivo. Para forzar a nuestra aplicación a aplicar estos cambios sin reiniciar, es necesario monitorear el archivo:
var watcher = new FileSystemWatcher { Path = Directory.GetCurrentDirectory(), Filter = "*.json", NotifyFilter = NotifyFilters.LastWrite }; watcher.Changed += (sender, eventArgs) => {
Cabe señalar que, en aras de la brevedad, omití el código de sincronización de flujo al trabajar con el campo
LogSupport.LogLevelSetters . Pero en la práctica, se requiere dicha sincronización.
El código completo de la aplicación se puede encontrar en
GitHub .
Desventajas
El código que se muestra arriba le permite resolver el problema de establecer un nivel de registro separado para cada solicitud. Pero tiene varias deficiencias. Hablemos de ellos.
1. Este enfoque cambia los nombres de los registros. Entonces, en lugar de "
MyClassLogger ", algo como "
Edlinsoft.Log.Debug.MyClassLogger " se almacenará en el repositorio de registros. Puedes vivir con él, pero no es muy conveniente. Quizás el problema se pueda superar cambiando el diseño del registro (diseño del registro).
2. Ahora es imposible usar instancias estáticas de las clases de registrador, ya que deben crearse por separado para cada solicitud. El problema más serio aquí, en mi opinión, es que los desarrolladores siempre deben tener esto en cuenta. Alguien podría crear accidentalmente un campo estático con un registrador y obtener resultados extraños. Puede superar esta situación creando una clase de contenedor para registradores en lugar de usar
las clases
log4net directamente. Tal contenedor siempre puede crear nuevas instancias de
log4net loggers para cada operación. En este caso, se puede usar libremente en campos estáticos.
3. El enfoque descrito crea muchas instancias de registradores. Esto consume memoria y ciclos de procesador tanto durante la creación como durante la recolección de basura. Dependiendo de su aplicación, esto puede o no ser un problema importante.
4. Cuando cambiamos el archivo JSON con las reglas, el código de la regla puede contener errores. Es muy simple usar bloques try-catch para que estos errores no destruyan nuestra aplicación principal. Sin embargo, de alguna manera necesitamos descubrir que algo salió mal. Hay dos tipos de errores:
- Errores de tiempo de compilación para código de regla en delegados.
- Errores de tiempo de ejecución de estos delegados.
De alguna manera, necesitamos descubrir estos errores, de lo contrario nuestro registro simplemente no funcionará, y ni siquiera lo sabremos.
5. El código de la regla en el archivo JSON puede, en principio, contener instrucciones. Esto podría conducir a problemas de seguridad. Es necesario limitar de alguna manera las capacidades de este código. Por otro lado, si un atacante puede escribir directamente en los archivos de su aplicación, entonces el problema de seguridad es obvio.
Conclusión
En general, no tuve la impresión de que tal solución debería reemplazar el enfoque existente para el registro. Una buena herramienta con la capacidad de filtrar entradas de registro puede ayudar aquí, incluso cuando se utiliza un solo nivel de registro para toda la aplicación. Sin embargo, espero que el análisis de este problema le dé reflexiones.