Welcome to the wolfSSL Forums!

carlo · 2020-06-24 13:58:13

carlo
Member
Offline

Registered: 2020-06-15
Posts: 21

Topic: My first successful connect (handshake)!

Full debug output...

daniel:~/projects/aicxx/ai-evio-testsuite/ai-evio-testsuite/src>tls_socket
WARNING : core size is limited (hard limit: 0 kb).  Core dumps might be truncated!
THREADPOOL    : Entering add_threads(30)
ThreadPool00    NOTICE        : Thread started. Set debug margin to "ThreadPool00    ".
ThreadPool01    NOTICE        : Thread started. Set debug margin to "ThreadPool01    ".
ThreadPool02    NOTICE        : Thread started. Set debug margin to "ThreadPool02    ".
ThreadPool03    NOTICE        : Thread started. Set debug margin to "ThreadPool03    ".
ThreadPool04    NOTICE        : Thread started. Set debug margin to "ThreadPool04    ".
ThreadPool05    NOTICE        : Thread started. Set debug margin to "ThreadPool05    ".
ThreadPool07    NOTICE        : Thread started. Set debug margin to "ThreadPool07    ".
ThreadPool06    NOTICE        : Thread started. Set debug margin to "ThreadPool06    ".
ThreadPool08    NOTICE        : Thread started. Set debug margin to "ThreadPool08    ".
ThreadPool09    NOTICE        : Thread started. Set debug margin to "ThreadPool09    ".
ThreadPool10    NOTICE        : Thread started. Set debug margin to "ThreadPool10    ".
ThreadPool11    NOTICE        : Thread started. Set debug margin to "ThreadPool11    ".
ThreadPool12    NOTICE        : Thread started. Set debug margin to "ThreadPool12    ".
ThreadPool13    NOTICE        : Thread started. Set debug margin to "ThreadPool13    ".
ThreadPool14    NOTICE        : Thread started. Set debug margin to "ThreadPool14    ".
ThreadPool15    NOTICE        : Thread started. Set debug margin to "ThreadPool15    ".
ThreadPool16    NOTICE        : Thread started. Set debug margin to "ThreadPool16    ".
ThreadPool17    NOTICE        : Thread started. Set debug margin to "ThreadPool17    ".
ThreadPool19    NOTICE        : Thread started. Set debug margin to "ThreadPool19    ".
ThreadPool18    NOTICE        : Thread started. Set debug margin to "ThreadPool18    ".
ThreadPool20    NOTICE        : Thread started. Set debug margin to "ThreadPool20    ".
ThreadPool21    NOTICE        : Thread started. Set debug margin to "ThreadPool21    ".
ThreadPool22    NOTICE        : Thread started. Set debug margin to "ThreadPool22    ".
ThreadPool23    NOTICE        : Thread started. Set debug margin to "ThreadPool23    ".
ThreadPool24    NOTICE        : Thread started. Set debug margin to "ThreadPool24    ".
ThreadPool25    NOTICE        : Thread started. Set debug margin to "ThreadPool25    ".
ThreadPool26    NOTICE        : Thread started. Set debug margin to "ThreadPool26    ".
ThreadPool27    NOTICE        : Thread started. Set debug margin to "ThreadPool27    ".
ThreadPool29    NOTICE        : Thread started. Set debug margin to "ThreadPool29    ".
THREADPOOL    : Entering AIThreadPool::new_queue(16, 1)
ThreadPool28    NOTICE        : Thread started. Set debug margin to "ThreadPool28    ".
THREADPOOL    :   Returning index #0; size is now 1 for utils::Vector<AIThreadPool::PriorityQueue, utils::VectorIndex<ordering_category::QueueHandle>, std::allocator<AIThreadPool::PriorityQueue> > at 0x7ffeacb27578
ThreadPool06    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool08    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool24    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool07    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool22    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool27    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool17    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool11    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool20    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool05    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool28    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool12    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool01    THREADPOOL    : Beginning of thread pool main loop (q = #0)
EVIO          : Entering EventLoop::EventLoop(#0)
EVIO          :   Entering EventLoopThread::init(#0)
ThreadPool16    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool02    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool04    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool00    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool23    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool21    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool03    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool13    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool18    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool10    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool09    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool15    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool26    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool25    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool29    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool19    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool14    THREADPOOL    : Beginning of thread pool main loop (q = #0)
EventLoopThr    NOTICE        : Thread started. Set debug margin to "EventLoopThr    ".
EventLoopThr    EVIO          : Entering EventLoopThread::emain() [no indentation]
EventLoopThr    SYSTEM        : epoll_create1(EPOLL_CLOEXEC) = 14
EventLoopThr    NOTICE        : Entering Signals::unblock(sigmask, 34, 0x55a873a79ae0)
EventLoopThr    NOTICE        :   Entering Signals::register_callback(34, 0x55a873a79ae0)
EventLoopThr    SYSTEM        : epoll_pwait() = <unfinished>
EVIO          : Entering evio::create<evio::TLSSocket>()
EVIO          :   Entering InputDevice::InputDevice() [FD:0x55a875899140]
EVIO          :   Entering OutputDevice::OutputDevice() [FD:0x55a875899140]
EVIO          :   Entering Socket::Socket() [FD:0x55a875899140]
TLS           :   Entering TLS::TLS() [0x55a8758990a0]
TLS           :     Entering evio::protocol::TLS::global_tls_initialization()
TLS           :       wolfSSL_Init() = SSL_SUCCESS
TLS           :       wolfSSL_CTX_new(wolfTLS_client_method()) = 0x55a875899270
TLS           :       wolfSSL_CTX_SetMinVersion(0x55a875899270, WOLFSSL_TLSV1_2) = SSL_SUCCESS
TLS           :       wolfSSL_CTX_load_verify_locations(s_context, "/etc/ssl/cert.pem", NULL) = SSL_SUCCESS
TLS           :       wolfSSL_CTX_load_verify_locations(s_context, "/usr/src/AUR/wolfssl/wolfssl-examples-git/certs/ca-cert.pem", NULL) = SSL_SUCCESS
EVIO          :   Returning device pointer 0x55a875898fc0 [FD:0x55a875899140].
EVIO          : Entering OutputDevice::set_source<>(0x7ffeacb27320) [FD:0x55a875899140]
EVIO          :   Entering OutputStream::create_buffer(FD:0x55a875899140, 1048320, 18446744073709551615)
IO            :     Entering StreamBuf(131040, 1048320, 18446744073709551615) [0x55a8758d64c0]
EVIO          :       StreamBufProducer::create: allocating new memory block of size 131040
EVIO          : Entering InputDevice::set_sink<>(0x7ffeacb272b8) [FD:0x55a875899140]
EVIO          :   Entering InputDecoder::create_buffer(FD:0x55a875899140, 65280, 18446744073709551615)
IO            :     Entering StreamBuf(8160, 65280, 18446744073709551615) [0x55a8758d6590]
EVIO          :       StreamBufProducer::create: allocating new memory block of size 8160
EVIO          : Entering TLS::set_device(FD:0x55a875899140, FD:0x55a875899140)
EVIO          : Entering Socket::connect(127.0.0.1:11111, 0, 0, AF_UNSPEC) [FD:0x55a875899140]
SYSTEM        :   socket(2, SOCK_STREAM | SOCK_NONBLOCK | SOCK_CLOEXEC, 0) = 15
NOTICE        :   Setting receive buffer size for socket 15 to 8160 bytes.
SYSTEM        :   setsockopt(15, SOL_SOCKET, SO_RCVBUF, {8160}, 4) = 0
NOTICE        :   Setting send buffer size for socket 15 to 131040 bytes.
SYSTEM        :   setsockopt(15, SOL_SOCKET, SO_SNDBUF, {131040}, 4) = 0
SYSTEM        :   connect(15, 127.0.0.1:11111, 16) = -1: EINPROGRESS (Operation now in progress)
EVIO          :   Entering FileDescriptor::init(15) [FD:0x55a875899140]
EVIO          :     Entering InputDevice::init_input_device() [FD:0x55a875899140]
IO            :     Entering OutputDevice::init_output_device() [FD:0x55a875899140]
EVIO          :   Entering InputDevice::start_input_device({{m_flags:FDS_RW|FDS_R_OPEN|FDS_W_OPEN|FDS_SAME, m_epoll_event:{events:, data:FD:0x55a875899140}}}) [FD:0x55a875899140]
EVIO          :     Entering EventLoopThread::start({m_flags:FDS_RW|FDS_R_OPEN|FDS_W_OPEN|FDS_SAME, m_epoll_event:{events:, data:FD:0x55a875899140}}, 32, FD:0x55a875899140)
EVIO          :       Incremented m_active to 1
EVIO          :       Incremented ref count (now 4) [FD:0x55a875899140]
SYSTEM        :       epoll_ctl(14, EPOLL_CTL_ADD, 15, {{events:EPOLLIN|EPOLLET, data:FD:0x55a875899140}}) = 0
EVIO          : Entering OutputDevice::start_output_device({m_flags:FDS_RW|FDS_R_OPEN|FDS_W_OPEN|FDS_SAME|FDS_R_ADDED|FDS_R_ACTIVE, m_epoll_event:{events:EPOLLIN|EPOLLET, data:FD:0x55a875899140}}) [FD:0x55a875899140]
EVIO          :   Entering EventLoopThread::start({m_flags:FDS_RW|FDS_R_OPEN|FDS_W_OPEN|FDS_SAME|FDS_R_ADDED|FDS_R_ACTIVE, m_epoll_event:{events:EPOLLIN|EPOLLET, data:FD:0x55a875899140}}, 128, FD:0x55a875899140)
EVIO          :     Incremented m_active to 2
SYSTEM        :     epoll_ctl(14, EPOLL_CTL_MOD, 15, {{events:EPOLLIN|EPOLLOUT|EPOLLET, data:FD:0x55a875899140}}) = 0
EVIO          : Entering StreamBuf::xsputn_a("GET /\r\n", 7) [0x55a8758d64c0] = 7
EVIO          : Entering TLSSocket::sync()
EventLoopThr    SYSTEM        : <continued> 1
TLS           :   m_session_state == preconnect
EventLoopThr    EVIO          : epoll_pwait new event(s): EPOLLOUT
IO            : Decremented ref count of device FD:0x55a875899140 to 3
EVIO          : Entering EventLoop::~EventLoop()
EventLoopThr    EVIO          : Queuing I/O event EPOLLOUT for FD:0x55a875899140 in thread pool queue #0
EVIO          :   Entering EventLoopThread::terminate(1)
EventLoopThr    SYSTEM        : epoll_pwait() = <unfinished>
EVIO          :     Sending wake-up signal 34
ThreadPool06    THREADPOOL    : Beginning of thread pool main loop (q = #0)
EventLoopThr    SYSTEM        :     FD:0x55a875899140: 15, FDS_RW|FDS_R_OPEN|FDS_W_OPEN|FDS_SAME|FDS_R_ADDED|FDS_W_ADDED|FDS_R_ACTIVE|FDS_W_ACTIVE
EVIO          :     Joining m_event_thread... <unfinished>
ThreadPool06    THREADPOOL    : Not going idle.
EventLoopThr    SYSTEM        : <continued> -1: EINTR (Interrupted system call)
ThreadPool06    EVIO          : Beginning of handling event EPOLLOUT for FD:0x55a875899140.
EventLoopThr    SYSTEM        : epoll_pwait() = <unfinished>
ThreadPool06    EVIO          : Entering TLSSocket::write_to_fd({1}, 15) [FD:0x55a875899140]
ThreadPool06    EVIO          :   m_session_state == preconnect
EventLoopThr    SYSTEM        :     FD:0x55a875899140: 15, FDS_RW|FDS_R_OPEN|FDS_W_OPEN|FDS_SAME|FDS_R_ADDED|FDS_W_ADDED|FDS_R_ACTIVE|FDS_W_ACTIVE
ThreadPool06    TLS           :   Entering TLS::session_init("www.google.com")
ThreadPool06    TLS           :     wolfSSL_new(0x55a875899270) = 0x7f14bc0018d0
ThreadPool06    TLS           :   wolfSSL_set_fd(0x7f14bc0018d0, 15) = SSL_SUCCESS
ThreadPool06    EVIO          :   session_state = handshake_want_write
ThreadPool06    TLS           :   wolfSSL_connect(0x7f14bc0018d0) = SSL_FATAL_ERROR (WOLFSSL_ERROR_WANT_READ: non-blocking socket wants data to be read)
ThreadPool06    TLS           :   wolfSSL_want_read(0x7f14bc0018d0) returned true.
ThreadPool06    EVIO          :   Entering OutputDevice::stop_output_device({1}) [FD:0x55a875899140]
ThreadPool06    SYSTEM        :     epoll_ctl(14, EPOLL_CTL_MOD, 15, {{events:EPOLLIN|EPOLLET, data:FD:0x55a875899140}}) = 0
ThreadPool06    EVIO          :     Decremented m_active to 1
ThreadPool06    EVIO          :     flags are now: FDS_RW|FDS_R_OPEN|FDS_W_OPEN|FDS_SAME|FDS_R_ADDED|FDS_W_ADDED|FDS_R_ACTIVE
ThreadPool06    EVIO          :   session_state == handshake_want_read
ThreadPool06    TLS           :   Set m_session_state to session_state (handshake_want_read).
ThreadPool06    EVIO          : Entering FileDescriptor::clear_pending_output_events(14, EPOLLOUT) [FD:0x55a875899140] returning new events: none
ThreadPool06    IO            : Decremented ref count of device FD:0x55a875899140 to 3
ThreadPool06    THREADPOOL    : task() returned 0
ThreadPool06    THREADPOOL    : Beginning of thread pool main loop (q = #0)
EventLoopThr    SYSTEM        : <continued> 1
EventLoopThr    EVIO          : epoll_pwait new event(s): EPOLLIN
EventLoopThr    EVIO          : Queuing I/O event EPOLLIN for FD:0x55a875899140 in thread pool queue #0
ThreadPool06    THREADPOOL    : Beginning of thread pool main loop (q = #0)
EventLoopThr    SYSTEM        : epoll_pwait() = <unfinished>
ThreadPool06    THREADPOOL    : Not going idle.
ThreadPool06    EVIO          : Beginning of handling event EPOLLIN for FD:0x55a875899140.
EventLoopThr    SYSTEM        :     FD:0x55a875899140: 15, FDS_RW|FDS_R_OPEN|FDS_W_OPEN|FDS_SAME|FDS_R_ADDED|FDS_W_ADDED|FDS_R_ACTIVE
ThreadPool06    EVIO          : Entering TLSSocket::read_from_fd({1}, 15) [FD:0x55a875899140]
ThreadPool06    TLS           :   m_session_state == handshake_want_read
EventLoopThr    SYSTEM        : <continued> 1
EventLoopThr    EVIO          : epoll_pwait event(s) EPOLLIN of fd FD:0x55a875899140 ignored because the event(s) EPOLLIN is/are already being handled by the thread pool.
EventLoopThr    SYSTEM        : epoll_pwait() = <unfinished>
EventLoopThr    SYSTEM        :     FD:0x55a875899140: 15, FDS_RW|FDS_R_OPEN|FDS_W_OPEN|FDS_SAME|FDS_R_ADDED|FDS_W_ADDED|FDS_R_ACTIVE
ThreadPool06    TLS           :   wolfSSL_connect(0x7f14bc0018d0) = SSL_FATAL_ERROR (WOLFSSL_ERROR_WANT_READ: non-blocking socket wants data to be read)
ThreadPool06    TLS           :   wolfSSL_want_read(0x7f14bc0018d0) returned true.
ThreadPool06    EVIO          : Entering FileDescriptor::clear_pending_input_event(14) [FD:0x55a875899140]
ThreadPool06    SYSTEM        :   epoll_ctl(14, EPOLL_CTL_MOD, 15, {{events:EPOLLIN|EPOLLET, data:FD:0x55a875899140}}) = 0
ThreadPool06    IO            : Decremented ref count of device FD:0x55a875899140 to 3
ThreadPool06    THREADPOOL    : task() returned 0
ThreadPool06    THREADPOOL    : Beginning of thread pool main loop (q = #0)
EventLoopThr    SYSTEM        : <continued> 1
EventLoopThr    EVIO          : epoll_pwait new event(s): EPOLLIN
EventLoopThr    EVIO          : Queuing I/O event EPOLLIN for FD:0x55a875899140 in thread pool queue #0
EventLoopThr    SYSTEM        : epoll_pwait() = <unfinished>
ThreadPool06    THREADPOOL    : Beginning of thread pool main loop (q = #0)
ThreadPool06    THREADPOOL    : Not going idle.
EventLoopThr    SYSTEM        :     FD:0x55a875899140: 15, FDS_RW|FDS_R_OPEN|FDS_W_OPEN|FDS_SAME|FDS_R_ADDED|FDS_W_ADDED|FDS_R_ACTIVE
ThreadPool06    EVIO          : Beginning of handling event EPOLLIN for FD:0x55a875899140.
EventLoopThr    SYSTEM        : <continued> 1
ThreadPool06    EVIO          : Entering TLSSocket::read_from_fd({1}, 15) [FD:0x55a875899140]
EventLoopThr    EVIO          : epoll_pwait event(s) EPOLLIN of fd FD:0x55a875899140 ignored because the event(s) EPOLLIN is/are already being handled by the thread pool.
ThreadPool06    TLS           :   m_session_state == handshake_want_read
EventLoopThr    SYSTEM        : epoll_pwait() = <unfinished>
EventLoopThr    SYSTEM        :     FD:0x55a875899140: 15, FDS_RW|FDS_R_OPEN|FDS_W_OPEN|FDS_SAME|FDS_R_ADDED|FDS_W_ADDED|FDS_R_ACTIVE
ThreadPool06    TLS           :   wolfSSL_connect(0x7f14bc0018d0) = SSL_FATAL_ERROR (WOLFSSL_ERROR_WANT_READ: non-blocking socket wants data to be read)
ThreadPool06    TLS           :   wolfSSL_want_read(0x7f14bc0018d0) returned true.
ThreadPool06    EVIO          : Entering FileDescriptor::clear_pending_input_event(14) [FD:0x55a875899140]
ThreadPool06    SYSTEM        :   epoll_ctl(14, EPOLL_CTL_MOD, 15, {{events:EPOLLIN|EPOLLET, data:FD:0x55a875899140}}) = 0
ThreadPool06    IO            : Decremented ref count of device FD:0x55a875899140 to 3
ThreadPool06    THREADPOOL    : task() returned 0
ThreadPool06    THREADPOOL    : Beginning of thread pool main loop (q = #0)
EventLoopThr    SYSTEM        : <continued> 1
EventLoopThr    EVIO          : epoll_pwait new event(s): EPOLLIN
EventLoopThr    EVIO          : Queuing I/O event EPOLLIN for FD:0x55a875899140 in thread pool queue #0
ThreadPool06    THREADPOOL    : Beginning of thread pool main loop (q = #0)
EventLoopThr    SYSTEM        : epoll_pwait() = <unfinished>
ThreadPool06    THREADPOOL    : Not going idle.
ThreadPool06    EVIO          : Beginning of handling event EPOLLIN for FD:0x55a875899140.
ThreadPool06    EVIO          : Entering TLSSocket::read_from_fd({1}, 15) [FD:0x55a875899140]
EventLoopThr    SYSTEM        :     FD:0x55a875899140: 15, FDS_RW|FDS_R_OPEN|FDS_W_OPEN|FDS_SAME|FDS_R_ADDED|FDS_W_ADDED|FDS_R_ACTIVE
ThreadPool06    TLS           :   m_session_state == handshake_want_read
EventLoopThr    SYSTEM        : <continued> 1
EventLoopThr    EVIO          : epoll_pwait event(s) EPOLLIN of fd FD:0x55a875899140 ignored because the event(s) EPOLLIN is/are already being handled by the thread pool.
EventLoopThr    SYSTEM        : epoll_pwait() = <unfinished>
EventLoopThr    SYSTEM        :     FD:0x55a875899140: 15, FDS_RW|FDS_R_OPEN|FDS_W_OPEN|FDS_SAME|FDS_R_ADDED|FDS_W_ADDED|FDS_R_ACTIVE
ThreadPool06    TLS           :   wolfSSL_connect(0x7f14bc0018d0) = SSL_SUCCESS
ThreadPool06    EVIO          :   Entering OutputDevice::start_output_device({m_flags:FDS_RW|FDS_R_OPEN|FDS_W_OPEN|FDS_SAME|FDS_R_ADDED|FDS_W_ADDED|FDS_R_ACTIVE, m_epoll_event:{events:EPOLLIN|EPOLLET, data:FD:0x55a875899140}}, {FuzzyCondition: before: fuzzy::True, after: fuzzy::True}) [FD:0x55a875899140]
ThreadPool06    COREDUMP      :     /home/carlo/projects/aicxx/ai-evio-testsuite/ai-evio-testsuite/evio/OutputDevice.cxx:112: bool evio::OutputDevice::start_output_device(const state_t::wat &, const utils::FuzzyCondition &): Assertion `condition.is_transitory_true()' failed.

Or, if you rather just see the wolfssl calls - look at the debug channel 'TLS':

TLS           :       wolfSSL_Init() = SSL_SUCCESS
TLS           :       wolfSSL_CTX_new(wolfTLS_client_method()) = 0x55a36e17bf20
TLS           :       wolfSSL_CTX_SetMinVersion(0x55a36e17bf20, WOLFSSL_TLSV1_2) = SSL_SUCCESS
TLS           :       wolfSSL_CTX_load_verify_locations(s_context, "/etc/ssl/cert.pem", NULL) = SSL_SUCCESS
TLS           :       wolfSSL_CTX_load_verify_locations(s_context, "/usr/src/AUR/wolfssl/wolfssl-examples-git/certs/ca-cert.pem", NULL) = SSL_SUCCESS
ThreadPool19    TLS           :     wolfSSL_new(0x55a36e17bf20) = 0x7fcaac0018d0
ThreadPool19    TLS           :   wolfSSL_set_fd(0x7fcaac0018d0, 15) = SSL_SUCCESS
ThreadPool19    TLS           :   wolfSSL_connect(0x7fcaac0018d0) = SSL_FATAL_ERROR (WOLFSSL_ERROR_WANT_READ: non-blocking socket wants data to be read)
ThreadPool19    TLS           :   wolfSSL_want_read(0x7fcaac0018d0) returned true.
ThreadPool19    TLS           :   wolfSSL_connect(0x7fcaac0018d0) = SSL_FATAL_ERROR (WOLFSSL_ERROR_WANT_READ: non-blocking socket wants data to be read)
ThreadPool19    TLS           :   wolfSSL_want_read(0x7fcaac0018d0) returned true.
ThreadPool19    TLS           :   wolfSSL_connect(0x7fcaac0018d0) = SSL_FATAL_ERROR (WOLFSSL_ERROR_WANT_READ: non-blocking socket wants data to be read)
ThreadPool19    TLS           :   wolfSSL_want_read(0x7fcaac0018d0) returned true.
ThreadPool19    TLS           :   wolfSSL_connect(0x7fcaac0018d0) = SSL_FATAL_ERROR (WOLFSSL_ERROR_WANT_READ: non-blocking socket wants data to be read)
ThreadPool19    TLS           :   wolfSSL_want_read(0x7fcaac0018d0) returned true.
ThreadPool19    TLS           :   wolfSSL_connect(0x7fcaac0018d0) = SSL_FATAL_ERROR (WOLFSSL_ERROR_WANT_READ: non-blocking socket wants data to be read)
ThreadPool19    TLS           :   wolfSSL_want_read(0x7fcaac0018d0) returned true.
ThreadPool19    TLS           :   wolfSSL_connect(0x7fcaac0018d0) = SSL_SUCCESS

carlo · 2020-06-24 14:27:57

carlo
Member
Offline

Registered: 2020-06-15
Posts: 21

Re: My first successful connect (handshake)!

I thought this output looks rather strange: `wolfSSL_connect` exclusively returns `WOLFSSL_ERROR_WANT_READ`.

Even after the first time I already stop monitoring the fd for writability.

I suppose therefore that the following is happening:
Upon the first call to `wolfSSL_connect` it calls send() and then recv() (which obviously fails),
then when there is something to read on the fd I call `wolfSSL_connect` again which now
reads the server reply and immediately writes something back to the socket (which happens
to succeed).

I am not sure I'm happy with this behavior... This means namely that I'm writing with the wrong
thread; I am using one thread to handle a writable socket and one thread to handle a readable
socket (one at a time), so that there is always at most one thread reading and at most one
thread writing.

If my socket is readable then the "read thread" calls `wolfSSL_connect` - if that subsequently
writes to the socket then that kinda messes up my thread-safety design

I can't think how this could lead to problems currently, because if `wolfSSL_connect` returns
`WANT_READ` I stop monitoring the socket for writability, which basically should make it
impossible that the 'write thread' start running for this socket.

However, I am assuming that it can also happen the other way around:

1) `wolfSSL_connect` tries to send(), but it fails to write all the bytes that it needs to write,
probably calls send() again(?) which blocks returns EAGAIN, and returns WANT_WRITE.
2) Now I am monitoring the socket (still) for readability and writability; the socket becomes
writable again and the 'write thread' calls `wolfSSL_connect`.
3) This time `wolfSSL_connect` manages to write everything - and (assumingly) immediately
continues with a call to recv() (as it would do in the non-blocking case).
4) The socket becomes readable - now the 'read thread' calls `wolfSSL_connect` too.

Ok, at least it is clear that my program would be violating something in that case: as long
as the 'write thread' didn't return yet from `wolfSSL_connect` I am not allowed to call it
from the `read thread`. However, I can not block -ever- my threads run till there is nothing
to do.

So, this means that in this situation my `read thread` can't do anything: it can't read the socket,
because the `write thread` is still inside `wolfSSL_connect`. I can't do nothing either though:
if the thread just returns then it will *immediately* return because the fd is still readable, causing
100% CPU usage, which is even worse than blocking (on a mutex). So now I need to stop
monitoring the fd for readability and then return.

Also I will have to keep track, in a thread-safe way, if some thread is inside `wolfSSL_connect`.

I guess I'll use my std::atomic<session_state_type> variable for that, which currently only
tracks what the last return value of `wolfSSL_connect` was - but that is not enough when
`wolfSSL_connect` calls read and/or write without regard for natural epoll synchronization .

Kaleb J. Himes · 2020-06-25 09:24:54

Kaleb J. Himes
Moderator
Offline

From: Bozeman
Registered: 2014-05-09
Posts: 777

Re: My first successful connect (handshake)!

carlo,

Thanks for your noted concerns. Due to the embedded design of the library we have a single I/O buffer. Since TLS packets can be anywhere from a few kilobytes up to 16kb we did not want to force users in constrained environments to have to set aside 32kb for reading and writing by default.

Since there is only one buffer for I/O this means that calls to wolfSSL_read() and wolfSSL_write must be mutex protected to avoid read and write calls stomping on eachother. One may not assume read/write separation until post handshake. (This is covered in the wolfSSL manual chapter 9 on "Thread Safety" https://www.wolfssl.com/docs/wolfssl-manual/ch9/)

Once the handshake is completed if there is a desire to handle reading and writing from separate threads we offer a feature called "write duplicate" so that users can make a COPY of the SSL_OBJECT and use the copy only for writing and the original only for reading.

We provide an example of setting up a duplicate SSL object here: https://github.com/wolfSSL/wolfssl-exam … writedup.c

Please let us know if this helps with the above concerns!

Warm Regards,

K

carlo · 2020-06-26 14:19:21

carlo
Member
Offline

Registered: 2020-06-15
Posts: 21

Re: My first successful connect (handshake)!

Hi Kaleb,

my remarks were exclusively about wolfSSL_connect, aka - the handshake. I already know that I'm not allowed to call that concurrently. It still poses the problem as stated, since I can't use a mutex.

Thanks for pointing me to `wolfSSL_write_dup` again, I will surely use that post-handshake even though that means I will have to include wolfSSL into my project because of the non-default configuration that it requires.

In the mean time I intercepted the actual reads and writes from/to the socket for more debug output!

So we can better see what is going on (just for fun):

daniel:~/projects/aicxx/ai-evio-testsuite/ai-evio-testsuite/src>tls_socket | egrep ' TLS '          
WARNING : core size is limited (hard limit: 0 kb).  Core dumps might be truncated!
ThreadPool20    TLS           :   Entering TLS::session_init("localhost")
ThreadPool20    TLS           :     wolfSSL_new(0x55d9f66c9120) = 0x7f87bc0018d0
ThreadPool20    TLS           :   wolfSSL_connect((WOLFSSL*)0x7f87bc0018d0) = <unfinished>
ThreadPool20    TLS           :         send(15, "\x16\x03\x03\x01;\x01\x00\x017\x03\x03\xBA\xE8\xE5\x11VD\x8B\xC0\xDE\xE9\t\xFC\xB8\xEAl\xFE28\xF1\x14\xA4\xED\xA5c\x97\xFA-\xED\xD5j\xCB\xAB\x00\x00X\x13\x01\x13\x02\x13\x03\x13\x04\x13\x05\xC0\xB4\xC0\xB5\xC0,\xC0+\xC00\xC0/\x00\x9F\x00\x9E\xCC\xA9\xCC\xA8\xCC\xAA\xC0'\xC0#\xC0(\xC0$\xC0\n\xC0\t\xC0\a\xC0\b\xC0\x14\xC0\x13\xC0\x11\xC0\x12\xC0\xAC\xC0\xAE\xC0\xAF\x00k\x00g\x009\x003\x00\x16\xCC\x14\xCC\x13\xCC\x15\xC0\x06\x00E\x00\x88\x00\xBE\x00\xC4\x01\x00\x00\xB6\x003\x00G\x00E\x00\x17\x00A\x04\x1F\xFDy'd\xA8;\xEA$\xE8\x1A\x06}\x8E\xF6\xCEYS\x183<\t\x99\xF2E\xA4t\x1F\x7FV<\rM\xCAv\xC6|]Z\xC6@Sl\xD8\e\xFEo\x9E(\xE91\xBF!\xBF\b\xDD\x13\xD9\xB7\xEA1\xD4\xBF(\x00+\x00\t\b\x03\x04\x03\x03\x03\x02\x03\x01\x00\r\x00\"\x00 \x06\x03\x05\x03\x04\x03\x02\x03\b\a\b\x06\b\v\b\x05\b\n\b\x04\b\t\x06\x01\x05\x01\x04\x01\x03\x01\x02\x01\x00\v\x00\x02\x01\x00\x00\n\x00&\x00$\x00\x19\x00\x1C\x00\x18\x00\e\x00\x1E\x00\x17\x00\x16\x00\x1A\x00\x1D\x00\x15\x00\x14\x00\x13\x00\x12\x00\x10\x00\x11\x00\x0F\x01\x01\x01\x00\x00\x16\x00\x00\x00\x17\x00\x00", 320, 0) = 320
ThreadPool20    TLS           :         recv(15, 0x7f87bc001b90, 5, 0) = -1
ThreadPool20    TLS           :   <continued> -1 (WOLFSSL_ERROR_WANT_READ: non-blocking socket wants data to be read)
ThreadPool20    TLS           :   wolfSSL_want_read((WOLFSSL*)0x7f87bc0018d0) returned true.
ThreadPool20    TLS           :   Set m_session_state to session_state (handshake_want_read).
ThreadPool20    TLS           :   m_session_state == handshake_want_read
ThreadPool20    TLS           :   wolfSSL_connect((WOLFSSL*)0x7f87bc0018d0) = <unfinished>
ThreadPool20    TLS           :         recv(15, {"\x16\x03\x03\x00Z"}, 5, 0) = 5
ThreadPool20    TLS           :         recv(15, {"\x02\x00\x00V\x03\x03\xB9\xE7\\\xAC\xBB\x82\x97\xB0\x05\x81\x06\xAD\x11\xF3\xCFl\x93\x90\xA1\xA6\a\x95\xDC\xB1\xC92\x81\x03\xCE\x8C\xB7\xA6 \xE5\xCF\xC1\x1E\x97.\xFB.\xAA@9W\xD1S\x968dKjL\xF5<\x84\x98\\\x88\xD5\xAC\xE3`Y\x0F\xC00\x00\x00\x0E\x00\x16\x00\x00\x00\v\x00\x02\x01\x00\x00\x17\x00\x00"}, 90, 0) = 90
ThreadPool20    TLS           :         recv(15, 0x7f87bc001b90, 5, 0) = -1
ThreadPool20    TLS           :   <continued> -1 (WOLFSSL_ERROR_WANT_READ: non-blocking socket wants data to be read)
ThreadPool20    TLS           :   wolfSSL_want_read((WOLFSSL*)0x7f87bc0018d0) returned true.
ThreadPool20    TLS           :   m_session_state == handshake_want_read
ThreadPool20    TLS           :   wolfSSL_connect((WOLFSSL*)0x7f87bc0018d0) = <unfinished>
ThreadPool20    TLS           :         recv(15, {"\x16\x03\x03\x04\xAC"}, 5, 0) = 5
ThreadPool20    TLS           :         recv(15, {"\v\x00\x04\xA8\x00\x04\xA5\x00\x04\xA20\x82\x04\x9E0\x82\x03\x86\xA0\x03\x02\x01\x02\x02\x01\x010\r\x06\t*\x86H\x86\xF7\r\x01\x01\v\x05\x000\x81\x941\v0\t\x06\x03U\x04\x06\x13\x02US1\x100\x0E\x06\x03U\x04\b\f\aMontana1\x100\x0E\x06\x03U\x04\a\f\aBozeman1\x110\x0F\x06\x03U\x04\n\f\bSawtooth1\x130\x11\x06\x03U\x04\v\f\nConsulting1\x180\x16\x06\x03U\x04\x03\f\x0Fwww.wolfssl.com1\x1F0\x1D\x06\t*\x86H\x86\xF7\r\x01\t\x01\x16\x10info@wolfssl.com0\x1E\x17\r180413152310Z\x17\r210107152310Z0\x81\x901\v0\t\x06\x03U\x04\x06\x13\x02US1\x100\x0E\x06\x03U\x04\b\f\aMontana1\x100\x0E\x06\x03U\x04\a\f\aBozeman1\x100\x0E\x06\x03U\x04\n\f\awolfSSL1\x100\x0E\x06\x03U\x04\v\f\aSupport1\x180\x16\x06\x03U\x04\x03\f\x0Fwww.wolfssl.com1\x1F0\x1D\x06\t*\x86H\x86\xF7\r\x01\t\x01\x16\x10info@wolfssl.com0\x82\x01\"0\r\x06\t*\x86H\x86\xF7\r\x01\x01\x01\x05\x00\x03\x82\x01\x0F\x000\x82\x01\n\x02\x82\x01\x01\x00\xC0\x95\b\xE1WA\xF2qm\xB7\xD2EA'\x01e\xC6E\xAE\xF2\xBC$0\xB8\x95\xCE/N\xD6\xF6\x1C\x88\xBC|\x9F\xFB\xA8g\x7F\xFE\\\x9CQu\xF7\x8A\xCA\a\xE75/\x8F\xE1\xBD{\xC0/|\xABd\xA8\x17\xFC\xCA]{\xBA\xE0!\xE5r.o.\x86\xD8\x95s\xDA\xAC\eS\xB9_?\xD7\x19\r%O\xE1ccQ\x8B\vd?\xADC\xB8\xA5\x1C\\4\xB3\xAE\x00\xA0c\xC5\xF6\x7F\vYhxs\xA6\x8C\x18\xA9\x02m\xAF\xC3\x19\x01.\xB8\x10\xE3\xC6\xCC@\xB4i\xA3F3i\x87n\xC4\xBB\x17\xA6\xF3\xE8\xDD\xADs\xBC{/!\xB5\xFDfQ\f\xBDT\xB3\xE1m_\x1C\xBC#s\xD1\t\x03\x89\x14\xD2\x10\xB9d\xC3*\xD0\xA1\x96J\xBC\xE1\xD4\x1A[\xC7\xA0\xC0\xC1cx\x0FD702\x96\x802#\x95\xA1w\xBA\x13\xD2\x97s\xE2]%\xC9j\r\xC39`\xA4\xB4\xB0iBB\t\xE9\xD8\b\xBC3 \xB3X\"\xA7\xAA\xEB\xC4\xE1\xE6a\x83\xC5\xD2\x96\xDF\xD9\xD0O\xAD\xD7\x02\x03\x01\x00\x01\xA3\x81\xFC0\x81\xF90\x1D\x06\x03U\x1D\x0E\x04\x16\x04\x14\xB3\x112\xC9\x92\x98\x84\xE2\xC9\xF8\xD0;n\x03B\xCA\x1F\x0E\x8E<0\x81\xC9\x06\x03U\x1D#\x04\x81\xC10\x81\xBE\x80\x14'\x8Eg\x11t\xC3&\x1D?\xED3c\xB3\xA4\xD8\x1D0\xE5\xE8\xD5\xA1\x81\x9A\xA4\x81\x970\x81\x941\v0\t\x06\x03U\x04\x06\x13\x02US1\x100\x0E\x06\x03U\x04\b\f\aMontana1\x100\x0E\x06\x03U\x04\a\f\aBozeman1\x110\x0F\x06\x03U\x04\n\f\bSawtooth1\x130\x11\x06\x03U\x04\v\f\nConsulting1\x180\x16\x06\x03U\x04\x03\f\x0Fwww.wolfssl.com1\x1F0\x1D\x06\t*\x86H\x86\xF7\r\x01\t\x01\x16\x10info@wolfssl.com\x82\t\x00\x86\xFF\xF5\x8E\x10\xDE\xB8\xFB0\f\x06\x03U\x1D\x13\x04\x050\x03\x01\x01\xFF0\r\x06\t*\x86H\x86\xF7\r\x01\x01\v\x05\x00\x03\x82\x01\x01\x00\xB4T`\xAD\xA0\x032\xDE\x02\x7F!J\x81\xC6\xED\xCD\xCD\xD8\x12\x8A\xC0\xBA\x82[u\xADT\xE3|\x80j\xAC.l N\xBEM\x82\xA7G\x13\\\xF4\xC6j+\x10\x99X\xDE\xABk|\"\x05\xC1\x83\x9D\xCB\xFF<\xE4-Wj\xA6\x96\xDF\xD3\xC1h\xE3\xD2\xC6\x83K\x97\xE2\xC62\x0E\xBE\xC4\x03\xB9\a\x8A[\xB8\x84\xBA\xC59?\x1CX\xA7U\xD7\xF0\x9B\xE8\xD2E\xB9\xE3\x83.\xEE\xB6qV\xB9:\xEE?'\xD8w\xE8\xFBDHe'GL\xFB\xFEr\xC3\xAC\x05{\x1D\xCB\xEB^e\x9A\xAB\x02\xE4\x88[;\x8B\v\xC7\xCC\xA9\xA6\x8B\xE1\x87\xB0\x19\x1A\f(Xo\x99R~\xED\xB0:h;\x8C\n\btr\xAB\xB9\t\xC5\xED\x04~o\v\x1C\t!\xD0\xCD\x7F\xF9\xC4^' \xE4\x85sR\x05\xD2\xBA\xF8\xD5\x8FA\xCC#.\x12m\xBC1\x98\xE7c\xA3\x8E&\xCD\xE8+\x88\xEE\xE2\xFE:tR4\x0E\xFD\x12\xE5^iP 14\xE41\xF1\xE7\xE4[\x03\x13\xDA\xACAl\xE7\xCF+"}, 1196, 0) = 1196
ThreadPool20    TLS           :         recv(15, 0x7f87bc001b90, 5, 0) = -1
ThreadPool20    TLS           :   <continued> -1 (WOLFSSL_ERROR_WANT_READ: non-blocking socket wants data to be read)
ThreadPool20    TLS           :   wolfSSL_want_read((WOLFSSL*)0x7f87bc0018d0) returned true.
ThreadPool20    TLS           :   m_session_state == handshake_want_read
ThreadPool20    TLS           :   wolfSSL_connect((WOLFSSL*)0x7f87bc0018d0) = <unfinished>
ThreadPool20    TLS           :         recv(15, {"\x16\x03\x03\x01M"}, 5, 0) = 5
ThreadPool20    TLS           :         recv(15, {"\f\x00\x01I\x03\x00\x17A\x04;D\xFB\x84\xB0\xAA\xCFj\x88]\xC4U\xBA`\xEFf\xEBe\xB5\x04\xCB.\xC0\x10i\agH'\xF2Ep\xB1k\xEF\xA8\nGU\xBF\xF6\xB5\x97B\xDF\\\xE3\xF3G\x8D\xD4S\x0E\xD5\x9F\xC2\x94o\xDC\n)\xEA\xF7\xD4\b\x06\x01\x00fI\x02\xD8\v\x17\xC5R\xF7\xFC+\x8E\xCE\tk\xF8}=\x94\xB1\a\xF6\xAB{\xB8,\xDE\xF4\x16\xA4\xD0&\\w\xE2]\x19\xDAdV\xE2\x04P\xCD\x97\xE5\xA6\xDD\x98<\xA1a\xCD\e(?6\xF6\x98\x06\xBC2\e\xFA[\xDB~\rF\xAD]\xBC\xA7\xC7\xEA\xD9\x84\xB3\x8Ec\xE08\xF7j\xCF\bq\x83\x9A\x86\xC0\xA4y,\rW:\xC3\xA4\xBA84\x94\xDA\x157{\xAE\x83\x86^\xF6\xE8\xF7\xFD\x1E\x14\x89d\x0E[\xF7\xCD\xCD\f\xCE\xD3@;\xE3`O\xE1!\xEB\x17\xF4\xE0\xBCk\xDD\xBE^e\x1E\\\xF8)\xE9\xF2(g\xD4B\xD7\v\x96\xBA\xDB\xFD\xEFe\xF4\x89\xB8c\xA5\x8A\xDB\xAFZf\xAFV0.\xFD\x11r\xFB@\xBE\xB0\e\xF7\x1711\x99v\xE7a\x9B:YBHTtd\xC5\x18#h?7\xA3\xD9\xD1\xD1\xE5\xA1\xD1yn\xB5\xD0:%^\xA3\xB3\xC5\x87\x94F W\x16\xEC\xAAO\xE2\xE5\x90\xCE\nX]\xAEa\xE7z,TTD\\$\xB9W\x9D\x91K\x10\x9D"}, 333, 0) = 333
ThreadPool20    TLS           :         recv(15, {"\x16\x03\x03\x00\x04"}, 5, 0) = 5
ThreadPool20    TLS           :         recv(15, {"\x0E\x00\x00\x00"}, 4, 0) = 4
ThreadPool20    TLS           :         send(15, "\x16\x03\x03\x00F\x10\x00\x00BA\x04\xC7\f\x1C\x15\xF3\xE8P\xDEe\x80\xD7\xCA\x86\xEC\xA5\xDBm\xAA>\x94\xA3vA\xC85\xC7\x92\xD5}~Xv\xA0\x8D\xC4 \x06\xE0\x14p\xE1ZU\xD1\xEF\xA8\xC9\xA1\x8AUo\xE8\xF6i\x14\xAD\x87p\ra\v\xB8\xB7E", 75, 0) = 75
ThreadPool20    TLS           :         send(15, "\x14\x03\x03\x00\x01\x01", 6, 0) = 6
ThreadPool20    TLS           :         send(15, "\x16\x03\x03\x00(\xFA\xF6oy\f\x81\x94\xD7D\x9DX\x87(\xA7\xE3\x88Y\xFD\xA77\x8D{\x87\x17\x95\xD6^\x8C\xEC\x12\xB7^\xE91\"\x7F\f\xD3q*", 45, 0) = 45
ThreadPool20    TLS           :         recv(15, 0x7f87bc001b90, 5, 0) = -1
ThreadPool20    TLS           :   <continued> -1 (WOLFSSL_ERROR_WANT_READ: non-blocking socket wants data to be read)
ThreadPool20    TLS           :   wolfSSL_want_read((WOLFSSL*)0x7f87bc0018d0) returned true.
ThreadPool20    TLS           :   m_session_state == handshake_want_read
ThreadPool20    TLS           :   wolfSSL_connect((WOLFSSL*)0x7f87bc0018d0) = <unfinished>
ThreadPool20    TLS           :         recv(15, {"\x14\x03\x03\x00\x01"}, 5, 0) = 5
ThreadPool20    TLS           :         recv(15, {"\x01"}, 1, 0) = 1
ThreadPool20    TLS           :         recv(15, {"\x16\x03\x03\x00("}, 5, 0) = 5
ThreadPool20    TLS           :         recv(15, {"\x17\x7F\xDA\xBE\x87\v\xDA\xE1\x00\"\xA4\x8B\x9C\xB7|B\f\xAB\x19\xD7\xC2\x06;m\xB2d#p\xE8\xBAc\xCAH%\xEC\\I\xB4\xBA3"}, 40, 0) = 40
ThreadPool20    TLS           :   <continued> SSL_SUCCESS

so you can see all send's and recv's of the handshake.

Welcome to the wolfSSL Forums!

My first successful connect (handshake)!

Posts: 4

1 Topic by carlo 2020-06-24 13:58:13

Topic: My first successful connect (handshake)!

2 Reply by carlo 2020-06-24 14:27:57 (edited by carlo 2020-06-24 14:28:47)

Re: My first successful connect (handshake)!

3 Reply by Kaleb J. Himes 2020-06-25 09:24:54

Re: My first successful connect (handshake)!

4 Reply by carlo 2020-06-26 14:19:21

Re: My first successful connect (handshake)!

Posts: 4