Logger en base... avec Spring

Avant un retour d’expérience sur Spring Roo dont j’avais vanté les mérites il y a quelque temps, je prends un moment pour vous donner une astuce technique simple mais efficace.

De plus en plus souvent, il m’est demandé que l’activité des applications soit loggée non plus simplement dans les fichiers du serveur, mais directement dans le système d’informations pour être consultée depuis l’IHM. Alors bon, ça tombe  bien, Log4j fournit de longue date le JDBCAppender qui permet justement d’injecter les logs en base, et vous trouverez sans problème un certain nombre de tutoriels clairs pour vous en servir. Voici un exemple glané en chemin :

# Define the root logger with file appender
log4j.rootLogger = DEBUG, sql
# Define the file appender
log4j.appender.sql=org.apache.log4j.jdbc.JDBCAppender
log4j.appender.sql.URL=jdbc:mysql://localhost/test
# Set Database Driver
log4j.appender.sql.driver=com.mysql.jdbc.Driver
# Set database user name and password
log4j.appender.sql.user=root
log4j.appender.sql.password=password
# Set the SQL statement to be executed.
log4j.appender.sql.sql=INSERT INTO LOGS VALUES ('%x', now() ,'%C','%p','%m')
# Define the xml layout for file appender
log4j.appender.sql.layout=org.apache.log4j.PatternLayout

Comme on le voit, il est nécessaire de fournir les paramètres de connexion et une requête SQL d’insertion correspondant à la structure de votre table de stockage. Les données sont transmises par un layout sous la forme de placeholders. Cependant, comme la configuration est définie dans le fichier de propriétés de Log4j, il parait difficile de ne pas dupliquer les informations de connexion qui vont changer selon l’environnement d’exécution. Par ailleurs, Log4j ne fournit pas de placeholder pour la stacktrace des throwables éventuels.

Alors, disons que nous utilisons Spring et que les données de connexion à notre base sont déjà spécifiées dans un fichier de propriétés importé dans le contexte d’application. Nous pouvons bien sûr instancier dans un bean un JDBCAppender et lui passer les paramètres récupérées par l’annotation @Value. Pas de problème particulier :

@Value("${database.driverClassName}")
private String driver;
@Value("${database.url}")
private String url;
@Value("${database.username}")
private String name;
@Value("${database.password}")
private String password;
...
@PostConstruct
public void initAutoLogger() {
  JDBCAppender appender = new JDBCAppender(); // instanciation
  appender.setName(this.getClass().getName());
  appender.setDriver(driver);
  appender.setURL(url);
  appender.setUser(name);
  appender.setPassword(password);

  appender.setSql(LOG_INSERT); // votre requête SQL d'insertion

  appender.activateOptions(); // initialisation obligatoire
  Logger logger = Logger.getRootLogger();
  logger.addAppender(appender); // injection
}

private static final String LOG_INSERT = "INSERT INTO journal_des_incidents " +
      "(date_incident, niveau, message) VALUES (now(), '%p', '%m')";

Voilà, en deux coups de cuillère à pot c’est plié ; pas de soucis, merci l’API. Mais, bon, je trouve ça encore un peu verbeux, je suis comme ça. Alors j’ai écrit une seconde version un peu plus légère :

@Autowired
private DataSource dataSource; // ben oui, c'est plus simple !
...
@PostConstruct
public void initAutoLogger() {
  JDBCAppender appender = new JDBCAppender() {
      @Override
      protected Connection getConnection() throws SQLException {
        return dataSource.getConnection();
      }

      /* par défaut, JDBCAppender conserve la connexion jusqu'à destruction */
      @Override
      protected void closeConnection(Connection conn) {
        try {
          if (conn != null) conn.close();
        } catch (SQLException e) {
          e.printStackTrace();
        }
      }
  };
...
}

Comme ça, on fait bien la job, c’est carré, le couplage est minimal. Et oui, car cela fonctionne même si vous décidez par la suite de récupérer votre DataSource via JNDI. C’est Spring qui s’occupe de tout, on ne fait que se servir sans rien présupposer. On a bon.

Reste la question des stacktraces. Et cette fois il va falloir en faire un peu plus. Pour parvenir à nos fins, nous devons remplir le contrat de l’appender pour dire qu’on veut traiter les exceptions (pas sûr que ce soit obligatoire, m’enfin c’était là…) et implémenter le traitement d’un nouveau placeholder que nous allons créer pour l’occasion (%s). Et pendant que nous y serons, on va faire un tout petit peu de protection contre l’injection SQL (voir les articles sur l’OWASP Top 10 publiés sur ce blog).
Voici comment on peut s’y prendre :

...
JDBCAppender appender = new JDBCAppender() {
  ...
};
appender.setLayout(new PatternLayout() {
    @Override
    public boolean ignoresThrowable() { // le contrat signalé
      return false;
    }

    @Override
    protected PatternParser createPatternParser(String pattern) {
      return new ThrowablePatternParser(pattern);
    }
  });

Comme vous le voyez, nous répondons poliment que nous ne souhaiterons pas ignorer (injonction contracdictoire ?) les exceptions accompagnant les logs, et nous définissons un pattern parser qui va s’occuper d’aiguiller le traitement de la requête SQL :

/** Prise en charge de l'Exception ; on gère un nouveau placeholder '%s'
 * Protection SQL Injection
 */
private static class ThrowablePatternParser extends PatternParser {
  ThrowablePatternParser(String pattern) {
    super(pattern);
  }

  @Override
  protected void finalizeConverter(char c) {
    PatternConverter pc = null;
    switch(c) {
    case 'm': // SQL Injection
      pc = new MessagePatternConverter(formattingInfo);
      currentLiteral.setLength(0);
      break;
    case 's': // stacktrace
      pc = new ThrowablePatternConverter(formattingInfo);
      currentLiteral.setLength(0);
      break;
    default:
      super.finalizeConverter(c);
      return;
    }
    addConverter(pc);
  }
}

Notre PatternParser surcharge la fonction idoine pour prendre en charge deux placeholders ; pour les cas “normaux”, on s’en réfère à la classe parente qui fait bien son travail, merci.

Voici maintenant comment on récupère et traite les exceptions qui sont portées par nos logs, pour les enregistrer (typiquement dans un CLOB) :

/** Parsing d'une éventuelle Exception ; protection SQL on met en forme la Stack Trace */
private static class ThrowablePatternConverter extends PatternConverter {
  ThrowablePatternConverter(FormattingInfo formattingInfo) {
    super(formattingInfo);
  }

  @Override
  protected String convert(LoggingEvent event) {
    final String[] strs = event.getThrowableStrRep();
    if (strs == null) {
      return null;
    }

    final StringBuffer sb = new StringBuffer();
    for (int i = 0; i < strs.length; i++) {
      sb.append(protectSQL(strs[i])).append(System.lineSeparator());
    }

    return sb.toString();
  }
}

Et enfin, voici comment on fait un petit effort pour éviter les catastrophes potentielles :

/** Parsing du message de log ; protection SQL */
private static class MessagePatternConverter extends PatternConverter {
  MessagePatternConverter(FormattingInfo formattingInfo) {
    super(formattingInfo);
  }

  public String convert(LoggingEvent event) {
    return protectSQL(event.getRenderedMessage()); // contrôler aussi la longueur ?
  }
}

private static String protectSQL(String text) {
  if (StringUtils.isBlank(text)) { // commons.lang3, je suis comme ça aussi
    return text;
  }
  return text.replaceAll("'", "''"); // le moins que l'on puisse faire
}

private static final String LOG_INSERT = "INSERT INTO journal_des_incidents " +
      "(date_incident, niveau, message, stacktrace) VALUES (now(), '%p', '%m', '%s')";

Et hop ! J’espère que ce blog vous fera gagner du temps.
Notez qu’il est bien sûr possible de préciser le niveau de l’appender pour ne journaliser, par exemple, que les messages ERROR et FATAL comme vous le feriez normalement.