Desenvolvimento de software se encaixa na área de ciências exatas, mas a tarefa em si está longe de ser algo exato. Aliás, muito longe disso. Programar sistemas, seja em qual for a linguagem, tem muito de numerologia, astrologia, tarô e outras mandingas populares. Sim, tem que ter, ou qual seria a razão para bugs ocorrerem? Falta de testes? Sim, claro, a falta de testes é um problema grave que muitos ainda tentam ignorar, mas mesmo em um software bem (?) testado bugs ocorrem - afinal, o teste certifica que o código escrito para alguma regra de negócio em particular de fato funciona, mas quem garante que a lógica utilizada está correta?
Pois é, esporadicamente acontece de nosso código estar de fato errado, e consequentemente o teste está certificando algo (a regra de negócio) que não é correto. Ossos do ofício.
No JForum 3, um bug recente foi bastante intrigante, peculiar. Apenas para situar e garantir que estamos todos no mesmo contexto, JForum é um sistema de fóruns de discussão, e fóruns contêm Tópicos, que contêm Posts. O bug em questão começou a ocorrer logo depois que adicionei uma funcionalidade nova no sistema, chamada de “Bad Words”, que nada mais é que um filtro de palavras “impróprias”. O que torna esse bug tão interessante é que o módulo de Bad Words gerava um erro muito inusitado, em um lugar desconexo, de forma confusa.
Para compreender melhor, a lógica era a seguinte:
- Utilizando o sistema de eventos do JForum 3, toda vez que um novo Post estivesse para ser inserido - ou seja, antes de persistir a mensagem em si -, o filtro de Bad Words era aplicado à mensagem, o qual ocasionalmente poderia modificar a mensagem original.
Até ai nada demais. O módulo de responder a mensagens existentes já existia a tempos, e com vários testes sendo aplicados. Tudo era gravado na mais perfeita ordem e exatidão. Porém, toda vez que o filtro de Bad Word entrava em ação, o sistema quebrava com um erro do Hibernate, acusando que havia objetos não salvos - o maldito “Transient Object Exception”. “Oras”, eu pensava, “mas é claro que o objeto é transiente. Eu estou adicionando ele agora, do que o Hibernate está reclamando?”. Isso sempre acontecia quando o módulo de Bad Words estava ativado. Se eu removesse ele, o erro parava.
Para tornar as coias mais claras, vale lembrar que Hibernate tem algumas regras de funcionanto bastante interessantes. Por exemplo, no momento em que chamamos session.save(entity), ele não executa o statement imediatamente, mas sim segura até uma ocasião melhor, que geralmente é o commit da transação ou um flush manual na sessão. Porém, o que muita gente não sabe é que, caso uma query qualquer - qualquer query mesmo, em qualquer entidade - seja executada antes do commit ou flush, o Hibernate força um flush na session automaticamente.
E por que isso é importante? Bem, porque a unica coisa que o filtro de Bad Word fazia era executar um badWordRepository.getAllBAdWords(), e nada mais. Se essa chamada fosse removida, o post era inserido com sucesso. Se ela fosse mantida, ocorria a Transient Exception. Estranho, não?! O código de reply a um tópico já existente era o seguinte:
-
public void reply(Topic topic, Post post) {
-
Topic current = this.topicRepository.get(topic.getId());
-
-
if (StringUtils.isEmpty(post.getSubject())) {
-
post.setSubject(current.getSubject());
-
}
-
-
this.performReplyValidations(post);
-
-
topic.setForum(current.getForum());
-
-
post.setTopic(current);
-
post.setForum(current.getForum());
-
-
if (!post.isWaitingModeration()) {
-
current.setLastPost(post);
-
current.getForum().setLastPost(post);
-
current.incrementTotalReplies();
-
post.getUser().incrementTotalPosts();
-
}
-
-
this.postRepository.add(post);
-
}
Eu costumo dizer que no JForum tudo tem uma razão de ser. Afinal, o sistema tem mais de 5 anos, e é extremamente estável. Muito do código existente está da maneira que está devido a muita ralação e testes, e por mais estranho que certas lógicas possam parecer, no fundo elas têm um sentido. Claro, não podemos aplicar isso ao sistema inteiro, mas é algo que se mostrou verdade inúmeras vezes. Nesse código ai, os testes passavam perfeitamente, e usando o sistema tudo funcionava perfeito. Por que então uma simples execução de query do Hibernate, em Bad Words, fazia acontecer um erro tão sem nexo como o Transient Object Exception?
Para quem conhece pouco de Hiberante, uma Transient Object Exception ocorre quando temos dois ou mais objetos dependentes entre si, e não salvamos algum deles, ai o Hibernate quebra dizendo “opa, espera ai. Você está me dizendo que quer salvar o objeto A, que tem uma dependência com o objeto B, mas você não está salvando o objeto B. Portanto, eu não sei o que fazer”. Ou algo parecido com isso.
Vale lembrar também que o filtro de Bad Words é invocado através do sistema de eventos do JForum 3, logo é natural que no código acima não haja uma chamada explícita a ele. O que é importante saber é apenas que, antes de ser persistido, a instância de post em questão é passada através de uma série de filtros, que podem ou não modificar o objeto em si.
Olhando e debugando o código do método reply(), não ficava claro a razão do bug. A transient object exception não parecia ter sentido algum. Afinal, o método recebia uma instância nova de um objeto Post, buscava no repositório o tópico atual, já existente, e associava o tópico com o novo post. Até ai tudo parecia normal - e, aliás, funcionava -, pois o tópico atual já estava na base de dados. então não deveria haver problema com objetos transientes. Depois de muito debugando, e tendo pedido a ajuda de várias pessoas, o Lucas Cavalcanti (colega de trabalho na Caelum) notou algo. Era uma luz para solucionar o problema.
Analizando o código com mais cuidado, vemos que o tópico atual é buscado no repositório, e armazenado na variável “current” (péssimo nome, deveria ser “currentTopic“). Mais abaixo, é feito “current.setLastPost(post)“. Ou seja, estamos associando o objeto novo (o post, no caso) com um objeto já existente. Hhhhmm, tudo bem, errado não está, pois logo em seguida chamamos o postRepository.add(post). Mas espera lá, antes de chamarmos add(post), o sistema de eventos é disparado, caindo na execução do método getAllBadWords() do módulo de Bad Words. E, como sabemos, a execução de uma query força o flush() automático no hibernate. E nesse ponto o tópico atual, representado pela variável “current”, foi associado a um objeto “post” novo (transiente), que AINDA não teve o seu save() invocado.
Bingo, tínhamos encontrado o bug. Faltava encontrar uma solução, que, graças a maneira de operar do Hibernate, foi bastante simples: mover a chamada a “postRepository.add(post)” algumas linhas para cima, ANTES da associação do post novo com o tópico atual. O código ficou assim:
-
// …
-
post.setForum(current.getForum());
-
-
// Código movido para cima
-
this.postRepository.add(post);
-
-
if (!post.isWaitingModeration()) {
-
current.setLastPost(post);
-
-
// …
Notem que a chamada ao método add() da postRepository foi feito antes da chamada ao setLastPost() da variável current. Bug resolvido. Tudo terminado? Não, falta o teste. A dificuldade nesse caso está na necessidade de testar a ordem das invocações. Sorte que temos Mocks para isso. A solução adotada foi então mockar o objeto current, o objeto postRepository, e garantir que a chamada ao método add() de PostRepository fosse feita antes da chamada ao método setLastPost() de Topic. O código do teste ficou assim:
-
@Test
-
public void replyPostRepositoryShouldBeCalledBeforeCurrentTopicSetLastPost() {
-
final Post post = new Post(); post.setSubject("subject"); post.setText("msg");
-
post.setUser(new User());
-
-
context.checking(new Expectations() {{
-
Topic topic = context.mock(Topic.class);
-
one(topicRepository).get(1); will(returnValue(topic));
-
-
one(postRepository).add(post); inSequence(sequence);
-
one(topic).setLastPost(post); inSequence(sequence);
-
-
allowing(topic).getForum(); will(returnValue(new Forum()));
-
one(topic).incrementTotalReplies();
-
}});
-
-
Topic topic = new Topic(); topic.setId(1);
-
topicService.reply(topic, post);
-
-
context.assertIsSatisfied();
-
}
Um muito obrigado ao Lucas pela ajuda na solução deste bug :).
