Improve amber logs

[faustinoaq]

Description

Currently Amber shows request and some response information on logs.

 | DELETE  "/languages/1"  | 14.55ms
Params: _method=delete&id=1
200  | GET  "/languages"  | 1.96ms
Params: 
 | DELETE  "/languages/2"  | 27.49ms
Params: _method=delete&id=2
200  | GET  "/languages"  | 1.66ms
Params: 
 | DELETE  "/languages/3"  | 24.58ms
Params: _method=delete&id=3
200  | GET  "/languages"  | 2.28ms
Params: 
 | DELETE  "/languages/4"  | 24.58ms
Params: _method=delete&id=4
200  | GET  "/languages"  | 1.68ms
Params: 
 | DELETE  "/languages/5"  | 27.02ms
Params: _method=delete&id=5
 | DELETE  "/languages/5"  | 397.0µs
Params: _method=delete&id=5
200  | GET  "/languages"  | 1.45ms

Would be useful to show query data on logs too, just like Rails and Phoenix,

Also adding time and aligned/tabulated logs would be useful and more readable.

Steps to Reproduce

1. create a new app
2. run the app
3. see the logs

Expected behavior: aligned and well spaced logs, also timestamp

Actual behavior: logs spreaded in terminal, using multiple lines and empty Params: without timestamps.

Reproduces how often: 100%

Versions

100%

Additional Information

We can follow Lucky/Kemal logs, or even better logs, using Rails/Phoenix pattern

I personally liked the Lucky logs 👇 However I think we can improve them, Lucky logs still lacks good tabulation and spacing.

@amberframework/contributors WDYT?

Reference: https://github.com/amberframework/granite-orm/issues/86

[marksiemers]

@faustinoaq
Improving the logs is a good idea. I think the lucky logs look a bit noisy (perhaps the lack of formatting / indentation).

I'm used to Rails logs, so that would be my bias. Should we start with a list of priorities that we want to see in the log, then think about the design of the output?

For a start:

• route information (verb, controller, action, pipeline, path)
• params
• http status code
• total response time
• database calls (if any - sql, params, optionally response time, rows returned)
• views rendered (including partials, optionally response times for each)

[faustinoaq]

@marksiemers So based in your topic list, an example would be:

GET | PostController  | :index     | :web | "/"       | "?limit=10"  | 200 | 8.5ms | SELECT * FROM posts LIMIT 10  | post/index.ecr
GET | PostController  | :index     | :web | "/"       | ""           | 200 | 1.2ms | SELECT * FROM posts           | post/index.ecr
GET | ApiController   | :index     | :api | "/api/v1" | "?limit=176" | 200 | 9.3ms | SELECT * FROM posts LIMIT 135 | No template
GET | ErrorController | :not_found | :web | "/none"   | ""           | 404 | 4.9ms | No database query             | error/not_found.ecr
GET | PostController  | :index     | :web | "/"       | ""           | 200 | 8.1ms | SELECT * FROM posts           | post/index.ecr
GET | PostController  | :index     | :web | "/"       | ""           | 200 | 5.8ms | SELECT * FROM posts           | post/index.ecr
GET | PostController  | :index     | :web | "/"       | ""           | 200 | 2.3ms | SELECT * FROM posts           | post/index.ecr
GET | ApiController   | :index     | :api | "/api/v1" | "?limit=124" | 200 | 9.3ms | SELECT * FROM posts LIMIT 576 | No template
GET | PostController  | :index     | :web | "/"       | ""           | 200 | 5.5ms | SELECT * FROM posts           | post/index.ecr
GET | PostController  | :index     | :web | "/"       | ""           | 200 | 6.8ms | SELECT * FROM posts           | post/index.ecr
GET | PostController  | :index     | :web | "/"       | ""           | 200 | 2.7ms | SELECT * FROM posts           | post/index.ecr
GET | PostController  | :index     | :web | "/"       | ""           | 200 | 3.8ms | SELECT * FROM posts           | post/index.ecr
GET | ErrorController | :not_found | :web | "/none"   | ""           | 404 | 4.9ms | No database query             | error/not_found.ecr
GET | PostController  | :index     | :web | "/"       | ""           | 200 | 6.9ms | SELECT * FROM posts           | post/index.ecr
GET | PostController  | :index     | :web | "/"       | ""           | 200 | 7.6ms | SELECT * FROM posts           | post/index.ecr
GET | PostController  | :index     | :web | "/"       | ""           | 200 | 4.6ms | SELECT * FROM posts           | post/index.ecr
GET | ApiController   | :index     | :api | "/api/v1" | "?limit=982" | 200 | 9.3ms | SELECT * FROM posts LIMIT 982 | No template

Maybe we can put some fields in a new line WDYT?

[eliasjpr]

bare in mind that the params and query could be of different length. I rather have the info be displayed vertically

[eliasjpr]

START 12/23/2017 00:23:34.000
REQUEST GET | PostController | :index | :web | "/" | 200 | 8.5ms
PARAMS | "?limit=10"
SQL | SELECT * FROM posts LIMIT 10
VIEW | post/index.ecr
END 12/23/2017 00:23:34.000

[faustinoaq]

@eliasjpr Yeah, I agree, though we should use a tabulated output

START   | 2017-11-01 00:23:34.000
REQUEST | GET, PostController, :index, :web, "/", 200, 8.5ms
PARAMS  | "?limit=10"
SQL     | SELECT * FROM posts LIMIT 10
VIEW    | post/index.ecr
END     | 2017-11-01 00:23:34.085

Or maybe omit, the labels and END, colorizing the verb (GET, POST, ...) to make it more visible:

2017-11-01 10:36:48:250 | GET, PostController, :index, :web
2017-11-01 10:44:24:570 | "/?limit=10", 200, 8.5ms
2017-11-01 10:47:51:426 | SELECT * FROM posts LIMIT 10
2017-11-01 10:18:21:748 | post/index.ecr
2017-11-01 10:44:40:643 | GET, SomeController, :show, :web
2017-11-01 10:27:56:291 | "/something", 200, 2.5ms
2017-11-01 10:11:22:654 | some/show.ecr
2017-11-01 10:25:36:244 | POST, PostController, :create, :web
2017-11-01 10:21:14:212 | "/?title=foo", 200, 1.2ms
2017-11-01 10:49:35:826 | INSERT INTO posts(title) VALUES (foo)
2017-11-01 10:12:45:572 | GET, SomeController, :show, :web
2017-11-01 10:17:21:315 | "/something", 200, 2.5ms
2017-11-01 10:51:18:590 | some/show.ecr
2017-11-01 10:59:21:708 | GET, ApiController, :index, :api
2017-11-01 10:24:55:576 | "/?limit=176", 200, 9.3ms
2017-11-01 10:44:36:632 | SELECT * FROM posts LIMIT 135
2017-11-01 10:42:22:841 | GET, ErrorController, :not_found, :web
2017-11-01 10:58:21:839 | "/", 404, 4.9ms
2017-11-01 10:44:21:246 | error/not_found.ecr
2017-11-01 10:39:11:177 | GET, PostController, :index, :web
2017-11-01 10:59:38:537 | "/", 200, 8.1ms
2017-11-01 10:36:17:475 | SELECT * FROM posts
2017-11-01 10:21:58:608 | post/index.ecr

[faustinoaq]

I think we can merge logs from Sentry, builds and executing commands too:

2017-11-01 10:36:48:250 | crystalizing...
2017-11-01 10:36:48:250 | watching files...
2017-11-01 10:36:48:250 | compiling app...
2017-11-01 10:36:48:250 | starting app...
2017-11-01 10:36:48:250 | [Amber 0.3.0] serving application "app" at http://0.0.0.0:3000
2017-11-01 10:36:48:250 | Server started in development.
2017-11-01 10:36:48:250 | Startup Time 00:00:00.0003040
2017-11-01 10:36:48:250 | GET, PostController, :index, :web
2017-11-01 10:44:24:570 | "/?limit=10", 200, 8.5ms
2017-11-01 10:47:51:426 | SELECT * FROM posts LIMIT 10
2017-11-01 10:18:21:748 | post/index.ecr
2017-11-01 10:36:48:250 | Shutting down Amber...

It looks more integrated with amber 😄

[marksiemers]

I'm going to revisit development logs for Phoenix and Rails to see what I like there.

I personally don't like the wall of timestamps on the left.

This, with indentation is what I like best so far for development logs:

START   | 2017-11-01 00:23:34.000
REQUEST | GET, PostController, :index, :web, "/", 200, 8.5ms
PARAMS  | "?limit=10"
SQL     | SELECT * FROM posts LIMIT 10
VIEW    | post/index.ecr
END     | 2017-11-01 00:23:34.085

That is an important distinction to make - development logs vs production logs. We should define what both need to look like (and test too).

[faustinoaq]

Yeah, I think we can remove the "timestamp wall" :)

Maybe we can hide things like SQL or even PARAMS in production mode

I still think we should integrate all logs, even the build and execute logs.

amber watch by example:

INFO    | Watching files...
INFO    | Compiling app...
INFO    | Starting app...
INFO    | [Amber 0.3.0] serving application "app" at http://0.0.0.0:3000
INFO    | Server started in development.
INFO    | Startup Time 00:00:00.0003040
START   | 2017-11-01 00:23:34.000
REQUEST | GET, PostController, :index, :web, "/", 200, 8.5ms
PARAMS  | "?limit=10"
SQL     | SELECT * FROM posts LIMIT 10
VIEW    | post/index.ecr
END     | 2017-11-01 00:23:34.085
INFO    | Changes in /src/controller/post_controller.cr
INFO    | Recompiling app...
INFO    | Restarting app...
INFO    | [Amber 0.3.0] serving application "app" at http://0.0.0.0:3000
INFO    | Server started in development.
INFO    | Startup Time 00:00:00.0003040
START   | 2017-11-01 00:23:34.000
REQUEST | GET, PostController, :index, :web, "/", 200, 8.5ms
PARAMS  | "?limit=10"
SQL     | SELECT * FROM posts LIMIT 10
VIEW    | post/index.ecr
END     | 2017-11-01 00:23:34.085
START   | 2017-11-01 00:23:34.000
REQUEST | GET, PostController, :index, :web, "/", 200, 8.5ms
PARAMS  | "?limit=10"
SQL     | SELECT * FROM posts LIMIT 10
VIEW    | post/index.ecr
END     | 2017-11-01 00:23:34.085
INFO    | Shutting down Amber...

[faustinoaq]

And hide fields when not needed so:

START   | 2017-11-01 00:23:34.000
REQUEST | GET, HomeController, :index, :web, "/", 200, 1.0ms
VIEW    | home/index.ecr
END     | 2017-11-01 00:23:34.001

So 👆 is perfectly valid and beautiful 😄

[marksiemers]

Just thinking out loud:

2017-11-01 00:23:34.000
     REQUEST | GET "/animals", params: {}
  CONTROLLER | AnimalController, :index, :web, (1.0ms)
       MODEL | Animal.all (1.2ms)
         SQL | "SELECT * FROM animals;" (0.2ms)
        VIEW | animals/index.ecr -> animals/_animal.ecr (1.0ms)
    RESPONSE | 200 OK in 3.4ms
2017-11-01 00:23:34.001

Or

GET "/animals", params: {}, 2017-11-01 00:23:34.000
  CONTR | AnimalController, :index, :web, (1.0ms)
  MODEL | Animal.all (1.2ms)
    SQL | "SELECT * FROM animals;" (0.2ms)
   VIEW | animals/index.ecr -> animals/_animal.ecr (1.0ms)
200 OK in 3.4ms, 2017-11-01 00:23:34.001

[faustinoaq]

I like the second one, but maybe putting the timestamp at beginning:

2017-11-01 00:23:34.000 | GET "/animals", params: {}
CONTROLLER | AnimalController, :index, :web, (1.0ms)
     MODEL | Animal.all (1.2ms)
       SQL | "SELECT * FROM animals;" (0.2ms)
      VIEW | animals/index.ecr -> animals/_animal.ecr (1.0ms)
2017-11-01 00:23:34.001 | 200 OK in 3.4ms

[marksiemers]

2017-11-01 00:23:34.000 | GET "/animals", params: {}
  CONTR | AnimalController, :index, :web, (1.0ms)
  MODEL | Animal.all (1.2ms)
    SQL | "SELECT * FROM animals;" (0.2ms)
   VIEW | animals/index.ecr -> animals/_animal.ecr (1.0ms)
2017-11-01 00:23:34.001 | 200 OK in 3.4ms

[faustinoaq]

@amberframework/contributors I like 👆 logs, any suggestions ?

[faustinoaq]

So, comparing...

Current logs:

🤖  compiling blog...
🤖  killing blog...
🤖  starting blog...
I, [2017-11-02 12:11:32 -0500 #12633]  INFO -- : [Amber 0.3.0] serving application "blog" at http://0.0.0.0:3000/
I, [2017-11-02 12:11:32 -0500 #12633]  INFO -- : Server started in development.
I, [2017-11-02 12:11:32 -0500 #12633]  INFO -- : Startup Time 00:00:00.0013140
200  | GET  "/posts"  | 1.29ms
Params: 
200  | GET  "/posts/new"  | 568.0µs
Params: 
I, [2017-11-02 12:18:12 -0500 #12633]  INFO -- : Shutting down Amber

New proposed logs:

🤖 compiling blog...
🤖 killing blog...
🤖 starting blog...
2017-11-02 12:11:32.500 | [Amber 0.3.0]
2017-11-02 12:11:32.500 | Serving application "blog" at http://0.0.0.0:3000/
2017-11-02 12:11:32.500 | Server started in development.
2017-11-02 12:11:32.500 | Startup Time 00:00:00.0013140
2017-11-01 00:23:34.000 | GET "/posts", params: {}
  CONTR | PostController, :index, :web, (290.0µs)
   VIEW | post/index.ecr (1.0ms)
2017-11-01 00:23:34.001 | 200 OK in 1.29ms
2017-11-01 00:23:34.000 | GET "/posts/new", params: {}
  CONTR | PostController, :new, :web, (568.0µs)
   VIEW | post/new.ecr -> post/_form.ecr (1.0ms)
2017-11-01 00:23:34.001 | 200 OK in 1.57ms
2017-11-02 12:18:12.500 | Shutting down Amber

Maybe the initial implementation would be not too fancy (detailed templates post/_form.ecr, detailed time, pipeline) but would be a great improvement.

[faustinoaq]

Do you think we should remove the 🤖 (robot) and 💎 (gem) emojis? I mean, I like them, but in some terminals doesn't look good at all.