static ssize_t socket_read_ssl(struct bus *b, listener *l, int pfd_i, connection_info *ci) { BUS_ASSERT(b, b->udata, ci->ssl); ssize_t accum = 0; while (ci->to_read_size > 0) { // ssize_t pending = SSL_pending(ci->ssl); ssize_t size = (ssize_t)syscall_SSL_read(ci->ssl, l->read_buf, ci->to_read_size); if (size == -1) { int reason = syscall_SSL_get_error(ci->ssl, size); switch (reason) { case SSL_ERROR_WANT_READ: BUS_LOG_SNPRINTF(b, 3, LOG_LISTENER, b->udata, 64, "SSL_read fd %d: WANT_READ", ci->fd); return accum; case SSL_ERROR_WANT_WRITE: BUS_ASSERT(b, b->udata, false); case SSL_ERROR_SYSCALL: { if (errno == 0) { print_SSL_error(b, ci, 1, "SSL_ERROR_SYSCALL errno 0"); BUS_ASSERT(b, b->udata, false); } else if (Util_IsResumableIOError(errno)) { errno = 0; continue; } else { BUS_LOG_SNPRINTF(b, 3, LOG_LISTENER, b->udata, 64, "SSL_read fd %d: errno %d", ci->fd, errno); print_SSL_error(b, ci, 1, "SSL_ERROR_SYSCALL"); set_error_for_socket(l, pfd_i, ci->fd, RX_ERROR_READ_FAILURE); return -1; } break; } case SSL_ERROR_ZERO_RETURN: { BUS_LOG_SNPRINTF(b, 3, LOG_LISTENER, b->udata, 64, "SSL_read fd %d: ZERO_RETURN (HUP)", ci->fd); set_error_for_socket(l, pfd_i, ci->fd, RX_ERROR_POLLHUP); return -1; } default: print_SSL_error(b, ci, 1, "SSL_ERROR UNKNOWN"); set_error_for_socket(l, pfd_i, ci->fd, RX_ERROR_READ_FAILURE); BUS_ASSERT(b, b->udata, false); } } else if (size > 0) { sink_socket_read(b, l, ci, size); accum += size; if ((size_t)accum == ci->to_read_size) { break; } } else { break; } } return accum; }
static void process_unpacked_message(listener *l, connection_info *ci, bus_unpack_cb_res_t result) { struct bus *b = l->bus; /* NOTE: message may be an unsolicited status message */ if (result.ok) { int64_t seq_id = result.u.success.seq_id; void *opaque_msg = result.u.success.msg; rx_info_t *info = ListenerHelper_FindInfoBySequenceID(l, ci->fd, seq_id); if (info) { switch (info->state) { case RIS_HOLD: /* Just save result, to match up later. */ BUS_ASSERT(b, b->udata, !info->u.hold.has_result); info->u.hold.has_result = true; info->u.hold.result = result; break; case RIS_EXPECT: { BUS_LOG_SNPRINTF(b, 3, LOG_LISTENER, b->udata, 128, "marking info %d, seq_id:%lld ready for delivery", info->id, (long long)result.u.success.seq_id); info->u.expect.error = RX_ERROR_READY_FOR_DELIVERY; BUS_ASSERT(b, b->udata, !info->u.hold.has_result); info->u.expect.has_result = true; info->u.expect.result = result; ListenerTask_AttemptDelivery(l, info); break; } case RIS_INACTIVE: default: BUS_ASSERT(b, b->udata, false); } } else { /* We received a response that we weren't expecting. */ if (seq_id != BUS_NO_SEQ_ID) { BUS_LOG_SNPRINTF(b, 2 - 2, LOG_LISTENER, b->udata, 128, "Couldn't find info for fd:%d, seq_id:%lld, msg %p", ci->fd, (long long)seq_id, opaque_msg); } if (b->unexpected_msg_cb) { b->unexpected_msg_cb(opaque_msg, seq_id, b->udata, ci->udata); } } } else { uintptr_t e_id = result.u.error.opaque_error_id; BUS_LOG_SNPRINTF(b, 1, LOG_LISTENER, b->udata, 128, "Got opaque_error_id of %lu (0x%08lx)", e_id, e_id); (void)e_id; /* Timeouts will clean up after it; give user code a chance to * clean up after it here, though technically speaking they * could in the unpack_cb above. */ b->error_cb(result, ci->udata); } }
static ssize_t socket_read_plain(struct bus *b, listener *l, int pfd_i, connection_info *ci) { ssize_t accum = 0; while (ci->to_read_size > 0) { ssize_t size = syscall_read(ci->fd, l->read_buf, ci->to_read_size); if (size == -1) { BUS_LOG_SNPRINTF(b, 6, LOG_LISTENER, b->udata, 64, "read: size %zd, errno %d", size, errno); if (errno == EAGAIN) { errno = 0; return accum; } else if (Util_IsResumableIOError(errno)) { errno = 0; continue; } else { BUS_LOG_SNPRINTF(b, 3, LOG_LISTENER, b->udata, 64, "read: socket error reading, %d", errno); set_error_for_socket(l, pfd_i, ci->fd, RX_ERROR_READ_FAILURE); errno = 0; return -1; } } if (size > 0) { BUS_LOG_SNPRINTF(b, 5, LOG_LISTENER, b->udata, 64, "read: %zd", size); sink_socket_read(b, l, ci, size); accum += size; } else { return accum; } } return accum; }
static ssize_t write_plain(struct bus *b, boxed_msg *box) { int fd = box->fd; uint8_t *msg = box->out_msg; size_t msg_size = box->out_msg_size; size_t sent_size = box->out_sent_size; size_t rem = msg_size - sent_size; BUS_LOG_SNPRINTF(b, 10, LOG_SENDER, b->udata, 64, "write %p to %d, %zd bytes", (void*)&msg[sent_size], fd, rem); /* Attempt a single write. ('for' is due to continue-based retry.) */ for (;;) { ssize_t wrsz = syscall_write(fd, &msg[sent_size], rem); if (wrsz == -1) { if (Util_IsResumableIOError(errno)) { errno = 0; continue; } else { /* will notify about closed socket upstream */ BUS_LOG_SNPRINTF(b, 1, LOG_SENDER, b->udata, 64, "write: socket error writing, %s", strerror(errno)); errno = 0; return -1; } } else if (wrsz > 0) { BUS_LOG_SNPRINTF(b, 5, LOG_SENDER, b->udata, 64, "sent: %zd", wrsz); return wrsz; } else { return 0; } } }
/* Notify the listener that the client has finished sending a message, and * transfer all details for handling the response to it. Blocking. */ static bool enqueue_EXPECT_message_to_listener(bus *b, boxed_msg *box) { /* Notify listener that it should expect a response to a * successfully sent message. */ BUS_LOG_SNPRINTF(b, 3, LOG_SENDER, b->udata, 128, "telling listener to EXPECT sent response, with box %p, seq_id %lld", (void *)box, (long long)box->out_seq_id); if (box->result.status == BUS_SEND_UNDEFINED) { box->result.status = BUS_SEND_REQUEST_COMPLETE; } struct listener *l = Bus_GetListenerForSocket(b, box->fd); for (int retries = 0; retries < SEND_NOTIFY_LISTENER_RETRIES; retries++) { #ifndef TEST uint16_t backpressure = 0; #endif /* If this succeeds, then this thread cannot touch the box anymore. */ if (Listener_ExpectResponse(l, box, &backpressure)) { Bus_BackpressureDelay(b, backpressure, LISTENER_EXPECT_BACKPRESSURE_SHIFT); return true; } else { BUS_LOG_SNPRINTF(b, 5, LOG_SENDER, b->udata, 64, "enqueue_request_sent: failed delivery %d", retries); syscall_poll(NULL, 0, SEND_NOTIFY_LISTENER_RETRY_DELAY); } } /* Timeout, will be treated as a TX error */ return false; }
SendHelper_HandleWrite_res SendHelper_HandleWrite(bus *b, boxed_msg *box) { SSL *ssl = box->ssl; ssize_t wrsz = 0; /* Attempt a single write to the socket. */ if (ssl == BUS_NO_SSL) { wrsz = write_plain(b, box); } else { assert(ssl); wrsz = write_ssl(b, box, ssl); } BUS_LOG_SNPRINTF(b, 5, LOG_SENDER, b->udata, 64, "wrote %zd", wrsz); if (wrsz == -1) { Send_HandleFailure(b, box, BUS_SEND_TX_FAILURE); return SHHW_ERROR; } else if (wrsz == 0) { /* If the OS set POLLOUT but we can't actually write, then * just go back to the poll() loop with no progress. * If we busywait on this, something is deeply wrong. */ BUS_LOG_SNPRINTF(b, 1, LOG_SENDER, b->udata, 128, "suspicious: wrote %zd bytes to <fd:%d, seq_id%lld>", wrsz, box->fd, (long long)box->out_seq_id); } else { /* Update amount written so far */ box->out_sent_size += wrsz; } size_t msg_size = box->out_msg_size; size_t sent_size = box->out_sent_size; size_t rem = msg_size - sent_size; BUS_LOG_SNPRINTF(b, 5, LOG_SENDER, b->udata, 64, "wrote %zd, rem is %zd", wrsz, rem); if (rem == 0) { /* check if whole message is written */ #ifndef TEST struct timeval done; #endif if (Util_Timestamp(&done, true)) { box->tv_send_done = done; } else { Send_HandleFailure(b, box, BUS_SEND_TIMESTAMP_ERROR); return SHHW_ERROR; } if (enqueue_EXPECT_message_to_listener(b, box)) { return SHHW_DONE; } else { Send_HandleFailure(b, box, BUS_SEND_TX_TIMEOUT_NOTIFYING_LISTENER); return SHHW_ERROR; } } else { return SHHW_OK; } }
static bool sink_socket_read(struct bus *b, listener *l, connection_info *ci, ssize_t size) { BUS_LOG_SNPRINTF(b, 3, LOG_LISTENER, b->udata, 64, "read %zd bytes, calling sink CB", size); #if DUMP_READ printf("\n"); for (int i = 0; i < size; i++) { if (i > 0 && (i & 15) == 0) { printf("\n"); } printf("%02x ", l->read_buf[i]); } printf("\n\n"); #endif bus_sink_cb_res_t sres = b->sink_cb(l->read_buf, size, ci->udata); if (sres.full_msg_buffer) { BUS_LOG(b, 3, LOG_LISTENER, "calling unpack CB", b->udata); bus_unpack_cb_res_t ures = b->unpack_cb(sres.full_msg_buffer, ci->udata); BUS_LOG_SNPRINTF(b, 3, LOG_LISTENER, b->udata, 64, "process_unpacked_message: ok? %d, seq_id:%lld", ures.ok, (long long)ures.u.success.seq_id); process_unpacked_message(l, ci, ures); } ci->to_read_size = sres.next_read; BUS_LOG_SNPRINTF(b, 3, LOG_LISTENER, b->udata, 64, "expecting next read to have %zd bytes", ci->to_read_size); /* Grow read buffer if necessary. */ if (ci->to_read_size > l->read_buf_size) { if (!ListenerTask_GrowReadBuf(l, ci->to_read_size)) { BUS_LOG_SNPRINTF(b, 3, LOG_MEMORY, b->udata, 128, "Read buffer realloc failure for %p (%zd to %zd)", l->read_buf, l->read_buf_size, ci->to_read_size); BUS_ASSERT(b, b->udata, false); } } return true; }
static void print_SSL_error(struct bus *b, connection_info *ci, int lvl, const char *prefix) { unsigned long errval = ERR_get_error(); char ebuf[256]; BUS_LOG_SNPRINTF(b, lvl, LOG_LISTENER, b->udata, 64, "%s -- ERROR on fd %d -- %s", prefix, ci->fd, ERR_error_string(errval, ebuf)); (void)ci; (void)lvl; (void)errval; (void)ebuf; (void)prefix; }
static void set_error_for_socket(listener *l, int id, int fd, rx_error_t err) { l->error_occured = true; /* Mark all pending messages on this socket as being failed due to error. */ struct bus *b = l->bus; BUS_LOG_SNPRINTF(b, 3, LOG_LISTENER, b->udata, 64, "set_error_for_socket %d, err %d", fd, err); for (int i = 0; i <= l->rx_info_max_used; i++) { rx_info_t *info = &l->rx_info[i]; switch (info->state) { case RIS_INACTIVE: break; case RIS_HOLD: /* We should set an error on the info, but let the timeout * or a pending EXPECT message handle the error. That way, * it can be handled via the status callback whenever * possible. */ info->u.hold.error = err; break; case RIS_EXPECT: { struct boxed_msg *box = info->u.expect.box; if (box && box->fd == fd) { info->u.expect.error = err; } break; } default: { BUS_LOG_SNPRINTF(b, 0, LOG_LISTENER, b->udata, 64, "match fail %d on line %d", info->state, __LINE__); BUS_ASSERT(b, b->udata, false); } } } connection_info *newly_inactive_ci = l->fd_info[id]; newly_inactive_ci->error = err; }
static bool do_blocking_connection(struct bus *b, SSL *ssl, int fd) { BUS_LOG_SNPRINTF(b, 2, LOG_SOCKET_REGISTERED, b->udata, 128, "SSL_Connect handshake for socket %d", fd); struct pollfd fds[1]; fds[0].fd = fd; fds[0].events = POLLOUT; bool connected = false; size_t elapsed = 0; while (!connected) { int pres = syscall_poll(fds, 1, TIMEOUT_MSEC); BUS_LOG_SNPRINTF(b, 5, LOG_SOCKET_REGISTERED, b->udata, 128, "SSL_Connect handshake for socket %d, poll res %d", fd, pres); if (pres < 0) { if (Util_IsResumableIOError(errno)) { errno = 0; } else { /* */ assert(false); } } else if (pres > 0) { if (fds[0].revents & (POLLOUT | POLLIN)) { int connect_res = SSL_connect(ssl); BUS_LOG_SNPRINTF(b, 5, LOG_SOCKET_REGISTERED, b->udata, 128, "socket %d: connect_res %d", fd, connect_res); if (connect_res == 1) { BUS_LOG_SNPRINTF(b, 5, LOG_SOCKET_REGISTERED, b->udata, 128, "socket %d: successfully connected", fd); connected = true; } else if (connect_res < 0) { int reason = SSL_get_error(ssl, connect_res); switch (reason) { case SSL_ERROR_WANT_WRITE: BUS_LOG(b, 4, LOG_SOCKET_REGISTERED, "WANT_WRITE", b->udata); fds[0].events = POLLOUT; break; case SSL_ERROR_WANT_READ: BUS_LOG(b, 4, LOG_SOCKET_REGISTERED, "WANT_READ", b->udata); fds[0].events = POLLIN; break; case SSL_ERROR_SYSCALL: { if (Util_IsResumableIOError(errno)) { errno = 0; break; } else { unsigned long errval = ERR_get_error(); char ebuf[256]; BUS_LOG_SNPRINTF(b, 1, LOG_SOCKET_REGISTERED, b->udata, 128, "socket %d: ERROR -- %s", fd, ERR_error_string(errval, ebuf)); } } break; default: { unsigned long errval = ERR_get_error(); char ebuf[256]; BUS_LOG_SNPRINTF(b, 1, LOG_SOCKET_REGISTERED, b->udata, 128, "socket %d: ERROR %d -- %s", fd, reason, ERR_error_string(errval, ebuf)); assert(false); } } } else { BUS_LOG_SNPRINTF(b, 5, LOG_SOCKET_REGISTERED, b->udata, 128, "socket %d: unknown state, setting event bask to (POLLIN | POLLOUT)", fd); fds[0].events = (POLLIN | POLLOUT); } } else if (fds[0].revents & POLLHUP) { BUS_LOG_SNPRINTF(b, 1, LOG_SOCKET_REGISTERED, b->udata, 128, "SSL_Connect: HUP on %d", fd); return false; } else if (fds[0].revents & POLLERR) { BUS_LOG_SNPRINTF(b,12, LOG_SOCKET_REGISTERED, b->udata, 128, "SSL_Connect: ERR on %d", fd); return false; } } else { BUS_LOG(b, 4, LOG_SOCKET_REGISTERED, "poll timeout", b->udata); elapsed += TIMEOUT_MSEC; if (elapsed > MAX_TIMEOUT) { BUS_LOG(b, 2, LOG_SOCKET_REGISTERED, "timed out", b->udata); return false; } } } return connected; }
void ListenerIO_AttemptRecv(listener *l, int available) { /* --> failure --> set 'closed' error on socket, don't die */ struct bus *b = l->bus; int read_from = 0; BUS_LOG(b, 3, LOG_LISTENER, "attempting receive", b->udata); for (int i = 0; i < l->tracked_fds; i++) { if (read_from == available) { break; } struct pollfd *fd = &l->fds[i + INCOMING_MSG_PIPE]; connection_info *ci = l->fd_info[i]; BUS_ASSERT(b, b->udata, ci->fd == fd->fd); BUS_LOG_SNPRINTF(b, 1, LOG_LISTENER, b->udata, 64, "poll: l->fds[%d]->revents: 0x%04x", // NOCOMMIT i + INCOMING_MSG_PIPE, fd->revents); /* If a socket is about to be shut down, we want to get a * complete read from it if possible, because it's likely to be * an UNSOLICITEDSTATUS message with a reason for the hangup. * Only do single reads otherwise, though, otherwise the * listener can end up blocking too long handling consecutive * reads on a busy connection and causing the incoming command * queue to get backed up. */ bool is_closing = fd->events & (POLLERR | POLLNVAL | POLLHUP); if (fd->revents & POLLIN) { // Try to read what we can (possibly before hangup) ssize_t cur_read = 0; size_t to_read = ci->to_read_size; do { BUS_LOG_SNPRINTF(b, 3, LOG_LISTENER, b->udata, 64, "reading %zd bytes from socket (buf is %zd)", ci->to_read_size, l->read_buf_size); BUS_ASSERT(b, b->udata, l->read_buf_size >= to_read); switch (ci->type) { case BUS_SOCKET_PLAIN: cur_read = socket_read_plain(b, l, i, ci); break; case BUS_SOCKET_SSL: cur_read = socket_read_ssl(b, l, i, ci); break; default: BUS_ASSERT(b, b->udata, false); } // -1: socket error // 0: no more to read } while (is_closing && cur_read > 0 && ci->to_read_size > 0); read_from++; } if (fd->revents & (POLLERR | POLLNVAL)) { read_from++; BUS_LOG(b, 2, LOG_LISTENER, "pollfd: socket error (POLLERR | POLLNVAL)", b->udata); set_error_for_socket(l, i, ci->fd, RX_ERROR_POLLERR); } else if (fd->revents & POLLHUP) { read_from++; BUS_LOG(b, 3, LOG_LISTENER, "pollfd: socket error POLLHUP", b->udata); set_error_for_socket(l, i, ci->fd, RX_ERROR_POLLHUP); } } if (l->error_occured) { // only conditionally do this to avoid wasting CPU /* This is done outside of the polling loop, to avoid erroneously repeat-polling * or skipping any individual file descriptors. */ move_errored_active_sockets_to_end(l); l->error_occured = false; } }
bool BusPoll_OnCompletion(struct bus *b, int fd) { /* POLL in a pipe */ #ifndef TEST struct pollfd fds[1]; #endif fds[0].fd = fd; fds[0].events = POLLIN; for (;;) { BUS_LOG(b, 5, LOG_SENDING_REQUEST, "Polling on completion...tick...", b->udata); #ifdef TEST errno = poll_errno; #endif BUS_LOG_SNPRINTF(b, 5, LOG_SENDING_REQUEST, b->udata, 64, "poll_on_completion, polling %d", fd); int res = syscall_poll(fds, 1, -1); BUS_LOG_SNPRINTF(b, 5, LOG_SENDING_REQUEST, b->udata, 64, "poll_on_completion for %d, res %d (errno %d)", fd, res, errno); if (res == -1) { if (Util_IsResumableIOError(errno)) { BUS_LOG_SNPRINTF(b, 5, LOG_SENDING_REQUEST, b->udata, 64, "poll_on_completion, resumable IO error %d", errno); errno = 0; continue; } else { BUS_LOG_SNPRINTF(b, 1, LOG_SENDING_REQUEST, b->udata, 64, "poll_on_completion, non-resumable IO error %d", errno); return false; } } else if (res == 1) { uint16_t msec = 0; #ifndef TEST uint8_t read_buf[sizeof(uint8_t) + sizeof(uint16_t)]; #endif if (fds[0].revents & (POLLERR | POLLHUP | POLLNVAL)) { BUS_LOG(b, 1, LOG_SENDING_REQUEST, "failed (broken alert pipe)", b->udata); return false; } BUS_LOG(b, 3, LOG_SENDING_REQUEST, "Reading alert pipe...", b->udata); #ifdef TEST errno = read_errno; #endif ssize_t sz = syscall_read(fd, read_buf, sizeof(read_buf)); if (sz == sizeof(read_buf)) { /* Payload: little-endian uint16_t, msec of backpressure. */ assert(read_buf[0] == LISTENER_MSG_TAG); msec = (read_buf[1] << 0) + (read_buf[2] << 8); Bus_BackpressureDelay(b, msec, LISTENER_BACKPRESSURE_SHIFT); BUS_LOG(b, 4, LOG_SENDING_REQUEST, "sent!", b->udata); return true; } else if (sz == -1) { if (Util_IsResumableIOError(errno)) { BUS_LOG_SNPRINTF(b, 5, LOG_SENDING_REQUEST, b->udata, 64, "poll_on_completion read, resumable IO error %d", errno); errno = 0; continue; } else { BUS_LOG_SNPRINTF(b, 2, LOG_SENDING_REQUEST, b->udata, 64, "poll_on_completion read, non-resumable IO error %d", errno); errno = 0; return false; } } else { BUS_LOG_SNPRINTF(b, 1, LOG_SENDING_REQUEST, b->udata, 64, "poll_on_completion bad read size %zd", sz); return false; } } else { /* This should never happen, but I have seen it occur on OSX. * If we log it, reset errno, and continue, it does not appear * to fall into busywaiting by always returning 0. */ BUS_LOG_SNPRINTF(b, 1, LOG_SENDING_REQUEST, b->udata, 64, "poll_on_completion, blocking forever returned %d, errno %d", res, errno); errno = 0; } } }
static ssize_t write_ssl(struct bus *b, boxed_msg *box, SSL *ssl) { uint8_t *msg = box->out_msg; size_t msg_size = box->out_msg_size; ssize_t rem = msg_size - box->out_sent_size; int fd = box->fd; (void)fd; ssize_t written = 0; assert(rem >= 0); while (rem > 0) { ssize_t wrsz = syscall_SSL_write(ssl, &msg[box->out_sent_size], rem); BUS_LOG_SNPRINTF(b, 5, LOG_SENDER, b->udata, 64, "SSL_write: socket %d, write %zd => wrsz %zd", fd, rem, wrsz); if (wrsz > 0) { written += wrsz; return written; } else if (wrsz < 0) { int reason = syscall_SSL_get_error(ssl, wrsz); switch (reason) { case SSL_ERROR_WANT_WRITE: /* We need to write more, but currently cannot write. * Log and go back to the poll() loop. */ BUS_LOG_SNPRINTF(b, 3, LOG_SENDER, b->udata, 64, "SSL_write: socket %d: WANT_WRITE", fd); return 0; case SSL_ERROR_WANT_READ: BUS_LOG_SNPRINTF(b, 0, LOG_SENDER, b->udata, 64, "SSL_write: socket %d: WANT_READ", fd); assert(false); // shouldn't get this; we're writing. break; case SSL_ERROR_SYSCALL: { if (Util_IsResumableIOError(errno)) { errno = 0; /* don't break; we want to retry on EINTR etc. until * we get WANT_WRITE, otherwise poll(2) may not retry * the socket for too long */ continue; } else { /* will notify about socket error upstream */ BUS_LOG_SNPRINTF(b, 1, LOG_SENDER, b->udata, 64, "SSL_write on fd %d: SSL_ERROR_SYSCALL -- %s", fd, strerror(errno)); errno = 0; return -1; } } case SSL_ERROR_SSL: BUS_LOG_SNPRINTF(b, 1, LOG_SENDER, b->udata, 64, "SSL_write: socket %d: error SSL (wrsz %zd)", box->fd, wrsz); /* Log error messages from OpenSSL */ for (;;) { unsigned long e = ERR_get_error(); if (e == 0) { break; } // no more errors BUS_LOG_SNPRINTF(b, 1, LOG_SENDER, b->udata, 128, "SSL_write error: %s", ERR_error_string(e, NULL)); } return -1; default: { BUS_LOG_SNPRINTF(b, 1, LOG_SENDER, b->udata, 64, "SSL_write on socket %d: match fail: error %d", box->fd, reason); return -1; } } } else { /* SSL_write should give SSL_ERROR_WANT_WRITE when unable * to write further. */ } } BUS_LOG_SNPRINTF(b, 3, LOG_SENDER, b->udata, 64, "SSL_write: leaving loop, %zd bytes written", written); return written; }