Kitura (Perfect mySQL) server crash: double free or corruption (!prev)

Server Development
1

I first noted this in Memory leaking in Vapor app, but it looks like a different issue. I'm running into a problem with a Swift server:

  • Swift version 5.0.1 (swift-5.0.1-RELEASE)
  • Ubuntu 16.04
  • Kitura 2.7.0
  • Perfect for mySQL interface (PerfectLib 3.1.4)

I'm so far only seeing this under load testing (using Locust; 75 simulated users):

*** Error in `/root/SyncServerII/.build/debug/Main': double free or corruption (!prev): 0x00007f8a8c12c510 ***
======= Backtrace: =========
/lib/x86_64-linux-gnu/libc.so.6(+0x777e5)[0x7f8aaee3d7e5]
/lib/x86_64-linux-gnu/libc.so.6(+0x8037a)[0x7f8aaee4637a]
/lib/x86_64-linux-gnu/libc.so.6(cfree+0x4c)[0x7f8aaee4a53c]
/usr/lib/swift/linux/libswiftCore.so(+0x3b703b)[0x7f8ab207c03b]

I'll see about running this with the Address Sanitizer shortly and will get back here with results.

2

Previously, without the address sanitizer, I got the crash on both of two trials with 75 simulated users. This time, with the address sanitizer in the build (swift build --sanitize=address -Xswiftc -DDEBUG -Xswiftc -DSERVER), it ran with no crash through 3000 requests with 75 simulated users. Upping to 100 simulated users, I got a crash after around 250 requests. Some of the normal logging of my server is included because that's where the address sanitizer output started. I've edited out some id logging info which doesn't seem relevant:

[2019-07-09T02:15:22.465Z] [INFO] [RequestHandler.swift:285 doRequest(createRequest:processRequest:)] Profile: Optional(Credentials.UserProfile); userId: [snip]
[2019-07-09T02:15:22.466Z] [INFO] [RequestHandler.swift:285 doRequest(createRequest:processRequest:)] Profile: Optional(Credentials.UserProfile); userId: [snip]
[2019-07-09T02:15:22.474Z] [DEBUG] [Repository.swift:103 lookup(key:modelInit:)] Found result!
[2019-07-09T02:15:22.482Z] [INFO] [Database.swift:56 init(showStartupInfo:)] DB CONNECTION STATS: opened: 3396; closed: 3339
[2019-07-09T02:15:22.491Z] [INFO] [Database.swift:56 init(showStartupInfo:)] DB CONNECTION STATS: opened: 3397; closed: 3339
[2019-07-09T02:15:22.491Z] [INFO] [Database.swift:56 init(showStartupInfo:)] DB CONNECTION STATS: opened: 3398; closed: 3339
AddressSanitizer:DEADLYSIGNAL

[2019-07-09T02:15:22.494Z] [INFO] [Database.swift:56 init(showStartupInfo:)] DB CONNECTION STATS: opened: 3399; closed: 3339
[2019-07-09T02:15:22.501Z] [INFO] [Database.swift:56 init(showStartupInfo:)] DB CONNECTION STATS: opened: 3400; closed: 3339
[2019-07-09T02:15:22.505Z] [INFO] [Database.swift:56 init(showStartupInfo:)] DB CONNECTION STATS: opened: 3401; closed: 3339
[2019-07-09T02:15:22.512Z] [DEBUG] [Repository.swift:103 lookup(key:modelInit:)] Found result!
[2019-07-09T02:15:22.517Z] [DEBUG] [Repository.swift:88 lookup(key:modelInit:)] No object found!
==7==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000000 (pc 0x7faaf1c46730 bp 0x7faabced6db0 sp 0x7faabced6cf8 T613)
[2019-07-09T02:15:22.515Z] [DEBUG] [Repository.swift:103 lookup(key:modelInit:)] Found result!
[2019-07-09T02:15:22.518Z] [DEBUG] [Repository.swift:88 lookup(key:modelInit:)] No object found!
[2019-07-09T02:15:22.515Z] [DEBUG] [Repository.swift:103 lookup(key:modelInit:)] Found result!==7==The signal is caused by a READ memory access.
==7==Hint: address points to the zero page.

[2019-07-09T02:15:22.536Z] [DEBUG] [Repository.swift:88 lookup(key:modelInit:)] No object found!
[2019-07-09T02:15:22.522Z] [DEBUG] [Repository.swift:103 lookup(key:modelInit:)] Found result!
[2019-07-09T02:15:22.525Z] [INFO] [Database.swift:56 init(showStartupInfo:)] DB CONNECTION STATS: opened: 3402; closed: 3339
[2019-07-09T02:15:22.521Z] [DEBUG] [Repository.swift:103 lookup(key:modelInit:)] Found result!
[2019-07-09T02:15:22.537Z] [DEBUG] [Repository.swift:88 lookup(key:modelInit:)] No object found!
[2019-07-09T02:15:22.543Z] [DEBUG] [Repository.swift:88 lookup(key:modelInit:)] No object found!
[2019-07-09T02:15:22.547Z] [DEBUG] [Repository.swift:88 lookup(key:modelInit:)] No object found!
[2019-07-09T02:15:22.547Z] [DEBUG] [Repository.swift:103 lookup(key:modelInit:)] Found result!
[2019-07-09T02:15:22.554Z] [DEBUG] [Repository.swift:88 lookup(key:modelInit:)] No object found!
[2019-07-09T02:15:22.599Z] [INFO] [FileController.swift:131 index(params:)] Number of entries in FileIndex: 88
#0 0x7faaf1c4672f (/usr/lib/swift/linux/libswiftCore.so+0x3fe72f)
#1 0x7faaf1b98d11 (/usr/lib/swift/linux/libswiftCore.so+0x350d11)
#2 0x7faaf19b1a21 (/usr/lib/swift/linux/libswiftCore.so+0x169a21)
#3 0x557119fc05c1 (/root/SyncServerII/.build/debug/Main+0xa8c5c1)
#4 0x55711a259b37 (/root/SyncServerII/.build/debug/Main+0xd25b37)
#5 0x55711a23f1e7 (/root/SyncServerII/.build/debug/Main+0xd0b1e7)
#6 0x55711a240ebf (/root/SyncServerII/.build/debug/Main+0xd0cebf)
#7 0x55711a241d63 (/root/SyncServerII/.build/debug/Main+0xd0dd63)
#8 0x557119824f5d (/root/SyncServerII/.build/debug/Main+0x2f0f5d)
#9 0x55711a241dd0 (/root/SyncServerII/.build/debug/Main+0xd0ddd0)
#10 0x557119917bb7 (/root/SyncServerII/.build/debug/Main+0x3e3bb7)
#11 0x55711991db1a (/root/SyncServerII/.build/debug/Main+0x3e9b1a)
#12 0x55711993cbc7 (/root/SyncServerII/.build/debug/Main+0x408bc7)
#13 0x55711993d0ad (/root/SyncServerII/.build/debug/Main+0x4090ad)
#14 0x55711993ea9f (/root/SyncServerII/.build/debug/Main+0x40aa9f)
#15 0x55711991b8ac (/root/SyncServerII/.build/debug/Main+0x3e78ac)
#16 0x55711991b319 (/root/SyncServerII/.build/debug/Main+0x3e7319)
#17 0x557119919c28 (/root/SyncServerII/.build/debug/Main+0x3e5c28)
#18 0x55711991f1f4 (/root/SyncServerII/.build/debug/Main+0x3eb1f4)
#19 0x55711991f475 (/root/SyncServerII/.build/debug/Main+0x3eb475)
#20 0x55711991f4cb (/root/SyncServerII/.build/debug/Main+0x3eb4cb)
#21 0x557119919c5e (/root/SyncServerII/.build/debug/Main+0x3e5c5e)
#22 0x55711991f1f4 (/root/SyncServerII/.build/debug/Main+0x3eb1f4)
#23 0x55711991f475 (/root/SyncServerII/.build/debug/Main+0x3eb475)
#24 0x55711991f4cb (/root/SyncServerII/.build/debug/Main+0x3eb4cb)
#25 0x55711991b33f (/root/SyncServerII/.build/debug/Main+0x3e733f)
#26 0x557119919c28 (/root/SyncServerII/.build/debug/Main+0x3e5c28)
#27 0x55711991f1f4 (/root/SyncServerII/.build/debug/Main+0x3eb1f4)
#28 0x55711991f475 (/root/SyncServerII/.build/debug/Main+0x3eb475)
#29 0x55711991f4cb (/root/SyncServerII/.build/debug/Main+0x3eb4cb)
#30 0x557119919c5e (/root/SyncServerII/.build/debug/Main+0x3e5c5e)
#31 0x55711991f1f4 (/root/SyncServerII/.build/debug/Main+0x3eb1f4)
#32 0x55711991f475 (/root/SyncServerII/.build/debug/Main+0x3eb475)
#33 0x55711991f4cb (/root/SyncServerII/.build/debug/Main+0x3eb4cb)
#34 0x55711991b33f (/root/SyncServerII/.build/debug/Main+0x3e733f)
#35 0x557119919c28 (/root/SyncServerII/.build/debug/Main+0x3e5c28)
#36 0x55711991f1f4 (/root/SyncServerII/.build/debug/Main+0x3eb1f4)
#37 0x55711991f475 (/root/SyncServerII/.build/debug/Main+0x3eb475)
#38 0x55711991f4cb (/root/SyncServerII/.build/debug/Main+0x3eb4cb)
#39 0x55711991b33f (/root/SyncServerII/.build/debug/Main+0x3e733f)
#40 0x557119919c28 (/root/SyncServerII/.build/debug/Main+0x3e5c28)
#41 0x55711991f1f4 (/root/SyncServerII/.build/debug/Main+0x3eb1f4)
#42 0x55711991f475 (/root/SyncServerII/.build/debug/Main+0x3eb475)
#43 0x55711991f4cb (/root/SyncServerII/.build/debug/Main+0x3eb4cb)
#44 0x557119917e0b (/root/SyncServerII/.build/debug/Main+0x3e3e0b)
#45 0x55711991db80 (/root/SyncServerII/.build/debug/Main+0x3e9b80)
#46 0x55711982509b (/root/SyncServerII/.build/debug/Main+0x2f109b)
#47 0x5571198a3ec0 (/root/SyncServerII/.build/debug/Main+0x36fec0)
#48 0x5571196f3c5f (/root/SyncServerII/.build/debug/Main+0x1bfc5f)
#49 0x557119700e68 (/root/SyncServerII/.build/debug/Main+0x1cce68)
#50 0x5571197b5391 (/root/SyncServerII/.build/debug/Main+0x281391)
#51 0x5571197b8d43 (/root/SyncServerII/.build/debug/Main+0x284d43)
#52 0x5571196f245c (/root/SyncServerII/.build/debug/Main+0x1be45c)
#53 0x5571196f3010 (/root/SyncServerII/.build/debug/Main+0x1bf010)
#54 0x5571196ecca7 (/root/SyncServerII/.build/debug/Main+0x1b8ca7)
#55 0x55711a279256 (/root/SyncServerII/.build/debug/Main+0xd45256)
#56 0x55711a2792fb (/root/SyncServerII/.build/debug/Main+0xd452fb)
#57 0x557119824f5d (/root/SyncServerII/.build/debug/Main+0x2f0f5d)
#58 0x55711a279980 (/root/SyncServerII/.build/debug/Main+0xd45980)
#59 0x557119917bb7 (/root/SyncServerII/.build/debug/Main+0x3e3bb7)
#60 0x55711991db1a (/root/SyncServerII/.build/debug/Main+0x3e9b1a)
#61 0x55711993cbc7 (/root/SyncServerII/.build/debug/Main+0x408bc7)
#62 0x55711993d0ad (/root/SyncServerII/.build/debug/Main+0x4090ad)
#63 0x55711993ea9f (/root/SyncServerII/.build/debug/Main+0x40aa9f)
#64 0x55711991b8ac (/root/SyncServerII/.build/debug/Main+0x3e78ac)
#65 0x557119919bd9 (/root/SyncServerII/.build/debug/Main+0x3e5bd9)
#66 0x55711991f1f4 (/root/SyncServerII/.build/debug/Main+0x3eb1f4)
#67 0x55711991f475 (/root/SyncServerII/.build/debug/Main+0x3eb475)
#68 0x55711991f4cb (/root/SyncServerII/.build/debug/Main+0x3eb4cb)
#69 0x557119c319cd (/root/SyncServerII/.build/debug/Main+0x6fd9cd)
#70 0x557119c34a67 (/root/SyncServerII/.build/debug/Main+0x700a67)
#71 0x55711993ea9f (/root/SyncServerII/.build/debug/Main+0x40aa9f)
#72 0x55711991b8ac (/root/SyncServerII/.build/debug/Main+0x3e78ac)
#73 0x557119919bd9 (/root/SyncServerII/.build/debug/Main+0x3e5bd9)
#74 0x55711991f1f4 (/root/SyncServerII/.build/debug/Main+0x3eb1f4)
#75 0x55711990f2d1 (/root/SyncServerII/.build/debug/Main+0x3db2d1)
#76 0x557119910c46 (/root/SyncServerII/.build/debug/Main+0x3dcc46)
#77 0x5571199147f8 (/root/SyncServerII/.build/debug/Main+0x3e07f8)
#78 0x557119bc89de (/root/SyncServerII/.build/debug/Main+0x6949de)
#79 0x557119bcae24 (/root/SyncServerII/.build/debug/Main+0x696e24)
#80 0x557119b54dd7 (/root/SyncServerII/.build/debug/Main+0x620dd7)
#81 0x7faaf20c3666 (/usr/lib/swift/linux/libdispatch.so+0x22666)
#82 0x7faaf20d77c7 (/usr/lib/swift/linux/libdispatch.so+0x367c7)
#83 0x7faaf0cf86b9 (/lib/x86_64-linux-gnu/libpthread.so.0+0x76b9)
#84 0x7faaee84841c (/lib/x86_64-linux-gnu/libc.so.6+0x10741c)

AddressSanitizer can not provide additional info.
SUMMARY: AddressSanitizer: SEGV (/usr/lib/swift/linux/libswiftCore.so+0x3fe72f)
Thread T613 created by T4 here:
#0 0x55711a5820dd (/root/SyncServerII/.build/debug/Main+0x104e0dd)
#1 0x7faaf20d3ce5 (/usr/lib/swift/linux/libdispatch.so+0x32ce5)

Thread T4 created by T3 here:
#0 0x55711a5820dd (/root/SyncServerII/.build/debug/Main+0x104e0dd)
#1 0x7faaf20d3ce5 (/usr/lib/swift/linux/libdispatch.so+0x32ce5)

Thread T3 created by T0 here:
#0 0x55711a5820dd (/root/SyncServerII/.build/debug/Main+0x104e0dd)
#1 0x7faaf20d3ce5 (/usr/lib/swift/linux/libdispatch.so+0x32ce5)

==7==ABORTING

3

It seems like this is the result of a thread safety problem. Can I recommend using thread sanitizer here as well? You may find this works better if you run the sanitizer in release mode, incidentally.

1 Like
4

Running with the thread sanitizer (swift build --sanitize=thread -Xswiftc -DDEBUG -Xswiftc -DSERVER), I got a large amount of output. I've eyeballed it, but not sure how to interpret it. Any advice would be appreciated. It's too long to post as text (and unfortunately it seems that the only files uploadable here are images), so here's a link:
http://cprince.com/tmp/ThreadSanitizer.txt

I now see there are occasional summaries. Doing grep "SUMMARY: ThreadSanitizer:" ThreadSanitizer.txt gives:

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/:? in $sIeg_IeyB_TR

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in $sIeg_IeyB_TR

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet27IncomingHTTPSocketProcessorC10inProgressSbvs

SUMMARY: ThreadSanitizer: Swift access race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/IncomingSocketManager.swift:220 in $s9KituraNet21IncomingSocketManagerC7process33_684BF7E5C6D71BC96F4DF81B5FFCF484LL15epollDescriptor20runRemoveIdleSocketsys5Int32V_SbtFyyXEfU_

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet21IncomingSocketHandlerC9processorAA0cD9Processor_pSgvg

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet21IncomingSocketHandlerC9processorAA0cD9Processor_pSgvg

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/IncomingSocketHandler.swift:419 in $s9KituraNet21IncomingSocketHandlerC5close33_F1F9040F439C50BA72402C6FB6C06BAELLyyF

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/IncomingSocketHandler.swift:409 in $s9KituraNet21IncomingSocketHandlerC14prepareToCloseyyF

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet27IncomingHTTPSocketProcessorC5stateAC5StateOvg

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTP/IncomingHTTPSocketProcessor.swift:297 in $s9KituraNet27IncomingHTTPSocketProcessorC5parse33_35F286AF5BE880D03C012662FD231F0BLLyy10Foundation6NSDataCF

SUMMARY: ThreadSanitizer: Swift access race ??:? in $s11Credentials11UserProfileC18extendedPropertiesSDySSypGvg

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet27IncomingHTTPSocketProcessorC5stateAC5StateOvg

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet27IncomingHTTPSocketProcessorC10inProgressSbvs

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTP/IncomingHTTPSocketProcessor.swift:297 in $s9KituraNet27IncomingHTTPSocketProcessorC5parse33_35F286AF5BE880D03C012662FD231F0BLLyy10Foundation6NSDataCF

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet27IncomingHTTPSocketProcessorC14keepAliveUntilSdvs

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in $sIeg_IeyB_TR

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in $sIeg_IeyB_TR

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in $sIeg_IeyB_TR

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in $s9KituraNet17HTTPServerRequestCAA06ServerD0A2aDP7headersAA16HeadersContainerCvgTW

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in $sIeg_IeyB_TR

SUMMARY: ThreadSanitizer: Swift access race ??:? in $s9KituraNet16HeadersContainerC7headersSDyS2S3key_SaySSG5valuetGvg

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in $s9KituraNet18HTTPServerResponseCAA06ServerD0A2aDP7headersAA16HeadersContainerCvgTW

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in $s10Foundation4DataV06InlineB0VyAESWcfCTf4xd_n

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet18HTTPServerResponseC7headersAA16HeadersContainerCvg

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet12ParseResultsC16httpVersionMajors6UInt16Vvg

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTP/HTTPServerResponse.swift:86 in $s9KituraNet18HTTPServerResponseC10statusCodeAA010HTTPStatusF0OSgvs

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet12ParseResultsC16httpVersionMinors6UInt16Vvg

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet12ParseResultsC6methodSSvg

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet12ParseResultsC6methodSSvg

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTP/HTTPServerResponse.swift:87 in $s9KituraNet18HTTPServerResponseC10statusCodeAA010HTTPStatusF0OSgvs

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTP/HTTPServerResponse.swift:87 in $s9KituraNet18HTTPServerResponseC10statusCodeAA010HTTPStatusF0OSgvs

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet27IncomingHTTPSocketProcessorC14keepAliveUntilSdvs

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura/Sources/Kitura/Headers.swift:71 in $s6Kitura7HeadersVySSSgSScis

SUMMARY: ThreadSanitizer: Swift access race ??:? in $s9KituraNet16HeadersContainerC7headersSDyS2S3key_SaySSG5valuetGvM

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in _swift_release_dealloc

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in $ss11_StringGutsV6appendyys01_aB5SliceVF

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTP/HTTPServerResponse.swift:259 in $s9KituraNet18HTTPServerResponseC26writeToSocketThroughBuffer33_8A9E8F62631F03CCFCED4F4223E40C30LL4textySS_tKF

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTP/HTTPServerResponse.swift:259 in $s9KituraNet18HTTPServerResponseC26writeToSocketThroughBuffer33_8A9E8F62631F03CCFCED4F4223E40C30LL4textySS_tKF

SUMMARY: ThreadSanitizer: data race ??:? in __CFSafelyReallocate

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTP/HTTPServerResponse.swift:180 in $s9KituraNet18HTTPServerResponseC3endyyKF

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet27IncomingHTTPSocketProcessorC5StateOMa

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet27IncomingHTTPSocketProcessorC5StateOMa

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet27IncomingHTTPSocketProcessorC5StateOMa

SUMMARY: ThreadSanitizer: data race queue.c:? in _dispatch_worker_thread

SUMMARY: ThreadSanitizer: Swift access race /root/Apps/SyncServerII/SyncServerII/Sources/Server/Utils/ServerStats.swift:40 in $s6Server0A11StatsKeeperC9increment4statyAA0A4StatO_tFyyXEfU_

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in $ss22_stringCompareInternal__9expectingSbs11_StringGutsV_ADs01_E16ComparisonResultOtFTf4xxn_n

SUMMARY: ThreadSanitizer: data race ??:? in $s10Foundation13__DataStorageC5bytes6lengthACSVSg_Sitcfc

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura/Sources/Kitura/Headers.swift:71 in $s6Kitura7HeadersVySSSgSScis

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in $ss11_StringGutsV6appendyys01_aB5SliceVF

SUMMARY: ThreadSanitizer: Swift access race ??:? in $s9KituraNet16HeadersContainerC7headersSDyS2S3key_SaySSG5valuetGvM

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in _swift_release_dealloc

SUMMARY: ThreadSanitizer: data race ??:? in handle_options

SUMMARY: ThreadSanitizer: data race ??:? in handle_options

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in $ss11_StringGutsV6appendyys01_aB5SliceVF

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in $ss11_StringGutsV6appendyys01_aB5SliceVF

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTP/HTTPServerResponse.swift:259 in $s9KituraNet18HTTPServerResponseC26writeToSocketThroughBuffer33_8A9E8F62631F03CCFCED4F4223E40C30LL4textySS_tKF

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTP/HTTPServerResponse.swift:259 in $s9KituraNet18HTTPServerResponseC26writeToSocketThroughBuffer33_8A9E8F62631F03CCFCED4F4223E40C30LL4textySS_tKF

SUMMARY: ThreadSanitizer: data race ??:? in __CFSafelyReallocate

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTP/HTTPServerResponse.swift:180 in $s9KituraNet18HTTPServerResponseC3endyyKF

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in $ss11_StringGutsV6appendyys01_aB5SliceVF

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in $ss11_StringGutsV6appendyys01_aB5SliceVF

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTP/HTTPServerResponse.swift:259 in $s9KituraNet18HTTPServerResponseC26writeToSocketThroughBuffer33_8A9E8F62631F03CCFCED4F4223E40C30LL4textySS_tKF

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTP/HTTPServerResponse.swift:259 in $s9KituraNet18HTTPServerResponseC26writeToSocketThroughBuffer33_8A9E8F62631F03CCFCED4F4223E40C30LL4textySS_tKF

SUMMARY: ThreadSanitizer: data race ??:? in __CFSafelyReallocate

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTP/HTTPServerResponse.swift:180 in $s9KituraNet18HTTPServerResponseC3endyyKF

SUMMARY: ThreadSanitizer: data race ??:? in $s10Foundation13__DataStorageC5bytes6lengthACSVSg_Sitcfc

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in $ss22_stringCompareInternal__9expectingSbs11_StringGutsV_ADs01_E16ComparisonResultOtFTf4xxn_n

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTP/IncomingHTTPSocketProcessor.swift:329 in $s9KituraNet27IncomingHTTPSocketProcessorC15parsingComplete33_35F286AF5BE880D03C012662FD231F0BLLyyFyycfU_

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTP/HTTPServerRequest.swift:111 in $s9KituraNet17HTTPServerRequestC7headersAA16HeadersContainerCvg

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTPParser/HTTPParser.swift:40 in $s9KituraNet10HTTPParserC7headersAA16HeadersContainerCvg

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTPParser/HTTPParser.swift:40 in $s9KituraNet10HTTPParserC7headersAA16HeadersContainerCvg

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet12ParseResultsC7headersAA16HeadersContainerCvg

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura/Sources/Kitura/Router.swift:565 in $s6Kitura6RouterC6handle7request8responsey0A3Net13ServerRequest_p_AG0G8Response_ptF

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet16HeadersContainerC7headersSDyS2S3key_SaySSG5valuetGvg

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTPParser/HTTPParser.swift:28 in $s9KituraNet10HTTPParserC3url10Foundation6NSDataCvg

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTP/HTTPServerRequest.swift:215 in $s9KituraNet17HTTPServerRequestC3url10Foundation4DataVvg

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in $s10Foundation4DataV06InlineB0VyAESWcfCTf4xd_n

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet12ParseResultsC16httpVersionMajors6UInt16Vvg

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in $ss22_stringCompareInternal__9expectingSbs11_StringGutsV_ADs01_E16ComparisonResultOtFTf4xxn_n

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet16HeadersContainerC7headersSDyS2S3key_SaySSG5valuetGvg

SUMMARY: ThreadSanitizer: data race ??:? in $s10Foundation13__DataStorageC5bytes6lengthACSVSg_Sitcfc

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in $s9KituraNet17HTTPServerRequestCAA06ServerD0A2aDP7headersAA16HeadersContainerCvgTW

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in $s10Foundation4DataV06InlineB0VyAESWcfCTf4xd_n

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet12ParseResultsC16httpVersionMajors6UInt16Vvg

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet12ParseResultsC16httpVersionMinors6UInt16Vvg

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet12ParseResultsC6methodSSvg

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet12ParseResultsC6methodSSvg

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet27IncomingHTTPSocketProcessorC10inProgressSbvg

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura/Sources/Kitura/Headers.swift:71 in $s6Kitura7HeadersVySSSgSScis

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet27IncomingHTTPSocketProcessorC14keepAliveUntilSdvg

SUMMARY: ThreadSanitizer: Swift access race ??:? in $s9KituraNet16HeadersContainerC7headersSDyS2S3key_SaySSG5valuetGvM

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in _swift_release_dealloc

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in $ss22_stringCompareInternal__9expectingSbs11_StringGutsV_ADs01_E16ComparisonResultOtFTf4xxn_n

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in $sIeg_IeyB_TR

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in $sIeg_IeyB_TR

SUMMARY: ThreadSanitizer: data race crtstuff.c:? in $s9KituraNet18HTTPServerResponseCAA06ServerD0A2aDP7headersAA16HeadersContainerCvgTW

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet18HTTPServerResponseC7headersAA16HeadersContainerCvg

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTP/HTTPServerResponse.swift:86 in $s9KituraNet18HTTPServerResponseC10statusCodeAA010HTTPStatusF0OSgvs

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTP/HTTPServerResponse.swift:87 in $s9KituraNet18HTTPServerResponseC10statusCodeAA010HTTPStatusF0OSgvs

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet27IncomingHTTPSocketProcessorC5stateAC5StateOvg

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet27IncomingHTTPSocketProcessorC5stateAC5StateOvg

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTP/IncomingHTTPSocketProcessor.swift:297 in $s9KituraNet27IncomingHTTPSocketProcessorC5parse33_35F286AF5BE880D03C012662FD231F0BLLyy10Foundation6NSDataCF

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTP/IncomingHTTPSocketProcessor.swift:297 in $s9KituraNet27IncomingHTTPSocketProcessorC5parse33_35F286AF5BE880D03C012662FD231F0BLLyy10Foundation6NSDataCF

SUMMARY: ThreadSanitizer: data race ??:? in $s9KituraNet27IncomingHTTPSocketProcessorC5stateAC5StateOvg

SUMMARY: ThreadSanitizer: data race /root/Apps/SyncServerII/SyncServerII/.build/checkouts/Kitura-net/Sources/KituraNet/HTTP/IncomingHTTPSocketProcessor.swift:297 in $s9KituraNet27IncomingHTTPSocketProcessorC5parse33_35F286AF5BE880D03C012662FD231F0BLLyy10Foundation6NSDataCF

SUMMARY: ThreadSanitizer: SEGV ??:? in swift_nonatomic_bridgeObjectRelease_n

5

Wow, there's a lot of output here. Quite a chunk of it comes from kitura-net (cc @IanPartridge), but I think the location of your bug is probably in this section (which I have demangled for you as best I can).

This is evidence of thread-unsafe behaviour in your code, particularly around the Credentials object. I'd begin by investigating whether you have correctly guarded the concurrent access to this class.

6

Thanks @lukasa! I'll definitely look into this. I don't recall doing any concurrent access consideration with my Credentials usage so this could be the culprit. The demangling helps! If you get a moment, could you please tell me the procedure you used to do that? Also, any thoughts about what leads you to believe it's Credentials usage versus other parts of the output? (Again, I will definitely look a the Credentials usage -- since some of that is in my control and I think I had no thread safety mechanism there).

7

Sure, to demangle any text it's sufficient to pipe it through swift demangle. I ideally you want to do that using the exact Swift that generated the binary, but if you cannot do that you can often get decent results with a similar Swift.

The other issues I saw were in Kitura, and as a result I suspect they did not cause your issue, or your issue would be very widespread: there are many Kitura users and only one user of your code, so 100% of users of your code have hit the issue and only a tiny fraction of Kitura issues have hit it.

Note that this is not me saying that this isn't the result of the Kitura issue: only that it's more likely that the Kitura behaviour is accidentally working, as others would have seen it earlier. So it's best to start with the code with the fewest users and work outwards from there.

8

Thanks for reporting this. We were aware of these thread sanitiser reports but as Cory correctly surmises we have never seen them manifest in practice. They are tracked at Thread sanitizer finds issues · Issue #237 · Kitura/Kitura-net · GitHub . We took a stab at resolving them a while back but the performance impact was too high. Having just discussed though we have some new ideas so we'll take a renewed look at this.

9

Many thanks @lukasa and @IanPartridge. Looking into this now.

10

I think I may have resolved this. Working on a fix now. It looks like my problem is occurring because:
a) I'm using the UserProfile extendedProperties of the Kitura Credentials to bridge some data in the request to my request processing, and
b) I'm re-using the same users multiple times in my load testing.

As far as I can tell the UserProfile extendedProperties are not thread safe (due to caching). I didn't think about this before, but with my load testing, and re-use of the same users in different concurrent requests, I think that's causing problems. I think I see a way in my code to avoid the use of the UserProfile extendedProperties entirely. I'm not sure more generally if this is a valid use case for Kitura Credentials.

2 Likes
11

Yes, this was the problem. Thanks again for your help!

1 Like