Amber: Improve amber logs

Created on 31 Oct 2017 · 26Comments · Source: amberframework/amber

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

create a new app
run the app
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.

screenshot_20171031_143928

screenshot_20171031_145419

@amberframework/contributors WDYT?

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

enhancement

Source

faustinoaq

Most helpful comment

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

marksiemers on 2 Nov 2017

👍2 ❤1 🎉1

All 26 comments

@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)

marksiemers on 1 Nov 2017

👍2

@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?

faustinoaq on 2 Nov 2017

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

eliasjpr on 2 Nov 2017

eliasjpr on 2 Nov 2017

@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 on 2 Nov 2017

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 😄

faustinoaq on 2 Nov 2017

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).

marksiemers on 2 Nov 2017

👍1

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 on 2 Nov 2017

👍1

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 😄

faustinoaq on 2 Nov 2017

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

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

marksiemers on 2 Nov 2017

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

faustinoaq on 2 Nov 2017

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

marksiemers on 2 Nov 2017

👍2 ❤1 🎉1

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

faustinoaq on 2 Nov 2017

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 on 2 Nov 2017

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.

faustinoaq on 2 Nov 2017

Was taking a shot at this. WSYGT?

screen shot 2017-11-04 at 4 30 01 pm

eliasjpr on 4 Nov 2017

👍1

@eliasjpr I like it, but why I, [ and ] INFO --, Do you think these symbols are useful? 😅

faustinoaq on 4 Nov 2017

INFO, DEBUG, ERROR are useful to see what type of log message it is.

On Nov 4, 2017 3:49 PM, "Faustino Aguilar" notifications@github.com wrote:

@eliasjpr https://github.com/eliasjpr I like it, but why I, [ and ]
INFO --, Do you think these symbols are useful? 😅

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
https://github.com/amberframework/amber/issues/346#issuecomment-341932138,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAHmpNuNDVKmDVyMlSaAPUf48DhPPH9lks5szNv8gaJpZM4QNhdV
.

elorest on 4 Nov 2017

screen shot 2017-11-04 at 7 11 27 pm

eliasjpr on 5 Nov 2017

🎉1

screen shot 2017-11-04 at 7 27 06 pm

eliasjpr on 5 Nov 2017

🎉1

@eliasjpr How it look when an error happens? or when you print something on console using pp

class HomeController < ApplicationController
  def index
    pp context # => How it looks like?
    render("index.ecr")
  end
end

Also

class HomeController < ApplicationController
  def index
    raise "Oops!" # => How it looks like?
  end
end

faustinoaq on 5 Nov 2017

@eliasjpr Is this going to go into the next amber release? If so, could you include some parameter filtering? see issue #379

I have an example branch here: https://github.com/amberframework/amber/compare/nick/filter_parameters?expand=1

fridgerator on 11 Nov 2017

I feel like I might be a little late to the party, but in my job I am frequently consuming logs from different sources. I usually wish that they were more standardized and easy to consume by other systems. I've found JSON and JSONL to be a great logging format but I can understand why it shouldn't be the standard for readability and development.

Is there a way that the logger could be configurable in a way similar to Log Rage where there are different kinds of LogFormatter types that allow you to set the type you want.

require "json"

class JSONLogger < Logger
  def log_request(msg)
     json.to_json(msg)
  end
end

class KeyValueLogger < Logger
  def log_request(msg)
   # some kind of hash 
  end
end

jpotts18 on 14 Nov 2017

I think we could definitely make that happen. Were already going to have to add hooks for filtering and log level is already a thing. It doesn't seem that hard add an option to turn on json output as well.

elorest on 14 Nov 2017

@eliasjpr - Do we have a PR on this anywhere?

marksiemers on 1 Dec 2017

I will be opening a PR over the weekend for this

eliasjpr on 1 Dec 2017

👍1

Was this page helpful?

0 / 5 - 0 ratings

Related issues

Granite template creates wrong float type

ZeroPointEnergy · 4Comments

Model: add -m option to change model: granite, crecto or jennifer

elorest · 7Comments

[CLI] Add new 'inspectdb' command for database introspection

blankoworld · 7Comments

Unexpected behavior on Cluster mode

faustinoaq · 5Comments

State of Amber Framework

eliasjpr · 6Comments