Pg: fatal error: concurrent map iteration and map write

[jayschwa]

Every now and then, we experience a panic because of concurrent map iteration and map write. I am not certain of the cause yet, but the panic seems to be coming from tryRelationStruct in go-pg. When examining our crash log, I found another go routine that stopped as it was writing to a map in the same function, which seems suspect to me.

I will still try to debug and share a reproducible example if I can come up with one. In the meantime, I am starting this issue in case someone else has noticed this or knows a solution.

fatal error: concurrent map iteration and map write

goroutine 299 [running]:
runtime.throw(0x14a8001, 0x26)
    /usr/local/go/src/runtime/panic.go:616 +0x81 fp=0xc4201817f0 sp=0xc4201817d0 pc=0x42c931
runtime.mapiternext(0xc4201818f0)
    /usr/local/go/src/runtime/hashmap.go:747 +0x55c fp=0xc420181880 sp=0xc4201817f0 pc=0x40a8fc
spell/vendor/github.com/go-pg/pg/orm.(*Table).tryRelationStruct(0xc42072a000, 0xc4207307e0, 0xc420181900)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/table.go:551 +0x167 fp=0xc420181960 sp=0xc420181880 pc=0x8c5517
spell/vendor/github.com/go-pg/pg/orm.(*Table).tryRelation(0xc42072a000, 0xc4207307e0, 0x0)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/table.go:399 +0x8c fp=0xc420181988 sp=0xc420181960 pc=0x8c3e8c
spell/vendor/github.com/go-pg/pg/orm.(*Table).initRelations(0xc42072a000)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/table.go:383 +0xbd fp=0xc420181a38 sp=0xc420181988 pc=0x8c3ced
spell/vendor/github.com/go-pg/pg/orm.(*Table).init(0xc42072a000)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/table.go:102 +0x2b fp=0xc420181a50 sp=0xc420181a38 pc=0x8c0d4b
spell/vendor/github.com/go-pg/pg/orm.(*tables).get(0xc420257fb0, 0x15c7520, 0x1409000, 0x12cd800, 0x15c7520)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/tables.go:86 +0x312 fp=0xc420181b40 sp=0xc420181a50 pc=0x8c8a92
spell/vendor/github.com/go-pg/pg/orm.(*tables).Get(0xc420257fb0, 0x15c7520, 0x1409000, 0xc420a86000)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/tables.go:98 +0x44 fp=0xc420181b78 sp=0xc420181b40 pc=0x8c8d34
spell/vendor/github.com/go-pg/pg/orm.GetTable(0x15c7520, 0x1409000, 0x197)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/tables.go:18 +0x41 fp=0xc420181ba8 sp=0xc420181b78 pc=0x8c85e1
spell/vendor/github.com/go-pg/pg/orm.newTableModelValue(0x10e8520, 0xc420812080, 0x197, 0x10e8520, 0xc420812080, 0x197, 0xc420099e00)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/model_table.go:64 +0x1ec fp=0xc420181cb0 sp=0xc420181ba8 pc=0x8ae96c
spell/vendor/github.com/go-pg/pg/orm.newTableModel(0x10b3c80, 0xc420812080, 0x180, 0x144a480, 0x1, 0xc420099e00)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/model_table.go:52 +0x232 fp=0xc420181d30 sp=0xc420181cb0 pc=0x8ae622
spell/vendor/github.com/go-pg/pg/orm.(*Query).Model(0xc420099e00, 0xc42085c0c0, 0x1, 0x1, 0x1)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/query.go:130 +0x15d fp=0xc420181d70 sp=0xc420181d30 pc=0x8b4ccd
spell/vendor/github.com/go-pg/pg/orm.NewQuery(0x15c42e0, 0xc420a5d900, 0xc42085c0c0, 0x1, 0x1, 0xc42085c0c0)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/query.go:54 +0x7f fp=0xc420181da8 sp=0xc420181d70 pc=0x8b406f
spell/vendor/github.com/go-pg/pg.(*DB).Model(0xc420a5d900, 0xc42085c0c0, 0x1, 0x1, 0x42b449)
    /go/src/spell/vendor/github.com/go-pg/pg/db.go:381 +0x55 fp=0xc420181de8 sp=0xc420181da8 pc=0x8dae75
spell/db.QueryUserDatasets(0x15c42e0, 0xc420a5d900, 0xc421160100)
    /go/src/spell/db/dataset_query.go:28 +0xa0 fp=0xc420181e40 sp=0xc420181de8 pc=0xa98b40
spell/servers/api/datasets.DatasetSquasher(0x15baa60, 0xc4210a2400, 0x0, 0x0)
    /go/src/spell/servers/api/datasets/datasets.go:107 +0x36f fp=0xc420181f08 sp=0xc420181e40 pc=0xfa594f
spell/utils/async.loggedCall(0x15baa60, 0xc4210a2400, 0x14ca190, 0x2, 0x0, 0x0)
    /go/src/spell/utils/async/async.go:29 +0x7a fp=0xc420181f50 sp=0xc420181f08 pc=0x995e1a
spell/utils/async.Repeat.func1(0x15baa60, 0xc4210a2400, 0x14ca190)
    /go/src/spell/utils/async/async.go:55 +0x7b fp=0xc420181fc8 sp=0xc420181f50 pc=0x9964bb
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:2361 +0x1 fp=0xc420181fd0 sp=0xc420181fc8 pc=0x45bf91
created by spell/utils/async.Repeat
    /go/src/spell/utils/async/async.go:49 +0x53\

goroutine 297 [runnable]:
spell/vendor/github.com/go-pg/pg/orm.(*Table).tryRelationStruct(0xc4206cc460, 0xc420a8c120, 0xc4209d3300)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/table.go:558 +0x4a7
spell/vendor/github.com/go-pg/pg/orm.(*Table).tryRelation(0xc4206cc460, 0xc420a8c120, 0xa)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/table.go:399 +0x8c
spell/vendor/github.com/go-pg/pg/orm.(*Table).initRelations(0xc4206cc460)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/table.go:383 +0xbd
spell/vendor/github.com/go-pg/pg/orm.(*Table).init(0xc4206cc460)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/table.go:102 +0x2b
spell/vendor/github.com/go-pg/pg/orm.(*tables).get(0xc420257fb0, 0x15c7520, 0x13ff800, 0x1, 0x0)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/tables.go:86 +0x312
spell/vendor/github.com/go-pg/pg/orm.(*Table).tryRelationStruct(0xc4206cc380, 0xc4203287e0, 0xc4209d3500)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/table.go:543 +0xb3
spell/vendor/github.com/go-pg/pg/orm.(*Table).tryRelation(0xc4206cc380, 0xc4203287e0, 0xc4209d3500)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/table.go:399 +0x8c
spell/vendor/github.com/go-pg/pg/orm.(*Table).initRelations(0xc4206cc380)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/table.go:383 +0xbd
spell/vendor/github.com/go-pg/pg/orm.(*Table).init(0xc4206cc380)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/table.go:102 +0x2b
spell/vendor/github.com/go-pg/pg/orm.(*tables).get(0xc420257fb0, 0x15c7520, 0x1382160, 0x1, 0x0)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/tables.go:86 +0x312
spell/vendor/github.com/go-pg/pg/orm.(*Table).tryRelationSlice(0xc4206cc1c0, 0xc4202efd40, 0xc4209d3900)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/table.go:411 +0x121
spell/vendor/github.com/go-pg/pg/orm.(*Table).tryRelation(0xc4206cc1c0, 0xc4202efd40, 0xc4209d3900)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/table.go:397 +0xc6
spell/vendor/github.com/go-pg/pg/orm.(*Table).initRelations(0xc4206cc1c0)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/table.go:383 +0xbd
spell/vendor/github.com/go-pg/pg/orm.(*Table).init(0xc4206cc1c0)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/table.go:102 +0x2b
spell/vendor/github.com/go-pg/pg/orm.(*tables).get(0xc420257fb0, 0x15c7520, 0x1461520, 0x143db00, 0x15c7520)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/tables.go:86 +0x312
spell/vendor/github.com/go-pg/pg/orm.(*tables).Get(0xc420257fb0, 0x15c7520, 0x1461520, 0xc4204103c0)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/tables.go:98 +0x44
spell/vendor/github.com/go-pg/pg/orm.GetTable(0x15c7520, 0x1461520, 0x197)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/tables.go:18 +0x41
spell/vendor/github.com/go-pg/pg/orm.newTableModelValue(0x10e84a0, 0xc42083c440, 0x197, 0x10e84a0, 0xc42083c440, 0x197, 0xc4204c5800)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/model_table.go:64 +0x1ec
spell/vendor/github.com/go-pg/pg/orm.newTableModel(0x10b3c00, 0xc42083c440, 0x180, 0x144a480, 0x1, 0xc4204c5800)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/model_table.go:52 +0x232
spell/vendor/github.com/go-pg/pg/orm.(*Query).Model(0xc4204c5800, 0xc420707030, 0x1, 0x1, 0xc4209d3df0)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/query.go:130 +0x15d
spell/vendor/github.com/go-pg/pg/orm.NewQuery(0x15c42e0, 0xc420714960, 0xc420707030, 0x1, 0x1, 0xc420707030)
    /go/src/spell/vendor/github.com/go-pg/pg/orm/query.go:54 +0x7f
spell/vendor/github.com/go-pg/pg.(*DB).Model(0xc420714960, 0xc420707030, 0x1, 0x1, 0x0)
    /go/src/spell/vendor/github.com/go-pg/pg/db.go:381 +0x55
spell/db.QueryRuns(0x15c42e0, 0xc420714960, 0x15bab20)
    /go/src/spell/db/run_query.go:29 +0xa9
spell/orchestrator.resumeExistingWorkers(0x15baa60, 0xc4200c86c0, 0x15baa60, 0xc4200c86c0)
    /go/src/spell/orchestrator/orchestrator.go:60 +0x10a
spell/orchestrator.Run(0x15baa60, 0xc4200c86c0, 0x0, 0x0)
    /go/src/spell/orchestrator/orchestrator.go:39 +0x321
spell/utils/async.loggedCall(0x15baaa0, 0xc4200c2020, 0x14ca0e0, 0xc400000002, 0x0, 0x0)
    /go/src/spell/utils/async/async.go:29 +0x7a
spell/utils/async.Repeat.func1(0x15baaa0, 0xc4200c2020, 0x14ca0e0)
    /go/src/spell/utils/async/async.go:55 +0x7b
created by spell/utils/async.Repeat
    /go/src/spell/utils/async/async.go:49 +0x53

[vmihailenco]

I think such behavior can be caused by having a has one relation to the same struct, e.g.

type Model struct {
    Id int
    ModelId int
    Model *Model
}

But for some reason I can't trigger a race test. Probably it requires some specific order of columns or my theory is wrong.

Anyway please try v6.14.0

[kangp3]

I was able to reproduce on v6.13.6, gist here. The problem occurred when there's a chain of has one relations, e.g. Grandparent references Parent references Child. When concurrent queries are run on Grandparent and Parent, the map iteration in the Grandparent query and map write in the Parent query run concurrently, raising the error.

Running the same test on v6.14.1 seems to resolve that specific issue, but it does seem like there is a read/write race between initRelations and tryRelationStruct.

Unfortunately, the race test only hits a race condition about 1 in 20 times, so I've attached a run_test.sh script in the gist that runs the test 100 times and writes the output of each of the failures to separate files. The script also creates the schema via psql as opposed to via go-pg, since creating the schema via CreateTable would populate all of the FieldMaps, making it impossible to produce the race.

Also included in the gist is the full log outputs of failed race tests in both v6.13.6 and v6.14.1.

[vmihailenco]

Thanks again for detailed explanation and reproducer. I was able to add a test and release a fix in v6.14.2. Please try.

[jayschwa]

Thank you for the quick fix. The issue seems to be resolved, so I'm going to close the issue.