Ao ler o
Radar de tecnologia da
ThoughtWorks , deparei-me com a técnica “
Log separado por solicitação ”. Na
Confirmit, fazemos uso extensivo do log e fiquei imaginando como essa funcionalidade poderia ser implementada.
Descrição do problema
Vamos ver o que está em jogo. Suponha que tenhamos um serviço da web. Em algum momento, ele começa a travar nos servidores de produção, mas apenas para alguns pedidos. Por exemplo, falhas ocorrem apenas para um usuário específico. Ou apenas em um ponto de acesso separado ... Precisamos encontrar um motivo. Nesse caso, o registro vem em nosso auxílio.
Podemos inserir instruções de registro suficientes em nosso código para entender a causa do problema. Essas instruções geralmente correspondem à sua mensagem com um certo nível de log (depuração, informações, aviso, ...). Além disso, o próprio log também possui seu próprio nível. Todas as mensagens com níveis acima do nível do log serão gravadas no armazenamento de log (arquivo, banco de dados, ...). Se o nível da mensagem for inferior ao nível do log, a mensagem será simplesmente descartada.
Quando nosso aplicativo funciona bem, queremos ver o menor número possível de entradas de log, para que seu tamanho permaneça pequeno. Ao mesmo tempo, se o aplicativo falhar, queremos que o log tenha entradas suficientes para que possamos entender a causa do problema. A dificuldade aqui é que geralmente definimos um nível de registro para todos os registradores em nosso aplicativo. Se tudo estiver em ordem, manteremos esse nível alto (por exemplo, Aviso). Se precisarmos procurar a causa da falha, instale-a abaixo (por exemplo, Debug).
Um nível de log por aplicativo
Quando definimos o nível de log no aplicativo baixo, nossos armazenamentos de log são preenchidos com uma massa de mensagens. Essas mensagens vêm de solicitações diferentes e são misturadas entre si, pois as solicitações podem ser atendidas simultaneamente. Isso leva a vários problemas em potencial:
- Como separar mensagens de pedidos problemáticos de mensagens de outros pedidos?
- As solicitações que não levam a falhas ainda gastam seu tempo gravando no repositório de logs, embora essas mensagens nunca sejam usadas.
- As mensagens de solicitações bem-sucedidas ocuparão espaço nos repositórios de log, embora essas mensagens nunca sejam usadas.
Honestamente, essas dificuldades não são intransponíveis. Para separar as mensagens dos pedidos "bons" das mensagens dos pedidos "ruins", você pode usar o
ID de correlação . Todos os sistemas modernos de processamento de logs permitem filtrar registros por vários critérios, incluindo este.
O desempenho também geralmente não é um problema importante. Os sistemas de log oferecem suporte à gravação assíncrona, de modo que o efeito do log maciço geralmente não é perturbador.
E agora o espaço em disco é relativamente barato, portanto, armazenar muitos registros não é um problema. Especialmente se pudermos excluir registros antigos de tempos em tempos.
No entanto, podemos melhorar este sistema? Podemos definir um nível de log separado para cada solicitação, dependendo de determinadas condições? Eu gostaria de considerar esse problema aqui.
Nível de log separado para cada solicitação
Deixe-me indicar os requisitos para a solução que implementarei. Deve haver uma maneira de estabelecer um nível de log separado para cada solicitação. Deve haver uma maneira flexível de especificar as condições que determinam a escolha desse nível para uma solicitação específica. E deve ser possível alterar essas condições durante a execução do programa sem a necessidade de reiniciá-lo.
Então, a tarefa está definida. Vamos começar.
Vou criar um serviço web simples baseado no .NET Core. Ele terá um único controlador:
[Route("api/[controller]")] [ApiController] public class ValuesController : ControllerBase { ...
Discutiremos a implementação da propriedade
Logger posteriormente. Para esta aplicação, usarei a biblioteca
log4net para o log. Esta biblioteca oferece uma oportunidade interessante. Eu estou falando sobre
herança de nível . Em resumo, se na configuração desta biblioteca você disser que o log com o nome
X deve ter o nível de log
Info , isso significa que todos os logs com nomes começando com
X. (por exemplo,
XY ,
XZ ,
XAB ) herdarão esse mesmo nível.
A partir daqui vem a ideia original. Para cada solicitação, determinarei de alguma forma o nível de log necessário. Então, criarei um novo log nomeado na configuração
log4net . Esse log terá o nível de log necessário. Depois disso, todos os objetos do criador de logs criados como parte da solicitação atual devem ter nomes começando com o nome desse novo log criado por mim. O único problema aqui é que o
log4net nunca remove os logs. Uma vez criados, eles existem ao longo da vida útil do aplicativo. Por esse motivo, criei inicialmente um log para cada nível possível de log:
<?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>
Agora eu tenho vários logs com os nomes
EdlinSoftware.Log.XXXX . Esses nomes servirão como prefixos de nomes de log usados nas consultas. Para evitar colisões entre solicitações, armazenarei o prefixo calculado para essa solicitação em uma instância
AsyncLocal . O valor desse objeto será definido no novo middleware OWIN:
app.Use(async (context, next) => { try { LogSupport.LogNamePrefix.Value = await LogSupport.GetLogNamePrefix(context); await next(); } finally { LogSupport.LogNamePrefix.Value = null; } });
Quando esse valor é definido, é muito fácil criar registradores com o prefixo de nome desejado:
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); } .... }
Agora está claro como obter uma instância de logger em nosso controlador:
[Route("api/[controller]")] [ApiController] public class ValuesController : ControllerBase { private ILog _logger; private ILog Logger { get => _logger ?? (_logger = LogSupport.GetLogger(typeof(ValuesController))); } .... }
Resta fazer apenas uma coisa: de alguma forma, definir as regras pelas quais escolhemos o nível de log para cada solicitação. Este deve ser um mecanismo bastante flexível. A idéia básica é usar scripts em C #. Vou criar um arquivo
LogLevelRules.json , onde definirei um conjunto de pares "regra - nível de log":
[ { "logLevel": "Debug", "ruleCode": "context.Request.Path.Value == \"/api/values/1\"" }, { "logLevel": "Debug", "ruleCode": "context.Request.Path.Value == \"/api/values/3\"" } ]
Aqui,
logLevel é o nível de log desejado e
ruleCode é um código C # que retorna um valor booleano para a solicitação especificada. O aplicativo executará os códigos de regra um por um. A primeira regra, cujo código retorna true, será usada para definir o nível apropriado de log. Se todas as regras retornarem falsas, o nível padrão será usado.
Para criar delegados a partir de uma representação de sequência de regras, a classe
CSharpScript é
usada :
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)); } }
Aqui, o método
Compile recupera uma lista de objetos lidos no arquivo
LogLevelRules.json . Ele cria um delegado de
corredor para cada regra.
Esta lista de delegados pode ser salva:
LogSupport.LogLevelSetters = new LogLevelRulesCompiler().Compile( new LogLevelRulesFileReader().ReadFile("LogLevelRules.json") );
e usado no 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; } }
Portanto, quando o aplicativo é iniciado, lemos
LogLevelRules.json , convertemos seu conteúdo na lista de delegados usando a classe
CSharpScript e salve essa lista no campo
LogSupport.LogLevelSetters . Em seguida, para cada solicitação, executamos delegados dessa lista para obter o nível de log.
A única coisa a fazer é rastrear alterações no arquivo
LogLevelRules.json . Se quisermos definir o nível de log para algumas consultas, adicionamos uma nova regra a esse arquivo. Para forçar nosso aplicativo a aplicar essas alterações sem reiniciar, é necessário monitorar o arquivo:
var watcher = new FileSystemWatcher { Path = Directory.GetCurrentDirectory(), Filter = "*.json", NotifyFilter = NotifyFilters.LastWrite }; watcher.Changed += (sender, eventArgs) => {
Deve-se observar que, por questões de brevidade, omiti o código de sincronização do fluxo ao trabalhar com o campo
LogSupport.LogLevelSetters . Mas, na prática, essa sincronização é necessária.
O código completo do aplicativo pode ser encontrado no
GitHub .
Desvantagens
O código mostrado acima permite solucionar o problema de definir um nível de log separado para cada solicitação. Mas ele tem várias deficiências. Vamos discuti-los.
1. Essa abordagem altera os nomes dos logs. Portanto, no repositório de logs, em vez de "
MyClassLogger ", algo como "
Edlinsoft.Log.Debug.MyClassLogger " será armazenado. Você pode viver com isso, mas não é muito conveniente. Talvez o problema possa ser superado alterando o layout do log (layout do log).
2. Agora é impossível usar instâncias estáticas das classes do criador de logs, pois elas devem ser criadas separadamente para cada solicitação. O problema mais sério aqui, na minha opinião, é que os desenvolvedores devem sempre ter isso em mente. Alguém pode criar acidentalmente um campo estático com um registrador e obter resultados estranhos. Você pode superar essa situação criando uma classe de wrapper para registradores em vez de usar as classes
log4net diretamente. Esse invólucro sempre pode criar novas instâncias de
log4net loggers para cada operação. Nesse caso, ele pode ser usado livremente em campos estáticos.
3. A abordagem descrita cria muitas instâncias de loggers. Isso consome ciclos de memória e processador durante a criação e durante a coleta de lixo. Dependendo do seu aplicativo, isso pode ou não ser um problema significativo.
4. Quando alteramos o arquivo JSON com as regras, o código da regra pode conter erros. É muito simples usar blocos try-catch para que esses erros não destruam nosso aplicativo principal. No entanto, precisamos de alguma forma descobrir que algo deu errado. Existem dois tipos de erros:
- Erros de tempo de compilação para código de regra em delegados.
- Erros de tempo de execução desses delegados.
De alguma forma, precisamos descobrir sobre esses erros, caso contrário, nosso registro simplesmente não funcionará e nem saberemos sobre isso.
5. O código da regra no arquivo JSON pode, em princípio, conter qualquer instrução. Isso pode levar a problemas de segurança. É necessário limitar de alguma forma os recursos desse código. Por outro lado, se um invasor conseguir gravar diretamente nos arquivos do seu aplicativo, o problema de segurança será óbvio.
Conclusão
Em geral, não tive a impressão de que essa solução substituísse a abordagem existente para o log. Uma boa ferramenta com a capacidade de filtrar entradas de log pode ajudar aqui, mesmo ao usar um único nível de log para todo o aplicativo. No entanto, espero que a análise deste problema dê a você um pensamento.