bug: DB connection locks up under load calling DB.Create(), regression in 6.1.0 vs 6.0.8

[saurori]

Description

Description

When using the DB connection directly (models.DB in a buffalo application), and calling .Create(model), if the number of concurrent requests exceeds the pool size, the application will lock up and not respond to further requests. This does not happen when using the tx transaction.

This issue is only present in version 6.1.0 and not in 6.0.8.

This is likely related to this issue: #364

Expected Behavior

The handler saves the model to the DB and returns.

Actual Behavior

The application locks up and does not accept any more requests.

To Reproduce

1. Use a setup similar to the one in this issue: Lock / contention when not using a transaction and exceeding pool limit buffalo-pop#28
2. Instead of .All(), create a model using .Create()
3. Make sure the DB pool size is low (3) and make 10 concurrent requests to the Handler

Related issues:

• Pop stops working when under high load #364
• Lock / contention when not using a transaction and exceeding pool limit buffalo-pop#28
• Very slow. Why by default in a new app? buffalo-pop#7
• feature: log transaction/connection ID to track SQL executions for a request #794
  • to track connection/transaction information in the log
  • feature: log transaction/connection ID to track SQL executions for a request #795

Additional Context

Details

Details

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

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

-> Go: Checking PATH
✓ Your PATH contains /Users/stefanaurori/Documents/dev/bin.

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

-> Node: Checking minimum version requirements
✓ Your version of Node, v19.2.0, meets the minimum requirements.

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

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

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

-> Yarn: Checking minimum version requirements
✘ Your version of Yarn, 4.0.0-rc.25, does not meet the minimum requirements.

Minimum versions of Yarn are:

* >=1.12

For help setting up your Yarn environment please follow the instructions for you platform at:

https://yarnpkg.com/en/docs/install

-> PostgreSQL: Checking installation
✓ The `postgres` executable was found on your system at: /opt/homebrew/bin/postgres

-> PostgreSQL: Checking minimum version requirements
✓ Your version of PostgreSQL, 14.6.0, meets the minimum requirements.

-> 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.37.0, 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/stefanaurori/Documents/dev/bin/buffalo

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

-> Buffalo: Application Details
Pwd         /Users/stefanaurori/Documents/dev/src/github.com/saurori/gobuffalo/coke
Root        /Users/stefanaurori/Documents/dev/src/github.com/saurori/gobuffalo/coke
GoPath      /Users/stefanaurori/Documents/dev
PackagePkg  coke
ActionsPkg  coke/actions
ModelsPkg   coke/models
GriftsPkg   coke/grifts
WithModules true
Name        coke
Bin         bin/coke
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 = "coke"
bin = "bin/coke"
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 coke

go 1.19

require (
	github.com/gobuffalo/buffalo v1.0.1
	github.com/gobuffalo/buffalo-pop/v3 v3.0.6
	github.com/gobuffalo/envy v1.10.2
	github.com/gobuffalo/grift v1.5.2
	github.com/gobuffalo/mw-csrf v1.0.1
	github.com/gobuffalo/mw-forcessl v1.0.1
	github.com/gobuffalo/mw-i18n/v2 v2.0.2
	github.com/gobuffalo/mw-paramlogger v1.0.1
	github.com/gobuffalo/pop/v6 v6.1.0
	github.com/gobuffalo/suite/v4 v4.0.3
	github.com/gofrs/uuid v4.3.1+incompatible
	github.com/unrolled/secure v1.13.0
)

require (
	github.com/BurntSushi/toml v1.2.1 // indirect
	github.com/Masterminds/semver/v3 v3.2.0 // 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.0 // indirect
	github.com/fatih/color v1.13.0 // indirect
	github.com/fatih/structs v1.1.0 // indirect
	github.com/felixge/httpsnoop v1.0.3 // 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 v0.3.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.16 // indirect
	github.com/gobuffalo/refresh v1.13.3 // indirect
	github.com/gobuffalo/tags/v3 v3.1.4 // indirect
	github.com/gobuffalo/validate/v3 v3.3.3 // 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/inconshreveable/mousetrap v1.1.0 // 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.13.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.13 // indirect
	github.com/mattn/go-isatty v0.0.16 // indirect
	github.com/mattn/go-sqlite3 v1.14.16 // indirect
	github.com/microcosm-cc/bluemonday v1.0.21 // 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.9.5 // indirect
	github.com/pkg/errors v0.9.1 // 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/crypto v0.4.0 // indirect
	golang.org/x/net v0.4.0 // indirect
	golang.org/x/sync v0.1.0 // indirect
	golang.org/x/sys v0.3.0 // indirect
	golang.org/x/term v0.3.0 // indirect
	golang.org/x/text v0.5.0 // indirect
	gopkg.in/yaml.v2 v2.4.0 // indirect
	gopkg.in/yaml.v3 v3.0.1 // indirect
)

[sio4]

Hi @saurori,
Thanks for raising this issue. I was working on this issue recently but could not make enough time due to my personal situation. This input is greatly helping me!

I have some questions about the reproduction conditions, the main questions are:

• Does this issue not happen in 6.0.8? I thought the issue is there since old versions of buffalo/pop/buffalo-pop set.
• Did you test it by fully disabling buffalo-pop? I found that when we enabled buffalo-pop, the tx is created regardless we use the tx or DB and it could be related to the issue.

I would like to use this issue as a tracking issue for this issue in pop, and gobuffalo/buffalo-pop#28 as the tracking issue for the buffalo-pop if it needed.

There are some related issues, so please let me update your OP to include the list of the issues and related issues/PRs.

[saurori]

This issue may be different than the ones I linked. I tested this very precisely against 6.0.8 and 6.1.0 and it does NOT occur in 6.0.8 when buffalo-pop is disabled, but is still an issue when enabled.

Tested (use models.DB):

• Pop 6.1.0 without buffalo-pop (no Transaction middleware) : issue is present
• Pop 6.0.8 without buffalo-pop (no Transaction middleware) : issue is NOT present
• Pop 6.1.0 with buffalo-pop (Transaction middleware enabled) : issue is present
• Pop 6.0.8 with buffalo-pop (Transaction middleware enabled) : issue is present

[sio4]

Ah! I see. Thanks for the kind sharing the information!

[sio4]

Confirmed.

The first table is the result of the test for #28, which used All(). (Selection)

version	pool	tx enabled	use tx	requests	latency	latency-95	200 OK	conns peak	conns left	E
v6.1.0	5	yes	yes	12537	59.9	218.6	100%	5	2
v6.1.0	5	yes	no	151	timeout	timeout	0.00%	5	5	*
v6.1.0	5	no	no	21093	35.3	97.3	100%	5	2

As we already knew, there was an issue when we use models.DB directly while popmw is enabled.

This symptom of the issue can be explained as a deadlock:

1. 5 requests almost at once, created 5 tx, and it make the connection pool empty
2. the handlers need another connection for DB, but they will not release connections for tx

The second table is for this issue, which used Create(). (Insertion)

version	pool	tx enabled	use tx	requests	latency	latency-95	200 OK	conns peak	conns left	E
v6.1.0	5	yes	yes	6834	110.4	410.9	100%	5	2
v6.1.0	5	yes	no	151	timeout	timeout	0.00%	5	5	*
v6.1.0	5	no	no	151	timeout	timeout	0.00%	5	5	**

Interestingly, no-mw + no-tx case also has the same symptom.

The main difference between v6.0.8 and v6.1.0 is the logging. I added transaction/connection information on the log line to track them with requests. Anyway, long story short, I found that this issue happened by this line:

v6.0.8...v6.1.0#diff-006ceb789dde7f1890eaf42061a363160cb61de6dc6495277349cfe99bd8343cR84

When the logging function was called with store value, it seems like there are some dark magic behind the scene. If I revert this to the old function, the symptom will disappear. (In case of the ID is UUID)

However, I don't want to write a quick patch for this because I was preparing another change to the logging stuff and the version will change this behavior (copying store) too.

Please use v6.0.8 if you have this issue!

[sio4]

Hi @saurori, I think I reproduced the issue you faced. Do you think I saw the same issue you described?

If so, I found the root cause but I still don't know what magic happened with sqlx's connection pool management. I guess some of Pop's usage is not desirable but did not dig more. I would like to continue working on another change for logging which could cover this issue too.

[sio4]

Hi @saurori, Could you please test with this branch? I was OK with this branch but I would like to get your confirmation.

https://github.com/gobuffalo/pop/tree/pass-connection-instead-of-store

[saurori]

@sio4 Thanks for digging into this. Here's what I found (let me know if you need me to test any other scenarios):

To confirm I am testing the right version:

go get github.com/gobuffalo/pop/v6@pass-connection-instead-of-store
go: downloading github.com/gobuffalo/pop/v6 v6.1.1-0.20221211163013-6f4136878a9c
go: upgraded github.com/gobuffalo/pop/v6 v6.1.0 => v6.1.1-0.20221211163013-6f4136878a9c

• TX middleware enabled, calling models.DB.Create(model) : 0% requests 200 OK
• TX middleware disabled, calling models.DB.Create(model) : 100% requests 200 OK
• TX middleware enabled, calling models.DB.Limit(10).All(&models) : 0% requests 200 OK
• TX middleware disabled, calling models.DB.Limit(10).All(&models) : 100% requests 200 OK

[sio4]

OMG! I found the root cause. Even though I am preparing PR #801 to improve the logging behavior, I need to understand what happened with this version so we can prevent the issue happen again.

I tested more and tracked the connection information from the underlying sql.DB, and I found that my fix for the logging was actually bad. I only considered transaction cases when making a log, and it made an additional unclosed transaction every time the app calls Create. The bad code is the following.

v6.0.8...v6.1.0#diff-ff87b7c4777a35588053a509583d66c9f404ccbea9e1c71d2a5f224d7ad1323eR69

Anyway, I will work on the PR and will fix it in the next version soon.
Thanks for your patience!