bug: LogLvl property seems to be ignored

[stormenergy91]

Description

By default all Buffalo projects have warning log. Since the last version (1.1.0) it was simply add this property in the App class definition and change the Log Level:

app = buffalo.New(buffalo.Options{
    Env:         ENV,
    SessionName: "_buffaloapp_session",
    LogLvl:      logrus.ErrorLevel,
})

But with the last release this seems to be ingored and always the warning errors are visible:

[POP] 2023/03/02 14:58:01 sql - UPDATE .....
[POP] 2023/03/02 14:58:01 sql - UPDATE .....

To Reproduce

Change LogLvl in App Class

Additional Context

No response

[sio4]

Hi @stormenergy91

I just tested it and it worked perfectly with my environment. However, I guess I understand what happened in your environment. Could you please post the output of buffalo info so we can verify if this is the case? (Actually, this is mandatory for bug reports)

By the way, the hint is your log output. This is not the format of Buffalo's logger but the default format of Pop, which means the logs were printed not by Buffalo but by Pop.

Recently, we changed Pop's logging system to include connection/transaction information (ID) when it prints SQL logs. See gobuffalo/pop/issues/794 and gobuffalo/pop/issues/795 for details.

After the change on Pop, we decoupled Buffalo and Pop completely, then fixed Buffalo-pop's logging feature to support the new transaction-aware logging system to make them work together properly. (gobuffalo/buffalo-pop/pull/77)

Please check your go.mod and make your app uses Pop v6.1.0 or higher and Buffalo-pop v3.0.7. It may fix the issue.

If the issue is not fixed with the version update, please let me know and post your result of buffalo info and the full log output.

[stormenergy91]

Thanks @sio4 for your help. I confirm that all warning messages are related to SQL operations so I think is a Pop probleme. I check my project and Pop and Buffalo-Pop are already at the last version. But in any case I'll the the warnign message with LogLvl set to ErrorLevel

Here thebuffalo info:

``` -> Go: Checking installation ✓ The `go` executable was found on your system at: /usr/local/go/bin/go -> Go: Checking minimum version requirements ✓ Your version of Go, 1.20.1, meets the minimum requirements. -> Go: Checking Package Management ✓ You are using Go Modules (`go`) for package management. -> Go: Checking PATH ✓ Your PATH contains /Users/stormenergy/.go/bin. -> Node: Checking installation ✓ The `node` executable was found on your system at: /usr/local/bin/node -> Node: Checking minimum version requirements ✓ Your version of Node, v16.17.0, meets the minimum requirements. -> NPM: Checking installation ✓ The `npm` executable was found on your system at: /usr/local/bin/npm -> NPM: Checking minimum version requirements ✓ Your version of NPM, 8.15.0, meets the minimum requirements. -> Yarn: Checking installation ✓ The `yarnpkg` executable was found on your system at: /usr/local/bin/yarnpkg -> Yarn: Checking minimum version requirements ✓ Your version of Yarn, 3.4.1, meets the minimum requirements. -> PostgreSQL: Checking installation ✘ The `postgres` executable could not be found on your system. For help setting up your Postgres environment please follow the instructions for you platform at: https://www.postgresql.org/download/ -> MySQL: Checking installation ✘ The `mysql` executable could not be found on your system. For help setting up your MySQL environment please follow the instructions for you platform at: https://www.mysql.com/downloads/ -> SQLite3: Checking installation ✓ The `sqlite3` executable was found on your system at: /usr/bin/sqlite3 -> SQLite3: Checking minimum version requirements ✓ Your version of SQLite3, 3.39.5, meets the minimum requirements. -> Cockroach: Checking installation ✘ The `cockroach` executable could not be found on your system. For help setting up your Cockroach environment please follow the instructions for you platform at: https://www.cockroachlabs.com/docs/stable/ -> Buffalo (CLI): Checking installation ✓ The `buffalo` executable was found on your system at: /Users/stormenergy/.go/bin/buffalo -> Buffalo (CLI): Checking minimum version requirements ✓ Your version of Buffalo (CLI), v0.18.14, meets the minimum requirements. -> Buffalo: Application Details Pwd /Users/stormenergy/Source/std/std08 Root /Users/stormenergy/Source/std/std08 GoPath /Users/stormenergy/.go PackagePkg std08 ActionsPkg std08/actions ModelsPkg std08/models GriftsPkg std08/grifts WithModules true Name std08 Bin bin/std08 VCS git WithPop true WithSQLite false WithDep false WithWebpack true WithNodeJs true WithYarn true WithDocker true WithGrifts true AsWeb true AsAPI false InApp true PackageJSON {map[build:webpack --mode production --progress dev:webpack --watch]} -> Buffalo: config/buffalo-app.toml name = "std08" bin = "bin/std08" vcs = "git" with_pop = true with_sqlite = false with_dep = false with_webpack = true with_nodejs = true with_yarn = true with_docker = true with_grifts = true as_web = true as_api = false -> Buffalo: config/buffalo-plugins.toml [[plugin]] binary = "buffalo-pop" go_get = "github.com/gobuffalo/buffalo-pop/v3@latest" -> Buffalo: go.mod module std08 go 1.20 require ( github.com/gobuffalo/buffalo v1.1.0 github.com/gobuffalo/buffalo-pop/v3 v3.0.7 github.com/gobuffalo/envy v1.10.2 github.com/gobuffalo/grift v1.5.2 github.com/gobuffalo/middleware v1.0.0 github.com/gobuffalo/pop/v6 v6.1.1 github.com/gobuffalo/suite/v4 v4.0.4 github.com/gobuffalo/validate/v3 v3.3.3 github.com/gofrs/uuid v4.3.1+incompatible github.com/gosimple/slug v1.13.1 github.com/pkg/errors v0.9.1 github.com/unrolled/secure v1.13.0 golang.org/x/crypto v0.0.0-20220722155217-630584e8d5aa ) require ( github.com/BurntSushi/toml v1.2.1 // indirect github.com/Masterminds/semver/v3 v3.1.1 // indirect github.com/aymerick/douceur v0.2.0 // indirect github.com/davecgh/go-spew v1.1.1 // indirect github.com/dustin/go-humanize v1.0.1 // indirect github.com/fatih/color v1.13.0 // indirect github.com/fatih/structs v1.1.0 // indirect github.com/felixge/httpsnoop v1.0.1 // indirect github.com/fsnotify/fsnotify v1.6.0 // indirect github.com/go-sql-driver/mysql v1.7.0 // indirect github.com/gobuffalo/events v1.4.3 // indirect github.com/gobuffalo/fizz v1.14.4 // indirect github.com/gobuffalo/flect v1.0.0 // indirect github.com/gobuffalo/github_flavored_markdown v1.1.3 // indirect github.com/gobuffalo/helpers v0.6.7 // indirect github.com/gobuffalo/httptest v1.5.2 // indirect github.com/gobuffalo/logger v1.0.7 // indirect github.com/gobuffalo/meta v0.3.3 // indirect github.com/gobuffalo/nulls v0.4.2 // indirect github.com/gobuffalo/plush/v4 v4.1.18 // indirect github.com/gobuffalo/refresh v1.13.3 // indirect github.com/gobuffalo/tags/v3 v3.1.4 // indirect github.com/gorilla/css v1.0.0 // indirect github.com/gorilla/handlers v1.5.1 // indirect github.com/gorilla/mux v1.8.0 // indirect github.com/gorilla/securecookie v1.1.1 // indirect github.com/gorilla/sessions v1.2.1 // indirect github.com/gosimple/unidecode v1.0.1 // indirect github.com/inconshreveable/mousetrap v1.0.1 // indirect github.com/jackc/chunkreader/v2 v2.0.1 // indirect github.com/jackc/pgconn v1.13.0 // indirect github.com/jackc/pgio v1.0.0 // indirect github.com/jackc/pgpassfile v1.0.0 // indirect github.com/jackc/pgproto3/v2 v2.3.1 // indirect github.com/jackc/pgservicefile v0.0.0-20200714003250-2b9c44734f2b // indirect github.com/jackc/pgtype v1.12.0 // indirect github.com/jackc/pgx/v4 v4.17.2 // indirect github.com/jmoiron/sqlx v1.3.5 // indirect github.com/joho/godotenv v1.4.0 // indirect github.com/kballard/go-shellquote v0.0.0-20180428030007-95032a82bc51 // indirect github.com/luna-duclos/instrumentedsql v1.1.3 // indirect github.com/mattn/go-colorable v0.1.9 // indirect github.com/mattn/go-isatty v0.0.14 // indirect github.com/mattn/go-sqlite3 v1.14.16 // indirect github.com/microcosm-cc/bluemonday v1.0.20 // indirect github.com/mitchellh/go-homedir v1.1.0 // indirect github.com/monoculum/formam v3.5.5+incompatible // indirect github.com/nicksnyder/go-i18n v1.10.1 // indirect github.com/pelletier/go-toml v1.2.0 // indirect github.com/pmezard/go-difflib v1.0.0 // indirect github.com/rogpeppe/go-internal v1.9.0 // indirect github.com/sergi/go-diff v1.2.0 // indirect github.com/sirupsen/logrus v1.9.0 // indirect github.com/sourcegraph/annotate v0.0.0-20160123013949-f4cad6c6324d // indirect github.com/sourcegraph/syntaxhighlight v0.0.0-20170531221838-bd320f5d308e // indirect github.com/spf13/cobra v1.6.1 // indirect github.com/spf13/pflag v1.0.5 // indirect github.com/stretchr/testify v1.8.1 // indirect golang.org/x/net v0.0.0-20221002022538-bcab6841153b // indirect golang.org/x/sync v0.1.0 // indirect golang.org/x/sys v0.0.0-20220908164124-27713097b956 // indirect golang.org/x/term v0.0.0-20220722155259-a9ba230a4035 // indirect golang.org/x/text v0.6.0 // indirect gopkg.in/yaml.v2 v2.4.0 // indirect gopkg.in/yaml.v3 v3.0.1 // indirect ) ```

I also add the warnig message when populate data in a custom User model:

POP] 2023/03/07 09:46:45 sql - BEGIN Transaction --- (conn=tx-7122446591380708498, tx=7122446591380708498)
Creating Admin User...
[POP] 2023/03/07 09:46:45 sql - INSERT INTO "users" ("avatar", "created_at", "email", "first_name", "id", "is_mail_active", "is_mobile_active", "is_staff", "is_superuser", "last_name", "mobile", "password_hash", "send_email_notifications", "send_web_notifications", "updated_at") VALUES (:avatar, :created_at, :email, :first_name, :id, :is_mail_active, :is_mobile_active, :is_staff, :is_superuser, :last_name, :mobile, :password_hash, :send_email_notifications, :send_web_notifications, :updated_at) | [{"id":"148cc4bf-8f51-4d6e-b4bb-dc696dc64538","first_name":"Utente","last_name":"Admin","mobile":"","email":"sandbox@stormenergy.com","password_hash":"$2a$10$VQgkOI77x5CusHpHEnLtYOfoeish1x.p3mWNpIUrc7DGD1c9o0i6y","is_staff":true,"is_superuser":true,"is_mobile_active":true,"is_mail_active":true,"avatar":"","send_web_notifications":false,"send_email_notifications":false,"created_at":"2023-03-07T09:46:45.301015+01:00","updated_at":"2023-03-07T09:46:45.301015+01:00"}] (conn=tx-7122446591380708498, tx=7122446591380708498)
[POP] 2023/03/07 09:46:45 sql - UPDATE "users" AS users SET "avatar" = :avatar, "email" = :email, "first_name" = :first_name, "is_mail_active" = :is_mail_active, "is_mobile_active" = :is_mobile_active, "is_staff" = :is_staff, "is_superuser" = :is_superuser, "last_name" = :last_name, "mobile" = :mobile, "password_hash" = :password_hash, "send_email_notifications" = :send_email_notifications, "send_web_notifications" = :send_web_notifications, "updated_at" = :updated_at WHERE users.id = :id | ["148cc4bf-8f51-4d6e-b4bb-dc696dc64538"] (conn=tx-7122446591380708498, tx=7122446591380708498)
Done
[POP] 2023/03/07 09:46:47 sql - END Transaction --- (conn=tx-7122446591380708498, tx=7122446591380708498)

[sio4]

Indeed, this is weird.

You already use Pop v6.1.1 and Buffalo-pop v3.0.7 in your go.mod. Also, the output you posted recently is the form of Pop's new logger which contains conn= and tx=, and the tx= has a non-zero value which means you use Transaction.

What I wonder is the sentence you wrote: "when populate data in a custom User model". Do you also see this kind of log when you just query any existing data for your model or just call a handler that does not use a database? The reason I asking this is:

• The Pop logger is set by buffalo-pop's tx middleware (using the app's logger)
• when the tx middleware is enabled, all handlers using the middleware will show the log regardless they use DB or not.

So I wonder if you use buffalo-pop middleware or use Pop transaction directly for finer control. If the later is your case, I would like to ask you to check how you configure the logging feature of Pop. With this change, we introduced a new Function to set TxLogger (logger for SQL executions) and you can set the logger with the following function.

Could you please check your app.go if you disabled pop transactions by default or related files and let me know what happened? If this is not your case, please provide us with your actions/app.go and models/models.go.

https://pkg.go.dev/github.com/gobuffalo/pop/v6#SetTxLogger

[sio4]

PS. I edited your last comment to make it short in the conversation history by adding <details> and </details> to make the long output to be collapsible. Also please make sure there is no real PII in your log posted before.

[stormenergy91]

Yes I'm using transaction, in my app.go there is:

app.Use(popmw.Transaction(models.DB))
app.Use(translations())

So i tried to set the custom logger with SetTxLogger but I don't understand how to implemt it. There is some example?

PS: Thanks for add details tag

[sio4]

Hmm, interesting. The first line of the quoted code in the last comment, popmw.Transaction() should set the logger inside it (gobuffalo/buffalo-pop/pull/77) so the tx aware logger of the App should be used for Pop too.

1. Could you please share your full app.go
2. Can you confirm if the other queries (not INSERT but SELECT or others) also be logged?
3. How about pages that have no DB connection? Do you see the following line for all requests?

[POP] 2023/03/07 09:46:45 sql - BEGIN Transaction --- (conn=tx-7122446591380708498, tx=7122446591380708498)

[sio4]

FYI, the log should be in the format of the following if the App's log is applied correctly and the log level is Debug.

DEBU[2023-03-09T09:58:45+09:00] BEGIN Transaction --- conn=tx-4102281454373580993 tx=4102281454373580993
DEBU[2023-03-09T09:58:45+09:00] END Transaction --- conn=tx-4102281454373580993 tx=4102281454373580993
INFO[2023-03-09T09:58:45+09:00] / conn=tx-4102281454373580993 content_type=text/html <...>

(I cannot reproduce the issue)

[stormenergy91]

After some research I founded what was the problem. The Pop log info are generated only in my grifts scripts. In this scripts i use the DB var configured in models/models.go and i see that now there is a new line pop.Debug = env == "development", If i comment this line no more log info.

Thansk anyway for the support!

[sio4]

Ah! got it! Thank you for sharing the details!

[stormenergy91]

@sio4 I noticed that if you build a project with buffalo build and than you do ./nameproject migrate you get all the pop info:

...
[POP] 2023/03/29 09:48:48 info - Successfully applied 44 migrations.
[POP] 2023/03/29 09:48:48 info - 0.2438 seconds
...

How I can disable POP logs also in migrate command? I don't want that this info are aviable in production builds.

Thanks

[sio4]

How I can disable POP logs also in migrate command? I don't want that this info are aviable in production builds.

Ah! Good point! However, there is no method to disable it for now. One possible workaround is redirecting the standard error to /dev/null since the log will be printed to the standard error. (coke migrate 2>/dev/null).

Could it be feasible for your condition? By the way, what is the reason for suppressing those logs? Does it break something? While I understand having more control is better for users, I wonder which specific case it affects badly.

[github-actions[bot]]

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment. Otherwise, this will be closed in 7 days.

[github-actions[bot]]

This issue was closed because it has been stalled for 30+7 days with no activity.