Crash ConnectionPool.swift

[pankajsoni19]

this is on debian 10 | ubuntu 18.04 on long running server process. This happens usually within few hours each time server is started.

0x7f3e5562472f
0x55ebb5605ca9, CNIOBoringSSL_OPENSSL_malloc at .build\/checkouts\/swift-nio-ssl\/Sources\/CNIOBoringSSL\/crypto\/mem.c:125
0x55ebb554c9cf, asn1_item_ex_d2i at .build\/checkouts\/swift-nio-ssl\/Sources\/CNIOBoringSSL\/crypto\/asn1\/tasn_dec.c:459
0x55ebb554cac8, asn1_template_ex_d2i at .build\/checkouts\/swift-nio-ssl\/Sources\/CNIOBoringSSL\/crypto\/asn1\/tasn_dec.c:554
0x55ebb554c052, CNIOBoringSSL_ASN1_item_ex_d2i at .build\/checkouts\/swift-nio-ssl\/Sources\/CNIOBoringSSL\/crypto\/asn1\/tasn_dec.c:486
0x55ebb56087d3, parse_x509 at .build\/checkouts\/swift-nio-ssl\/Sources\/CNIOBoringSSL\/crypto\/pem\/pem_info.c:100
0x55ebb5620733, CNIOBoringSSL_X509_load_cert_crl_file at .build\/checkouts\/swift-nio-ssl\/Sources\/CNIOBoringSSL\/crypto\/x509\/by_file.c:254
0x55ebb56247f4, CNIOBoringSSL_X509_STORE_load_locations at .build\/checkouts\/swift-nio-ssl\/Sources\/CNIOBoringSSL\/crypto\/x509\/x509_d2.c:91
0x55ebb5ada0e9, generic not re-abstracted specialization <Swift.Int32> of closure #1 (Swift.UnsafePointer<Swift.Int8>) throws -> A1 in (extension in NIOSSL):Swift.Optional<A where A == Swift.String>.withCString<A>((Swift.Optional<Swift.UnsafePointer<Swift.Int8>>) throws -> A1) throws -> A1 at \/home\/admin\/server\/<compiler-generated>:0
0x55ebb5adab36, static NIOSSL.NIOSSLContext.(configureCertificateValidation in _2F13A2EC078EF6ECDDA8904A8474FC3D)(context: Swift.OpaquePointer, verification: NIOSSL.CertificateVerification, trustRoots: Swift.Optional<NIOSSL.NIOSSLTrustRoots>) throws -> () at \/home\/admin\/server\/<compiler-generated>:0
0x55ebb5adab36, function signature specialization <Arg[0] = Owned To Guaranteed, Arg[1] = Owned To Guaranteed> of NIOSSL.NIOSSLContext.init(configuration: NIOSSL.TLSConfiguration, callbackManager: Swift.Optional<NIOSSL.CallbackManagerProtocol>) throws -> NIOSSL.NIOSSLContext at \/home\/admin\/server\/.build\/checkouts\/swift-nio-ssl\/Sources\/NIOSSL\/SSLContext.swift:163
0x55ebb53eae32, AsyncHTTPClient.HTTP1ConnectionProvider.(makeChannel in _FE10872964386AE53EF9FE2B5059993A)(preference: AsyncHTTPClient.HTTPClient.EventLoopPreference) -> NIO.EventLoopFuture<NIO.Channel> at \/home\/admin\/server\/.build\/checkouts\/async-http-client\/Sources\/AsyncHTTPClient\/ConnectionPool.swift:417
0x55ebb53fdb27, AsyncHTTPClient.HTTP1ConnectionProvider.getConnection(preference: AsyncHTTPClient.HTTPClient.EventLoopPreference, setupComplete: NIO.EventLoopFuture<()>, logger: Logging.Logger) -> NIO.EventLoopFuture<AsyncHTTPClient.Connection> at .build\/checkouts\/async-http-client\/Sources\/AsyncHTTPClient\/ConnectionPool.swift:308

[Lukasa]

Can you provide information about exactly what version of swift-nio-ssl is in use here (you can derive it from Package.resolved). The line at the top of your call stack does not have a trap statement in it in the most recent version (it's just a call to malloc) so I'm not sure how you're seeing a crash.

[pankajsoni19]

{
        "package": "swift-nio-ssl",
        "repositoryURL": "https://github.com/apple/swift-nio-ssl.git",
        "state": {
          "branch": null,
          "revision": "62bf5083df970e67c886210fa5b857eacf044b7c",
          "version": "2.10.2"
        }
      }

Package.resolved.txt

[Lukasa]

Yeah, ok, that is the current version and so this is simply a call to malloc. I'm surprised to find it traps. How are you getting this call stack?

[pankajsoni19]

The log message has some keywords added by me for grep. Its this way in code

S3Logger.shared.log(message: "boot: ##trapcatch##: \(str)")

So do ignore the initial keywords. I updated my comment above.

[Lukasa]

Sure, but what I mean is: how was the backtrace gathered?

[pankajsoni19]

I do not fully understand your question, but

backtrace is given as events by library.
https://github.com/pankajsoni19/swift-backtrace.git ( I modified the parent version to have a callback handler for crash logs )

Backtrace.BACK_TRACE_LOG_CALLBACK_HANDLER = {(str: String) in
        S3Logger.shared.log(message: "boot: ##trapcatch##: \(str)")
}

All generated logs including backtrace events are pushed to a central log server via redis queue. It's from here I copied the logs and shared with you.

The above error happens when we get http request say req0 on our webserver ( Vapor ) , we make a internal request to analytics db using http client and send back the result to req0.

This occurs very randomly, but consistently, as server would crash in 4-5 hours on very light loads [ 5-10 requests per second ]

[Lukasa]

Do you have the exit code for the program, or any indication of which of the signals you hooked? I suspect this isn't a trap but one of the other kinds of signals, and it would be important to know which one it was.

[pankajsoni19]

not sure if this is related to this, but I digged through syslog of the host where program was running, and could find this at around same time.

Feb  3 10:40:19 kernel: [20400.974129] traps: NIO-ELT-0-#0[11838] general protection ip:7f3e542c54a6 sp:7f3e4fbe1c00 error:0 in libc-2.28.so[7f3e54263000+148000]

Exit code: I have not installed this as a service, and this was running in background, so cant help with that..
the signals are in above git repo, mainly [SIGTERM, SIGSEGV, SIGINT, SIGILL, SIGABRT, SIGFPE]

[pankajsoni19]

I have not gone through the code, but the endpoint is plain http, why its ssl even in the code path?

[Lukasa]

Are you sure you aren't being redirected to a HTTPS endpoint? That would require us to establish a TLS state.

If the general protection log does match, my best guess here is that you ran out of memory. Do you have any memory statistics to verify this?

[pankajsoni19]

yes, the endpoint is http. the service has been deployed for more than a year.
Memory is more than 80% free on server. cpu usage reached max 5%. aws t3a.medium instance.

Same machine, older deployment works. I am attaching package.resolved for it.
package.resolved-old.txt

I compared the package differences. The issue seems really absurd.

[Lukasa]

Soto uses async http client and uses HTTPS. The crash is probably coming from there.

[Lukasa]

Do you have any additional logging from soto? It should be possible to correlate the crash with logs from soto, especially at these low loads.

[Lukasa]

Additionally, is it possible to run the server with lldb attached and wait for it to crash? This will give us vastly more diagnostic information: you can get a complete backtrace, as well as more information about what exact error occurred.