Esta semana tive uma necessidade de log específica em um de nossos sistemas, que acabou gerando uma excelente adição para o nosso framework de desenvolvimento. A necessidade era saber o que acontecia em produção que acabava gerando um bug raro de valores no final do dia, e que fomos incapazes de reproduzir mesmo com uma grande quantidade de testes unitários. Aparentemente o bug está associado a uma condição de multi-usuário que é muito complicada de reproduzir. Para resolver este bug precisaríamos saber a seqüência exata em que as operações foram realizadas, e isto só seria possível com log.

A necessidade de log de negócio acaba surgindo vez por outra em aplicações. E, praticamente para cada sistema que eu já participei, foi feita uma solução diferente para log, com vantagens e desvantagens. Alguns usam log em banco, colocando triggers nas tabelas e replicando as informações, o que é extremamente simples de fazer mas gera grandes problemas de contenção e espaço utilizado. Outros usam versões do log4net gerando dados em arquivos, o que também é relativamente simples de fazer porém gera também dificuldade em ambientes massivamente multi-usuário – sem falar na dificuldade de processar os arquivos depois. Já fiz também log em banco, com e sem log4net, com bons resultados, mas sempre com uma solução específica para cada caso, o que causava um bom esforço de manutenção.

Outro ponto que sempre me incomodou é a questão da intrusividade das funções de log na regra de negócio. Tirando a solução em trigger de banco, qualquer implementação de log4net foi sempre feita com chamadas específicas de log dentro da rotina de negócio. Isto polui a rotina e dificulta a manutenção. Eu sempre tentei criar algo tipo AOP, mas nunca consegui uma solução boa. Mesmo atualmente, as bibliotecas conhecidas de AOP (PostSharp, Spring.Net etc.) não são uma boa opção para o nosso ambiente por serem um framework completo, de grande impacto…. Usar qualquer uma delas só pra log de algumas regras de negócio pra mim seria usar um canhão pra matar uma mosca.

Assim, resolvemos desta vez fazer algo decente, já incorporado ao framework, e que usasse uma abordagem AOP na medida do possível. Graças à tecnologia do Castle Windsor IoC usada atualmente no framework, isto foi relativamente simples de ser feito. Definimos na nossa arquitetura que o log de uma regra deveria ser expresso através da observação de parâmetros e retornos da função, antes e depois dela ser executada. Através do uso destas condições pré e pós, é possível identificar exatamente como aquela função afetou os dados.

Para implementar, o que fizemos foi usar o log4net para salvar eventos em banco. Até aí, solução padrão. O passo seguinte foi definir atributos AOP para marcar uma regra de negócio como sendo logada. O ideal teria sido definir as condições pré e pós no próprio atributo, porém o C# atualmente não suporta nada que não seja estático nos atributos; e usar strings eu acho uma prática ruim. A solução usada foi definir um tipo para o atributo que apontasse para uma classe que definiria quais são todas as condições, utilizando lambda.

O resultado ficou excelente. Abaixo está um exemplo do atributo na regra de negócio:

[Log(typeof(AtualizarValorDePosicaoLog))]
public void AtualizarValorAnterioDePosicao(Contrato contrato, 

                                    Posicao posicao, decimal valor) {

E no tipo de definição das condições, fica assim:

public class AtualizarValorDePosicaoLog : LoggerBase {

  public AtualizarValorDePosicaoLog() : base(

    Properties.PreCondition("valor"),
    Properties.PreCondition<Contrato>(

      c => c.Id, c => c.Tipo, c => c.TipoBacen, 

      c => c.Moeda, c => c.Posto, c => c.ValorMoedaEstrangeira, 
      c => c.ValorMoedaNacional, c => c.ValorUSD, c => c.TipoPagamento),
    Properties.PreCondition<Posicao>(

      p => p.Id, p => p.ValorPosicaoAnterior, p => p.Conformidade, 

      p => p.Baixa, p => p.Transferencias, 
      p => p.TotalCompra, p => p.TotalVenda, p => p.Moeda, p => p.Posto, 

      p => p.Tipo),

    Properties.PostCondition<Posicao>(

      p => p.Id, p => p.ValorPosicaoAnterior, p => p.Conformidade, 

      p => p.Baixa, p => p.Transferencias, 
      p => p.TotalCompra, p => p.TotalVenda, p => p.Moeda, p => p.Posto, 

      p => p.Tipo)) { }
    }

Na execução, o interceptor da classe de serviço busca o atributo, instancia o tipo de definição e coleta os dados, antes e depois da rotina executar. Para minimizar o impacto em tempo de execução, o logger simplesmente armazena um dicionário com todas as condições recolhidas, serializando num XML. Posteriormente, de maneira assíncrona e com baixa prioridade, um executor analisa os registros de log gerados e expande cada condição em tabelas do tipo dicionário.

Com isto o impacto ficou bem pequeno e conseguimos fazer algo quase puramente AOP e sem nenhuma definição em string! Finalmente conseguimos uma implementação boa para log, que deve nos atender por muito tempo.

Nesta solução, alem da equipe da WhiteFox, tivemos a colaboração do arquiteto Fernando Bichara, da Perlink.