Logs issues for lucky and avram.

[zw963]

I met several log issues when i do develop use lucky, in fact, i asked one question before in discuss, check #1784, but that did not clear my doubts, instead, more questions.

Following clover project is a tiny project which almost follow the document based on lucky 1.0

https://github.com/zw963/clover

All following issue is reproducible on this project, on the konsole terminal in Arch linux.

---

1. as mention in the document and Not print the SQL logs when use avram as a stand along ORM. #1784, when i set following config in config/log, i expect to see the SQL query log, but i can't.

DB::Log.level = :info
Avram::QueryLog.dexter.configure(:info)

So, Is i do somethings wrong, or document is wrong?

---

2. When i set DB::Log.level = :debug, some logs appear, but not what i want.

Check following screenshot.

I suppose Executing the query in the redbox should clickable, right? but not work on my konsole, i guess i run the process by builtin nox, so any thing wrong?

---

3. After comment backend.formatter = Lucky::PrettyLogFormatter.proc, i can see the SQL query log now.

web          | 2023-04-09T07:27:48.337013Z   INFO - lucky:  -- local: {"method" => "GET", "path" => "/fortunes", "request_id" => nil}
web          | 2023-04-09T07:27:48.337032Z  DEBUG - lucky:  -- local: {"handled_by" => "Fortunes::Index"}
web          | 2023-04-09T07:27:48.337363Z  DEBUG - db: Executing query -- query: "SELECT users.id, users.created_at, users.updated_at, users.email, users.encrypted_password FROM users WHERE users.id = $1 ORDER BY users.id ASC LIMIT 1", args: ["1"]
web          | 2023-04-09T07:27:48.338193Z  DEBUG - db: Executing query -- query: "SELECT fortunes.id, fortunes.created_at, fortunes.updated_at, fortunes.text, fortunes.user_id FROM fortunes", args: []
web          | 2023-04-09T07:27:48.338597Z  DEBUG - lucky: Rendered Fortunes::IndexPage
web          | 2023-04-09T07:27:48.338708Z   INFO - lucky:  -- local: {"status" => 200, "duration" => "1.68ms", "request_id" => nil}

But, when i revert the Avram::QueryLog.dexter.configure setting to :none, i can still see above SQL query log, some things is wrong?

[jwoertink]

I suppose Executing the query in the redbox should clickable, right?

No, this is not meant to be clickable since that's not a cross platform compatible action for standard terminals.

when i revert the Avram::QueryLog.dexter.configure setting to :none, i can still see above SQL

There's 2 places where logging happens currently. In Avram itself through an event emitter https://github.com/luckyframework/avram/blob/376379a54ca115395e1b7eaf2afeeef86720d469/src/avram.cr#L38-L56 and then also at the CrystalDB level https://github.com/crystal-lang/crystal-db/blob/87dc8aafaf1fe5acc2c2203ea7610d0949bda207/src/db/statement.cr#L145 This is where you're seeing the "Executing query" in the red box.

Crystal DB doesn't really give us a good way to hook in to the query methods to customize our logging, so we end up having to emit 2 separate logs depending on what your needs are. If you need to silence all logs, be sure to turn off both

DB::Log.level = :none
Avram::QueryLog.dexter.configure(:none)

[zw963]

So, how to show the SQL query log in lucky? Do we need update our document for clarity?

[jwoertink]

Ok... so apparently that's not possible... I guess it broke at some point, and no one has brought it up. I just tried in a new project and can't get any SQL to log out... 🤷‍♂️ I'll open an issue, but I have no idea how to fix it.

[jwoertink]

luckyframework/avram#937

[grvm]

@jwoertink I had the same issue, but couldn't figure out what was wrong & where,

So, to make it work, I have Monkey Patched the emit_log method defined in the pg-db module, which was logging Executing query everywhere, and now I see all the queries. Didn't go too deep, since I just wanted logs to work. Here is what I've done:

module DB
  class Statement
    protected def emit_log(args : Enumerable)
      Log.debug &.emit(command, query: command, args: MetadataValueConverter.arg_to_log(args))
    end
  end
end

The original is

    protected def emit_log(args : Enumerable)
      Log.debug &.emit("Executing query", query: command, args: MetadataValueConverter.arg_to_log(args))
    end

[jwoertink]

Yeah, that's what I've noticed too. It feels like we'd have to basically add some patches in order to make this work, but really, it should probably be updated in crystal-db directly, I'd imagine. Good find!

[grvm]

Yeah, I have the same thoughts. 👍🏻