fhir icon indicating copy to clipboard operation
fhir copied to clipboard

Published 20 hours ago • verified publisher icon eug48

Parallel writes end up in write conflicts

Open 0xmichalis opened this issue 5 years ago • 5 comments

When multiple processes try to write to the fhir server, the requests fail with write conflicts. I am able to work around this issue by using the X-Mutex-Name header documented here but I was wondering whether this issue is meant to be fixed appropriately by having some sort of deterministic concurrency control baked into the server.

ps.1 The writes in the server are independent resources in my case (they are all resource creations).

ps.2 I am using the all-in-one image that bakes Mongo in it.

handlePanics: recovered: (WriteConflict) WriteConflict
MongoDB operation error (/go/src/github.com/eug48/fhir/server/mongo_data_access.go:434)
github.com/eug48/fhir/server.convertMongoErr
	/go/src/github.com/eug48/fhir/server/mongo_data_access.go:1148
github.com/eug48/fhir/server.(*mongoSession).PostWithID
	/go/src/github.com/eug48/fhir/server/mongo_data_access.go:434
github.com/eug48/fhir/server.(*BatchController).doRequest
	/go/src/github.com/eug48/fhir/server/batch_controller.go:417
github.com/eug48/fhir/server.(*BatchController).Post
	/go/src/github.com/eug48/fhir/server/batch_controller.go:303
github.com/eug48/fhir/server.(*BatchController).Post-fm
	/go/src/github.com/eug48/fhir/server/routing.go:128
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109
github.com/eug48/fhir/fhir-server/middleware.ClientSpecifiedMutexesMiddleware.func2
	/go/src/github.com/eug48/fhir/fhir-server/middleware/client_specified_mutexes.go:95
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109
github.com/eug48/fhir/server.AbortNonFhirXMLorJSONRequestsMiddleware
	/go/src/github.com/eug48/fhir/server/middleware.go:43
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109
github.com/eug48/fhir/server.EnableXmlToJsonConversionMiddleware.func1
	/go/src/github.com/eug48/fhir/server/middleware.go:14
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.RecoveryWithWriter.func1
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/recovery.go:76
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.LoggerWithWriter.func1
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/logger.go:84
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Engine).handleHTTPRequest
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/gin.go:383
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Engine).ServeHTTP
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/gin.go:349
net/http.serverHandler.ServeHTTP
	/usr/local/go/src/net/http/server.go:2697
net/http.(*conn).serve
	/usr/local/go/src/net/http/server.go:1830
runtime.goexit
	/usr/local/go/src/runtime/asm_amd64.s:2361
failed to create Encounter
github.com/eug48/fhir/server.(*BatchController).doRequest
	/go/src/github.com/eug48/fhir/server/batch_controller.go:419
github.com/eug48/fhir/server.(*BatchController).Post
	/go/src/github.com/eug48/fhir/server/batch_controller.go:303
github.com/eug48/fhir/server.(*BatchController).Post-fm
	/go/src/github.com/eug48/fhir/server/routing.go:128
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109
github.com/eug48/fhir/fhir-server/middleware.ClientSpecifiedMutexesMiddleware.func2
	/go/src/github.com/eug48/fhir/fhir-server/middleware/client_specified_mutexes.go:95
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109
github.com/eug48/fhir/server.AbortNonFhirXMLorJSONRequestsMiddleware
	/go/src/github.com/eug48/fhir/server/middleware.go:43
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109
github.com/eug48/fhir/server.EnableXmlToJsonConversionMiddleware.func1
	/go/src/github.com/eug48/fhir/server/middleware.go:14
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.RecoveryWithWriter.func1
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/recovery.go:76
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.LoggerWithWriter.func1
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/logger.go:84
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Engine).handleHTTPRequest
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/gin.go:383
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Engine).ServeHTTP
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/gin.go:349
net/http.serverHandler.ServeHTTP
	/usr/local/go/src/net/http/server.go:2697
net/http.(*conn).serve
	/usr/local/go/src/net/http/server.go:1830
runtime.goexit
	/usr/local/go/src/runtime/asm_amd64.s:2361
    goroutine 15 [running]:
runtime/debug.Stack(0x149e000, 0xc42066da00, 0x149e000)
	/usr/local/go/src/runtime/debug/stack.go:24 +0xa7
github.com/eug48/fhir/server.ErrorToOpOutcome(0xf54200, 0xc421e3ac80, 0xc4214e1580, 0x1)
	/go/src/github.com/eug48/fhir/server/errors.go:29 +0x474
github.com/eug48/fhir/server.(*BatchController).Post(0xc4200f9b80, 0xc4217ac370)
	/go/src/github.com/eug48/fhir/server/batch_controller.go:318 +0x25f4
github.com/eug48/fhir/server.(*BatchController).Post-fm(0xc4217ac370)
	/go/src/github.com/eug48/fhir/server/routing.go:128 +0x34
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next(0xc4217ac370)
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109 +0x43
github.com/eug48/fhir/fhir-server/middleware.ClientSpecifiedMutexesMiddleware.func2(0xc4217ac370)
	/go/src/github.com/eug48/fhir/fhir-server/middleware/client_specified_mutexes.go:95 +0xbc
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next(0xc4217ac370)
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109 +0x43
github.com/eug48/fhir/server.AbortNonFhirXMLorJSONRequestsMiddleware(0xc4217ac370)
	/go/src/github.com/eug48/fhir/server/middleware.go:43 +0x1c7
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next(0xc4217ac370)
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109 +0x43
github.com/eug48/fhir/server.EnableXmlToJsonConversionMiddleware.func1(0xc4217ac370)
	/go/src/github.com/eug48/fhir/server/middleware.go:14 +0x9e
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next(0xc4217ac370)
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109 +0x43
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.RecoveryWithWriter.func1(0xc4217ac370)
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/recovery.go:76 +0x5a
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next(0xc4217ac370)
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109 +0x43
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.LoggerWithWriter.func1(0xc4217ac370)
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/logger.go:84 +0xcc
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next(0xc4217ac370)
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109 +0x43
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Engine).handleHTTPRequest(0xc420386000, 0xc4217ac370)
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/gin.go:383 +0x586
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Engine).ServeHTTP(0xc420386000, 0x14a4f60, 0xc420384fc0, 0xc4210a2800)
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/gin.go:349 +0x153
net/http.serverHandler.ServeHTTP(0xc4200a9a00, 0x14a4f60, 0xc420384fc0, 0xc4210a2800)
	/usr/local/go/src/net/http/server.go:2697 +0xbc
net/http.(*conn).serve(0xc4214fd680, 0x14a71a0, 0xc42270f640)
	/usr/local/go/src/net/http/server.go:1830 +0x651
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2798 +0x27b
[GIN] 2019/05/22 - 11:08:34 | 500 |    322.9276ms |       10.1.11.3 | POST     /


2019/05/22 11:08:34 [Recovery] 2019/05/22 - 11:08:34 panic recovered:
POST / HTTP/1.1
Host: fhirserver:3001
Accept-Encoding: gzip
Content-Length: 1117334
Content-Type: application/json
User-Agent: Go-http-client/1.1


session.Finish error: (NoSuchTransaction) Transaction 1 has been aborted.
/usr/local/go/src/runtime/panic.go:502 (0x4344b8)
/go/src/github.com/eug48/fhir/server/mongo_data_access.go:115 (0xd7df3f)
/go/src/github.com/eug48/fhir/server/batch_controller.go:321 (0xd76e85)
/go/src/github.com/eug48/fhir/server/routing.go:128 (0xd99813)
/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109 (0x947e52)
/go/src/github.com/eug48/fhir/fhir-server/middleware/client_specified_mutexes.go:95 (0x9a37eb)
/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109 (0x947e52)
/go/src/github.com/eug48/fhir/server/middleware.go:43 (0xd7d0b6)
/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109 (0x947e52)
/go/src/github.com/eug48/fhir/server/middleware.go:14 (0xd98dbd)
/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109 (0x947e52)
/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/recovery.go:76 (0x959d69)
/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109 (0x947e52)
/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/logger.go:84 (0x958bbb)
/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109 (0x947e52)
/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/gin.go:383 (0x950a25)
/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/gin.go:349 (0x9502b2)
/usr/local/go/src/net/http/server.go:2697 (0x68bc0b)
/usr/local/go/src/net/http/server.go:1830 (0x687d40)
/usr/local/go/src/runtime/asm_amd64.s:2361 (0x460df0)

handlePanics: recovered: (WriteConflict) WriteConflict
MongoDB operation error (/go/src/github.com/eug48/fhir/server/mongo_data_access.go:434)
github.com/eug48/fhir/server.convertMongoErr
	/go/src/github.com/eug48/fhir/server/mongo_data_access.go:1148
github.com/eug48/fhir/server.(*mongoSession).PostWithID
	/go/src/github.com/eug48/fhir/server/mongo_data_access.go:434
github.com/eug48/fhir/server.(*BatchController).doRequest
	/go/src/github.com/eug48/fhir/server/batch_controller.go:417
github.com/eug48/fhir/server.(*BatchController).Post
	/go/src/github.com/eug48/fhir/server/batch_controller.go:303
github.com/eug48/fhir/server.(*BatchController).Post-fm
	/go/src/github.com/eug48/fhir/server/routing.go:128
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109
github.com/eug48/fhir/fhir-server/middleware.ClientSpecifiedMutexesMiddleware.func2
	/go/src/github.com/eug48/fhir/fhir-server/middleware/client_specified_mutexes.go:95
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109
github.com/eug48/fhir/server.AbortNonFhirXMLorJSONRequestsMiddleware
	/go/src/github.com/eug48/fhir/server/middleware.go:43
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109
github.com/eug48/fhir/server.EnableXmlToJsonConversionMiddleware.func1
	/go/src/github.com/eug48/fhir/server/middleware.go:14
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.RecoveryWithWriter.func1
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/recovery.go:76
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.LoggerWithWriter.func1
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/logger.go:84
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Engine).handleHTTPRequest
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/gin.go:383
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Engine).ServeHTTP
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/gin.go:349
net/http.serverHandler.ServeHTTP
	/usr/local/go/src/net/http/server.go:2697
net/http.(*conn).serve
	/usr/local/go/src/net/http/server.go:1830
runtime.goexit
	/usr/local/go/src/runtime/asm_amd64.s:2361
failed to create Encounter
github.com/eug48/fhir/server.(*BatchController).doRequest
	/go/src/github.com/eug48/fhir/server/batch_controller.go:419
github.com/eug48/fhir/server.(*BatchController).Post
	/go/src/github.com/eug48/fhir/server/batch_controller.go:303
github.com/eug48/fhir/server.(*BatchController).Post-fm
	/go/src/github.com/eug48/fhir/server/routing.go:128
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109
github.com/eug48/fhir/fhir-server/middleware.ClientSpecifiedMutexesMiddleware.func2
	/go/src/github.com/eug48/fhir/fhir-server/middleware/client_specified_mutexes.go:95
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109
github.com/eug48/fhir/server.AbortNonFhirXMLorJSONRequestsMiddleware
	/go/src/github.com/eug48/fhir/server/middleware.go:43
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109
github.com/eug48/fhir/server.EnableXmlToJsonConversionMiddleware.func1
	/go/src/github.com/eug48/fhir/server/middleware.go:14
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.RecoveryWithWriter.func1
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/recovery.go:76
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.LoggerWithWriter.func1
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/logger.go:84
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Engine).handleHTTPRequest
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/gin.go:383
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Engine).ServeHTTP
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/gin.go:349
net/http.serverHandler.ServeHTTP
	/usr/local/go/src/net/http/server.go:2697
net/http.(*conn).serve
	/usr/local/go/src/net/http/server.go:1830
runtime.goexit
	/usr/local/go/src/runtime/asm_amd64.s:2361
    goroutine 52 [running]:
runtime/debug.Stack(0x149e000, 0xc420365600, 0x149e000)
	/usr/local/go/src/runtime/debug/stack.go:24 +0xa7
github.com/eug48/fhir/server.ErrorToOpOutcome(0xf54200, 0xc4203fba00, 0xc421e27580, 0x1)
	/go/src/github.com/eug48/fhir/server/errors.go:29 +0x474
github.com/eug48/fhir/server.(*BatchController).Post(0xc4200f9b80, 0xc4217ac420)
	/go/src/github.com/eug48/fhir/server/batch_controller.go:318 +0x25f4
github.com/eug48/fhir/server.(*BatchController).Post-fm(0xc4217ac420)
	/go/src/github.com/eug48/fhir/server/routing.go:128 +0x34
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next(0xc4217ac420)
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109 +0x43
github.com/eug48/fhir/fhir-server/middleware.ClientSpecifiedMutexesMiddleware.func2(0xc4217ac420)
	/go/src/github.com/eug48/fhir/fhir-server/middleware/client_specified_mutexes.go:95 +0xbc
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next(0xc4217ac420)
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109 +0x43
github.com/eug48/fhir/server.AbortNonFhirXMLorJSONRequestsMiddleware(0xc4217ac420)
	/go/src/github.com/eug48/fhir/server/middleware.go:43 +0x1c7
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next(0xc4217ac420)
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109 +0x43
github.com/eug48/fhir/server.EnableXmlToJsonConversionMiddleware.func1(0xc4217ac420)
	/go/src/github.com/eug48/fhir/server/middleware.go:14 +0x9e
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next(0xc4217ac420)
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109 +0x43
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.RecoveryWithWriter.func1(0xc4217ac420)
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/recovery.go:76 +0x5a
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next(0xc4217ac420)
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109 +0x43
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.LoggerWithWriter.func1(0xc4217ac420)
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/logger.go:84 +0xcc
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Context).Next(0xc4217ac420)
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109 +0x43
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Engine).handleHTTPRequest(0xc420386000, 0xc4217ac420)
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/gin.go:383 +0x586
github.com/eug48/fhir/vendor/github.com/gin-gonic/gin.(*Engine).ServeHTTP(0xc420386000, 0x14a4f60, 0xc420385180, 0xc4210a2a00)
	/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/gin.go:349 +0x153
net/http.serverHandler.ServeHTTP(0xc4200a9a00, 0x14a4f60, 0xc420385180, 0xc4210a2a00)
	/usr/local/go/src/net/http/server.go:2697 +0xbc
net/http.(*conn).serve(0xc422cde460, 0x14a71a0, 0xc42270f8c0)
	/usr/local/go/src/net/http/server.go:1830 +0x651
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2798 +0x27b
[GIN] 2019/05/22 - 11:08:34 | 500 |    249.0425ms |       10.1.11.6 | POST     /


2019/05/22 11:08:34 [Recovery] 2019/05/22 - 11:08:34 panic recovered:
POST / HTTP/1.1
Host: fhirserver:3001
Accept-Encoding: gzip
Content-Length: 1117334
Content-Type: application/json
User-Agent: Go-http-client/1.1


session.Finish error: (NoSuchTransaction) Transaction 1 has been aborted.
/usr/local/go/src/runtime/panic.go:502 (0x4344b8)
/go/src/github.com/eug48/fhir/server/mongo_data_access.go:115 (0xd7df3f)
/go/src/github.com/eug48/fhir/server/batch_controller.go:321 (0xd76e85)
/go/src/github.com/eug48/fhir/server/routing.go:128 (0xd99813)
/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109 (0x947e52)
/go/src/github.com/eug48/fhir/fhir-server/middleware/client_specified_mutexes.go:95 (0x9a37eb)
/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109 (0x947e52)
/go/src/github.com/eug48/fhir/server/middleware.go:43 (0xd7d0b6)
/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109 (0x947e52)
/go/src/github.com/eug48/fhir/server/middleware.go:14 (0xd98dbd)
/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109 (0x947e52)
/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/recovery.go:76 (0x959d69)
/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109 (0x947e52)
/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/logger.go:84 (0x958bbb)
/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/context.go:109 (0x947e52)
/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/gin.go:383 (0x950a25)
/go/src/github.com/eug48/fhir/vendor/github.com/gin-gonic/gin/gin.go:349 (0x9502b2)
/usr/local/go/src/net/http/server.go:2697 (0x68bc0b)
/usr/local/go/src/net/http/server.go:1830 (0x687d40)
/usr/local/go/src/runtime/asm_amd64.s:2361 (0x460df0)

0xmichalis avatar May 22 '19 11:05 0xmichalis

That's interesting - are you able to share what the requests look like? There's actually a new command-line switch requestsDumpDir that logs everything to a directory.

These transaction write conflicts are coming from MongoDB and the server is probably supposed to automatically retry the transaction. However I don't understand how resource creations can cause such conflicts..

eug48 avatar May 23 '19 05:05 eug48

Sure, it's a record generated by synthea (record.tar.gz). Note that I am using the same record in all of those parallel requests and rely on the fact that every time a new resource is PUT, the server will return the created resource with its new ID.

0xmichalis avatar May 23 '19 18:05 0xmichalis

I have reproduced write conflict errors when processing that bundle but only during the first transactions.. Running it again with lots of concurrency then works fine. I don't quite understand why it happens but perhaps something to do with some one-off index work that takes a database-wide lock. Do you also see the first transaction(s) failing or intermittent failures?

eug48 avatar Jun 03 '19 06:06 eug48

My context is tests running in parallel - when run serially (or with the same X-Mutex-Name set on every request), I don't see this issue.

0xmichalis avatar Jun 03 '19 12:06 0xmichalis

But when you run them in parallel how often do transactions fail? Can you attach log output? Thanks.

eug48 avatar Jun 03 '19 13:06 eug48