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

Panic in Simpleworker #2241

Closed
Mido-sys opened this issue Apr 17, 2022 · 19 comments
Closed

Panic in Simpleworker #2241

Mido-sys opened this issue Apr 17, 2022 · 19 comments
Assignees
Labels
bug Something isn't working s: fixed was fixed or solution offered

Comments

@Mido-sys
Copy link

Mido-sys commented Apr 17, 2022

Hello,

I'm getting panic in Debug logger when a simple worker completes the job

level=debug time="2022-04-17T22:20:12Z" msg="completed job %!s(PANIC=String method: runtime error: invalid memory address or nil pointer dereference)

That's the culprit and this code panics too

@Mido-sys
Copy link
Author

@sio4 , hopefully, a fix will land in v0.18.6 :)

@sio4 sio4 self-assigned this Apr 17, 2022
@sio4 sio4 added the bug Something isn't working label Apr 17, 2022
@sio4
Copy link
Member

sio4 commented Apr 17, 2022

Aha... so did you get the message for "performing job..." at line 81 too? If then, it could be an issue with calling the function. There is no nil checking, so I will add that as soon as possible (my working hours just start within 10 min so maybe this evening)

If you can see the "performing job..." line correctly, but see panic for the "completed job..." line, it could be another issue. In this case, please let me know what was your job definition and if this issue is easily reproducible. Providing steps for reproducing or sample application could be the best.

buffalo/worker/simple.go

Lines 80 to 111 in e8274e6

func (w *Simple) Perform(job Job) error {
w.Logger.Debugf("performing job %s", job)
if job.Handler == "" {
err := fmt.Errorf("no handler name given for %s", job)
w.Logger.Error(err)
return err
}
w.moot.Lock()
defer w.moot.Unlock()
if h, ok := w.handlers[job.Handler]; ok {
// TODO: consider to implement timeout and/or cancellation
w.wg.Add(1)
go func() {
defer w.wg.Done()
err := safe.RunE(func() error {
return h(job.Args)
})
if err != nil {
w.Logger.Error(err)
}
w.Logger.Debugf("completed job %s", job)
}()
return nil
}
err := fmt.Errorf("no handler mapped for name %s", job.Handler)
w.Logger.Error(err)
return err
}

@Mido-sys
Copy link
Author

@sio4, Yes, it throws the same error in both lines.

No worries. Thanks for taking the time in solving this :)

@sio4
Copy link
Member

sio4 commented Apr 18, 2022

I took a look at the issue but I could not reproduce the issue and I feel like there is no reason for the panic on that part.

The below is the definition of Job and it should not be a nil in any case, and the String() function should work even if the structure is empty. Could you please share some more of your code, especially the Job you submitted?

buffalo/worker/job.go

Lines 14 to 26 in e8274e6

type Job struct {
// Queue the job should be placed into
Queue string
// Args that will be passed to the Handler when run
Args Args
// Handler that will be run by the worker
Handler string
}
func (j Job) String() string {
b, _ := json.Marshal(j)
return string(b)
}

@Mido-sys
Copy link
Author

@sio4, Yes, weirdly, it's throwing a panic in the string. An improvement will be actually checking the error returned by json.Marshal and not ignore them. If there's an error then just return an empty string and use the logger to spit out the error.

I will try to marshal that Job and see if it panics. It could be an underlying data structure causing this, and it might be a proto issue.

@sio4
Copy link
Member

sio4 commented Apr 18, 2022

No, what I understand from the error message is that the panic is on executing the String() against the Job but not on the inside of the String() function. It seems like the Job you passed to the Perform was a nil which is not possible in normal cases.

So I want to see your code block of the Job definition and how it calls the Perform function to verify my extreme theory. The only possible situation I can imagine now is that you did something like:

	var j *Job
	w.Perform(*j)

but maybe not. Right?

In this case, I declare the variable j without memory allocation and passed it as an argument of Perform in the wrong way.

For the panic on String(), please check this playground code: https://go.dev/play/p/G_qUrWgwGyf for your information.

@sio4
Copy link
Member

sio4 commented Apr 18, 2022

By the way, what are your versions? Could you provide the output of buffalo info?

@Mido-sys
Copy link
Author

Mido-sys commented Apr 18, 2022

@sio4 , The job isn't a pointer, and the job does execute and fans out the notification as intended.

w.Perform(worker.Job{
		Queue:   "default",
		Handler: "push_notification",
		Args: worker.Args{
			"context": c,
			"r":       re.r,
			"u":       req,
		},
	})

I checked all of the Arguments none of them are nil. If any is nill, then it won't be able to perform the job, and it safely returns

@Mido-sys
Copy link
Author

Buffalo Version:

require (
        github.com/gobuffalo/buffalo v0.18.5
        github.com/gobuffalo/envy v1.10.1
        github.com/gobuffalo/logger v1.0.6
        github.com/gobuffalo/mw-csrf v1.0.0
        github.com/gobuffalo/mw-forcessl v0.0.0-20200131175327-94b2bd771862
        github.com/gobuffalo/mw-i18n v1.1.0
        github.com/gobuffalo/mw-paramlogger v1.0.0
        github.com/gobuffalo/packr/v2 v2.8.1
        github.com/gobuffalo/plush/v4 v4.1.10-0.20220324170703-6c2169a56f63
        github.com/gobuffalo/suite/v3 v3.0.2
        github.com/gobuffalo/tags v2.1.7+incompatible
)

require(
     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/meta v0.3.1 // indirect
        github.com/gobuffalo/nulls v0.4.1 // indirect
        github.com/gobuffalo/packd v1.0.1 // indirect
        github.com/gobuffalo/pop/v5 v5.3.4 // indirect
        github.com/gobuffalo/pop/v6 v6.0.1 // indirect
        github.com/gobuffalo/tags/v3 v3.1.2 // indirect
        github.com/gobuffalo/validate/v3 v3.3.1 // indirect
)

@sio4
Copy link
Member

sio4 commented Apr 18, 2022

Oh, that is much more interesting. So the job worked without any issue but those two debugging outputs had panic?

What is your OS, system architecture, and golang version? also, please post your output of buffalo info to check any hints.

@Mido-sys
Copy link
Author

Mido-sys commented Apr 18, 2022

@sio4, Yes, the job worked fine. That's the weird part. And it's not a data race issue. I thought maybe for some reason it gets fired twice. One with a job and the other Nil, but that wasn't the case. The job ran once.

OS: ubuntu 18.04 x64
Golang: 1.18.1. I tested it with Go 1.17 and it threw the same error

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

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

-> Go: Checking PATH
✓ Your PATH contains REMOVED/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, v14.16.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.1.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.21.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 was found on your system at: /usr/bin/mysql

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

-> SQLite3: Checking installation
✘ The `sqlite3` executable could not be found on your system.
For help setting up your SQLite3 environment please follow the instructions for you platform at:

https://www.sqlite.org/download.html

-> 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: /usr/local/bin/buffalo

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

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

-> Buffalo: config/buffalo-app.toml
name = "REMOVED"
bin = "bin/REMOVED"
vcs = "git"
with_pop = true
with_sqlite = false
with_dep = false
with_webpack = false
with_nodejs = false
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/v2"

-> Buffalo: go.mod
module REMOVED

go 1.17

require (
        bitbucket.org/REMOVED/helpers/money v0.0.0-20220214114623-8e66da081c2b
        bitbucket.org/REMOVED/helpers/redis/emails v0.0.0-20220416153634-fc4c1e8cbf6f
        bitbucket.org/REMOVED/helpers/redis/templates v0.0.0-20210917145841-c33787a84524
        bitbucket.org/REMOVED/proto v0.0.0-20220417112620-921301107f9a
        github.com/go-playground/validator/v10 v10.9.0
        github.com/go-redis/redis/v8 v8.11.5
        github.com/gobuffalo/buffalo v0.18.5
        github.com/gobuffalo/envy v1.10.1
        github.com/gobuffalo/logger v1.0.6
        github.com/gobuffalo/mw-csrf v1.0.0
        github.com/gobuffalo/mw-forcessl v0.0.0-20200131175327-94b2bd771862
        github.com/gobuffalo/mw-i18n v1.1.0
        github.com/gobuffalo/mw-paramlogger v1.0.0
        github.com/gobuffalo/packr/v2 v2.8.1
        github.com/gobuffalo/plush/v4 v4.1.10-0.20220324170703-6c2169a56f63
        github.com/gobuffalo/suite/v3 v3.0.2
        github.com/gobuffalo/tags v2.1.7+incompatible
        github.com/golang/protobuf v1.5.2
        github.com/gorilla/sessions v1.2.1
        github.com/markbates/grift v1.5.0
        github.com/pkg/errors v0.9.1
        github.com/sirupsen/logrus v1.8.1
        github.com/spf13/viper v1.11.0
        github.com/stretchr/testify v1.7.1
        github.com/unrolled/secure v1.0.9
        google.golang.org/grpc v1.45.0
        google.golang.org/protobuf v1.28.0
)

require (
        bitbucket.org/REMOVED/app_error v0.0.0-20220416134420-59e77bd715a7 // indirect
        github.com/BurntSushi/toml v1.0.0 // indirect
        github.com/Masterminds/semver/v3 v3.1.1 // indirect
        github.com/Rhymond/go-money v1.0.3 // indirect
        github.com/aymerick/douceur v0.2.0 // indirect
        github.com/cespare/xxhash/v2 v2.1.2 // indirect
        github.com/davecgh/go-spew v1.1.1 // indirect
        github.com/dgryski/go-rendezvous v0.0.0-20200823014737-9f7001d12a5f // 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-playground/locales v0.14.0 // indirect
        github.com/go-playground/universal-translator v0.18.0 // 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/meta v0.3.1 // indirect
        github.com/gobuffalo/nulls v0.4.1 // indirect
        github.com/gobuffalo/packd v1.0.1 // indirect
        github.com/gobuffalo/pop/v5 v5.3.4 // indirect
        github.com/gobuffalo/pop/v6 v6.0.1 // indirect
        github.com/gobuffalo/tags/v3 v3.1.2 // indirect
        github.com/gobuffalo/validate/v3 v3.3.1 // indirect
        github.com/gofrs/uuid v4.1.0+incompatible // indirect
        github.com/gofrs/uuid/v3 v3.1.2 // 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/grpc-ecosystem/grpc-gateway v1.16.0 // indirect
        github.com/hashicorp/hcl v1.0.0 // 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/leodido/go-urn v1.2.1 // indirect
        github.com/luna-duclos/instrumentedsql v1.1.3 // indirect
        github.com/magiconair/properties v1.8.6 // indirect
        github.com/markbates/errx v1.1.0 // 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/mattn/go-colorable v0.1.12 // indirect
        github.com/mattn/go-isatty v0.0.14 // indirect
        github.com/mattn/go-sqlite3 v2.0.3+incompatible // indirect
        github.com/microcosm-cc/bluemonday v1.0.16 // indirect
        github.com/mitchellh/go-homedir v1.1.0 // indirect
        github.com/mitchellh/mapstructure v1.4.3 // indirect
        github.com/monoculum/formam v3.5.5+incompatible // indirect
        github.com/pelletier/go-toml v1.9.4 // indirect
        github.com/pelletier/go-toml/v2 v2.0.0-beta.8 // 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/shopspring/decimal v1.2.1-0.20210622222456-cc4584f0a5de // indirect
        github.com/sourcegraph/annotate v0.0.0-20160123013949-f4cad6c6324d // indirect
        github.com/sourcegraph/syntaxhighlight v0.0.0-20170531221838-bd320f5d308e // indirect
        github.com/spf13/afero v1.8.2 // indirect
        github.com/spf13/cast v1.4.1 // indirect
        github.com/spf13/cobra v1.4.0 // indirect
        github.com/spf13/jwalterweatherman v1.1.0 // indirect
        github.com/spf13/pflag v1.0.5 // indirect
        github.com/subosito/gotenv v1.2.0 // indirect
        golang.org/x/crypto v0.0.0-20220411220226-7b82a4e95df4 // indirect
        golang.org/x/net v0.0.0-20220412020605-290c469a71a5 // indirect
        golang.org/x/sync v0.0.0-20210220032951-036812b2e83c // indirect
        golang.org/x/sys v0.0.0-20220412211240-33da011f77ad // indirect
        golang.org/x/term v0.0.0-20210927222741-03fcf44c2211 // indirect
        golang.org/x/text v0.3.7 // indirect
        google.golang.org/genproto v0.0.0-20220407144326-9054f6ed7bac // indirect
        gopkg.in/alexcesaro/quotedprintable.v3 v3.0.0-20150716171945-2caba252f4dc // indirect
        gopkg.in/ini.v1 v1.66.4 // indirect
        gopkg.in/yaml.v2 v2.4.0 // indirect
        gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b // indirect
)

@sio4
Copy link
Member

sio4 commented Apr 18, 2022

I thought maybe for some reason it gets fired twice. One with a job and the other Nil, but that wasn't the case. The job ran once.

Yeah, I thought similar situation but since we don't have proper logs, cannot prove it. :-( How about adding some application-level logs when calling Perform? such as logger.Debugf("calling perform with %s", job)

OS: ubuntu 18.04 x64 Golang: 1.18.1. I tested it with Go 1.17 and it threw the same error

By the way, you mention that your go version is 1.18.1, and also tested with 1.17, but from the output of buffalo info, it seems like the actual version of golang is 1.14.13. (see below, and please check that again in your env) Also buffalo cli version is too old too. Is this information correct?

-> 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.13, meets the minimum requirements.
<...>
-> Buffalo (CLI): Checking minimum version requirements
✓ Your version of Buffalo (CLI), v0.16.21, meets the minimum requirements.
<...>

@Mido-sys
Copy link
Author

@sio4 ,
yes, it's weird that it's reporting Go 1.14.13. The only env I got is Go 1.18.1. Not sure why the tool not reporting correctly the go version.

So I found the culprit and as expected it was due to the sync.Map in the default_context being nil.

panic: runtime error: invalid memory address or nil pointer dereference [recovered]
	panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x47b166]

goroutine 141 [running]:
encoding/json.(*encodeState).marshal.func1()
	/usr/local/go/src/encoding/json/encode.go:328 +0x6e
panic({0xfa2120, 0x1ad21d0})
	/usr/local/go/src/runtime/panic.go:1038 +0x215
sync.(*Map).Range(0x1, 0xc00023d268)
	/usr/local/go/src/sync/map.go:324 +0x26
github.com/gobuffalo/buffalo.(*DefaultContext).Data(0xc0002763f0)
	/REMOVED/pkg/mod/github.com/gobuffalo/[email protected]/default_context.go:238 +0x50
github.com/gobuffalo/buffalo.(*DefaultContext).MarshalJSON(0x10b95e0)
	/REMOVED/pkg/mod/github.com/gobuffalo/[email protected]/default_context.go:279 +0x3f
encoding/json.marshalerEncoder(0xc000713e80, {0x10b95e0, 0xc0002763f0, 0x492169}, {0x0, 0x30})
	/usr/local/go/src/encoding/json/encode.go:479 +0xbe
encoding/json.(*encodeState).reflectValue(0x10865a0, {0x10b95e0, 0xc0002763f0, 0xc00023d470}, {0xf2, 0x3f})
	/usr/local/go/src/encoding/json/encode.go:360 +0x78
encoding/json.interfaceEncoder(0xc000713e80, {0x10865a0, 0xc000668890, 0x30}, {0x7a, 0xf2})
	/usr/local/go/src/encoding/json/encode.go:716 +0xc8
encoding/json.structEncoder.encode({{{0xc000867ef0, 0x40ff30, 0x10}, 0xc000c39320}}, 0xc000713e80, {0x10c1a00, 0xc000668880, 0xc000466b70}, {0x0, 0x1})

We had similar issues in the past if we wanted to access ctx.Value with a string key when the default_context is manually created and not through an HTTP request.

@Mido-sys
Copy link
Author

@sio4 , maybe a better fix is to do something similar to this

@sio4
Copy link
Member

sio4 commented Apr 21, 2022

Oh, Got it. So you passed the buffalo.Context to the worker as an argument. Now I understand what happens.

w.Perform(worker.Job{
		Queue:   "default",
		Handler: "push_notification",
		Args: worker.Args{
			"context": c,
			"r":       re.r,
			"u":       req,
		},
	})

However, if it's the case, the issue is on your usage of the background workers. The argument should be able to be serialized in JSON format, and also it should not be a memory reference (should be a kind of call by value). The reason is simple. The concept of the background worker is "distributed long-running task execution on the other machine" even though the Simple worker itself is designed to run the job in the same process in a new goroutine.

Currently, your job works fine since the memories you passed to the worker are still accessible by goroutine in the same process. However, if you extend your service and want to run those long-running tasks on separated machines, and want to replace the worker with another worker that supports remote queueing via message queues such as https://github.com/gobuffalo/gocraft-work-adapter, https://github.com/stanislas-m/amqp-work-adapter, or whatever, they will not work since your arguments cannot be serialized as a JSON message which is needed to be passed to the other machine via a message queue. (you should be free to replace any worker adapter implementation without code change which calls Perform.)

For flexibility, the Arg is simply defined as type Args map[string]interface{} but users should make sure their argument is able to be converted as JSON marshaled string.

buffalo/worker/job.go

Lines 5 to 11 in e8274e6

// Args are the arguments passed into a job
type Args map[string]interface{}
func (a Args) String() string {
b, _ := json.Marshal(a)
return string(b)
}

So the solution is that you should collect which information is needed for the job (e.g. user id, message to the user, or database key for the additional information), add those values to your own Arg structure, make sure the Arg is able to be marshaled as JSON safely, then pass the Arg to the job.

I think I need to consider improving our document for the part, and also try to find a way to verify the arguments programmatically too.

Can it be the answer?

@sio4
Copy link
Member

sio4 commented Apr 21, 2022

Anyway, even though the usage of background workers should be improved to make it compatible with the fundamental concept of it, still the bug you found (DefaultContext.Data() could make a panic) should be addressed and I made a PR #2246 to fix the issue. It will prevent the panic you faced.

@Mido-sys
Copy link
Author

@sio4 , apologies for the late response. Yes, I agree better documentation would be needed for the purpose and parameters of how to use the simple worker model.

Yes, thanks for pushing the PR. I confirm that the PR fixed the issue.

I agree with your suggestion on improving the usage of the simple worker model on our end and we will apply those changes.

@Mido-sys
Copy link
Author

Fixed in PR#2246

@sio4
Copy link
Member

sio4 commented Apr 22, 2022

@Mido-sys

No problem! We all live in our own time zone, no need to saying sorry for the very small latency :-)

Yes, thanks for pushing the PR. I confirm that the PR fixed the issue.

Happy to hear that! Have a good weekend!

@sio4 sio4 added the s: fixed was fixed or solution offered label Sep 26, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
bug Something isn't working s: fixed was fixed or solution offered
Projects
None yet
Development

No branches or pull requests

2 participants