Bug: Buffalo app is never gracefully shut down

[elivlo]

Description

I might have discovered a bug shutting down the buffalo app. I wanted to listen for the event EvtAppStop and never received it. Then I looked into the file server.go . I wondered that no log message contained Shutting down application, so I dived deeper into the code. The buffalo server is not implementing the concurrency model the right way, if I'm understanding it right. See here.
I think the code is at least missing something in this go routine (and maybe somewhere else):

buffalo/server.go

Lines 20 to 97 in 1f21020

	func (a *App) Serve(srvs ...servers.Server) error {
	a.Logger.Infof("Starting application at http://%s", a.Options.Addr)
	payload := events.Payload{
	"app": a,
	}
	if err := events.EmitPayload(EvtAppStart, payload); err != nil {
	return err
	}
	if len(srvs) == 0 {
	if strings.HasPrefix(a.Options.Addr, "unix:") {
	tcp, err := servers.UnixSocket(a.Options.Addr[5:])
	if err != nil {
	return err
	}
	srvs = append(srvs, tcp)
	} else {
	srvs = append(srvs, servers.New())
	}
	}
	ctx, cancel := sigtx.WithCancel(a.Context, syscall.SIGTERM, os.Interrupt)
	defer cancel()
	go func() {
	// gracefully shut down the application when the context is cancelled
	<-ctx.Done()
	a.Logger.Info("Shutting down application")
	events.EmitError(EvtAppStop, ctx.Err(), payload)
	if err := a.Stop(ctx.Err()); err != nil {
	events.EmitError(EvtAppStopErr, err, payload)
	a.Logger.Error(err)
	}
	if !a.WorkerOff {
	// stop the workers
	a.Logger.Info("Shutting down worker")
	events.EmitPayload(EvtWorkerStop, payload)
	if err := a.Worker.Stop(); err != nil {
	events.EmitError(EvtWorkerStopErr, err, payload)
	a.Logger.Error(err)
	}
	}
	for _, s := range srvs {
	if err := s.Shutdown(ctx); err != nil {
	a.Logger.Error(err)
	}
	}
	}()
	// if configured to do so, start the workers
	if !a.WorkerOff {
	go func() {
	events.EmitPayload(EvtWorkerStart, payload)
	if err := a.Worker.Start(ctx); err != nil {
	a.Stop(err)
	}
	}()
	}
	for _, s := range srvs {
	s.SetAddr(a.Addr)
	go func(s servers.Server) {
	if err := s.Start(ctx, a); err != nil {
	a.Stop(err)
	}
	}(s)
	}
	<-ctx.Done()
	return a.Context.Err()
	}

I tested with buffalo version v0.18.2 and go1.17.5. It seems that the goroutine (for shutdown) has no time to run when SIGTERM or SIGINT stops the application.

Steps to Reproduce the Problem

I created a new buffalo app with buffalo new. Then I started and stopped it in production and development mode.

Also add the following lines to main.go:

func init() {
	events.Listen(func(e events.Event) {
		fmt.Println(e.Kind)
	})
}

1. buffalo new testapp --api
2. buffalo build -o testapp
3. ./testapp
4. Stop app in three ways:
   + Hit CTRL+C
   + kill -s SIGTERM <pid>
   + kill -s SIGINT <pid>

Expected Behavior

Buffalo should wait until all application processes are terminated. This also includes functions that run on shut down in my opinion.

$ ./testapp
INFO[2022-01-15T20:24:02+01:00] Starting application at http://127.0.0.1:3000
buffalo:app:start
INFO[2022-01-15T20:24:02+01:00] Starting Simple Background Worker
buffalo:worker:start
^CINFO[2022-01-15T20:24:06+01:00] Shutting down application
buffalo:app:stop
INFO[2022-01-15T20:24:06+01:00] Shutting down worker
buffalo:worker:stop
INFO[2022-01-15T20:24:06+01:00] Stopping Simple Background Worker
$

Actual Behavior

$ ./testapp
INFO[2022-01-15T20:17:53+01:00] Starting application at http://127.0.0.1:3000
buffalo:app:start
INFO[2022-01-15T20:17:53+01:00] Starting Simple Background Worker
buffalo:worker:start
^C
$

Info

-> Go: Checking installation
✓ The `go` executable was found on your system at: /home/elias/.gvm/gos/go1.17.5/bin/go

-> Go: Checking minimum version requirements
✓ Your version of Go, 1.17.5, meets the minimum requirements.

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

-> Go: Checking PATH
✘ Your PATH (/home/elias/.nvm/versions/node/v15.0.1/bin:/home/elias/.gvm/pkgsets/go1.17.5/global/bin:/home/elias/.gvm/gos/go1.17.5/bin:/home/elias/.gvm/pkgsets/go1.17.5/global/overlay/bin:/home/elias/.gvm/bin:/home/elias/.gvm/bin:/usr/local/bin:/usr/local/sbin:/usr/bin:/usr/sbin:/var/lib/snapd/snap/bin:/home/elias/bin) does not contain /home/elias/.gvm/pkgsets/go1.17.5/global/bin.

Without /home/elias/.gvm/pkgsets/go1.17.5/global/bin in your `PATH` any Go executables can not be run globally.

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

https://www.gopherguides.com/courses/preparing-your-environment-for-go-development

-> Node: Checking installation
✓ The `node` executable was found on your system at: /home/elias/.nvm/versions/node/v15.0.1/bin/node

-> Node: Checking minimum version requirements
✓ Your version of Node, v15.0.1, meets the minimum requirements.

-> NPM: Checking installation
✓ The `npm` executable was found on your system at: /home/elias/.nvm/versions/node/v15.0.1/bin/npm

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

-> Yarn: Checking installation
✓ The `yarnpkg` executable was found on your system at: /home/elias/.nvm/versions/node/v15.0.1/bin/yarnpkg

-> Yarn: Checking minimum version requirements
✓ Your version of Yarn, 1.22.17, 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 was found on your system at: /usr/bin/mysql

-> MySQL: Checking minimum version requirements
✓ Your version of MySQL, 8.0.27, meets the minimum requirements.

-> 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.36.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: /home/elias/.gvm/pkgsets/go1.17.5/global/bin/buffalo

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

-> Buffalo: Application Details
Pwd         /home/elias/testapp
Root        /home/elias/testapp
GoPath      /home/elias/.gvm/pkgsets/go1.17.5/global
PackagePkg  testapp
ActionsPkg  testapp/actions
ModelsPkg   testapp/models
GriftsPkg   testapp/grifts
WithModules true
Name        testapp
Bin         bin/testapp
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 = "testapp"
bin = "bin/testapp"
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/v3@latest"

-> Buffalo: go.mod
module testapp

go 1.17

require (
	github.com/gobuffalo/buffalo v0.18.2
	github.com/gobuffalo/buffalo-pop/v3 v3.0.2
	github.com/gobuffalo/envy v1.10.1
	github.com/gobuffalo/mw-contenttype v0.0.0-20190224202710-36c73cc938f3
	github.com/gobuffalo/mw-forcessl v0.0.0-20200131175327-94b2bd771862
	github.com/gobuffalo/mw-i18n/v2 v2.0.1
	github.com/gobuffalo/mw-paramlogger v1.0.0
	github.com/gobuffalo/pop/v6 v6.0.1
	github.com/gobuffalo/suite/v4 v4.0.2
	github.com/gobuffalo/x v0.1.0
	github.com/markbates/grift v1.5.0
	github.com/rs/cors v1.8.2
	github.com/unrolled/secure v1.0.9
)

require (
	github.com/BurntSushi/toml v0.4.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.0 // 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.5.1 // indirect
	github.com/go-sql-driver/mysql v1.6.0 // indirect
	github.com/gobuffalo/events v1.4.2 // indirect
	github.com/gobuffalo/fizz v1.14.0 // indirect
	github.com/gobuffalo/flect v0.2.4 // indirect
	github.com/gobuffalo/github_flavored_markdown v1.1.1 // indirect
	github.com/gobuffalo/helpers v0.6.4 // indirect
	github.com/gobuffalo/httptest v1.5.1 // indirect
	github.com/gobuffalo/logger v1.0.6 // indirect
	github.com/gobuffalo/meta v0.3.1 // indirect
	github.com/gobuffalo/mw-csrf v1.0.0 // indirect
	github.com/gobuffalo/nulls v0.4.1 // indirect
	github.com/gobuffalo/plush/v4 v4.1.9 // indirect
	github.com/gobuffalo/tags/v3 v3.1.2 // indirect
	github.com/gobuffalo/validate/v3 v3.3.1 // indirect
	github.com/gofrs/uuid v4.2.0+incompatible // 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.0.0 // indirect
	github.com/jackc/chunkreader/v2 v2.0.1 // indirect
	github.com/jackc/pgconn v1.10.1 // indirect
	github.com/jackc/pgio v1.0.0 // indirect
	github.com/jackc/pgpassfile v1.0.0 // indirect
	github.com/jackc/pgproto3/v2 v2.1.1 // indirect
	github.com/jackc/pgservicefile v0.0.0-20200714003250-2b9c44734f2b // indirect
	github.com/jackc/pgtype v1.8.1 // indirect
	github.com/jackc/pgx/v4 v4.13.0 // indirect
	github.com/jmoiron/sqlx v1.3.4 // indirect
	github.com/joho/godotenv v1.4.0 // indirect
	github.com/karrick/godirwalk v1.16.1 // indirect
	github.com/kballard/go-shellquote v0.0.0-20180428030007-95032a82bc51 // indirect
	github.com/luna-duclos/instrumentedsql v1.1.3 // indirect
	github.com/markbates/oncer v1.0.0 // indirect
	github.com/markbates/refresh v1.12.0 // indirect
	github.com/markbates/safe v1.0.1 // indirect
	github.com/markbates/sigtx v1.0.0 // 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.9 // indirect
	github.com/microcosm-cc/bluemonday v1.0.16 // 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.3 // indirect
	github.com/pkg/errors v0.9.1 // indirect
	github.com/pmezard/go-difflib v1.0.0 // indirect
	github.com/rogpeppe/go-internal v1.8.0 // indirect
	github.com/sergi/go-diff v1.2.0 // indirect
	github.com/sirupsen/logrus v1.8.1 // 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.2.1 // indirect
	github.com/spf13/pflag v1.0.5 // indirect
	github.com/stretchr/testify v1.7.0 // indirect
	golang.org/x/crypto v0.0.0-20211117183948-ae814b36b871 // indirect
	golang.org/x/net v0.0.0-20211112202133-69e39bad7dc2 // indirect
	golang.org/x/sync v0.0.0-20210220032951-036812b2e83c // indirect
	golang.org/x/sys v0.0.0-20210809222454-d867a43fc93e // indirect
	golang.org/x/term v0.0.0-20210927222741-03fcf44c2211 // indirect
	golang.org/x/text v0.3.6 // indirect
	gopkg.in/yaml.v2 v2.4.0 // indirect
	gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b // indirect
)

[github-actions]

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

[github-actions]

This issue was closed because it has been stalled for 5 days with no activity.

[sio4]

Indeed, it looks like you found a serious bug which should be addressed as soon as possible!

I tested the behavior with my test application and I am working on it. Please let me take a look into the issue and I will get back as soon as possible.

[elivlo]

Hi @sio4, thanks for your reply and much more important the fix :)
I was a little uncertain when no maintainer replied to this issue because the last release was months age. But I'm relieved now that I see someone who is taking care of it.

[sio4]

Hi @elivlo, could you please check if the issue is resolved with the development branch of buffalo? or will you wait until the next release? I am going to close this issue now, but please feel free to reopen it if the issue is not resolved by my PR.