Add more information to log

[treagod]

Debug Log Enhancement Proposal

Overview

This proposal aims to enhance the existing development server log functionality.

Currently, Marten's logging is limited to recording server requests and the application's start and end. While this serves its purpose during development, there is room for improvement to facilitate quicker problem identification.

This proposal introduces to include database queries within the log. Additionally, it modifies the presentation of request information for each server interaction, clearly indicating the initiation and completion of each request. This shall help the developer to distinguish database queries with their respective requests.

Implementation

To implement this enhancement, a straightforward compiler define -Ddebug_log is introduced. Enabling this flag triggers the replacement of the current query/server log mechanism with an augmented version. The -Ddebug_log flag is applied during the marten serve compilation process and can potentially be utilized in release builds as well.

Visual Representation

See the images below to see how the -Ddebug_log flag alters the output:

Log output with the -Ddebug_log flag enabled

Log output with the -Ddebug_log flag disabled

Visual Differentiation

The color scheme might seem like it could suggest errors 😄 my intention was to make the log unique and consistent with Marten Brand's colors. If we need to highlight errors in the future, we can use a distinct red color.

Final words

This is not meant to be merged right now, but more as a guidance for future improvement. I don't have that much experience with the queries right now and I might missing something.

This is for opinions and improvements on this matter.

[ellmetha]

Hey @treagod! 👋

Thanks for the proposal! I am not sure why we would need to introduce a dedicated compilation flag in order to enable additional debug logging. Is it to avoid the Time#measure call in non-debug situations?

Out of curiosity, have you looked at the log_level setting? By default, this setting is set to "info" but changing the logging severity to "debug" is perfectly possible. When doing so, crystal-db already generates some debug-level logs for queries being executed. For example this I what I have in one of my projects when activating debug logs:

[I] [2023-08-07 15:36:42 UTC] [Server] "GET /" 200 - 8.336833ms
[D] [2023-08-07 15:36:43 UTC] [Server] Executing query
  query: SELECT profiles_profile.id, profiles_profile.user_id, profiles_profile.username, profiles_profile.bio, profiles_profile.image_url FROM "profiles_profile"  WHERE profiles_profile.username = ? LIMIT 21 OFFSET 0
  args: ["username"]

Ideally, I think it would be preferable to generate debug-level logs that are displayed only if the user sets the logging level to "debug" (by changing the considered setting). Having additional command line options for the serve command (in order to easily change the logging level) could also be an option.

I also think it would be nice to take into account the fact that crystal-db already generates logs for executed queries. Their logs are missing the actual latency though, so maybe we could only add this missing piece of information as a debug log entry? I think crystal-db also provides a def_around_query_or_exec that we can use to possibly override the default query-related debug logs, this could also be an option to add logs with elapsed times. 🙂

[treagod]

To be honest: I didn't see the log_level, my bad. I'm still not used to all settings. Is there a reason that it isn't set to debug during development? Same question for debug. Maybe at least add them to to development.cr as comments to be more visible for newcomers.

def_around_query_or_exec seems good! Even though I think the output is to verbose, but I'll have a look at it. What do you think about coloring the queries so that it's easier to distinguish the normal output from the query output?

[ellmetha]

To be honest: I didn't see the log_level, my bad. I'm still not used to all settings. Is there a reason that it isn't set to debug during development? Same question for debug.

The debug setting should already be set to true in the development.cr file that generated for new project (reference). Regarding log_level, I think it really comes down to choosing a default that is relatively "production ready". An info log level seems relatively safe in this regard. That being said, we could definitely ensure that log_level is set to debug in the development.cr setting file that is generated for new projects. 🙂

What do you think about coloring the queries so that it's easier to distinguish the normal output from the query output?

Ideally, I would say that maybe it's safer to not colorize them given that we can't know for sure how the logs will be ingested and processed. But if we can conditionally colorize/not colorize based on whether we are in debug mode then it could be an option I guess.