Log del uso de la herramienta

[fdodino]

Como parte de mejorar la experiencia de usuario queremos registrar un log de la actividad de las personas que trabajan en Wollok. Dentro del mismo proyecto, queremos grabar un registro de

• operaciones que tarden más de x milisegundos (que se pueda configurar en el package.json): build, validación, ejecución de tests, ejecución de un comando del REPL, etc.
• errores que tire el IDE (Wollok LSP a su vez debe evitar que salte el popup, pero acá queremos que quede registrado para poder entender si hay algo que arreglar)
• no estoy seguro de si tiene sentido guardar un log de cosas que se fueron haciendo: run test, run all tests, levantar el REPL, qué comandos del REPL se ejecutaron

Como herramienta de logging existe Pino y Winston (ambos desconocidos por mí) según este artículo. Idealmente deberíamos buscar que sea estructurado el logging, quizás que se acote el tamaño y hay que agregarlo al gitignore (abrir un issue en wollok-ts-cli). Me encantaría agregar un comando en wollok-lsp-ide que mande el log a una casilla de correo nuestra, creo que hay que ser claros respecto a que no se envía ninguna info sensible.

Tareas derivadas

• build environment for file => qué file - agregar timestamp
• revisar los errores: "No source map for node" => qué node

[PalumboN]

A mí pedagógicamente me interesa saber cuántas veces corrieron los tests y sus resultados. Y si lo hicieron con algún Warning / Error en el código también me interesa saber cuáles.
🤓

[fdodino]

Bueno, @PalumboN , hoy retomé un poquito (todavía estoy en Mar Azul, el domingo vuelvo y el miércoles me vuelvo a ir a Mendoza una semanita), pero ya curioseé y

• me copa winston más que pino (el benchmark de 5x que ellos pregonan es medio falopa y la sintaxis de winston me parece más copada)
• ya se que admite formatters distintos para cada transport: esto es, quiero que haya un transport a la consola para que se siga mostrando el log actual pero que además lo formatee en json al archivo. Hay un bug que no estoy muy seguro de si nos afecta, lo voy a probar
• habría que ver qué onda el tamaño del log, yo por ahora lo dejaría que suba (no lo ignoraría), si vemos que en UNSAM/UNQ no causa problemas lo dejamos y si no lo agregamos en el .gitignore
• tendríamos que ver si podemos integrarlo en el wollok-ts-cli o si tenemos que cambiar la API de ts-cli para que nos devuelva la info
• y yo armaría un componente nuevo que maneje el tema del logging, cosa de poder cambiar el framework si lo necesitamos

[fdodino]

Hoy probé configurar un logger para el cliente y el server, los puse en un directorio utils hermano de client/src y server/src. El archivo tsconfig.json necesitaba tener dos root dirs:

    "rootDirs": [
      "src",
      "../utils",
    ],

El import se hace

import { logger } from './logger'

Pero ahora que lo pensé un toque más la implementación del logger no deja de ser un pasamanos y no le veo mucha utilidad (más allá de wrappear el framework que se use por atrás). Por ahora lo voy a volver para atrás y pienso usar directamente winston, veremos si después se justifica la necesidad.

[fdodino]

Update: ya configuré en LSP el server para que empiece a generar logs tanto en consola como en un file, que va a tener el nombre wollok.log. Una duda que me generaba era si la extensión no tenía que ser json, pero en realidad no es un json posta, porque cada log no está encerrado en un raíz con formato lista: [ ]. Pero hay una extensión que te permite prettificarlo:

https://marketplace.visualstudio.com/items?itemName=dmytro-pustovit.json-logs

Ahora estoy puliendo un poco los logs (ahí se ve que estoy tratando de decir qué file está buildeando y validando, ya capturo los errores de validación para que los muestre también en la consola y tengo dos formatters diferentes para la consola y para el file).

[fdodino]

A modo de recordatorio para cuando retome dejo acá qué hice hasta ahora:

Wollok LSP IDE

Qué hay

• tenemos un logger de Winston configurado para que se muestre por consola y por archivo
• loguea errores de buildeo de environment y rebuilds, en el caso de la performance por consola loguea los tiempos y en el archivo wollok.log solo loguea lo que se pase de un threshold de 100 ms (usa íconos distintos)
• en la consola de standard output solo muestra un mensaje, se colorea bonito. En el archivo te deja el level, el timestamp, el mensaje, y cosas adicionales en formato json
• al buildear ahora dice qué file se buildea y lo hace con un relative path. Cuando hay un error de buildeo el file va completo, porque puede ser útil ver si en el path hay espacios o caracteres raros.

Qué falta

• Agregar el resultado del diagnóstico del buildeo cuando hay errores (el archivo debe guardar la lista de errores como atributo, en la consola solo indicar en el mensaje cantidad de errores y warnings)
• Poder configurar el threshold en ms
• Agregar más tests unitarios
• Hacer una prueba general de cómo funciona y si hay que agregar algo

Wollok TS CLI

• Voy a agregar directamente el log del archivo en TS-CLI , porque cambiar la API es un laburo mucho mayor y no se justifica por ahora. Ya hice una prueba de concepto y funciona, pero el logger que usamos es de otro paquete loglevel que tengo que investigar: es el que permite usar chalk para colorear la terminal pero hace que tenga caracteres raros en el file. Se puede sanitizar el mensaje para el file pero hay que toquetear la configuración para poder mandarlo a la terminal (probé usar el standard output y no logueaba nada por consola, quizás hay que usar otro transport, hay que tunearlo)
• Igualmente quizás haya que hacer un laburito de loguear cosas diferentes para el archivo y para la terminal porque tiene más sentido que en el archivo haya menos verbosidad.

Otros tickets a crear

• Cuando renombrás un archivo se rompen todas las referencias, estaría bueno ver si podemos hacer un full rebuild del environment (o resetearlo previamente) para que no queden las versiones viejas
• A veces siguen saltando los popups cuando por ejemplo le sacás el nombre al program
• Más allá de saltar el popup, cuando querés correr los tests y tenés ese error en el program te rompe los tests, si los tests no tienen que ver con el program no deberían interferir en la ejecución
• Probé hacer object pepita inherits pepita y me decía que tenía que usar self en el inherits pepita, hay que abrir otro issue
• Podríamos configurar el level en LSP IDE para ver si queremos que sea más verboso o no (por default no y que loguee de info para arriba o si no que loguee de debug para arriba)

Cómo se ve

Consola Output

File

{"level":"info","message":"⌛ Building environment for main.wpgm | 109 ms","timestamp":"2024-01-16T03:49:58.704Z"}
{"level":"info","message":"⌛ Building environment for utils/object.wlk | 122 ms","timestamp":"2024-01-16T22:20:18.780Z"}
{"file":"file:///home/dodain/workspace/wollok-dev/wollok-workspace/demo/pruebita/main.wpgm","level":"error","message":"✘ Failed to rebuild document: Error: Failed to parse home/dodain/workspace/wollok-dev/wollok-workspace/demo/pruebita/main.wpgm: \n-- PARSING FAILED --------------------------------------------------\n\n  1 | import example.*\n  2 | \n> 3 | program  {\n    |          ^\n  4 |   const pepita = new Bird()\n  5 |   const semilla = new Seed()\n\nExpected one of the following: \n\nidentifier, whitespace\n","timestamp":"2024-01-16T22:23:20.053Z"}
{"file":"file:///home/dodain/workspace/wollok-dev/wollok-workspace/demo/pruebita/main.wpgm","level":"error","message":"✘ Failed to rebuild document: Error: Failed to parse home/dodain/workspace/wollok-dev/wollok-workspace/demo/pruebita/main.wpgm: \n-- PARSING FAILED --------------------------------------------------\n\n  1 | import example.*\n  2 | \n> 3 | program {\n    |         ^\n  4 |   const pepita = new Bird()\n  5 |   const semilla = new Seed()\n\nExpected one of the following: \n\nidentifier, whitespace\n","timestamp":"2024-01-16T22:23:20.748Z"}
{"file":"file:///home/dodain/workspace/wollok-dev/wollok-workspace/demo/pruebita/main.wpgm","level":"error","message":"✘ Failed to rebuild document: Error: Failed to parse home/dodain/workspace/wollok-dev/wollok-workspace/demo/pruebita/main.wpgm: \n-- PARSING FAILED --------------------------------------------------\n\n  1 | import example.*\n  2 | \n> 3 | program {\n    |         ^\n  4 |   const pepita = new Bird()\n  5 |   const semilla = new Seed()\n\nExpected one of the following: \n\nidentifier, whitespace\n","timestamp":"2024-01-16T22:36:30.759Z"}
{"file":"file:///home/dodain/workspace/wollok-dev/wollok-workspace/demo/pruebita/main.wpgm","level":"error","message":"✘ Failed to rebuild document: Error: Failed to parse home/dodain/workspace/wollok-dev/wollok-workspace/demo/pruebita/main.wpgm: \n-- PARSING FAILED --------------------------------------------------\n\n  1 | import example.*\n  2 | \n> 3 | program {\n    |         ^\n  4 |   const pepita = new Bird()\n  5 |   const semilla = new Seed()\n\nExpected one of the following: \n\nidentifier, whitespace\n","timestamp":"2024-01-16T22:36:30.760Z"}
{"level":"info","message":"⌛ Building environment for utils/object.wlk | 106 ms","timestamp":"2024-01-16T22:36:31.106Z"}
{"level":"info","message":"⌛ Building environment for example.wlk | 104 ms","timestamp":"2024-01-16T22:36:31.385Z"}
{"file":"file:///home/dodain/workspace/wollok-dev/wollok-workspace/demo/pruebita/main.wpgm","level":"error","message":"✘ Failed to rebuild document: Error: Failed to parse home/dodain/workspace/wollok-dev/wollok-workspace/demo/pruebita/main.wpgm: \n-- PARSING FAILED --------------------------------------------------\n\n  1 | import example.*\n  2 | \n> 3 | program  {\n    |          ^\n  4 |   const pepita = new Bird()\n  5 |   const semilla = new Seed()\n\nExpected one of the following: \n\nidentifier, whitespace\n","timestamp":"2024-01-16T22:37:48.563Z"}
{"level":"info","message":"⌛ Building environment for main.wpgm | 131 ms","timestamp":"2024-01-16T22:37:49.136Z"}
{"level":"info","message":"⌛ Building environment for main.wpgm | 103 ms","timestamp":"2024-01-16T22:37:49.368Z"}
{"level":"info","message":"⌛ Building environment for testExample.wtest | 135 ms","timestamp":"2024-01-16T23:55:51.811Z"}
{"level":"info","message":"⌛ Building environment for example.wlk | 105 ms","timestamp":"2024-01-16T23:55:52.116Z"}
{"level":"info","message":"⌛ Building environment for testExample.wtest | 117 ms","timestamp":"2024-01-16T23:56:58.720Z"}
{"level":"info","message":"⌛ Building environment for testExample.wtest | 106 ms","timestamp":"2024-01-16T23:56:58.828Z"}
{"level":"info","message":"⌛ Building environment for example.wlk | 105 ms","timestamp":"2024-01-16T23:56:58.939Z"}
{"level":"info","message":"⌛ Building environment for example.wlk | 123 ms","timestamp":"2024-01-16T23:56:59.063Z"}
{"level":"info","message":"⌛ Building environment for main.wpgm | 104 ms","timestamp":"2024-01-17T00:01:10.342Z"}
{"level":"info","message":"⌛ Building environment for testExample.wtest | 104 ms","timestamp":"2024-01-17T00:02:55.147Z"}
{"level":"info","message":"Puede ser puede ser","timestamp":"2024-01-17T00:02:55.243Z"}
{"level":"info","message":"⌛ Building environment for example.wlk | 110 ms","timestamp":"2024-01-17T00:02:55.360Z"}
{"level":"info","message":"⌛ Building environment for example.wlk | 126 ms","timestamp":"2024-01-17T00:02:55.488Z"}
{"level":"info","message":"⌛ Building environment for main.wpgm | 105 ms","timestamp":"2024-01-17T00:02:55.594Z"}
{"level":"info","message":"⌛ Building environment for testExample.wtest | 101 ms","timestamp":"2024-01-17T02:41:14.934Z"}
{"level":"info","message":"Running all tests matching \u001b[3m\u001b[34mtestExample.\"test para pepita\".\"energia inicial de pepita\"\u001b[39m\u001b[23m on \u001b[3m\u001b[34m/home/dodain/workspace/wollok-dev/wollok-workspace/demo/pruebita\u001b[39m\u001b[23m","timestamp":"2024-01-17T02:41:20.643Z"}
{"level":"info","message":"Running 1 tests...","timestamp":"2024-01-17T02:41:20.825Z"}
{"level":"info","message":"","timestamp":"2024-01-17T02:41:20.856Z"}
{"level":"info","message":"  ","timestamp":"2024-01-17T02:41:20.856Z"}
{"level":"info","message":"    ","timestamp":"2024-01-17T02:41:20.857Z"}
{"level":"info","message":"\n","timestamp":"2024-01-17T02:41:20.858Z"}
{"level":"info","message":"⌛ Building environment for example.wlk | 124 ms","timestamp":"2024-01-17T10:40:35.750Z"}

[fdodino]

El viernes 27/01 retomo ésto.

[PalumboN]

Cuando renombrás un archivo se rompen todas las referencias, estaría bueno ver si podemos hacer un full rebuild del environment (o resetearlo previamente) para que no queden las versiones viejas

#134 ;)

[fdodino]

@PalumboN , el log que te genera cada vez que corrés los tests (le puse que emita la performance, que loguee el stack trace de las fallas):

{
    "failures": [],
    "level": "info",
    "message": "🧪 Test runner executed matching testExample.\"test para pepita\" on /home/dodain/workspace/wollok-dev/wollok-workspace/demo/pruebita",
    "result": {
        "failed": 0,
        "ok": 2
    },
    "timeElapsed": 186,
    "timestamp": "2024-01-26T23:02:54.681Z"
}
{
    "failures": [
        {
            "error": [
                "wollok.lib.AssertionException: Expected <101> but found <100>",
                "  at testExample.\"test para pepita\".\"energia inicial de pepita\" [testExample.wtest:5]"
            ],
            "test": "testExample.\"test para pepita\".\"energia inicial de pepita\""
        }
    ],
    "level": "info",
    "message": "🧪 Test runner executed matching testExample.\"test para pepita\" on /home/dodain/workspace/wollok-dev/wollok-workspace/demo/pruebita",
    "result": {
        "failed": 1,
        "ok": 1
    },
    "timeElapsed": 221,
    "timestamp": "2024-01-26T23:03:09.295Z"
}

[fdodino]

@PalumboN @ivojawer Y ésto es lo que loguearíamos con un programa, los games no los incluiría porque eso entra en loop y es más heavy loguear algo que tenga sentido:

{
    "error": [
        "wollok.lang.MessageNotUnderstoodException: a Seed does not understand chachini()",
        "  at example.Bird.eat(food) [example.wlk:6]",
"  at main.pepe [main.wpgm:3]"
    ],
    "level": "info",
    "message": "🚀 Program executed main.pepe on /home/dodain/workspace/wollok-dev/wollok-workspace/demo/pruebita",
    "ok": false,
    "timeElapsed": 184,
    "timestamp": "2024-01-26T23:04:30.885Z"
}
{
    "level": "info",
    "message": "🚀 Program executed main.pepe on /home/dodain/workspace/wollok-dev/wollok-workspace/demo/pruebita",
    "ok": true,
    "timeElapsed": 171,
    "timestamp": "2024-01-26T23:05:07.013Z"
}

[fdodino]

No estoy logueando en el programa tampoco lo que se emita por consola, para tratar de no ser muy verboso (tampoco estoy muy seguro si tiene sentido, tenemos github para ver en qué estado estaba la cosa en un momento determinado)

[PalumboN]

Buenísimo Fer, muy groso!! :D

Yo de los juegos loggearia al menos que se ejecutó un game (sin info de lo que pasa dentro). Pero eso al menos me deja ver cuántas veces se probó el juego durante el desarrollo (y si se puede tener el tiempo que estuvo corriendo el juego mejor).
Con eso podemos hacer estudios sobre testing manual vs automatizado :)

Por otro lado, me parece bien que estés yendo a por todo con la info de logging.
Si en producción detectamos que el archivo se va a la mierda en tamaño podemos tunearlo iterativamente luego.

Abrazo grande!

[PalumboN]

@fdodino este issue ya está? Si quedaron cosas podemos moverlas a otro issue y cerrar este.

[fdodino]

@PalumboN , sí, no se por qué no lo cerré cuando lo implementamos. Bien revisando issues!