Log a warning when a handler returns nil without calling c.Render(200...

[Baggerone]

Description

Logging improvement request.
There seems to be no log that indicates that a buffalo handler returned a nil error without first calling c.Render() with a 200-300 response code.

This would be very helpful when using transactions, so that there is an indication of why the transaction is rolled back despite no error being triggered in the code.

(I ignorantly wasted several hours trying to troubleshoot my situation.)

Steps to Reproduce the Problem

1. In app.go, include app.Use(popmw.Transaction(models.DB))
2. In a handler that creates an entry in the db have it end with return nil
3. Hit that app endpoint and go look at the database and the logs.

Expected Behavior

A log to say that the transaction was cancelled because nil was returned from the handler without c.Render(200...) being called first.

Actual Behavior

The database will not include the entry that was supposed to have been created, but the logs will have no warning or error to tell you that the transaction was cancelled.

Info

Please run buffalo info and paste the information below where it says "PASTE_HERE".

> 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.14.2, meets the minimum requirements.

-> Go: Checking Package Management
✓ You are using Go Modules (`go`) for package management.

-> Go: Checking PATH
✓ Your PATH contains /go/bin.

-> Node: Checking installation
✓ The `node` executable was found on your system at: /usr/bin/node

-> Node: Checking minimum version requirements
✓ Your version of Node, v12.16.2, meets the minimum requirements.

-> NPM: Checking installation
✓ The `npm` executable was found on your system at: /usr/bin/npm

-> NPM: Checking minimum version requirements
✓ Your version of NPM, 6.14.4, meets the minimum requirements.

-> Yarn: Checking installation
✓ The `yarnpkg` executable was found on your system at: /usr/bin/yarnpkg

-> Yarn: Checking minimum version requirements
✓ Your version of Yarn, 1.22.4, 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.27.2, 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: /go/bin/buffalo

-> Buffalo (CLI): Checking minimum version requirements
✓ Your version of Buffalo (CLI), v0.16.8, meets the minimum requirements.

-> Buffalo: Application Details
Pwd         /translatethis
Root        /translatethis
GoPath      /go
PackagePkg  bitbucket.org/silintl/translate-this-api
ActionsPkg  bitbucket.org/silintl/translate-this-api/actions
ModelsPkg   bitbucket.org/silintl/translate-this-api/models
GriftsPkg   bitbucket.org/silintl/translate-this-api/grifts
WithModules true
Name        translate-this-api
Bin         bin/translate-this-api
VCS         git
WithPop     true
WithSQLite  false
WithDep     false
WithWebpack false
WithNodeJs  false
WithYarn    false
WithDocker  true
WithGrifts  true
AsWeb       false
AsAPI       true
InApp       true
PackageJSON {map[]}

-> Buffalo: config/buffalo-app.toml
name = "translate-this-api"
bin = "bin/translate-this-api"
vcs = "git"
with_pop = true
with_sqlite = false
with_dep = false
with_webpack = false
with_nodejs = false
with_yarn = false
with_docker = true
with_grifts = true
as_web = false
as_api = true

-> Buffalo: config/buffalo-plugins.toml
[[plugin]]
  binary = "buffalo-pop"
  go_get = "github.com/gobuffalo/buffalo-pop/v2"

-> Buffalo: go.mod
module bitbucket.org/silintl/translate-this-api

go 1.14

require (
	github.com/Masterminds/semver/v3 v3.1.0 // indirect
	github.com/aws/aws-sdk-go v1.31.1
	github.com/clipperhouse/uax29 v1.6.3
	github.com/gobuffalo/buffalo v0.16.9
	github.com/gobuffalo/buffalo-pop/v2 v2.0.6
	github.com/gobuffalo/envy v1.9.0
	github.com/gobuffalo/events v1.4.1
	github.com/gobuffalo/fizz v1.9.10 // indirect
	github.com/gobuffalo/mw-contenttype v0.0.0-20190224202710-36c73cc938f3
	github.com/gobuffalo/mw-forcessl v0.0.0-20200131175327-94b2bd771862
	github.com/gobuffalo/mw-paramlogger v1.0.0
	github.com/gobuffalo/nulls v0.4.0
	github.com/gobuffalo/packr/v2 v2.8.0
	github.com/gobuffalo/pop/v5 v5.1.3
	github.com/gobuffalo/suite/v3 v3.0.0
	github.com/gobuffalo/validate v2.0.4+incompatible
	github.com/gobuffalo/validate/v3 v3.3.0
	github.com/gobuffalo/x v0.1.0 // indirect
	github.com/gofrs/uuid v3.3.0+incompatible
	github.com/gorilla/pat v0.0.0-20180118222023-199c85a7f6d1
	github.com/gorilla/sessions v1.2.0
	github.com/jcmturner/gokrb5/v8 v8.3.0 // indirect
	github.com/karrick/godirwalk v1.15.6 // indirect
	github.com/lib/pq v1.6.0 // indirect
	github.com/markbates/goth v1.64.1
	github.com/markbates/grift v1.5.0
	github.com/mattn/go-colorable v0.1.6 // indirect
	github.com/monoculum/formam v0.0.0-20200527175922-6f3cce7a46cf // indirect
	github.com/mrjones/oauth v0.0.0-20190623134757-126b35219450
	github.com/onsi/ginkgo v1.12.2 // indirect
	github.com/pkg/errors v0.9.1
	github.com/rogpeppe/go-internal v1.6.0 // indirect
	github.com/rollbar/rollbar-go v1.2.0
	github.com/rs/cors v1.7.0
	github.com/sirupsen/logrus v1.6.0 // indirect
	github.com/spf13/cobra v1.0.0 // indirect
	github.com/stretchr/testify v1.6.0
	github.com/unrolled/secure v1.0.7
	golang.org/x/crypto v0.0.0-20200510223506-06a226fb4e37 // indirect
	golang.org/x/net v0.0.0-20200528225125-3c3fba18258b // indirect
	golang.org/x/oauth2 v0.0.0-20181203162652-d668ce993890
	golang.org/x/sys v0.0.0-20200523222454-059865788121 // indirect
	gopkg.in/yaml.v3 v3.0.0-20200601152816-913338de1bd2 // indirect
)

[paganotoni]

@Baggerone this one is related with the buffalo-pop middleware. Moving the issue there.

[github-actions]

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.

[sio4]

It seems like this issue is similar to gobuffalo/buffalo#2300 (fixed by gobuffalo/buffalo#2334). The current behavior is something like the following:

When the controller returns an error:

DEBU[2022-10-07T18:30:56+09:00] --- BEGIN Transaction ---
DEBU[2022-10-07T18:30:56+09:00] --- ROLLBACK Transaction ---
ERRO[2022-10-07T18:30:56+09:00] error db=0s params="{}" request_id=4e89496142495081b778-f69bc8ba256445c0378a status=500 tx=kzCInTjmJdEMCQbFJgMRVtQZajRSwf
INFO[2022-10-07T18:30:56+09:00] /error/ db=0s duration=2.661444ms human_size="33 kB" method=GET params="{}" path=/error/ request_id=4e89496142495081b778-f69bc8ba256445c0378a size=33238 status=500 tx=kzCInTjmJdEMCQbFJgMRVtQZajRSwf

When the controller panic:

DEBU[2022-10-07T18:31:00+09:00] --- BEGIN Transaction ---
DEBU[2022-10-07T18:31:00+09:00] --- ROLLBACK Transaction (inner function panic) ---
ERRO[2022-10-07T18:31:00+09:00] transaction was rolled back due to inner panic db=0s params="{}" request_id=369b41b1362d1bc00d67-1c9cebe15cfc759723b3 status=500 tx=uElIJBJRGMvJNrIsgPlpBFwSjHxrWD
INFO[2022-10-07T18:31:00+09:00] /panic/ db=0s duration=2.622052ms human_size="33 kB" method=GET params="{}" path=/panic/ request_id=369b41b1362d1bc00d67-1c9cebe15cfc759723b3 size=33279 status=500 tx=uElIJBJRGMvJNrIsgPlpBFwSjHxrWD

When the controller returns nil:

DEBU[2022-10-07T18:31:26+09:00] --- BEGIN Transaction ---
DEBU[2022-10-07T18:31:26+09:00] --- ROLLBACK Transaction ---
INFO[2022-10-07T18:31:26+09:00] /nil/ db=0s duration=1.74566ms human_size="0 B" method=GET params="{}" path=/nil/ request_id=50ca8a5db3d08a343e0b-6df8283bcc90cabaa373 size=0 status=0 tx=DINSOaTngPPNAJYfvZWZkhRwgrdevB

All of them end with rollback, and the first two cases will put two lines of logs. Access log in INFO, and ERROR log.

The case of nil is somewhat tricky, but still, there is a log line with status=0 which could be interpreted as an error. I would like to address this case in the near future but not a higher priority.

[sio4]

Finally, the implementation is that Buffalo's hidden middleware will log it when the status code was not set but the handler returns nil. This log is Debug level since it could be verbose in the production if a user still wants to use this behavior though.

https://github.com/gobuffalo/buffalo/blob/b29eff1c75683fed800fef648278a84a7accf994/middleware.go#L145-L148