Referential Integrity errors log goroutines dying

[heynemann]

Whenever I get a referential integrity error in dat (a FK violated) I get the following log:

SSSSSS19:57:49.958360 ERR dat:sqlx queryStruct.3
   err: pq: insert or update on table "offers" violates foreign key constraint "offers_game_id_fkey"
   sql: WITH upd AS ( UPDATE "offers" SET "game_id" = $1, "offer_template_id" = $2, "player_id" = $3 WHERE (id=$4) RETURNING "id","created_at","updated_at","claimed_at"), ins AS ( INSERT INTO "offers"("game_id","offer_template_id","player_id") SELECT $1,$2,$3 WHERE NOT EXISTS (SELECT 1 FROM upd) RETURNING "id","created_at","updated_at","claimed_at") SELECT * FROM ins UNION ALL SELECT * FROM upd
   args: $1=invalid-game $2=e6683585-2fb6-4dd9-8069-f4014a16638e $3=player-3 $4=00000000-0000-0000-0000-000000000000
goroutine 22 [running]:
runtime/debug.Stack(0x10, 0xc42018cc20, 0xc0180)
	/usr/local/Cellar/go/1.7.4_2/libexec/src/runtime/debug/stack.go:24 +0x79
github.com/topfreegames/offers/vendor/github.com/mgutz/logxi/v1.(*HappyDevFormatter).getLevelContext(0xc42008fc60, 0x3, 0xc420329a40, 0x0, 0x0, 0x0, 0x0, 0xc420078c78, 0x5)
	/Users/heynemann/Dropbox/dev/go/src/github.com/topfreegames/offers/vendor/github.com/mgutz/dat/sqlx-runner/exec.go:77 +0x33c
github.com/topfreegames/offers/vendor/github.com/mgutz/dat/sqlx-runner.(*Execer).queryStructFn(0xc420366000, 0x489060, 0xc42033ad20, 0x0, 0x0)
	/Users/heynemann/Dropbox/dev/go/src/github.com/topfreegames/offers/vendor/github.com/mgutz/dat/sqlx-runner/exec.go:395 +0x235
github.com/topfreegames/offers/vendor/github.com/mgutz/dat/sqlx-runner.(*Execer).queryStruct(0xc420366000, 0x489060, 0xc42033ad20, 0xc42033ae01, 0xc4203270c0)
	/Users/heynemann/Dropbox/dev/go/src/github.com/topfreegames/offers/vendor/github.com/mgutz/dat/sqlx-runner/exec.go:355 +0x63
github.com/topfreegames/offers/vendor/github.com/mgutz/dat/sqlx-runner.(*Execer).QueryStruct(0xc420366000, 0x489060, 0xc42033ad20, 0x4, 0xc42033adc0)
	/Users/heynemann/Dropbox/dev/go/src/github.com/topfreegames/offers/vendor/github.com/mgutz/dat/sqlx-runner/execer.go:133 +0x97
github.com/topfreegames/offers/models.UpsertOffer.func1(0x594979, 0x594978)
	/Users/heynemann/Dropbox/dev/go/src/github.com/topfreegames/offers/models/offer.go:62 +0x267
github.com/topfreegames/offers/models.(*MixedMetricsReporter).WithDatastoreSegment(0x0, 0x54e514, 0x6, 0x54e8e6, 0x6, 0xc42018d4c8, 0x0, 0x0)
	/Users/heynemann/Dropbox/dev/go/src/github.com/topfreegames/offers/models/mixed_metrics_reporter.go:40 +0x183
github.com/topfreegames/offers/models.UpsertOffer(0x7b3900, 0xc420332240, 0xc42033ad20, 0x0, 0xc42004f588, 0x2afe3)
	/Users/heynemann/Dropbox/dev/go/src/github.com/topfreegames/offers/models/offer.go:63 +0xbc
github.com/topfreegames/offers/models_test.glob..func4.3.3()
	/Users/heynemann/Dropbox/dev/go/src/github.com/topfreegames/offers/models/offer_test.go:135 +0xd1
github.com/topfreegames/offers/vendor/github.com/onsi/ginkgo/internal/leafnodes.(*runner).runSync(0xc420258b40, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/Users/heynemann/Dropbox/dev/go/src/github.com/topfreegames/offers/vendor/github.com/onsi/ginkgo/internal/leafnodes/runner.go:104 +0x8d
github.com/topfreegames/offers/vendor/github.com/onsi/ginkgo/internal/leafnodes.(*runner).run(0xc420258b40, 0xc42004f7b0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/Users/heynemann/Dropbox/dev/go/src/github.com/topfreegames/offers/vendor/github.com/onsi/ginkgo/internal/leafnodes/runner.go:63 +0xe1
github.com/topfreegames/offers/vendor/github.com/onsi/ginkgo/internal/leafnodes.(*ItNode).Run(0xc420290720, 0x7aa5c0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/Users/heynemann/Dropbox/dev/go/src/github.com/topfreegames/offers/vendor/github.com/onsi/ginkgo/internal/leafnodes/it_node.go:25 +0x64
github.com/topfreegames/offers/vendor/github.com/onsi/ginkgo/internal/spec.(*Spec).runSample(0xc42009cfc0, 0x0, 0x7aa5c0, 0xc420142c90)
	/Users/heynemann/Dropbox/dev/go/src/github.com/topfreegames/offers/vendor/github.com/onsi/ginkgo/internal/spec/spec.go:167 +0x4fd
github.com/topfreegames/offers/vendor/github.com/onsi/ginkgo/internal/spec.(*Spec).Run(0xc42009cfc0, 0x7aa5c0, 0xc420142c90)
	/Users/heynemann/Dropbox/dev/go/src/github.com/topfreegames/offers/vendor/github.com/onsi/ginkgo/internal/spec/spec.go:118 +0xbe
github.com/topfreegames/offers/vendor/github.com/onsi/ginkgo/internal/specrunner.(*SpecRunner).runSpecs(0xc42025b0e0, 0x597001)
	/Users/heynemann/Dropbox/dev/go/src/github.com/topfreegames/offers/vendor/github.com/onsi/ginkgo/internal/specrunner/spec_runner.go:144 +0x262
github.com/topfreegames/offers/vendor/github.com/onsi/ginkgo/internal/specrunner.(*SpecRunner).Run(0xc42025b0e0, 0x19)
	/Users/heynemann/Dropbox/dev/go/src/github.com/topfreegames/offers/vendor/github.com/onsi/ginkgo/internal/specrunner/spec_runner.go:61 +0xf0
github.com/topfreegames/offers/vendor/github.com/onsi/ginkgo/internal/suite.(*Suite).Run(0xc420073090, 0x96f828, 0xc42009ca80, 0x55aaf9, 0x19, 0xc4202f6040, 0x1, 0x1, 0x7b0980, 0xc420142c90, ...)
	/Users/heynemann/Dropbox/dev/go/src/github.com/topfreegames/offers/vendor/github.com/onsi/ginkgo/internal/suite/suite.go:59 +0x23b
github.com/topfreegames/offers/vendor/github.com/onsi/ginkgo.RunSpecsWithCustomReporters(0x7ab300, 0xc42009ca80, 0x55aaf9, 0x19, 0xc42018df00, 0x1, 0x1, 0x0)
	/Users/heynemann/Dropbox/dev/go/src/github.com/topfreegames/offers/vendor/github.com/onsi/ginkgo/ginkgo_dsl.go:207 +0x27b
github.com/topfreegames/offers/vendor/github.com/onsi/ginkgo.RunSpecs(0x7ab300, 0xc42009ca80, 0x55aaf9, 0x19, 0xc43476ccb6)
	/Users/heynemann/Dropbox/dev/go/src/github.com/topfreegames/offers/vendor/github.com/onsi/ginkgo/ginkgo_dsl.go:188 +0x195
github.com/topfreegames/offers/models_test.TestApi(0xc42009ca80)
	/Users/heynemann/Dropbox/dev/go/src/github.com/topfreegames/offers/models/models_suite_test.go:24 +0x64
testing.tRunner(0xc42009ca80, 0x596db8)
	/usr/local/Cellar/go/1.7.4_2/libexec/src/testing/testing.go:610 +0x81
created by testing.(*T).Run
	/usr/local/Cellar/go/1.7.4_2/libexec/src/testing/testing.go:646 +0x2ec

Any ideas on what's going on? It makes me uneasy to see that whenever a referential integrity error happens.

[heynemann]

Another weird behavior I`m seeing is that if I silence logging (LOGXI="*=ERR,dat:sqlx=OFF") then the above does not happen, but I also stop receiving error messages from the Database.

My tests that verify that a model was not found fail if I run then without logging and pass otherwise.

$ go test  // Works, but ugly output
$ LOGXI="*=ERR,dat:sqlx=OFF" go test // fails

[mgutz]

The logging error is fixed in the next minor release of v2. The logxi logger had a logical error which I've since fixed. I'm concentrating on a release for our product so I probably won't get this for a couple of weeks. Keep the logger on for now or some errors might silently get swallowed.

[heynemann]

Should we be using v2?

[mgutz]

Yes v2 is the version that removes most of the panics, fixes logging and some JSON marshalling issues. Actually the next update in a couple of weeks will fix logging callstack, swallowing of errors when dat logging is disabled and marhsalling issues. I advise moving to v2 if you can. It gets most of my attention