Inversão de Controle e Logging

Hoje em dia já sabemos bem as vantagens de utilizar uma API de log como o famoso Log4J. Várias encarnações e variantes existem, inclusive para outras plataformas como o Log4Net, mas o conceito é sempre o mesmo, externalizar informações que permitam saber o que está acontecendo no código. Na prática, a funcionalidade de logging é muito importante e vital para quando o código está em produção e as restrições de segurança apenas permitem ter acesso ao arquivo de log.

Tipicamente o logger – o objeto responsável por realizar o registro da informação – é obtido e associado à classe para depois ser usado explicitamente no código. Com ferramentas como o Log4J cada classe detém uma instancia do logger que lhe corresponde. O log4j também se encarrega de criar apenas uma instancia para cada Logger (padrão Shared Object) de forma que o método de onde obtemos o Logger para a classe (padrão Service Locator), só crie o objeto da primeira vez. Normalmente os programadores atribuem o logger a um campo estático com base no argumento de que apenas um objeto é necessário. Correto, mas se deixarmos o campo não estático o resultado será o mesmo em termos de objetos na memoria. Apenas teremos mais referencias ao mesmo objecto.

O uso de campos estáticos aliados a implementações de Service Locator também elas acessíveis estaticamente dá origem a um código mais simples de escrever, contudo mais acoplado e portanto mais difícil de testar e evoluir. Coisas estáticas são controladas pela VM e quase não existem formas de interceptar a criação e destruição dos objetos. É por isso que métodos estáticos são considerados coisas ruins (static is evil).

Se quisermos fugir desdes problemas  o caminho que nos sobra é utilizar Inversão de Dependência, ou seja, nenhuma classe pode ter conhecimento da criação dos objetos que usa. Para os objetos de log isto significa utilizar um campo de instancia, em vez de um campo estático, e injetar o logger, em vez de usar o método estático da API de log. Com isto deixamos de nos preocupar sobre qual, como e quando a funcionalidade de log será usada. Passa a ser responsabilidade do instanciador da classe prover o objeto correto. Então o código que normalmente é algo como:

public class SampleService {

   private static ILog logger = LogManager.GetLogger(typeOf(MyApp));

   public void MetodoA(){

     logger.info("Entering application at " + new DateTime());
   }
}

passaria a ser algo como :

public class SampleService {

   private ILog logger;

   public  SampleService (ILog logger){
       this.logger = logger;
   }

   public void MetodoA(){

     logger.info("Entering application at " + new DateTime());
   }
 }

Repare que o objeto de log passa a ser uma dependência explicita da classe ILog. Do ponto de vista do design orientado a objetos é isto mesmo que deve acontecer ao usar a inversão de controle. Mas se entendermos o logging como uma capacidade ortogonal do software, isto não é muito prático. Deveria ser possível usar logging com injeção de dependência e sem ter que se preocupar com um dependência explicita no construtor, da mesma forma como usaríamos outras capacidades ortogonais como controle de transação e segurança.É possível fazer isto de várias formas. Poderíamos utilizar Programação Orientada a Aspetos, com ou sem weaving em tempo de compilação. Mas na prática é mais comum termos à mão um Contêiner de Injeção, como o Spring ou o Guice, que já são comuns em ambientes de desenvolvimento hoje em dia. Ao usar um contêiner de injeção necessitaríamos de configurar todos os objetos a sua injeção do logger correto, e mais uma vez isso obrigaria a um controle explicito, em que não estamos interessados.Com o Spring é relativamente simples criar um pós-processador que se encarrega de incluir a instancia do Logger na classe. Também podemos usar o mecanismo de fábrica e prover uma fábrica para o tipo de interface que estivermos usamos. Contudo, o injetor com pós-processador tem algumas vantagens sobre a fabrica porque permite informar ao mecanismo de decide que log usar e qual a classse em que o logger está sendo injetado. Este conceito de “contexto de injeção” não existe na fábrica mas é essencial para escolher o log certo. Sendo o nosso objeto controlado pelo Spring o código ficaria assim:

public class SampleService {

private ILog logger;

public  SampleService (){
}

public void MetodoA(){
logger.info("Entering application at {0}" , new DateTime());
}
}

Não é mais necessário que o construtor receba o logger porque o pós-processador irá garantir que ele será injetado. O trade-off aqui é utilizar o contêiner de injeção para permitir esconder as dependências ortogonais que existem entre a classe do serviço e a API de logging. Dito de outra forma, é usada o contêiner para realizar injeções em campos privados. Ao fazer isto, somos obrigados a transferir para o contêiner de injeção a configuração de como obter o objeto correto. O Spring, como os outros contêiner de injeção permite utilizar objetos fábrica (padrão Factory) para isto delegando a estes a construção ou obtenção real do objeto de log e em particular é possível injetar esse objeto de fábrica no pós-processador. Usamos o Spring como um motor de injeção e deixamos o controle da injeção do quê injetar em uma classe nossa. Aqui também estamos usando a inversão de controle não deixando o Spring decidir como obter o objeto de log. Para isso precisamos de desenhar um objeto novo cuja responsabilidade será obter a instancia correta para o logger:

public interface ILoggerProvider {
ILogger Provide(InjectionPoint point);
}

O segredo é a classe InjectionPoint, que nos dá a informação de onde a injeção está sendo feita. Normalmente basta a classe a que o campo pertence, mas há liberdade de acrescentar outras coisas. Entenda que estamos invertendo o controle várias vezes. Não apenas o Spring não saberá criar o objeto ele ainda terá que nos dizer onde está tentando injetar o objeto. A implementação, para o Log4Net, por exemplo, ficaria assim :

public class Log4NetLoggerProvider : ILoggerProvider
{
   public ILog Provide(InjectionPoint point){
 	return LogManager.GetLogger(point.SurroundingType);
   }
}

Ao olho destreinado parece que estamos realizando sobre-engenharia. Um monte classes a mais, um framework a mais e tudo para escrever a mesma linha que tínhamos antes. Isto é correto. Parece realmente que estamos jogando trabalho fora. Mas agora imagine que seu projeto não tem apenas um serviço, tem 10, 20, 30… e que tem 100 classes onde é preciso injetar logging. Tudo bem que escrever 100 linhas iguais por copy-paste não dá muito trabalho, o trabalho vem quando você precisa mudar alguma coisa. Quando você está rodando a aplicação em ambientes diferentes do de produção em que o Log deve se comportar de forma diferente, ou quando você precisa testar a classe unitariamente. Com a chamada estática explicita no seu código não há como alterar nada em runtime para existe um comportamento diferente. Como a Inversão de Controle você simplesmente passa outro objeto no construtor. Com o Contêiner de Inversão, você simplesmente utiliza outra implementação do ILoggerProvider.  Podemos argumentar que esta forma de injetar o logger é muito menos simples que a forma tradicional. Sim, é verdade. É muito menos simples. Mas é muito mais desacoplada. É comum terem que existir trade-offs entre um bom design e facilidade de produzir código. Essa escolha é de cada um, o ponto aqui é demonstrar como você pode realizar a inversão, se e quando quiser, ou precisar.

Mas a Inversão de Controle não pára por aqui. Ainda temos uma dependência direta de uma interface da API de log. Esta interface nos obriga a criar objetos de mensagem e tem métodos utilitários para usar Strings. Isto é bom a maioria das vezes. Mas nem sempre. Um dos idiomas muito usado junto com apis de logger é o use de concatenação de Strings para prover mensagens legíveis para seres humanos e que mesmo assim contenham a informação que precisamos. Como diminuir o uso deste idioma ?

A solução para o dilema é criar uma interface própria para um logger, com a respetiva implementação que delega para o framework de log preferido. Esta solução é a mais desacoplada e nos permite evoluir as funcionalidades de log independentemente da API que usamos (padrão Bridge). Por exemplo, API modernas permitem enviar templates de mensagem e passar os parâmetros à parte, em vez de obrigar a concatenar tudo em um string único. Isto aumenta a simplicidade para quem escreve , a legibilidade para quem lê e a performance.

É comum isolar a API de log real do seu código. Isto permite um nível de indireção a mais que lhe permite mudar de implementação de log quando e pela razão que quiser. Esta prática é comum e o famoso framework Commons Logging (tanto em java como em .net) serve exatamente para isto. Frameworks de mercado com o Hibernate e o referido Spring utilizam-se desta estratégia tanto nas suas versões java como .net.Recentemente, no mundo java, uma nova API começou a ser adotada como mediador entre o código e a real implementação do log, o SLF4J (Simple Logging Façade 4 Java) Quando apareceu o SLF4J o pessoal que quis migrar teve que mudar o seu código, pois o SLF4J concorre com o Commons-Loggin em funcionalidade e é mais moderno (por exemplo, dando a opção de usar os referidos templates). Embora exista a opção de combinar ambos, convenhamos que do ponto de vista de design é uma confusão. Ou se usa um, ou se usa outro. Isto significa que isolar uma API de terceiros usando uma API de terceiros não resolve muito. O Commons-Logging é uma API da Apache para projetos da Apache., que acontece que é open source. Mas conceitualmente a Commons-Logging , do ponto de vista da Apache, é uma API própria, não de terceiros. Isto significa que não apenas queremos isolar a real implementação do Logging, como queremos isolá-la através de uma API nossa. Com a nossa inversão de controle e delegação ao contêiner de injeção podemos usar uma estratégia semelhante facilmente.

Primeiro criamos um interface para o logger, ILogger e modificamos a nossa classe e o nosso provider

</p>

<pre>public class SampleService {

   private ILogger logger;

   public void MetodoA(){

     logger.info("Entering application at {0}" , new Date());

   }
}

public class Log4NetLoggerProvider : ILoggerProvider
{
   public ILogger Provide(InjectionPoint point){
 	return new Log4NetWrapper(LogManager.GetLogger(point.SurroundingType));
   }
}

Um simples refactoring de ILog para ILogger que qualquer IDE, que mereça esse nome, sabe fazer hoje em dia. É importante entender que não estamos mudando nada em termos de performance de logging nem estamos criando mais instancia do que necessário pois o framework já controla isso, mas se estivermos usando um framework que não controla isso podemos usar o próprio Spring para fazer esse controle usando um factory especifico que encapsula o factory do framework. Este tipo de inversão que se utiliza de um mediador (padrão Bridge) nos permite ainda acionar features na nossa interface de log que não necessariamente existem no framework usado por baixo dos panos.Como exemplo da capacidade de extensão, podemos usar a ideia de não criar a mensagem com operadores de concatenação e deixar o framework fazer isso depois e só quando a mensagem for realmente ser logada. É comum mensagens de debug conterem vários detalhes e valores que são capturados mesmo quando o nivel de debug está desabilitado.

public class MyApp {

   private ILogger logger;

   public void MetodoA(String a, String b) {

     // versão comum
     logger.info("foi usando a=" + a + “ e b= “ + b);

   }
 }

Estamos explicitamente concatenando, seria melhor deixar isso para quem sabe, assim:

public class MyApp {

   private ILogger logger;

   public void MetodoA(String a, String b) {

     // versão nova
     logger.info("foi usando a= {0} e b= {1}“, a,  b);

   }
 }

O controle do que fazer com a e b é tirado do nosso código e colocado no código do logger. Isto é uma nova inversão de controle Desta forma, o logger só precisa subsituir os placeholders {n} com os valores das variáveis se o nivel info estiver habilitado. Além disso, a forma como isso será feito é deixado para a implementação do logger e o codigo cliente não tem que se preocupar com concatenações. No cenário onde aquele nivel de log não está habilitado, este método simplesmente retorna sem nunca ter havido nenhuma manipulação de String.

Esta funcionalidade já existe em algumas API de Log ( como no SLF4J). Mas se você está usando um objeto de Log original da API de Log e ele não tem uma funcionalidade você não tem como a incluir. Sobretudo em linguagens que não têm capacidade para extensão, como Java, por exemplo. Mesmo que a linguagem tenha essa capacidade o uso de extensões deixa o código num estágio de uso de magia do compilador e não um bom design OO.

Nem todo o log é tão simples quando registrar um a e um b. Algumas vezes precisamos montar informações complexas (xml, ou json, por exemplo) para logarmos informações mais ricas. O ideal é só incorrer no algortimo que busca e monta as informações se o nivel necessário estiver habilitado. Isso nos leva a escrever codigo como :

public class MyApp {
   private ILogger logger;

   public void metodoA(String a, String b) {
       if (logger.isDebugEnabled()){
           // busca informações complexas
           logger.debug( mensagemComplexa);
       }
   }
 }

em que usamos um if para decidir com base no estado do logger. O ideal seria postergar a pesquisa dos dados passando um objeto que faz isso ( padrão Command), em vez da string final que pode nem ser logada realmente. Temos uma interface que irá ser invocada depois e apenas quando o sistema de logging souber que realmente é necessario e/ou um método que aceita delgates. O design da interface pode ser simples e não se preocupar com novas inversões de control porque já sabemos que ao ser invocada é porque é realmente necessária. Por exemplo:

    private ILogger logger;

   public void metodoA(String a, String b) {
       logger.debug(()=> CriaMensagemComplexa(a, b));
   }
    public string CriaMensagemComplexa(String a, String b){
        // super complexa forma de obter a mensagem
        return mensagem
    }
 }

Utilizar Inversão de Controle (IoC) é simples primeiro ha que garantir que a classe não conhece como as instancias das outras classes que usa são instanciadas ou obtidas, e depois  delegar ao máximo o “como” as coisas são realizadas. Isto diminui o conhecimento que cada classe tem de como a outra funciona e por consequência diminui o acoplamento.

Quando mais inversão você utiliza, mais injeção irá necessitar. Automatizar a injeção é uma prática comum e razoável hoje em dia se usadas ferramentas como o Spring. O uso de um contêiner de injeção não é obrigatório, mas é muito mais prático e confortável. Como bônus o uso destes sistemas permite fazer injeções onde normalmente não seria possível, como em campos privados. Se estamos interessados em implementar uma inversão de dependência mais ortogonal como a de serviços como Logging , Transação ou Segurança queremos que o programador tenha o minimo de trabalho e contato com o como estas coisas funcionam. Afinal elas são ortogonais e podem nem sequer estar presentes. Claro que se você decide usar capacidades ortogonais  em objetos dos quais você não controla a criação ( como objetos criados por outros frameworks ) então você tem algumas opções: a) utilizar a OO pura e obter o objeto de outra forma e injetar manualmente no construtor , b) você aplica os princípios da inversão de controlo recursivamente até que todos os objectos que precisam de logging sejam controlados pelo contêiner, ou c) aumenta a tecnologia para dar suporte a esses outros cenários usando weaving de compilação (ou , em java, manipulação de classloader). É tudo uma questão de quanto você , realmente, quer que seu código seja desacoplado e se você pode dormir de noite sabendo disso.

Criar uma interface para um sistema de log pode parecer um desperdício, mas permite criar mecanismos mais amigáveis para postergar ao máximo a obtenção e processamento de informações que são apenas necessárias quando o log realmente for usado. Não apenas postergar, mas deixar o logger decidir o que fazer com a mensagem. Uma forma de melhorar ainda mais isto é produzir objetos de mensagem de log que é o que normalmente os frameworks usam por baixo dos panos e não strings. Desta forma o objeto de mensagem pode viajar dentro do framework subjacente sem nunca ter, realmente, produzido a mensagem. Não é sempre que você vai realmente precisar de mudar de implementação do motor de logging (depende muito dos seus requisitos não-funcionais), mas se você controla segurança e transação confiando em contêiner, porque log não ?

A capacidade de usar Inversão de Controle, e a sua contra-parte a Injeção de Dependência, nos permite usar, testar e evoluir as capacidades do código de forma desacoplada. Isto é muito vantajoso para código de infraestrutura como logging ( e outros como profiling, transaction … ), especialmente quando associados ao padrão Service, mas usando um contêiner de injeção é possível associar a qualquer objeto representando qualquer papel – claro, desde de que ele seja controlado pelo contêiner.

Como bônus, para os curiosos, segue  o pós-processador final em Spring.Net ( seria semelhante em java) :

 public class LoggerInjectionPostProcessor : IObjectPostProcessor
    {
        private ILoggerProvider provider;

        public LoggerInjectionPostProcessor(ILoggerProvider provider) {
           this.provider = provider;
        }

        public object PostProcessAfterInitialization(object instance, string objectName)
        {
            FieldInfo[] fields = instance.GetType().GetFields(
                        BindingFlags.NonPublic |
                        BindingFlags.Instance);

            foreach (FieldInfo f in fields)
            {
                if (f.FieldType.Equals(typeof(ILogger)))
                {
                    f.SetValue(instance, provider.Provide(new InjectionPoint() {SurroundingType = instance.GetType()}));
                }
            }

            return instance;
        }

        public object PostProcessBeforeInitialization(object instance, string name)
        {
            return instance;
        }
    }




Desenvolvido por hacklab/ com WordPress