bug: LogLvl property seems to be ignored
stormenergy91 opened this issue · 13 comments
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
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.
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 the buffalo 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)
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.
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.
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
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.
- Could you please share your full
app.go - Can you confirm if the other queries (not INSERT but SELECT or others) also be logged?
- 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)
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)
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!
Ah! got it! Thank you for sharing the details!
@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
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.
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.
This issue was closed because it has been stalled for 30+7 days with no activity.