search

an-tao / trantor

a non-blocking I/O tcp network lib based on c++14/17
Other
390 stars 133 forks source link

Assertion `ssl_' failed #325

Closed Mis1eader-dev closed 6 months ago

Mis1eader-dev commented 6 months ago

A Drogon webserver with WebSockets has been crashing randomly from time to time, the TRACE logs contain the following:

20240229 09:02:23.470644 UTC 24915 TRACE [onHttpRequest] new request:<Hidden>:63375->10.19.0.5:443 - HttpServer.cc:345
20240229 09:02:23.470652 UTC 24915 TRACE [onHttpRequest] Headers POST /api/data/get - HttpServer.cc:347
20240229 09:02:23.470655 UTC 24915 TRACE [onHttpRequest] http path=/api/data/get - HttpServer.cc:348
20240229 09:02:23.470801 UTC 24915 TRACE [runTaskInQueue] move task into queue - ConcurrentTaskQueue.cc:42
20240229 09:02:23.470836 UTC 24731 TRACE [queueFunc] got a new task! - ConcurrentTaskQueue.cc:65
20240229 09:02:23.471001 UTC 24915 TRACE [renderToBuffer] response(no body):HTTP/1.1 200 OK
content-length: 158
content-type: application/json; charset=utf-8
access-control-allow-credentials: true
access-control-allow-origin: <Hidden>

 - HttpResponseImpl.cc:707
20240229 09:02:25.313576 UTC 24912 TRACE [sendWsData] send 0 bytes - WebSocketConnectionImpl.cc:73
20240229 09:02:25.385077 UTC 24912 TRACE [recvData] Received 28 bytes from lower layer - OpenSSLProvider.cc:536
20240229 09:02:25.385116 UTC 24912 TRACE [processApplicationData] Received 6 bytes from SSL - OpenSSLProvider.cc:747
20240229 09:02:25.385128 UTC 24912 TRACE [parse] data encoded! - WebSocketConnectionImpl.cc:291
20240229 09:02:25.657833 UTC 24913 TRACE [sendWsData] send 0 bytes - WebSocketConnectionImpl.cc:73
20240229 09:02:25.730819 UTC 24913 TRACE [recvData] Received 28 bytes from lower layer - OpenSSLProvider.cc:536
20240229 09:02:25.730859 UTC 24913 TRACE [processApplicationData] Received 6 bytes from SSL - OpenSSLProvider.cc:747
20240229 09:02:25.730867 UTC 24913 TRACE [parse] data encoded! - WebSocketConnectionImpl.cc:291
20240229 09:02:43.470979 UTC 24729 TRACE [~CacheMap] CacheMap destruct! - CacheMap.h:161
20240229 09:02:43.471045 UTC 24729 TRACE [~CacheMap] CacheMap destruct! - CacheMap.h:161
20240229 09:02:43.471081 UTC 24729 TRACE [~CacheMap] CacheMap destruct! - CacheMap.h:161
20240229 09:02:43.471118 UTC 24729 TRACE [~CacheMap] CacheMap destruct! - CacheMap.h:161
20240229 09:02:43.471145 UTC 24729 TRACE [~CacheMap] CacheMap destruct! - CacheMap.h:161
20240229 09:02:55.313692 UTC 24912 TRACE [sendWsData] send 0 bytes - WebSocketConnectionImpl.cc:73
20240229 09:02:55.388575 UTC 24912 TRACE [recvData] Received 28 bytes from lower layer - OpenSSLProvider.cc:536
20240229 09:02:55.388621 UTC 24912 TRACE [processApplicationData] Received 6 bytes from SSL - OpenSSLProvider.cc:747
20240229 09:02:55.388630 UTC 24912 TRACE [parse] data encoded! - WebSocketConnectionImpl.cc:291
20240229 09:02:55.658490 UTC 24913 TRACE [sendWsData] send 0 bytes - WebSocketConnectionImpl.cc:73
20240229 09:02:55.738012 UTC 24913 TRACE [recvData] Received 28 bytes from lower layer - OpenSSLProvider.cc:536
20240229 09:02:55.738055 UTC 24913 TRACE [processApplicationData] Received 6 bytes from SSL - OpenSSLProvider.cc:747
20240229 09:02:55.738063 UTC 24913 TRACE [parse] data encoded! - WebSocketConnectionImpl.cc:291
20240229 09:03:24.082473 UTC 24915 TRACE [handleClose] connection closed, fd=78 - TcpConnectionImpl.cc:276
20240229 09:03:24.082507 UTC 24915 TRACE [handleClose] write buffer size: 0 - TcpConnectionImpl.cc:277
20240229 09:03:24.082473 UTC 24913 TRACE [handleClose] connection closed, fd=76 - TcpConnectionImpl.cc:276
20240229 09:03:24.082514 UTC 24913 TRACE [handleClose] write buffer size: 0 - TcpConnectionImpl.cc:277
20240229 09:03:24.082529 UTC 24913 TRACE [onConnection] conn disconnected! - HttpServer.cc:118
20240229 09:03:24.082529 UTC 24915 TRACE [onConnection] conn disconnected! - HttpServer.cc:118
20240229 09:03:24.082557 UTC 24915 TRACE [handleClose] to call close callback - TcpConnectionImpl.cc:292
20240229 09:03:24.082557 UTC 24913 TRACE [handleClose] to call close callback - TcpConnectionImpl.cc:292
20240229 09:03:24.082561 UTC 24913 TRACE [connectionClosed] connectionClosed - TcpServer.cc:201
20240229 09:03:24.082561 UTC 24915 TRACE [connectionClosed] connectionClosed - TcpServer.cc:201
20240229 09:03:24.082641 UTC 24915 TRACE [handleClose] connection closed, fd=77 - TcpConnectionImpl.cc:276
20240229 09:03:24.082646 UTC 24915 TRACE [handleClose] write buffer size: 0 - TcpConnectionImpl.cc:277
20240229 09:03:24.082654 UTC 24915 TRACE [onConnection] conn disconnected! - HttpServer.cc:118
20240229 09:03:24.082660 UTC 24913 TRACE [handleClose] connection closed, fd=74 - TcpConnectionImpl.cc:276
20240229 09:03:24.082664 UTC 24913 TRACE [handleClose] write buffer size: 0 - TcpConnectionImpl.cc:277
20240229 09:03:24.082670 UTC 24915 TRACE [handleClose] to call close callback - TcpConnectionImpl.cc:292
20240229 09:03:24.082671 UTC 24913 TRACE [onConnection] conn disconnected! - HttpServer.cc:118
20240229 09:03:24.082672 UTC 24915 TRACE [connectionClosed] connectionClosed - TcpServer.cc:201
20240229 09:03:24.082680 UTC 24913 TRACE [handleClose] to call close callback - TcpConnectionImpl.cc:292
20240229 09:03:24.082683 UTC 24913 TRACE [connectionClosed] connectionClosed - TcpServer.cc:201
20240229 09:03:24.082736 UTC 24913 TRACE [~Socket] Socket deconstructed:76 - Socket.cc:245
20240229 09:03:24.082736 UTC 24915 TRACE [~Socket] Socket deconstructed:78 - Socket.cc:245
20240229 09:03:24.082813 UTC 24913 TRACE [~Socket] Socket deconstructed:74 - Socket.cc:245
20240229 09:03:24.082824 UTC 24915 TRACE [~Socket] Socket deconstructed:77 - Socket.cc:245
20240229 09:03:24.082855 UTC 24912 TRACE [handleClose] connection closed, fd=75 - TcpConnectionImpl.cc:276
20240229 09:03:24.082864 UTC 24912 TRACE [handleClose] write buffer size: 0 - TcpConnectionImpl.cc:277
20240229 09:03:24.082873 UTC 24912 TRACE [onConnection] conn disconnected! - HttpServer.cc:118
20240229 09:03:24.082886 UTC 24912 TRACE [handleClose] to call close callback - TcpConnectionImpl.cc:292
20240229 09:03:24.082889 UTC 24912 TRACE [connectionClosed] connectionClosed - TcpServer.cc:201
20240229 09:03:24.082937 UTC 24912 TRACE [~Socket] Socket deconstructed:75 - Socket.cc:245
20240229 09:03:25.313798 UTC 24912 TRACE [sendWsData] send 0 bytes - WebSocketConnectionImpl.cc:73
20240229 09:03:25.387629 UTC 24912 TRACE [recvData] Received 28 bytes from lower layer - OpenSSLProvider.cc:536
20240229 09:03:25.387667 UTC 24912 TRACE [processApplicationData] Received 6 bytes from SSL - OpenSSLProvider.cc:747
20240229 09:03:25.387676 UTC 24912 TRACE [parse] data encoded! - WebSocketConnectionImpl.cc:291
20240229 09:03:25.658600 UTC 24913 TRACE [sendWsData] send 0 bytes - WebSocketConnectionImpl.cc:73
20240229 09:03:25.746352 UTC 24913 TRACE [recvData] Received 28 bytes from lower layer - OpenSSLProvider.cc:536
20240229 09:03:25.746391 UTC 24913 TRACE [processApplicationData] Received 6 bytes from SSL - OpenSSLProvider.cc:747
20240229 09:03:25.746399 UTC 24913 TRACE [parse] data encoded! - WebSocketConnectionImpl.cc:291
20240229 09:03:55.313893 UTC 24912 TRACE [sendWsData] send 0 bytes - WebSocketConnectionImpl.cc:73
20240229 09:03:55.387386 UTC 24912 TRACE [recvData] Received 28 bytes from lower layer - OpenSSLProvider.cc:536
20240229 09:03:55.387454 UTC 24912 TRACE [processApplicationData] Received 6 bytes from SSL - OpenSSLProvider.cc:747
20240229 09:03:55.387482 UTC 24912 TRACE [parse] data encoded! - WebSocketConnectionImpl.cc:291
20240229 09:03:55.658698 UTC 24913 TRACE [sendWsData] send 0 bytes - WebSocketConnectionImpl.cc:73
20240229 09:03:55.743083 UTC 24913 TRACE [recvData] Received 28 bytes from lower layer - OpenSSLProvider.cc:536
20240229 09:03:55.743123 UTC 24913 TRACE [processApplicationData] Received 6 bytes from SSL - OpenSSLProvider.cc:747
20240229 09:03:55.743131 UTC 24913 TRACE [parse] data encoded! - WebSocketConnectionImpl.cc:291
20240229 09:04:25.314001 UTC 24912 TRACE [sendWsData] send 0 bytes - WebSocketConnectionImpl.cc:73
20240229 09:04:25.389970 UTC 24912 TRACE [recvData] Received 28 bytes from lower layer - OpenSSLProvider.cc:536
20240229 09:04:25.390017 UTC 24912 TRACE [processApplicationData] Received 6 bytes from SSL - OpenSSLProvider.cc:747
20240229 09:04:25.390027 UTC 24912 TRACE [parse] data encoded! - WebSocketConnectionImpl.cc:291
20240229 09:04:25.658847 UTC 24913 TRACE [sendWsData] send 0 bytes - WebSocketConnectionImpl.cc:73
20240229 09:04:25.762248 UTC 24913 TRACE [recvData] Received 28 bytes from lower layer - OpenSSLProvider.cc:536
20240229 09:04:25.762296 UTC 24913 TRACE [processApplicationData] Received 6 bytes from SSL - OpenSSLProvider.cc:747
20240229 09:04:25.762319 UTC 24913 TRACE [parse] data encoded! - WebSocketConnectionImpl.cc:291
20240229 09:04:49.730472 UTC 24912 TRACE [newConnection] new connection:fd=74 address=172.104.20.247:61000 - TcpServer.cc:62
20240229 09:04:49.730531 UTC 24912 TRACE [TcpConnectionImpl] new connection:172.104.20.247:61000->138.68.65.191:443 - TcpConnectionImpl.cc:78
20240229 09:04:55.658911 UTC 24913 TRACE [sendWsData] send 0 bytes - WebSocketConnectionImpl.cc:73
20240229 09:04:55.748443 UTC 24913 TRACE [recvData] Received 28 bytes from lower layer - OpenSSLProvider.cc:536
20240229 09:04:55.748491 UTC 24913 TRACE [processApplicationData] Received 6 bytes from SSL - OpenSSLProvider.cc:747
20240229 09:04:55.748500 UTC 24913 TRACE [parse] data encoded! - WebSocketConnectionImpl.cc:291
20240229 09:05:06.782158 UTC 24915 TRACE [newConnection] new connection:fd=75 address=<Hidden>:61376 - TcpServer.cc:62
20240229 09:05:06.782206 UTC 24915 TRACE [TcpConnectionImpl] new connection:<Hidden>:61376->10.19.0.5:443 - TcpConnectionImpl.cc:78

And in stdout we noticed the following:

our-server: /home/our-user/our-server/drogon/trantor/trantor/net/inner/tlsprovider/OpenSSLProvider.cc:481: OpenSSLProvider::OpenSSLProvider(trantor::TcpConnection*, trantor::TLSPolicyPtr, trantor::SSLContextPtr): Assertion `ssl_' failed.
our-server: /home/our-user/our-server/drogon/trantor/trantor/net/inner/tlsprovider/OpenSSLProvider.cc:481: OpenSSLProvider::OpenSSLProvider(trantor::TcpConnection*, trantor::TLSPolicyPtr, trantor::SSLContextPtr): Assertion `ssl_' failed.
our-server: /home/our-user/our-server/drogon/trantor/trantor/net/inner/tlsprovider/OpenSSLProvider.cc:481: OpenSSLProvider::OpenSSLProvider(trantor::TcpConnection*, trantor::TLSPolicyPtr, trantor::SSLContextPtr): Assertion `ssl_' failed.

What might be the problem?

Edit: The IP 172.104.20.247 has been kept intentionally, it has been trying to connect before with a different IP, and I believe it is the one causing this crash.

an-tao commented 6 months ago

Can you print the call stack from the dumped core file during a crash?

Mis1eader-dev commented 6 months ago

I believe core dumps are disabled by default on Ubuntu, I'll enable it and wait for that malicious user or bot to crash the server again

Mis1eader-dev commented 6 months ago

I haven't encountered this crash again, I had fixed an issue from the /api/data/get endpoint and it no longer crashes on the assert. Closing as a false positive.