Skip to content
This repository has been archived by the owner on Feb 24, 2024. It is now read-only.

bug: LogLvl property seems to be ignored #2368

Closed
stormenergy91 opened this issue Mar 2, 2023 · 13 comments
Closed

bug: LogLvl property seems to be ignored #2368

stormenergy91 opened this issue Mar 2, 2023 · 13 comments
Assignees
@sio4
Labels
s: closed s: triage Some tests need to be run to confirm the issue stale

Comments

@stormenergy91
Copy link

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
Copy link
Member

sio4 commented Mar 3, 2023

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.

@sio4 sio4 added the s: triage Some tests need to be run to confirm the issue label Mar 3, 2023
@sio4 sio4 self-assigned this Mar 3, 2023
@stormenergy91
Copy link
Author

stormenergy91 commented Mar 7, 2023 •
edited by sio4
Loading

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":"[email protected]","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
Copy link
Member

sio4 commented Mar 8, 2023 •
edited
Loading

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
Copy link
Member

sio4 commented Mar 8, 2023

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
Copy link
Author

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
Copy link
Member

sio4 commented Mar 9, 2023

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
Copy link
Member

sio4 commented Mar 9, 2023 •
edited
Loading

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
Copy link
Author

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
Copy link
Member

sio4 commented Mar 24, 2023

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

@stormenergy91
Copy link
Author

@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

@stormenergy91 stormenergy91 reopened this Apr 4, 2023
@sio4
Copy link
Member

sio4 commented Apr 5, 2023

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
Copy link

github-actions bot commented May 6, 2023

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 github-actions bot added the stale label May 6, 2023
@github-actions
Copy link

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

@github-actions github-actions bot closed this as not planned Won't fix, can't repro, duplicate, stale May 13, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@sio4 sio4

Labels
s: closed s: triage Some tests need to be run to confirm the issue stale
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@sio4 @stormenergy91