sábado, 3 de marzo de 2018

Tutorial sobre Logback Parte II: Configuración, Formato y Colores

Introducción

En un post anterior se revisaron algunos temas básicos que permiten empezar a usar Logback en un proyecto Java. Ahora se mostrarán algunas opciones para configurar esta librería, según la necesidad.

Se continuará con el proyecto de dicho post anterior: https://github.com/guillermo-varela/jetty-jersey-logback-demo/tree/part-i

Configuración

Logback sigue la siguiente secuencia de verificaciones para realizar su configuración, hasta encontrar una que se cumpla:

  1. Si se tiene la propiedad del sistema "logback.configurationFile", su valor sería la ruta (URL, archivo externo o interno en la aplicación) en que se tiene un archivo XML o Groovy con la configuración, por ejemplo iniciar la aplicación con el parámetro "-Dlogback.configurationFile=/path/config.xml".
  2. Busca un archivo "logback.groovy" en el classpath.
  3. Busca un archivo "logback-test.xml" en el classpath.
  4. Busca un archivo "logback.xml" en el classpath.
  5. Intenta buscar una clase que tenga la configuración de Logback en código. Dicha clase debe implementar la interfaz Configurator y se indica su nombre completo (fully qualified class name) en el archivo "META-INF\services\ch.qos.logback.classic.spi.Configurator".
  6. Finalmente, si ninguna de las opciones anteriores fue posible, se usa la configuración por defecto que se realiza mediante la clase BasicConfigurator de Logback (enviando los logs a la consola).
La configuración usando archivos XML es la más común entre las opciones disponibles, aunque existe una herramienta en la página web de Logback que permite convertir una configuración XML a Groovy, la cual puede ser de utilidad cuando se requiere una configuración más dinámica.

Cuando se utiliza una herramienta como Maven o Gradle para construir y compilar el proyecto se pueden tener carpetas de recursos que se usen durante el desarrollo pero que no hagan parte del paquete final desplegado en producción. Con las dos herramientas mencionadas se tiene por defecto la carpeta "src/test/resources" en la cual se puede crear el archivo "logback-test.xml" con más detalles incluidos en logs que sean de utilidad, mientras que en "src/main/resources" el archivo "logback.xml" contiene sólo los detalles necesarios en producción.

Formato de Logs (Layout)

En Logback, un Layout es un componente que toma los datos de un evento registrado en logs y los convierte en una cadena (String).

Dado que hasta ahora no se ha adicionado ninguna configuración en el proyecto, al ejecutarlo se realiza la configuración por defecto, enviando los datos a la consola:

Figura 1 - Formato de logs por defecto

Los datos mostrados en esta configuración son:
  • Hora del evento, incluyendo milisegundos.
  • Nombre del hilo que ejecutó el evento.
  • Nivel del evento.
  • Nombre completo del Logger. Como se mencionó en el post anterior, la manera más común de obtener una instancia de Logger es usando la clase que registra el evento en logs (LoggerFactory.getLogger(UsersResource.class) por ejemplo), por esta razón no solamente los logs registrados directamente por el código de la aplicación, sino también los de Jetty aparecen con el nombre completo de las clases; sin embargo, si se usará cualquier otra cadena para obtener el Logger sería ese nombre el que aparezca.
  • Mensaje del evento.
Bien sea por preferencias personales, facilidad de visualización o necesidad de información diferente, Logback permite cambiar esta estructura de información en logs mediante el uso de una implementación de la interfaz Layout, de entre las cuales la más usada es PatternLayout.

PatternLayout permite indicar los datos del evento que se enviarán a logs, así como cualquier otro texto libre que se considere necesario. Logback permite representar los datos del evento mediante "Conversion Words", cada uno precedido del símbolo "%" y al procesar el evento serán reemplazados de manera similar a como lo hace la función "printf()" de varios lenguajes de programación. La lista completa de opciones disponibles se puede encontrar en la documentación de Logback.

Para este ejemplo la configuración se realizará mediante un archivo "logback.xml", inicialmente con lo siguiente:

src/main/resources/logback.xml
<configuration>

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>[%-5level] [%d{ISO8601}] [%logger{36}] - %msg%n</pattern>
    </encoder>
  </appender>

  <root level="ALL">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>
  • Etiqueta "configuration": Es la raíz del archivo XML de configuración.
  • Etiqueta "appender": Logback usa componentes Appender para escribir el contenido de los logs en diferentes tipos de destino, según la implementación usada. En este ejemplo se usará "ConsoleAppender", que es la misma usada en la configuración por defecto, y se le asigna el nombre "STDOUT" (abreviación de Standard Output), aunque puede ser cualquier otro nombre.
  • Etiqueta "encoder": Encoders son intermediarios que toman el contenido de un evento enviado a logs (String) y convertirlo a un arreglo de bytes para enviarlo mediante un OutputStream al Appender respectivo.
  • Etiqueta "pattern": Al usarla se está indicando que para el layout del contenido de los eventos se usará PatternLayout. En este ejemplo cada uno de los datos del evento (excepto el mensaje) se está encerrando entre corchetes ([ ]) sólo como ayuda visual, no es algo necesario.
    • %-5level: Con el Modificador de Formato "-5" se indica que este campo en la cadena del log tendrá como mínimo 5 caracteres dado que si el contenido es menor, la diferencia será rellenada con espacios a la derecha. En este caso se tiene como Conversion Word el valor "level" para que el log tenga el nivel en que fue registrado. Así por ejemplo se pueden tener valores como [DEBUG] o [INFO ], recordando el espacio al final si no tiene 5 caracteres, lo cual puede ser útil para que al ver los logs se tenga consistencia en su longitud.
    • %d{ISO8601}: "%d" corresponde a la fecha en que se registró el evento, mientras que "{ISO8601}" hace las veces de parámetro que indica el formato en que se mostrará dicha fecha, que en este caso será el estándar "ISO 8601".
    • %logger{36}: Muestra el nombre del Logger usado para registrar el evento, acortando su longitud para que no supere los 36 caracteres, esto con el fin de reducir el contenido del log a sólo lo realmente necesario, aclarando que este límite es opcional. En general los nombres de los Logger se jerarquizan con separación por puntos, siendo la parte más significativa el extremo derecho, así por ejemplo cuando se trata del nombre completo de una clase lo paquetes pueden acotarse a una sola letra para que el total no supere el límite indicado, pero el nombre de la clase (parte más significativa) no será acortado para evitar perder información importante. Así "com.blogspot.nombre_temp.jetty.jersey.logback.demo.DemoStarter" puede pasar "c.b.n.j.j.logback.demo.DemoStarter".
    • -: Texto libre que simplemente separa los datos previos del evento del mensaje.
    • %msg%n: Muestra el contenido del mensaje (%msg) y a continuación adiciona un salto de línea (%n), de no hacer esto último todos los eventos se mostrarían en una sola línea de la consola o archivo.
  • Etiqueta "root": Como se mencionaba previamente, las instancias de Logger tienen una jerarquía y la instancia raíz o padre de todos es "root". En caso de no definir configuraciones específicas para otras instancias de Logger se usará la que se defina dentro de esta etiqueta. En la etiqueta como tal sólo se tiene el atributo "level" para indicar el nivel mínimo de eventos a tener en cuenta.
  • Etiqueta "appender-ref": Indica el nombre del Appender configurado que se usará para enviar los eventos. En este ejemplo sólo se tiene uno, pero se pueden tener varias de estas etiquetas para enviar los eventos a varios destinos de ser necesario.
Como pudo verse en los valores indicados en la etiqueta "pattern" cada "Conversion Word" por lo general tiene la siguiente estructura:


Al ejecutar nuevamente el proyecto, ahora con esta configuración se tiene:

Figura 2 - Logs en consola con nuevo formato

Información de Estado de Logback

Para ver el proceso de inicialización de Logback y ver por ejemplo cuál es el archivo de configuración que se usará para la aplicación se debe modificar la etiqueta "configuration" adicionando el atributo debug="true".

src/main/resources/logback.xml
<configuration debug="true">
  ...
</configuration>

Así, al principio, en la salida estándar se debe tener un contenido similar al siguiente cuando se inicia la aplicación:
01:48:34,005 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
01:48:34,005 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
01:48:34,005 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/home/workspace/jetty-jersey-logback-demo/bin/logback.xml]
01:48:34,110 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
01:48:34,112 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
01:48:34,123 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
01:48:34,155 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to ALL
01:48:34,155 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
01:48:34,155 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
01:48:34,158 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@1bc6a36e - Registering current configuration as safe fallback point
...

Colores

Cuando se está trabajando con sistemas operativos basados en Unix (Mac y Linux por ejemplo), es posible adicionar colores al resultado de los logs registrados, tanto en Consola como en los archivos, usando Códigos de Escape ANSI.

Estos colores son visibles en herramientas texto que muestran el contenido directamente en Terminal (por ejemplo cat, tail y more), pero editores de texto propiamente como por ejemplo vim mostrarán el contenido en texto de los códigos de escape en lugar de los colores (aunque para el caso particular de vim existe el plugin AnsiEsc que permite interpretar dichos códigos)

src/main/resources/logback.xml
<configuration debug="true">

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%highlight([%-5level]) [%d{ISO8601}] %cyan([%logger{36}]) - %msg%n</pattern>
    </encoder>
  </appender>

  <root level="ALL">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

  • %highlight([%-5level]): Los niveles de logs ya tienen asociados colores en Logback, por lo que la instrucción "highlight" simplemente hace que aparezcan.
  • %cyan([%logger{36}]): Hace que el nombre del Logger aparezca en color cian (cyan, azul claro). Cabe aclarar que se dispone de más colores y se pueden aplicar a otros campos del evento enviado a logs.

Para quienes usen Eclipse, deberán instalar el plugin "ANSI Escape in Console" para que los colores sean visibles en consola.
Figura 3 - Colores en logs

Nota: En sistemas Windows la consola de Eclipse funciona sin necesidad de dicha librería, sólo con el plugin antes mencionado, pero fuera de esta los colores sólo serán visibles usando Jansi, como lo indica la documentación de Logback.

Múltiples Archivos de Configuración

Cuando se tiene una aplicación muy grande, con muchos módulos o funcionalidades es posible que cada una de estas requiera su propia configuración de Logback y para evitar tener un solo archivo igualmente grande con todas las configuraciones, es posible tener un archivo para cada módulo/funcionalidad e importarlos en un archivo principal.

Este ejemplo es muy pequeño para dicha demostración, pero la documentación oficial de Logback ilustra muy bien esta opción: http://logback.qos.ch/manual/configuration.html#fileInclusion

Conclusión

Se ha logrado avanzar un poco en las posibilidades de configuración para extender un poco más la información que se tiene sobre los eventos en logs y personalizarla según se necesite.

En un próximo post se mostrará la configuración específica para las instancias de Logger. Por lo pronto el proyecto hasta este punto se puede descargar en: https://github.com/guillermo-varela/jetty-jersey-logback-demo/tree/part-ii

Referencias

Publicadas por a la/s 2 comentarios:
Etiquetas: , , , , , ,

miércoles, 1 de junio de 2016

Tutorial sobre Logback Parte III: Loggers

Introducción

En post anteriores se revisado la librería Logback para registrar eventos (logs) en proyecto Java así como algunas de sus opciones de configuración.

Ahora se explicará un poco mejor el funcionamiento de los Loggers y su configuración.

Interfaz Logger

Ya se había indicado en previos posts que el registro de los eventos se realiza mediante instancias de implementaciones la interfaz de SLF4J Logger, las cuales se pueden obtener mediante la clase LoggerFactory (encargada de encontrar la implementación de Logback), también de SLF4J, mediante sus métodos:

static Logger getLogger(String name)
static Logger getLogger(Class clazz)

El primer método obtiene un Logger basado directamente en el nombre indicado como parámetro. Dicho nombre se busca en la configuración de Logback (bien sea XML, Groovy o código Java) y en caso de no encontrarse, la instancia obtenida tendrá la misma configuración que el Logger root.

El segundo método a su vez usa el nombre completo de la clase (fully qualified class name) que se tiene como parámetro como el nombre del Logger y la instancia se obtiene de la misma manera que el primero. Lo más común es que la clase indicada sea la misma desde la cual se registra el evento.

Ambos métodos retornan siempre la misma instancia para un nombre de Logger indicado y se pueden usar de manera segura en aplicaciones de múltiples hilos (thread safe). Esta última característica es la que permite que se puedan tener Loggers como variables (o constantes) estáticas, en lugar de crear una nueva variable para cada instancia o método que registra el evento.

src/main/java/com/blogspot/nombre_temp/jetty/jersey/logback/demo/resource/UsersResource.java
package com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource;

import java.util.HashSet;
import java.util.Set;

import javax.ws.rs.Consumes;
import javax.ws.rs.POST;
import javax.ws.rs.Path;
import javax.ws.rs.Produces;
import javax.ws.rs.core.MediaType;

import org.apache.commons.lang3.Validate;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import com.blogspot.nombre_temp.jetty.jersey.logback.demo.model.DemoResponse;
import com.blogspot.nombre_temp.jetty.jersey.logback.demo.model.User;

@Path("/users")
@Consumes(MediaType.APPLICATION_JSON)
@Produces(MediaType.APPLICATION_JSON)
public class UsersResource {

    private static Logger logger = LoggerFactory.getLogger(UsersResource.class);

    private static final Set USERS = new HashSet();

    @POST
    public DemoResponse create(User user) {
        logger.info("Creating user: {}", user);
        DemoResponse response = new DemoResponse();

        try {
            Validate.notNull(user, "The user cannot be null");
            logger.debug("Trying to add user with id: {}", user.getId());

            if (USERS.add(user)) {
                logger.info("User created");
            } else {
                logger.warn("User repeated");
                response.setError(true);
                response.setMessage("User repeated");
            }
        } catch (Exception e) {
            logger.error("Error creating the user: {}", user, e);
            response.setError(true);
            response.setMessage(e.getMessage());
        }

        logger.info("User processed with response: {}", response);
        return response;
    }
}

En este ejemplo puede verse que sólo se está obtenido una instancia de Logger y se asigna como constante privada de la clase "UsersResource" y se usa varias veces en el método "create" registrando eventos en los diferentes niveles de log disponibles.

En aquel primer post también se mencionaban los métodos que expone Logger para registrar eventos en cada nivel y su funcionamiento usando vargars como parámetros para construir la cadena a enviar a logs.

Configuración de Loggers

Al ejecutar la aplicación los logs en consola tienen eventos no sólo del código de la aplicación, sino también de Jetty en modo DEBUG, lo cual hace que sea muy difícil de leer.

Figura 1 - Logs de la aplicación y las librerías

Lo que se hará ahora es configurar Logback para que sólo los eventos de la aplicación aparezcan desde el nivel DEBUG, pero los de Jetty desde INFO.

src/main/resources/logback.xml
<configuration debug="true">

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%highlight([%-5level]) [%d{ISO8601}] %cyan([%logger{36}]) - %msg%n</pattern>
    </encoder>
  </appender>

  <logger name="org.eclipse.jetty" level="INFO">
  </logger>

  <root level="ALL">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

Figura 2 - Logs de la aplicación con eventos de Jetty en INFO

Al ejecutar la aplicación con esta configuración puede verse que ya aparecen menos eventos de Jetty en la consola, sólo los que tienen nivel INFO, lo cual permite ver de una manera mucho más clara los logs que de verdad son de interés.

Jerarquía de Loggers

En uno de los eventos de Jetty aparece que el nombre del Logger que registró en logs es "org.eclipse.jetty.util.log", pero en el archivo "logback.xml" en la etiqueta "logger" sólo se indicó el nombre "org.eclipse.jetty". Igualmente se tienen otros logs de Jetty con diferentes nombres de Logger en la consola y otros que ya no aparecen, es decir también se vieron afectados por la restricción del nivel (atributo "level").

Esto se debe a que la configuración de los Logger se realiza de manera jerárquica, en donde el Logger "padre" de todos los demás es "root". Cada Logger adicional se jerarquiza basado en su nombre y usando puntos como separador, así un Logger de nombre "org.eclipse.jetty" es "padre" de "org.eclipse.jetty.util.log" por lo que este último hereda la configuración definida en "logback.xml" para su Logger "padre" (en este caso el límite del nivel de logs a INFO).

De la misma manera el Logger "org.eclipse.jetty" (y todos sus "hijos") hereda la configuración del Logger "root" por lo cual los eventos registrados van a la consola.

Loggers para Pruebas y Producción

Normalmente en ambientes de producción sólo se requieren los logs hasta el nivel INFO, mientras que en ambientes de desarrollo o pruebas sí se muestran los niveles DEBUG o TRACE.

En el post anterior se explicaba que es posible tener un archivo "logback-test.xml" con la configuración necesaria para pruebas y "logback.xml" para producción.

src/test/resources/logback-test.xml
<configuration debug="true">

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%highlight([%-5level]) [%d{ISO8601}] %cyan([%logger{36}]) - %msg%n</pattern>
    </encoder>
  </appender>

  <logger name="org.eclipse.jetty" level="INFO">
  </logger>

  <root level="ALL">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

src/main/resources/logback.xml
<configuration debug="true">

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%highlight([%-5level]) [%d{ISO8601}] %cyan([%logger{36}]) - %msg%n</pattern>
    </encoder>
  </appender>

  <root level="INFO">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

Teniendo claro el funcionamiento de las jerarquías en los Loggers puede verse que en "logback-test.xml" se define el Logger "root" para que incluya todos los niveles y en el caso de Jetty (así como cualquier otra librería que genere demasiados logs) de tiene un Logger aparte con nivel INFO, mientras que en "logback.xml" dado que sólo tiene un Appender sólo es necesario definir el Logger "root" con el nivel INFO.

Conclusión

Configurar y usar los Loggers mediante SLF4J y Logback es bastante fácil, una vez se entiende el concepto de la herencia o jerarquías entre los Loggers, ya que al tener la posibilidad de compartir configuraciones se evita la duplicación de las configuraciones.

Adicionalmente, dado que en el código se están usando las clases e interfaces de SLF4J se facilita el que en un futuro se cambie la implementación de las clases de Logging (bien sea para usar una librería diferente de Logback o simplemente cambiar su versión), sin necesidad de cambiar el código de la aplicación, sólo la configuración en caso de ser necesario.

En un próximo post se mostrarán algunos Appenders adicionales que tiene Logback, para enviar los eventos registrados a destinos diferentes de la consola. Por lo pronto el proyecto hasta este punto se puede descargar desde: https://github.com/guillermo-varela/jetty-jersey-logback-demo/tree/part-iii

Referencias

Publicadas por a la/s 1 comentario:
Etiquetas: , , , , , ,

lunes, 16 de mayo de 2016

Tutorial sobre Logback Parte I: Uso Básico y Niveles de Logs

http://logback.qos.ch/images/logos/lblogo.jpg

Introducción

Logback es una librería de registro de eventos (logging) desarrollada en Java por el mismo autor de la tradicional Log4J con el objetivo de ser su sucesora mediante un rediseño completo de su código y la aplicación de varias mejoras.

Como puede verse en el registro de Maven Central, Logback se encuentra bajo constante trabajo por lo que se puede considerar como un proyecto activo. Requiere como mínimo el JDK 1.6

Para demostrar algunas de sus características se usará como base el proyecto desarrollado en el post sobre "API REST usando Jersey y Jetty Embebido": https://github.com/guillermo-varela/jetty-jersey-example

Proyectos y Dependencias

Logback fue diseñado para ser una implementación de Simple Logging Facade for Java (SLF4J) con el fin de que pueda ser usado dentro o en conjunto con cualquier proyecto que use las interfaces de SLF4J en su código para referenciar las clases encargadas de registrar en logs, es por esto que para usar Logback se requiere slf4j-api.

Aunque se tienen varios proyectos dentro del grupo "ch.qos.logback", la funcionalidad básica de logging se obtiene mediante:

  • logback-core: Contiene las funcionalidades core de logging de Logback necesarias para los demás módulos.
  • logback-classic: Implementa las interfaces de SLf4J.

Al adicionar estas librerías al proyecto como dependencias Gradle se debe tener algo como lo siguiente:

gradle.properties
version=1.0.0-SNAPSHOT

jettyVersion=9.3.8.v20160314
jerseyVersion=2.22.2
logbackVersion=1.1.7
slf4jVersion=1.7.21

org.gradle.daemon=true

build.gradle
plugins {
  id 'net.researchgate.release' version '2.3.5'
}

apply plugin: 'java'
apply plugin: 'application'

sourceCompatibility = 1.8
targetCompatibility = 1.8

mainClassName = 'com.blogspot.nombre_temp.jetty.jersey.logback.demo.DemoStarter'

jar {
    manifest {
        attributes 'Implementation-Title': 'Jetty, Jersey and Logback Example', 'Implementation-Version': version
        attributes 'Main-Class': mainClassName
    }
}

task wrapper(type: Wrapper) {
    gradleVersion = '2.13'
}

repositories {
    jcenter()
}

dependencies {
    compile "org.eclipse.jetty:jetty-server:$jettyVersion"
    compile "org.eclipse.jetty:jetty-servlet:$jettyVersion"

    compile "org.glassfish.jersey.core:jersey-server:$jerseyVersion"
    compile "org.glassfish.jersey.containers:jersey-container-servlet:$jerseyVersion"
    compile "org.glassfish.jersey.media:jersey-media-json-jackson:$jerseyVersion"

    compile "org.slf4j:slf4j-api:$slf4jVersion"
    compile "ch.qos.logback:logback-core:$logbackVersion"
    compile "ch.qos.logback:logback-classic:$logbackVersion"
}

En las líneas 5 y 6 de "gradle.properties" y 36-38 de "build.gradle" se indican las versiones de las librerías y se incluyen como dependencias del proyecto.

Ejemplo Básico de Logging


com.blogspot.nombre_temp.jetty.jersey.logback.demo.DemoStarter
package com.blogspot.nombre_temp.jetty.jersey.logback.demo;

import org.eclipse.jetty.server.Server;
import org.eclipse.jetty.server.ServerConnector;
import org.eclipse.jetty.servlet.ServletContextHandler;
import org.eclipse.jetty.servlet.ServletHolder;
import org.eclipse.jetty.util.thread.QueuedThreadPool;
import org.glassfish.jersey.server.ServerProperties;
import org.glassfish.jersey.servlet.ServletContainer;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.HealthResource;

public class DemoStarter {

    private static Logger logger = LoggerFactory.getLogger(DemoStarter.class);

    public static void main(String[] args) {
        System.out.println("Starting!");
        logger.trace("Starting!");
        logger.debug("Starting!");
        logger.info("Starting!");
        logger.warn("Starting!");
        logger.error("Starting!");

        ServletContextHandler contextHandler = new ServletContextHandler(ServletContextHandler.NO_SESSIONS);
        contextHandler.setContextPath("/");

        QueuedThreadPool queuedThreadPool = new QueuedThreadPool(10, 1);
        final Server jettyServer = new Server(queuedThreadPool);

        int acceptors = Runtime.getRuntime().availableProcessors();

        ServerConnector serverConnector = new ServerConnector(jettyServer, acceptors, -1);
        serverConnector.setPort(8080);
        serverConnector.setAcceptQueueSize(10);

        jettyServer.addConnector(serverConnector);
        jettyServer.setHandler(contextHandler);

        ServletHolder jerseyServlet = contextHandler.addServlet(ServletContainer.class, "/*");
        jerseyServlet.setInitOrder(0);
        jerseyServlet.setInitParameter(ServerProperties.PROVIDER_PACKAGES, HealthResource.class.getPackage().getName());

        try {
            jettyServer.start();

            Runtime.getRuntime().addShutdownHook(new Thread() {
                @Override
                public void run() {
                    try {
                        logger.info("Stopping!");

                        jettyServer.stop();
                        jettyServer.destroy();
                    } catch (Exception e) {
                        e.printStackTrace();
                    }
                }
            });

            jettyServer.join();
        } catch (Exception e) {
            e.printStackTrace();
        }
    }
}
  • Línea 17: Se obtiene una referencia de un Logger asociado a la clase actual mediante LoggerFactory. También es posible obtener un Logger a partir de un nombre personalizado para el Logger, pero usar la clase de la clase en la que se encuentra es la forma más común. Cabe anotar que cada vez que se use "LoggerFactory.getLogger()" con el mismo nombre o clase como parámetro se obtendrá la misma instancia del Logger, por lo que no hay necesidad de preocuparse de llenar la memoria de instancias repetidas.
  • Línea 20: A manera de ejemplo se deja imprimiendo en consola el texto "Starting!".
  • Líneas 21-25: Para cada nivel de logging se tiene un método disponible en Logger, los cuales también están enviando el texto "Starting!". Se detallará el tema los niveles más adelante.

Por defecto Logback envía las entradas en logs a la consola (standard output) por lo que al ejecutar la aplicación se debe tener un resultado similar al siguiente:
Starting!
16:58:49.697 [main] DEBUG com.blogspot.nombre_temp.jetty.jersey.logback.demo.DemoStarter - Starting!
16:58:49.735 [main] INFO com.blogspot.nombre_temp.jetty.jersey.logback.demo.DemoStarter - Starting!
16:58:49.735 [main] WARN com.blogspot.nombre_temp.jetty.jersey.logback.demo.DemoStarter - Starting!
16:58:49.735 [main] ERROR com.blogspot.nombre_temp.jetty.jersey.logback.demo.DemoStarter - Starting!
16:58:49.825 [main] DEBUG org.eclipse.jetty.util.log - Logging to Logger[org.eclipse.jetty.util.log] via org.eclipse.jetty.util.log.Slf4jLog
16:58:49.917 [main] INFO org.eclipse.jetty.util.log - Logging initialized @1721ms
16:58:49.967 [main] DEBUG org.eclipse.jetty.util.DecoratedObjectFactory - Adding Decorator: org.eclipse.jetty.util.DeprecationWarning@53bd815b
16:58:50.008 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - o.e.j.s.ServletContextHandler@48cf768c{/,null,null} added {org.eclipse.jetty.servlet.ServletHandler@59f95c5d,MANAGED}
16:58:50.019 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - org.eclipse.jetty.server.Server@2aae9190 added {qtp125130493{STOPPED,1<=0<=10,i=0,q=0},AUTO}
16:58:50.149 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - HttpConnectionFactory@3339ad8e[HTTP/1.1] added {HttpConfiguration@555590{32768/8192,8192/8192,https://:0,[]},POJO}
16:58:50.161 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - ServerConnector@3419866c{null,[]}{0.0.0.0:0} added {org.eclipse.jetty.server.Server@2aae9190,UNMANAGED}

Con este ejemplo se puede ver la ventaja de usar una librería de logging con respecto a usar simplemente "System.out". En la línea 1 se ve simplemente el texto "Starting!", mientras que entre las líneas 2 y 5 adicional a "Starting!" Logback ha adicionado:

  • Hora en que se presentó el evento enviado a logs.
  • Nombre del hilo que procesó la instrucción.
  • Nivel de log.
  • Nombre asignado al Logger, en este caso es el nombre completo de la clase.

Toda esta información quedó disponible sin tener que adicionarla manualmente en el código de la aplicación, lo cual no sólo deja el código más sencillo de leer mientras que en logs aparece información más completa que permita diagnosticar o hacer seguimiento de lo que hizo un usuario en la aplicación o de los errores generados.

Cabe anotar que los mensajes "Starting!" enviados a logs no apareció el que se reportó con el nivel "TRACE" (logger.trace()), esto se debe a que por defecto el nivel mínimo que se tendrá en cuenta para los logs es "DEBUG". Es posible tener por ejemplo que para ambientes de desarrollo o pruebas se envíen los mensajes desde "DEBUG" pero en producción tener sólo desde "INFO" sin modificar el código de la aplicación.

Desde la línea 6 en adelante empiezan a aparecer registros de logs generados por Jetty, los cuales no salían antes de agregar las librerías de logging. Esto se debe a que al momento de iniciar Jetty intenta buscar si SLf4J se encuentra presente, en cuyo caso usará este API para generar los logs.

Nótese también que en el código no se están usando clases de Logback, sólo se usa la interfaz Logger y la clase LoggerFactory, ambas de SLF4J; internamente esta librería tratará de encontrar una librería de logging que implemente sus interfaces en el classpath de la aplicación.

Niveles de Log

Logback, al igual que otras librerías de logging, permiten asignar un nivel de importancia a los eventos (logs) registrados. De esta manera se pueden clasificar los mensajes, determinar cuáles se deben ignorar según la configuración usada e inclusive en caso de usar escritura asíncrona determinar que mensajes descartar cuando la cola de mensajes para enviar se llena.

Los niveles en Logback se encuentran definidos como constantes de la clase Level y en orden de menor a mayor importancia se tienen:

  • TRACE: Mensajes de importancia mínima, usado generalmente sólo en ambientes de desarrollo.
  • DEBUG: Mensajes que son de utilidad sólo durante el desarrollo o las pruebas de una aplicación para verificar el comportamiento de la aplicación. Aunque la configuración por defecto tiene este nivel como el mínimo a usar, normalmente se deshabilita en ambientes de producción.
  • INFO: Mensajes que muestran las actividades de los usuarios y/o el progreso de una tarea dentro de la aplicación que se consideran normales (parte del flujo esperado). Dependiendo del tipo de aplicación la legislación de algunos países puede exigir el registro y almacenamiento de logs, en dichos casos se recomienda que los mensajes a almacenar estén en este nivel en adelante.
  • WARN: Como su nombre (en inglés) lo indica, en este nivel se deben asociar los mensajes que representen una advertencia, mas no un error.
  • ERROR: Es el nivel más alto disponible y corresponde a mensajes que señalan un error, bien sea cometido por el usuario o excepciones internas de la aplicación. Es recomendable incluir el objeto de la excepción generada (en caso de haberlo) junto con el mensaje del error, esto con el fin de que Logback incluya su traza en el log y se pueda determinar más fácilmente la causa del error, lo cual se explicará más adelante.

Adicionalmente se tienen los valores ALL y OFF, los cuales no son realmente niveles disponibles para los mensajes sino que se pueden configurar para indicar que se deben tener en cuenta todos los niveles de logs o descartar todos los mensajes respectivamente.

Registrar Eventos (Logs)

Para cada nivel de log se tienen varios métodos usando el mismo nombre del nivel en la interfaz Logger, como se pudo ver en el ejemplo de la clase "DemoStarter". Aunque estos métodos están sobrecargados (overloading) los más comúnmente usados son:

  • <nivel>(String mensaje): Registra un mensaje en el nivel indicado por el nombre del método.
  • <nivel>(String plantilla, Object... parámetros): El primer parámetro es una plantilla para el mensaje que se registrará mientras que el segundo contiene los valores que se incluirán usando vargars; los valores se incluyen en la plantilla usando llaves vacías "{}" como marcadores de posición (placeholders). Por ejemplo, si la plantilla es "User {} sent the value: {}" y los valores son "test" y "123", el mensaje registrado será "User test sent the value: 123".
La ventaja de usar el método con la plantilla en lugar de concatenar todo en una sola cadena manualmente, aparte de que el código queda más claro, es que Logback verifica si el mensaje con el nivel usado debe o no registrarse antes de procesar la plantilla con sus valores. De esta manera si por ejemplo se trata de un mensaje de nivel "DEBUG" pero este no se está teniendo en cuenta, al no concatenar ni procesar la plantilla se tiene un ahorro en rendimiento, ya que el procesamiento constante de cadenas puede impactar la aplicación en ese aspecto.

Ejemplo Práctico

Para tener un ejemplo un poco más cercano a un uso real de registro de logs, se incluirá un servicio que permite adicionar usuarios al sistema, validando que se envíen datos y que no sean repetidos.


build.gradle
plugins {
  id 'net.researchgate.release' version '2.3.5'
}

apply plugin: 'java'
apply plugin: 'application'

sourceCompatibility = 1.8
targetCompatibility = 1.8

mainClassName = 'com.blogspot.nombre_temp.jetty.jersey.logback.demo.DemoStarter'

jar {
    manifest {
        attributes 'Implementation-Title': 'Jetty, Jersey and Logback Example', 'Implementation-Version': version
        attributes 'Main-Class': mainClassName
    }
}

task wrapper(type: Wrapper) {
    gradleVersion = '2.13'
}

repositories {
    jcenter()
}

dependencies {
    compile "org.eclipse.jetty:jetty-server:$jettyVersion"
    compile "org.eclipse.jetty:jetty-servlet:$jettyVersion"

    compile "org.glassfish.jersey.core:jersey-server:$jerseyVersion"
    compile "org.glassfish.jersey.containers:jersey-container-servlet:$jerseyVersion"
    compile "org.glassfish.jersey.media:jersey-media-json-jackson:$jerseyVersion"

    compile "org.slf4j:slf4j-api:$slf4jVersion"
    compile "ch.qos.logback:logback-core:$logbackVersion"
    compile "ch.qos.logback:logback-classic:$logbackVersion"

    compile "org.apache.commons:commons-lang3:3.4"
}
  • Línea 40: Se incluye la librería "Apache Commons" para usar un par de métodos que serán de utilidad para este ejemplo.

com.blogspot.nombre_temp.jetty.jersey.logback.demo.DemoStarter
package com.blogspot.nombre_temp.jetty.jersey.logback.demo;

import org.apache.commons.lang3.builder.ReflectionToStringBuilder;
import org.apache.commons.lang3.builder.ToStringStyle;
import org.eclipse.jetty.server.Server;
import org.eclipse.jetty.server.ServerConnector;
import org.eclipse.jetty.servlet.ServletContextHandler;
import org.eclipse.jetty.servlet.ServletHolder;
import org.eclipse.jetty.util.thread.QueuedThreadPool;
import org.glassfish.jersey.server.ServerProperties;
import org.glassfish.jersey.servlet.ServletContainer;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.HealthResource;

public class DemoStarter {

    private static Logger logger = LoggerFactory.getLogger(DemoStarter.class);

    public static void main(String[] args) {
        logger.info("Starting!");
        ReflectionToStringBuilder.setDefaultStyle(ToStringStyle.SHORT_PREFIX_STYLE);

        ServletContextHandler contextHandler = new ServletContextHandler(ServletContextHandler.NO_SESSIONS);
        contextHandler.setContextPath("/");

        QueuedThreadPool queuedThreadPool = new QueuedThreadPool(10, 1);
        final Server jettyServer = new Server(queuedThreadPool);

        int acceptors = Runtime.getRuntime().availableProcessors();

        ServerConnector serverConnector = new ServerConnector(jettyServer, acceptors, -1);
        serverConnector.setPort(8080);
        serverConnector.setAcceptQueueSize(10);

        jettyServer.addConnector(serverConnector);
        jettyServer.setHandler(contextHandler);

        ServletHolder jerseyServlet = contextHandler.addServlet(ServletContainer.class, "/*");
        jerseyServlet.setInitOrder(0);
        jerseyServlet.setInitParameter(ServerProperties.PROVIDER_PACKAGES, HealthResource.class.getPackage().getName());

        try {
            jettyServer.start();

            Runtime.getRuntime().addShutdownHook(new Thread() {
                @Override
                public void run() {
                    try {
                        logger.info("Stopping!");

                        jettyServer.stop();
                        jettyServer.destroy();
                    } catch (Exception e) {
                        logger.error("Error on shutdown", e);
                    }
                }
            });

            jettyServer.join();
        } catch (Exception e) {
            logger.error("Error starting", e);
        }
    }
}

com.blogspot.nombre_temp.jetty.jersey.logback.demo.model.DemoResponse
package com.blogspot.nombre_temp.jetty.jersey.logback.demo.model;

import java.util.Date;

import org.apache.commons.lang3.builder.ReflectionToStringBuilder;

public class DemoResponse {

    private Date date;
    private boolean error;
    private String message;

    public DemoResponse() {
        date = new Date();
    }

    public DemoResponse(boolean error) {
        this();
        this.error = error;
    }

    public Date getDate() {
        return date;
    }

    public void setDate(Date date) {
        this.date = date;
    }

    public boolean isError() {
        return error;
    }

    public void setError(boolean error) {
        this.error = error;
    }

    public String getMessage() {
        return message;
    }

    public void setMessage(String message) {
        this.message = message;
    }

    @Override
    public String toString() {
        return ReflectionToStringBuilder.toString(this);
    }
}
Esta clase representa la respuesta base que se dará en los servicios de la aplicación. En la implementación del método "toString()" se está usando la antes mencionada clase "ReflectionToStringBuilder" la cual tomará todos los atributos de la instancia e incluirá sus valores en la cadena retornada.

En este caso aunque "DemoResponse" sólo tiene 3 atributos y no sería mayor problema concatenar manualmente sus valores, pero se muestra el uso de "ReflectionToStringBuilder" que también puede ser de utilidad para clases de más atributos y no será necesario modificar el método "toString()" al adicionar, eliminar o modificar los atributos disponibles.

com.blogspot.nombre_temp.jetty.jersey.logback.demo.model.User
package com.blogspot.nombre_temp.jetty.jersey.logback.demo.model;

import org.apache.commons.lang3.builder.HashCodeBuilder;
import org.apache.commons.lang3.builder.ReflectionToStringBuilder;

public class User {

    private Integer id;
    private String name;
    private String password;

    public Integer getId() {
        return id;
    }

    public void setId(Integer id) {
        this.id = id;
    }

    public String getName() {
        return name;
    }

    public void setName(String name) {
        this.name = name;
    }

    public String getPassword() {
        return password;
    }

    public void setPassword(String password) {
        this.password = password;
    }

    @Override
    public int hashCode() {
        return new HashCodeBuilder().append(id).build();
    }

    @Override
    public boolean equals(Object object) {
        if (object instanceof User) {
            User other = (User) object;
            if (id == null) {
                if (other.getId() == null) {
                    return true;
                }
            } else if (id.equals(other.getId())) {
                return true;
            }
        }
        return false;
    }

    @Override
    public String toString() {
        return ReflectionToStringBuilder.toStringExclude(this, "password");
    }
}
Ahora se tiene una clase que represente los datos de los usuarios que se agregarán. Los métodos "equals()" y "hashCode()" están basados en el ID del usuario, mientras que en "toString()" se muestra como se pueden excluir atributos con datos sensibles que no deben incluirse en logs, en este caso "password".

com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource
package com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource;

import java.util.HashSet;
import java.util.Set;

import javax.ws.rs.Consumes;
import javax.ws.rs.POST;
import javax.ws.rs.Path;
import javax.ws.rs.Produces;
import javax.ws.rs.core.MediaType;

import org.apache.commons.lang3.Validate;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import com.blogspot.nombre_temp.jetty.jersey.logback.demo.model.DemoResponse;
import com.blogspot.nombre_temp.jetty.jersey.logback.demo.model.User;

@Path("/users")
@Consumes(MediaType.APPLICATION_JSON)
@Produces(MediaType.APPLICATION_JSON)
public class UsersResource {

    private static Logger logger = LoggerFactory.getLogger(UsersResource.class);

    private static final Set<User> USERS = new HashSet<User>();

    @POST
    public DemoResponse create(User user) {
        logger.info("Creating user: {}", user);
        DemoResponse response = new DemoResponse();

        try {
            Validate.notNull(user, "The user cannot be null");
            logger.debug("Trying to add user with id: {}", user.getId());

            if (USERS.add(user)) {
                logger.info("User created");
            } else {
                logger.warn("User repeated");
                response.setError(true);
                response.setMessage("User repeated");
            }
        } catch (Exception e) {
            logger.error("Error creating the user: {}", user, e);
            response.setError(true);
            response.setMessage(e.getMessage());
        }

        logger.info("User processed with response: {}", response);
        return response;
    }
}
  • Línea 19: Se define que la ruta (path) del nuevo servicio será "users".
  • Línea 24: Se obtiene una instancia de Logger para registrar los eventos en este servicio (resource).
  • Línea 26: Para mantener el ejemplo sencillo, los usuarios se almacenarán en un Set de la misma clase.
  • Línea 30: Se registra la recepción de un nuevo usuario en el nivel "INFO". Nótese que para registrar los datos del nuevo usuario no se está obteniendo atributo por atributo sino que se deja como parámetro la variable "user", de esta manera Java usará automáticamente el método "toString()" el cual ya fue definido previamente para precisamente retornar el valor de los atributos; esto permite tener un código un poco más limpio/claro al momento de usar logs.
  • Línea 34: En caso de enviar un  POST sin cuerpo/contenido, la variable "user" será null, en cuyo caso "Validate.notNull()" lanzará una excepción con el mensaje indicado.
  • Línea 35: Para efectos de la demostración, se registra el ID del nuevo usuario con nivel "DEBUG".
  • Líneas 37-43: En caso de adicionar exitosamente el usuario se registra un mensaje de éxito, de lo contrario se envía un mensaje con nivel "WARN" y se indica esto en la respuesta a retornar.
  • Líneas 44-48: Si se genera una excepción (por ejemplo una llamada sin datos) se registra el error generado en logs y se da indicación de esto en la respuesta. En la invocación de "logger.error()" puede verse que sólo se tiene un placeholder en la plantilla del mensaje, pero dos parámetros luego de esta: la variable con los datos del usuario y la excepción generada. Logback se encargará automáticamente de incluir sólo los datos del usuario en el mensaje y luego dejar la traza de la excepción en logs.
Usando una herramienta que permita enviar peticiones HTTP Post (Postman en este caso) podrá verse el resultado en logs al enviarse una petición sin cuerpo:
17:11:01.411 [qtp963601816-17] INFO com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - Creating user: null
17:11:01.421 [qtp963601816-17] ERROR com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - Error creating the user: null
java.lang.NullPointerException: The user cannot be null
 at org.apache.commons.lang3.Validate.notNull(Validate.java:222)
 at com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource.create(UsersResource.java:34)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 at java.lang.reflect.Method.invoke(Method.java:483)
...
Figura 1 - Respuesta a petición sin cuerpo

En la primera línea del log puede verse que aparece el mensaje "Creating user: null", lo cual en un ambiente de producción puede indicar fue el usuario/cliente quien desde un principio no envió los datos necesarios.

Ya en la segunda línea aparece el mensaje con el error, seguido de la traza de la excepción generada como se comentaba anteriormente lo haría Logback por su cuenta.

Al enviar los datos completos de un nuevo usuario el resultado es el siguiente:
18:31:32.640 [qtp963601816-20] INFO com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - Creating user: User[id=1,name=Test 1]
18:31:32.672 [qtp963601816-20] DEBUG com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - Trying to add user with id: 1
18:31:32.672 [qtp963601816-20] INFO com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - User created
18:31:32.672 [qtp963601816-20] INFO com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - User processed with response: DemoResponse[date=Sun May 15 18:31:32 COT 2016,error=false,message=<null>]

Figura 2 - Petición y respuesta de un nuevo usuario

Puede verse que la secuencia de mensajes en logs es la esperada, inclusive la primera línea no está mostrando el valor del atributo "password" que se indicó se debía excluir en el método "toString()" de "User".

Cuando se intenta almacenar un usuario con un ID repetido se debe obtener lo siguiente:
18:53:50.441 [qtp963601816-20] INFO com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - Creating user: User[id=1,name=Test 1]
18:53:50.441 [qtp963601816-20] DEBUG com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - Trying to add user with id: 1
18:53:50.441 [qtp963601816-20] WARN com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - User repeated
18:53:50.441 [qtp963601816-20] INFO com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - User processed with response: DemoResponse[date=Sun May 15 18:53:50 COT 2016,error=true,message=User repeated]

Figura 3 - Petición y respuesta de un usuario repetido

En la línea 3 puede verse el registro de log esperado con el nivel "WARN" indicando que el usuario está repetido.

Conclusiones

En esta primera parte se ha querido dar simplemente una introducción al uso de Logback con su configuración por defecto y los niveles de logs disponibles para categorizar (o priorizar) los mensajes.

En un próximo post se mostrarán algunas de las opciones de configuración disponibles en Logback, por lo pronto el proyecto desarrollado hasta aquí se puede descargar desde: https://github.com/guillermo-varela/jetty-jersey-logback-demo/tree/part-i

Referencias

Publicadas por a la/s No hay comentarios.:
Etiquetas: , , , , , ,

lunes, 4 de abril de 2016

Prácticas Recomendadas para Proyectos con AngularJS 1.x Parte V: Pruebas


Introducción

En posts anteriores se ha venido desarrollando una aplicación web con AngularJS 1.5, aplicando las recomendaciones que han sido aceptadas por el propio equipo de Google tanto en estructura del proyecto, secciones y rutas como el estilo de desarrollo de componentes como Directivas, Constantes, Controladores y Servicios, e inclusive se han abordado algunos puntos a tener en cuenta para publicar en un ambiente de producción.

Ahora para finalizar esta serie de posts se tratará el tema de las pruebas en la aplicación, tanto unitarias como las conocidas como end-to-end (e2e).

Pruebas Unitarias

Herramientas y Librerías

Para las pruebas se recomienda usar una librería que permita escribir el código de manera clara y descriptiva, casi como una historia.

Dos de las librerías más usadas son Jasmine y Mocha. Personalmente prefiero Jasmine (desde la versión 2) ya que es la que se usa en los tutoriales oficiales de Google de AngularJS y adicionalmente incluye varias de las características más requeridas en una librería de este tipo: aserciones (assertions) y mocks/spy/stubs, mientras que con Mocha se requiere de librerías adicionales para ello, aunque esto último puede ser una ventaja para Mocha si se tiene preferencia por otras librerías de aserciones o mocks. Una comparación más detallada sobre ambas librerías se puede encontrar en: http://thejsguy.com/2015/01/12/jasmine-vs-mocha-chai-and-sinon.html

Para ejecutar las pruebas unitarias se usará Karma ya que su fácil configuración y uso permite que puedan ejecutarse las pruebas tanto localmente como en un servidor de integración continua.

Como se mencionó anteriormente Jasmine ya permite construir mocks, pero para seguir la recomendación se usará Sinon.JS para ello.

Dado que las pruebas unitarias también se escriben usando JavaScript se requiere de un navegador web que lo interprete y lo ejecute sobre el código de la aplicación web, sin embargo existen pocas razones prácticas para usar un navegador con interfaz gráfica para este propósito por lo que se usará PhantomJS, el cual es un navegador web basado en WebKit precisamente sin interfaz gráfica.

Para usar estas librerías/herramientas más fácilmente mediante Gulp se instalarán los siguientes plugins:
  • karma: Paquete principal de Karma.
  • karma-angular-filesort: La tarea de Gulp "inject" está usando el plugin "gulp-angular-filesort" para ordenar adecuadamente los archivos JavaScript que se referencian en "index.html" según las dependencias declaradas. Este nuevo plugin permite hacer lo mismo pero de manera interna en Karma al momento de iniciar las pruebas.
  • karma-ng-html2js-preprocessor: Algunas pruebas unitarias requieren el uso de las vistas HTML de la aplicación web, por ejemplo las pruebas de directivas (o en general las que usen el método "scope.$digest()"). Este plugin toma el contenido de los archivos HTML y los adiciona en un "$templateCache" para que pueda durante en las pruebas en lugar de tener que configurar el servicio "$httpBackend" con cada llamado a estos archivos manualmente y evitando así los errores "Unexpected GET /file.html".
  • karma-spec-reporter: Se adiciona este plugin para reportar el resultado de las pruebas de una manera un poco más clara.
npm install karma karma-phantomjs-launcher karma-jasmine karma-angular-filesort karma-ng-html2js-preprocessor karma-spec-reporter --save-dev

Adicionalmente se requieren dos dependencias de desarrollo mediante Bower:
  • angular-mocks: Provee varias funcionalidades para el desarrollo de pruebas de AngularJS, como por ejemplo servicios mock propios de AngularJS.
  • jasmine-sinon: Permite usar algunos matchers adicionales de Sinon.JS dentro del código Jasmine, instalando de paso ambas librerías también como dependencias.
bower install angular-mocks#1.5.0 jasmine-sinon --save-dev

Nota: En este caso se indica manualmente la versión de "angular-mocks" (1.5.0) para que coincida con la misma que se tiene de AngularJS en la aplicación.

Para configurar Karma se puede usar el comando "karma init" (debe ejecutarse desde la raíz del proyecto) el cual realizará una serie de preguntas sobre el código para las pruebas:
karma init

Which testing framework do you want to use ?
Press tab to list possible options. Enter to move to the next question.
> jasmine

Do you want to use Require.js ?
This will add Require.js plugin.
Press tab to list possible options. Enter to move to the next question.
> no

Do you want to capture any browsers automatically ?
Press tab to list possible options. Enter empty string to move to the next question.
> PhantomJS
>

What is the location of your source and test files ?
You can use glob patterns, eg. "js/*.js" or "test/**/*Spec.js".
Enter empty string to move to the next question.
> app/**/*.js
>

Should any of the files included by the previous patterns be excluded ?
You can use glob patterns, eg. "**/*.swp".
Enter empty string to move to the next question.
>

Do you want Karma to watch all the files and run the tests on change ?
Press tab to list possible options.
> yes


Config file generated at "D:\angularjs-demo\karma.conf.js".

Al finalizar se debe tener un nuevo archivo "karma.conf.js" con la configuración se indicó en las respuestas anteriores. Algunos cambios son requeridos para trabajar con todas las herramientas previamente mencionadas, así que debe abrirse el archivo y dejarlo como el siguiente ejemplo:

karma.conf.js
// Karma configuration

module.exports = function(config) {
  config.set({

    // base path that will be used to resolve all patterns (eg. files, exclude)
    basePath: '',


    // frameworks to use
    // available frameworks: https://npmjs.org/browse/keyword/karma-adapter
    frameworks: ['jasmine', 'angular-filesort'],


    // list of files / patterns to load in the browser
    files: [
      // bower:js
      // endbower
      'app/**/*.js',
      'app/**/*.html'
    ],


    angularFilesort: {
      whitelist: [
        'app/**/*.js'
      ]
    },


    // list of files to exclude
    exclude: [
    ],


    // preprocess matching files before serving them to the browser
    // available preprocessors: https://npmjs.org/browse/keyword/karma-preprocessor
    preprocessors: {
      'app/**/*.html': ['ng-html2js']
    },


    ngHtml2JsPreprocessor: {
      stripPrefix: 'app/',
      moduleName: 'weatherApp.templates'
    },


    // test results reporter to use
    // possible values: 'dots', 'progress'
    // available reporters: https://npmjs.org/browse/keyword/karma-reporter
    reporters: ['spec'],


    // web server port
    port: 9876,


    // enable / disable colors in the output (reporters and logs)
    colors: true,


    // level of logging
    // possible values: config.LOG_DISABLE || config.LOG_ERROR || config.LOG_WARN || config.LOG_INFO || config.LOG_DEBUG
    logLevel: config.LOG_INFO,


    // enable / disable watching file and executing tests whenever any file changes
    autoWatch: true,


    // start these browsers
    // available browser launchers: https://npmjs.org/browse/keyword/karma-launcher
    browsers: ['PhantomJS'],


    // Continuous Integration mode
    // if true, Karma captures browsers, runs the tests and exits
    singleRun: false,

    // Concurrency level
    // how many browser should be started simultaneous
    concurrency: Infinity
  })
}

  • Línea 12: Se indica que se usarán la librerías Jasmin (para escribir las pruebas) y el plugin "angular-filesort" dentro de Karma.
  • Líneas 17-18: Más adelante se creará una tarea de Gulp que inyecte las dependencias de Bower en la lista de archivos que se deben tener en cuenta para las pruebas.
  • Líneas 19-20: Se incluyen los archivos JavaScript y HTML de la aplicación en la lista de archivos que se deben tener en cuenta para las pruebas.
  • Líneas 24-28: Mediante la propiedad "whitelist" se indica que sólo los archivos JavaScript de la aplicación deben procesarse por el plugin "karma-angular-filesort".
  • Líneas 43-46: Configuración del plugin "karma-ng-html2js-preprocessor" para que no incluya el prefijo "app/" en la ruta de las vistas HTML en el "$templateCache" generado y se le asignará el módulo "weatherApp.templates", el cual no corresponde a ninguno que se esté usando en la aplicación, se usará sólo para las pruebas.
  • Línea 74: Se especifica que las pruebas ejecutadas con Karma usarán PhantomJS como navegador.

gulp-paths.json
{
  "app": "./app/",
  "js": ["**/*.js"],
  "jsApp": ["**/*.js", "!**/*.spec.js"],
  "jsMin": "js/scripts.min.js",
  "css": ["**/*.css"],
  "views": ["**/*.html", "!index.html"],
  "templatesCache": "templates.js",
  "dist": "./dist/"
}

Se agrega la entrada "jsApp" con expresiones regulares que permiten incluir el código JavaScript de la aplicación y excluir el código de pruebas (sufijo ".spec.js"), es decir que donde se ese esta entrada sólo se tendrá en cuenta el código realmente funcional de la aplicación.

La razón para tener los archivos con las pruebas unitarias también dentro de "app" es que se recomienda tener el archivo con las pruebas unitarias de un componente en la misma carpeta que el componente probado, así las pruebas son más fáciles de encontrar a primera vista, mejorando la probabilidad de tener ambos archivos actualizados.

Adicionalmente se modificará el archivo ".jshintrc" para indicar que se usará Jasmine y otros elementos de pruebas, para que no sean reportados como errores en el código JavaScript:

.jshintrc
{
  "node": true,
  "browser": true,
  "bitwise": true,
  "curly": true,
  "eqeqeq": true,
  "forin": true,
  "freeze": true,
  "latedef": "nofunc",
  "noarg": true,
  "nonbsp": true,
  "nonew": true,
  "undef": true,
  "unused": true,
  "strict": true,
  "jasmine": true,
  "globals": {
    "angular": false,
    "google": false,
    "sinon": false,
    "inject": false
  }
}


gulpfile.js
'use strict';

var gulp        = require('gulp');
var plugins     = require('gulp-load-plugins')();
var paths       = require('./gulp-paths.json');
var wiredep     = require('wiredep').stream;
var del         = require('del');
var st          = require('st');
var runSequence = require('run-sequence');
var KarmaServer = require('karma').Server;

// Search for js and css files created for injection in index.html
gulp.task('inject', function () {
  return gulp.src('./index.html', {cwd: paths.app})
    .pipe(plugins.inject(
      gulp.src(paths.jsApp, {cwd: paths.app}).pipe(plugins.angularFilesort()), {
        relative: true
    }))
    .pipe(plugins.inject(
      gulp.src(paths.css, {cwd: paths.app, read: false}), {
        relative: true
    }))
    .pipe(gulp.dest(paths.app));
});

// Inject libraries via Bower in between of blocks "bower:xx" in index.html
gulp.task('wiredep', ['inject'], function () {
  return gulp.src('index.html', {cwd: paths.app})
    .pipe(wiredep({
      'ignorePath': '..'
    }))
    .pipe(gulp.dest(paths.app));
});

// Inject libraries via Bower in between of blocks "bower:xx" in karma.conf.js
gulp.task('wiredep-karma', function () {
  return gulp.src('./karma.conf.js')
    .pipe(wiredep({devDependencies: true}))
    .pipe(gulp.dest('./'));
});

// Run test once and exit
gulp.task('test', ['wiredep-karma'], function (done) {
  new KarmaServer({
    configFile: __dirname + '/karma.conf.js',
    singleRun: true
  }, done).start();
});

// Watch for file changes and re-run tests on each change
gulp.task('tdd', ['wiredep-karma'], function (done) {
  new KarmaServer({configFile: __dirname + '/karma.conf.js'}, done).start();
});

// Compress into a single file the ones in between of blocks "build:xx" in index.html
gulp.task('compress', ['wiredep'], function () {
  return gulp.src('index.html', {cwd: paths.app})
    .pipe(plugins.useref({ searchPath: ['./', paths.app] }))
    .pipe(plugins.if('*/scripts.min.js', plugins.replaceTask({
      patterns: [
        {
          match: 'debugInfoEnabled',
          replacement: 'false'
        },
        {
          match: 'debugLogEnabled',
          replacement: 'false'
        }
      ]
    })))
    .pipe(plugins.if('**/*.js', plugins.ngAnnotate()))
    .pipe(plugins.if('**/*.js', plugins.uglify({
      mangle: true
    }).on('error', plugins.util.log)))
    .pipe(plugins.if('**/*.css', plugins.cssnano()))
    .pipe(gulp.dest(paths.dist));
});

gulp.task('templates:build', function () {
  return gulp.src(paths.views, {cwd: paths.app})
    .pipe(plugins.htmlmin({collapseWhitespace: true}))
    .pipe(plugins.angularTemplatecache({
      module: 'weatherApp',
      moduleSystem: 'IIFE'
    }))
    .pipe(plugins.uglify({
      mangle: true
    }))
    .pipe(gulp.dest(paths.dist));
});

gulp.task('templates:concat', ['templates:build'], function () {
  return gulp.src([paths.jsMin, paths.templatesCache], {cwd: paths.dist})
    .pipe(plugins.concat(paths.jsMin))
    .pipe(gulp.dest(paths.dist));
});

gulp.task('templates:clean', ['templates:concat'], function () {
  return del(paths.dist + paths.templatesCache);
});

// Copies the assets into the dist folder
gulp.task('copy:assets', function () {
  return gulp.src('assets*/**', {cwd: paths.app})
    .pipe(gulp.dest(paths.dist));
});

// Looks for code correctness errors in JS and prints them
gulp.task('jshint', function() {
  return gulp.src(paths.js, {cwd: paths.app})
    .pipe(plugins.jshint())
    .pipe(plugins.jshint.reporter('jshint-stylish'))
    .pipe(plugins.jshint.reporter('fail'));
});

// Looks for code style errors in JS and prints them
gulp.task('jscs', function () {
  return gulp.src(paths.js, {cwd: paths.app})
    .pipe(plugins.jscs())
    .pipe(plugins.jscs.reporter())
    .pipe(plugins.jscs.reporter('fail'));
});

// Cleans the dist folder
gulp.task('clean:dist', function () {
  return del(paths.dist + '**/*');
});

// Watch changes on application files
gulp.task('watch', function() {
  gulp.watch(paths.css, {cwd: paths.app}, ['inject']);
  gulp.watch(paths.jsApp, {cwd: paths.app}, ['jshint', 'jscs', 'inject']);
  gulp.watch(['./bower.json'], ['wiredep']);
  gulp.watch('**/*.html', {cwd: paths.app}, function(event) {
    gulp.src(event.path)
      .pipe(plugins.connect.reload());
  });
});

// Starts a development web server
gulp.task('server', function () {
  plugins.connect.server({
    root: paths.app,
    hostname: '0.0.0.0',
    port: 8080,
    livereload: true,
    middleware: function (connect, opt) {
      return [
        st({
          path: 'bower_components',
          url: '/bower_components'
        })
      ];
    }
  });
});

// Starts a server using the production build
gulp.task('server-dist', ['build'], function () {
  plugins.connect.server({
    root: paths.dist,
    hostname: '0.0.0.0',
    port: 8080
  });
});

// Production build
gulp.task('build', function (done) {
  runSequence('jshint', 'jscs', 'clean:dist', 'compress', 'templates:clean', 'copy:assets', done);
});

// Generates the documentation
gulp.task('ngdocs', function () {
  var options = {
    title: "Weather Web App Documentation",
    html5Mode: false
  };
  return gulp.src(paths.jsApp, {cwd: paths.app})
    .pipe(plugins.ngdocs.process(options))
    .pipe(gulp.dest('./docs'));
});

// Starts a server with the docs
gulp.task('server-docs', ['ngdocs'], function () {
  plugins.connect.server({
    root: './docs',
    hostname: '0.0.0.0',
    port: 8081
  });
});

gulp.task('default', ['inject', 'wiredep', 'server', 'watch', 'tdd']);
  • Línea 10: Se agrega una variable con el servidor que inicia las pruebas usando Karma.
  • Línea 16: En la tarea "inject" sólo se requiere el código funcional de la aplicación, para no inyectar el código de pruebas en "index.html", es por ello que se cambia "paths.js" por "paths.jsApp".
  • Líneas 36-40: Se crea la tarea "wiredep-karma" para que mediante "wiredep" se agreguen las dependencias de Bower en el archivo "karma.conf.js" entre los comentarios "bower:js" y "endbower", incluyendo las dependencias de desarrollo.
  • Líneas 43-48: Para ejecutar las pruebas unitarias se crea la tarea "test" para iniciar Karma, luego de ejecutar "wiredep-karma". Aquí se usa "__dirname" dado que se requiere indicar la ruta completa de la ubicación del archivo "karma.conf.js". Teniendo "singleRun" con valor "true" se indica que al ejecutar esta tarea las pruebas sólo se ejecutarán una vez, lo cual puede ser útil para verificar cambios recientes localmente o para ejecutar las pruebas en un servidor de integración continua.
  • Líneas 51-53: Se crea la tarea "tdd" que como su nombre lo indica permite a quienes practican el Desarrollo Orientado a Pruebas (Test-driven Development - TDD) puedan desarrollar cambios en la aplicación y cada vez que se guardan las pruebas se ejecutan para saber si los últimos cambios afectan las pruebas unitarias.
  • Línea 178: La documentación sólo se genera con base en el código funcional, así que también e cambia "paths.js" por "paths.jsApp".
  • Línea 192: Se adiciona la tarea "tdd" a la lista de tareas que se ejecutan al usar el comando "gulp" para que pueda verse el resultado de las pruebas mientras se desarrolla.

Pruebas de Directivas

A continuación se mostrarán las pruebas unitarias para la directiva que se desarrolló en la aplicación "waSectionHeader":

app/widgets/wa-section-header/wa-section-header.directive.spec.js
(function() {
  'use strict';

  describe('waSectionHeader', function() {

    var $scope;
    var $compile;

    beforeEach(function() {
      module('weatherApp.widgets');
      module('weatherApp.templates');

      inject(function($rootScope, _$compile_) {
        $scope = $rootScope.$new();
        $compile = _$compile_;
      });
    });

    it('Adds the header to the HTML content from plain text', function() {
      var element = '';

      element = $compile(element)($scope);
      $scope.$digest();

      expect(element.find('h1').text()).toEqual('Plain Title');
      expect(element.find('p').text()).toEqual('Plain Subtitle');
    });

    it('Adds the header to the HTML content from the scope', function() {
      $scope.header = {
        title: 'Scope Title',
        subtitle: 'Scope Subtitle'
      };

      var element = '';

      element = $compile(element)($scope);
      $scope.$digest();

      expect(element.find('h1').text()).toEqual('Scope Title');
      expect(element.find('p').text()).toEqual('Scope Subtitle');
    });
  });
}());
  • Línea 4: Se empieza definiendo una suite de pruebas con Jasmine usando la función "describe". Una suite de pruebas (test suite) es un conjunto de pruebas unitarias relacionadas, bien sea porque pruebas un mismo componente o una misma funcionalidad. En este caso se tiene como descripción de la suite el nombre de la directiva "waSectionHeader".
  • Líneas 6-7: Definición de variables globales dentro de la prueba, las cuales serán usadas en varios métodos de prueba.
  • Líneas 9-17:  Se define una función que se ejecutará antes de cada uno de los métodos de prueba en la suite, usando "beforeEach", la cual:
    • Carga los módulos "weatherApp.widgets" (en el que se encuentra la directiva) y "weatherApp.templates" (en el que se cargan las vistas HTML para las pruebas).
    • Usa la función "inject" para inyectar como dependencias los servicios "$rootScope" y "$compile" y asignarlos a las variables globales de la suite. En el caso de "$compile" se tiene entre símbolos guión bajo "_" ya que "inject" ofrece la posibilidad de indicar los nombres de las dependencias de esta manera, quitando internamente dichos símbolos al buscar los objetos a retornar, permitiendo así que las variables a las que se asignen las dependencias obtenidas puedan tener el mismo nombre del servicio y tener así mayor claridad para leer el código.
  • Líneas 19-27: Mediante la función "it" se define un método de prueba, especificación o "Spec" con una descripción que explique lo que se está probando, que idealmente debe ser una sola funcionalidad. En este caso se probará que la directiva pueda tomar el texto del título y subtítulo como texto indicado directamente en el HTML.
    • Línea 20: Se crea el texto HTML con la directiva y los textos para título y subtítulo.
    • Línea 22: Compila el HTML y se retorna un objeto "element" que tendrá el DOM generado a partir de la directiva.
    • Línea 23: Usando "$digest" se procesa la directiva usada y a partir de ese momento la variable "element" ya tiene el DOM con el HTML resultante.
    • Líneas 25-26: Se comprueba que el resultado obtenido sea el esperado usando expectativas (expectations) mediante la función "expect", la cual recibe como parámetro el valor obtenido como resultado de la operación que se está probando (en este caso el texto generado dentro de los tags "h1" y "p") y se contrasta mediante el comparador (matcher) "toEqual" con el valor que se espera tener. Si todas las comprobaciones son exitosas, se considera que la prueba ha sido exitosa, pero si al menos una falla, entonces se considera una prueba fallida.
  • Líneas 29-42: De manera similar el método de prueba anterior, se verifica que la directiva pueda tomar valores para mostrar un título y subtítulo, pero esta vez los toma de un objeto que se encuentre dentro del scope usando en el HTML.
Al ejecutar las pruebas mediante el comando "gulp test" debe obtenerse un resultado como el siguiente:
Figura 1 - Pruebas unitarias exitosas

Si se introduce un error en alguna de las comparaciones, al ejecutar nuevamente "gulp test" podrá verse cómo se reportan los errores:

Figura 2 - Prueba unitaria con error

Como se puede ver en la figura 2, se indica tanto la descripción de la prueba que falló, como la razón del error (Expected 'Plain Subtitle' to equal 'Plain Subtitle Test'.) e inclusive la línea del archivo en la que se presentó el error.

Nota: Al final de una ejecución con pruebas fallidas puede aparecer una traza adicional de error "Error: 1 at formatError ..." con invocaciones internas de Gulp. Esto se debe a que la tarea de Gulp se reporta como ejecutada con error. Un pull-request fue enviado al repositorio que tiene la documentación de la integración entre Karma y Gulp (gulp-karma) para que al finalizar Karma la tarea de Gulp se reportara como exitosa, pero fue rechazado ya que en procesos automatizados (construcción/entrega continua por ejemplo) se requiere verificar si las tareas se ejecutaron correctamente antes de por ejemplo generar o desplegar una nueva versión. Dicha traza con las invocaciones internas no representan un problema para la ejecución de las pruebas, así que simplemente puede ignorarse.

Pruebas de Servicios

Ahora se realizarán las pruebas unitarias del servicio "WeatherService".

app/core/weather.service.spec.js
(function() {
  'use strict';

  describe('WeatherService', function() {

    var WeatherService;
    var $httpBackend;
    var fakeData = {
      name: 'Fake City',
      sys: {
        country: 'Fake Country'
      },
      weather: [{
        description: 'This is a test',
        icon: 'test'
      }],
      main: {
        temp: 20
      }
    };
    var expectedData = {
      name: 'Fake City',
      country: 'Fake Country',
      description: 'This is a test',
      temperature: 20,
      image: 'http://openweathermap.org/img/w/test.png'
    };

    beforeEach(function() {
      module('weatherApp.core');

      inject(function(_WeatherService_, _$httpBackend_) {
        WeatherService = _WeatherService_;
        $httpBackend = _$httpBackend_;
      });
    });

    afterEach(function() {
      $httpBackend.resetExpectations();
    });

    it('Should return the city info', function(done) {
      $httpBackend
        .expectGET(/http:\/\/api\.openweathermap\.org\/data\/2\.5\/weather\?.*/g)
        .respond(fakeData);

      WeatherService.checkCity()
        .then(
          function(data) {
            expect(data).toEqual(expectedData);
            done();
          });

      $httpBackend.flush();
    });

    it('Should handle an unexisting city response', function(done) {
      $httpBackend
        .expectGET(/http:\/\/api\.openweathermap\.org\/data\/2\.5\/weather\?.*/g)
        .respond({
          cod: '404'
        });

      WeatherService.checkCity()
        .catch(
          function(error) {
            expect(error).toEqual('City not found');
            done();
          });

      $httpBackend.flush();
    });
  });
}());
  • Línea 34: Se inyecta el servicio "$httpBackend" el cual permite indicar que debe responder el servicio "$http" cuando sea llamado por alguno de los componentes que hagan parte de la prueba para evitar que los datos de la prueba dependan de componentes o servicios externos. En este caso "WeatherService" usa "$http" para consultar el clima mediante el API de OpenWeatherMap. A diferencia de las funciones de prueba anteriores, aquí se está indicando el parámetro "done" el cual es una función que se debe llamar cuando se tenga código ejecutado asíncronamente, como es el caso de "WeatherService.checkCity" el cual retorna una promesa.
  • Líneas 38-40: Al finalizar la ejecución de cada una de las funciones de prueba se invocará "$httpBackend.resetExpectations()" borrar las expectativas antes de iniciar otra prueba.
  • Líneas 42-55: Se define un método de prueba en el cual se espera que cuando se consulte una ciudad se obtengan los datos del clima en esta.
    • Líneas 43-45: Usando "$httpBackend" se indica que al hacerse un llamado a la URL de OpenWeatherMap se responda con el objeto indicado en la variable global "fakeData". Aquí se usa una expresión regular en lugar de una cadena (string) para la URL para no tener que especificar todos los parámetros GET (query string).
    • Líneas 47-52: Se invoca la función "WeatherService.checkCity" y se espera que al resolver exitosamente la promesa el resultado sea igual al objeto de la variable global "expectedData" y se invoca la función "done" para indicar que la prueba ha finalizado.
    • Línea 54: Para indicar que todas las peticiones HTTP deben responder se invoca "$httpBackend.flush()".
  • Líneas 57-72: Ahora se define una prueba que permite verificar que cuando se obtiene como respuesta que la ciudad no existe la promesa se rechace y que el valor indicado como la razón del rechazo sea el texto "City not found".

Pruebas de Controladores

Para las pruebas del controlador "CityController" se tiene lo siguiente:

app/home/city/city.controller.spec.js
(function() {
  'use strict';

  describe('CityController', function() {

    var $controller;
    var $q;
    var $scope;
    var WeatherService;
    var WeatherServiceMock;
    var $window;
    var $windowMock;
    var mockTitle = 'Mock Title';
    var mockCity = {
      name: 'Mock City',
      country: 'Mock Country',
      description: 'This is a test',
      temperature: 20,
      image: 'http://url.com/test.png'
    };

    beforeEach(function() {
      module('weatherApp.home');
      module('weatherApp.templates');

      inject(function($rootScope, _$q_, _$controller_, _$window_, _WeatherService_) {
        $scope = $rootScope.$new();
        $scope.pageTitle = mockTitle;
        $q = _$q_;
        $controller = _$controller_;
        $window = _$window_;
        $windowMock = sinon.mock($window);

        WeatherService = _WeatherService_;
        WeatherServiceMock = sinon.mock(WeatherService);
      });
    });

    afterEach(function() {
      WeatherServiceMock.restore();
      $windowMock.restore();
    });

    it('Should have the city weather info', function() {
      var cityController = buildCityController(1, $q.resolve(mockCity));

      expect(cityController.cityWeather).toBe(mockCity);
      expect($scope.pageTitle).toEqual(mockCity.name + ' - ' + mockTitle);
      WeatherServiceMock.verify();
    });

    it('Should handle an unexisting city', function() {
      $windowMock.expects('alert').once().withArgs('Error checking the weather.');

      var cityController = buildCityController(1, $q.reject());
      var unknownCity = {
        name: 'Unknown City'
      };

      expect(cityController.cityWeather).toEqual(unknownCity);
      expect($scope.pageTitle).toEqual(unknownCity.name + ' - ' + mockTitle);
      WeatherServiceMock.verify();
      $windowMock.verify();
    });

    function buildCityController(cityId, cityResult) {
      WeatherServiceMock.expects('checkCity').once().withArgs(cityId).returns(cityResult);

      var cityController = $controller('CityController', {
        $rootScope: $scope,
        $stateParams: {
          cityId: cityId
        },
        $window: $window,
        WeatherService: WeatherService
      });

      // Required to resolve the promise on WeatherService
      $scope.$apply();

      return cityController;
    }
  });
}());
  • Línea 32: Usando "sinon.mock" se crea un mock del servicio "$window" para no usar directamente el servicio real y adicionalmente poder crear expectativas y comprobaciones sobre este, dado que el controlador lo usa para mostrar una alerta en el navegador web si la ciudad consultada no existe.
  • Línea 35: Se crea también un mock para el servicio "WeatherService" para que no se realicen llamados reales al API de OpenWeatherMap.
  • Línea 39-42: Luego de cada prueba se invoca "restore" para borrar las expectativas indicadas en los mocks.
  • Líneas 44-50: En la primera prueba se espera que al consultar una ciudad se pueda ver la información del clima:
    • Línea 45: Se construye el controlador indicando que el ID de la ciudad será "1" y la respuesta de "WeatherServiceMock" será una promesa exitosamente resuelta con los datos del objeto de la variable global "mockCity" usando "$q.resolve".
    • Línea 47: Se comprueba que el valor resultante en "cityController.cityWeather" sea el objeto de la variable global "mockCity". Aunque el comprobador (matcher) "toEqual" pudo haberse usado, ahora se tiene "toBe" simplemente como demostración. Mientras "toEqual" comprueba que dos valores u objetos sean equivalentes (que los atributos de los objetos tengan los mismos valores), "toBe" compara si dos objetos son exactamente el mismo, lo cual ocurre en este caso ya que al usar un mock para indicar los datos de la ciudad, estos siempre corresponderán al objeto que se usó como parámetro en la expectativa.
    • Línea 48: Dado que en el controlador se modifica el título de la página ($scope.pageTitle) según la ciudad encontrada, se comprueba que el resultado final corresponda con el nombre de la ciudad retornada por el mock.
    • Línea 49: Adicionalmente para verificar que el mock "WeatherServiceMock" haya sido llamado de acuerdo a la expectativa indicada (una sola vez con el parámetro "1") se usa "verify()".
  • Líneas 52-64: Se prueba que el controlador sea capaz de manejar un intento de consultar una ciudad que no exista.
    • Línea 53: Cuando se obtiene como resultado que la ciudad no existe, el controlador está usando el servicio "$window" para mostrar una alerta al usuario en el navegador web. Aquí se crea una expectativa en el mock de ese servicio que espera que la función "alert" sea llamada una vez con el parámetro "Error checking the weather.".
    • Línea 55: Esta vez se crea el controlador, pero indicando que la respuesta de "WeatherServiceMock" será una promesa rechazada usando "$q.reject()".
    • Línea 60: Al rechazarse la promesa de "WeatherService" en el controlador se ejecuta la función "checkCityError" la cual crea un objeto con el atributo "name" de valor "Unknown City" y lo asigna a "cityWeather". Dado que en este caso "cityController.cityWeather" tendrá un objeto que es equivalente, pero el mismo que la variable local "unknownCity", se debe usar el comparador "toEqual".
    • Líneas 66-82: Centraliza la lógica requerida para crear instancias del "CityController" usando los mocks y demás datos necesarios para ello (como se define en el constructor de CityController), así cualquier función de prueba puede simplemente invocarla con los parámetros que necesite la prueba. Se hace de esta manera ya que la consulta del clima en una ciudad se hace cuando se inicializa el controlador, en lugar de en una función ejecutada con una acción del usuario. Se usa también "$scope.$apply()" para que AngularJS inicie los procesos internos necesarios para responder las promesas que se indicaron como resultado (cityResult).

Al ejecutar de nuevo todas las pruebas (gulp test) se obtiene un resumen con el resultado de todas las ejecuciones en las suites desarrolladas:

Figura 3 - Varias suites de pruebas ejecutadas

Pruebas end-to-end (e2e)

Mientras las pruebas unitarias se centran en verificar el código de la aplicación, las pruebas end-to-end procuran simular algunos comportamientos de los usuarios reales en la aplicación y verificar que el resultado obtenido sea lo que un usuario espera.

Para ejecutar este tipo de pruebas el propio equipo de desarrollo de AngularJS creó la herramienta Protractor, la cual está basada en WebDriverJs (Selenium), para tomar escenarios de prueba y ejecutarlos en navegadores web simulando navegación del usuario.

Al usar Selenium se hace necesario que como pre-requisito se necesite tener instalado el JDK de Java.

Protactor se debe instalar de manera global mediante el comando "npm install -g protractor", el cual también instalará "webdriver-manager" para facilitar la integración entre Protactor y Selenium.

Posteriormente debe ejecutarse "webdriver-manager update" para descargar (o actualizar) los archivos de Selenium.

Archivo de Configuración

Para configurar Protactor basta con crear un archivo "conf.js" en la raíz del proyecto:

conf.js
exports.config = {
  framework: 'jasmine',
  seleniumAddress: 'http://localhost:4444/wd/hub',
  baseUrl: 'http://localhost:8080',
  specs: ['tests/e2e-scenarios.js']
}

Los escenarios de pruebas estarán desarrollados usando Jasmine (al igual que las pruebas unitarias), estarán en el archivo "tests/e2e-scenarios.js" y se ejecutarán sobre la aplicación web que se encuentre disponible en la URL "http://localhost:8080". Por defecto el navegador usado será Google Chrome, pero puede cambiarse definiendo la llave "capabilities.browserName".

Escenarios de Prueba

tests/e2e-scenarios.js
(function() {
  'use strict';

  describe('weatherApp', function() {

    describe('home', function () {
      beforeEach(function() {
        browser.get('/');
      });

      it('Should has an appropriate title', function() {
        expect(browser.getTitle()).toEqual('Home - Weather Web App');
      });

      it('Should has a list of cities', function() {
        var cities = element.all(by.css('.list-group-item')).getText();

        expect(cities.count()).toEqual(15);
        expect(cities.get(2).getText()).toEqual('Cali - CO');
      });
    });

    describe('city', function() {
      beforeEach(function() {
        browser.get('/#/home/city/3687925');
      });

      it('Should has an appropriate title', function() {
        expect(browser.getTitle()).toEqual('Cali - Weather Web App');
      });
    });

  });
}());
  • Línea 4: Se define la suite de pruebas "weatherApp" para la aplicación.
  • Líneas 6-21: Para la sección "home" se define una suite anidada (nested).
    • Líneas 7-9: Antes de cada prueba se accederá en el navegador web a la raíz (/). La variable global de Protactor "browser" es la que permite manipular el navegador web.
    • Líneas 11-13: Función de prueba que verifica que el título en el navegador sea "Home - Weather Web App" usando expectativas y matchers de Jasmine.
    • Líneas 15-20: Función de prueba para identificar si la sección está mostrando la lista de ciudades.
      • Línea 16: Mediante es localizador (locator) "by.css" de Protactor se obtiene el objeto del "ElementFinder" que se espera tenga la lista de ciudades. En "app/home/home.html" se tiene que cada elemento de la lista de ciudades tendrá la clase CSS "list-group-item".
      • Líneas 18-19: Se comprueba que la lista de ciudades tenga 15 elementos y que la tercera que se muestra sea "Cali - CO".
  • Líneas 23-31: Para la sección "city" se define otra suite anidada en la que se prueba si al consultar una ciudad se llega a una página que tenga como título el nombre de la misma seguida del nombre de la aplicación.

Para ejecutar las pruebas e2e se requiere de tres comandos, cada uno ejecutado bien sea en una instancia diferente de la línea de comandos (consola/terminal) o enviándolos a ejecutar en background (si ello es soportado):
  • webdriver-manager start: Inicia el servidor de Selenium, del cual puede comprobarse su estado accediendo a la URL indicada en el campo "seleniumAddress" del archivo de configuración (http://localhost:4444/wd/hub).
  • gulp server-dist: Para esta aplicación es la tarea de Gulp que genera los archivos de la aplicación para producción e inicia un servidor web con la aplicación en "http://localhost:8080", tal como se indicó que se haría en el campo "baseUrl" del archivo de configuración.
  • protractor conf.js: Ejecuta los escenarios de prueba abriendo un navegador web y usando Selenium ejecuta las acciones indicadas en los escenarios.
Por cada prueba exitosa en el reporte final de las pruebas aparecerá un punto verde y al final se tendrá un resumen del número de pruebas ejecutas.

Figura 4 - Pruebas e2e exitosas

Mientras que al tener errores, aparecerá una F en lugar del punto y una descripción del error.

Figura 5 - Pruebas e2e con error

Nota: Debido a la complejidad que puede llegar a tener el mantenimiento de las pruebas e2e, especialmente en aplicaciones de mayor tamaño y/o con más elementos gráficos, el propio equipo de Google recomienda mantener el número de pruebas e2e relativamente bajo (en caso de decidir usar este tipo de pruebas) ya que puede darse que se termine invirtiendo demasiado tiempo ajustando las pruebas e2e cada vez que se hacen cambios en la aplicación. Un ejemplo de ello se puede encontrar en: http://googletesting.blogspot.com.co/2015/04/just-say-no-to-more-end-to-end-tests.html

Conclusiones

Con las recomendaciones aplicadas para el desarrollo de aplicaciones web con AngularJS vemos que no solamente se puede llegar a tener una aplicación web completamente funcional sino también con un esquema de pruebas que permite asegurar un poco más su estabilidad a medida que se incluyen cambios en esta.

De esta manera se ha dado cobertura a un buen número de las recomendaciones oficiales, aunque se recomienda leerlas ya que algunas han quedado por fuera de lo que se vio en esta serie de posts o también se van añadiendo o modificando con el tiempo.

El proyecto que se desarrolló se puede descargar desde: https://github.com/guillermo-varela/angularjs-demo/tree/part-v

Referencias

https://github.com/johnpapa/angular-styleguide/blob/master/a1/README.md
https://docs.angularjs.org/api/ngMock
http://jasmine.github.io
Publicadas por a la/s No hay comentarios.:
Etiquetas: , , ,
Suscribirse a: Entradas (Atom)