SSLproxy/pxyconn.c

/*-
 * SSLsplit - transparent SSL/TLS interception
 * https://www.roe.ch/SSLsplit
 *
 * Copyright (c) 2009-2018, Daniel Roethlisberger <daniel@roe.ch>.
 * All rights reserved.
 *
 * Redistribution and use in source and binary forms, with or without
 * modification, are permitted provided that the following conditions are met:
 * 1. Redistributions of source code must retain the above copyright notice,
 *    this list of conditions and the following disclaimer.
 * 2. Redistributions in binary form must reproduce the above copyright notice,
 *    this list of conditions and the following disclaimer in the documentation
 *    and/or other materials provided with the distribution.
 *
 * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDER AND CONTRIBUTORS ``AS IS''
 * AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
 * IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
 * ARE DISCLAIMED.  IN NO EVENT SHALL THE COPYRIGHT HOLDER OR CONTRIBUTORS BE
 * LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR
 * CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF
 * SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS
 * INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN
 * CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE)
 * ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE
 * POSSIBILITY OF SUCH DAMAGE.
 */

#include "pxyconn.h"

#include "prototcp.h"
#include "protossl.h"
#include "protohttp.h"
#include "protoautossl.h"
#include "protopassthrough.h"

#include "privsep.h"
#include "pxysslshut.h"
#include "ssl.h"
#include "opts.h"
#include "sys.h"
#include "util.h"
#include "base64.h"
#include "url.h"
#include "log.h"
#include "attrib.h"
#include "proc.h"

#include <netinet/in.h>
#include <arpa/inet.h>
#include <stdlib.h>
#include <stdio.h>
#include <string.h>
#include <errno.h>

#include <event2/event.h>
#include <event2/listener.h>
#include <event2/bufferevent.h>
#include <event2/bufferevent_ssl.h>
#include <event2/buffer.h>
#include <event2/thread.h>
#include <event2/dns.h>

#include <openssl/ssl.h>
#include <openssl/err.h>
#include <openssl/rand.h>
#include <openssl/x509.h>
#include <openssl/x509v3.h>
#include <assert.h>
#include <sys/param.h>

#ifdef HAVE_NETFILTER
#include <glob.h>
#endif /* HAVE_NETFILTER */

/*
 * Maximum size of data to buffer per connection direction before
 * temporarily stopping to read data from the other end.
 */
#define OUTBUF_LIMIT	(128*1024)

/*
 * Proxy connection context state, describes a proxy connection
 * with source and destination socket bufferevents, SSL context and
 * other session state.  One of these exists per handled proxy
 * connection.
 */

#ifdef HAVE_LOCAL_PROCINFO
/* local process data - filled in iff pid != -1 */
typedef struct pxy_conn_lproc_desc {
	struct sockaddr_storage srcaddr;
	socklen_t srcaddrlen;

	pid_t pid;
	uid_t uid;
	gid_t gid;

	/* derived log strings */
	char *exec_path;
	char *user;
	char *group;
} pxy_conn_lproc_desc_t;
#endif /* HAVE_LOCAL_PROCINFO */

int descriptor_table_size = 0;

static enum protocol
pxy_setup_proto(pxy_conn_ctx_t *ctx)
{
	ctx->protoctx = malloc(sizeof(proto_ctx_t));
	if (!ctx->protoctx) {
		return PROTO_ERROR;
	}
	memset(ctx->protoctx, 0, sizeof(proto_ctx_t));

	// Default to tcp
	prototcp_setup(ctx);

	if (ctx->spec->upgrade) {
		return protoautossl_setup(ctx);
	} else if (ctx->spec->http) {
		if (ctx->spec->ssl) {
			return protohttps_setup(ctx);
		} else {
			return protohttp_setup(ctx);
		}
	} else if (ctx->spec->pop3) {
		if (ctx->spec->ssl) {
			return (protossl_setup(ctx) != PROTO_ERROR) ? PROTO_POP3S : PROTO_ERROR;
		} else {
			return PROTO_POP3;
		}
	} else if (ctx->spec->smtp) {
		if (ctx->spec->ssl) {
			return (protossl_setup(ctx) != PROTO_ERROR) ? PROTO_SMTPS : PROTO_ERROR;
		} else {
			return PROTO_SMTP;
		}
	} else if (ctx->spec->ssl) {
		return protossl_setup(ctx);
	} else {
		return PROTO_TCP;
	}
}

static enum protocol
pxy_setup_proto_child(pxy_conn_child_ctx_t *ctx)
{
	ctx->protoctx = malloc(sizeof(proto_child_ctx_t));
	if (!ctx->protoctx) {
		return PROTO_ERROR;
	}
	memset(ctx->protoctx, 0, sizeof(proto_child_ctx_t));

	// Default to tcp
	prototcp_setup_child(ctx);

	if (ctx->conn->spec->upgrade) {
		return protoautossl_setup_child(ctx);
	} else if (ctx->conn->spec->http) {
		if (ctx->conn->spec->ssl) {
			return protohttps_setup_child(ctx);
		} else {
			return protohttp_setup_child(ctx);
		}
	} else if (ctx->conn->spec->pop3) {
		if (ctx->conn->spec->ssl) {
			return (protossl_setup_child(ctx) != PROTO_ERROR) ? PROTO_POP3S : PROTO_ERROR;
		} else {
			return PROTO_POP3;
		}
	} else if (ctx->conn->spec->smtp) {
		if (ctx->conn->spec->ssl) {
			return (protossl_setup_child(ctx) != PROTO_ERROR) ? PROTO_SMTPS : PROTO_ERROR;
		} else {
			return PROTO_SMTP;
		}
	} else if (ctx->conn->spec->ssl) {
		return protossl_setup_child(ctx);
	} else {
		return PROTO_TCP;
	}
}

static pxy_conn_ctx_t * MALLOC NONNULL(2,3,4)
pxy_conn_ctx_new(evutil_socket_t fd,
                 pxy_thrmgr_ctx_t *thrmgr,
                 proxyspec_t *spec, opts_t *opts,
			     evutil_socket_t clisock)
{
#ifdef DEBUG_PROXY
	log_dbg_level_printf(LOG_DBG_MODE_FINEST, "pxy_conn_ctx_new: ENTER fd=%d\n", fd);
#endif /* DEBUG_PROXY */

	pxy_conn_ctx_t *ctx = malloc(sizeof(pxy_conn_ctx_t));
	if (!ctx) {
		log_err_level_printf(LOG_CRIT, "Error allocating memory\n");
		evutil_closesocket(fd);
		return NULL;
	}
	memset(ctx, 0, sizeof(pxy_conn_ctx_t));

	ctx->id = thrmgr->conn_count++;

#if defined (DEBUG_PROXY)
	log_dbg_level_printf(LOG_DBG_MODE_FINEST, "pxy_conn_ctx_new: id=%llu, fd=%d\n", ctx->id, fd);
#endif /* DEBUG_PROXY */
	
	ctx->type = CONN_TYPE_PARENT;
	ctx->fd = fd;
	ctx->conn = ctx;
	ctx->thrmgr = thrmgr;
	ctx->spec = spec;

	ctx->protoctx = malloc(sizeof(proto_ctx_t));
	if (!ctx->protoctx) {
		log_err_level_printf(LOG_CRIT, "Error allocating memory\n");
		evutil_closesocket(fd);
		free(ctx);
		return NULL;
	}
	memset(ctx->protoctx, 0, sizeof(proto_ctx_t));
	ctx->proto = pxy_setup_proto(ctx);
	if (ctx->proto == PROTO_ERROR) {
		log_err_level_printf(LOG_CRIT, "Error allocating memory\n");
		evutil_closesocket(fd);
		free(ctx->protoctx);
		free(ctx);
		return NULL;
	}

	ctx->opts = opts;
	ctx->clisock = clisock;

	ctx->ctime = time(NULL);
	ctx->atime = ctx->ctime;
	
	ctx->next = NULL;

	pxy_thrmgr_attach(ctx);
	
#ifdef HAVE_LOCAL_PROCINFO
	ctx->lproc.pid = -1;
#endif /* HAVE_LOCAL_PROCINFO */
#ifdef DEBUG_PROXY
	if (OPTS_DEBUG(ctx->opts)) {
		log_dbg_printf("%p             pxy_conn_ctx_new\n", (void*)ctx);
	}
#endif /* DEBUG_PROXY */
	return ctx;
}

static pxy_conn_child_ctx_t * MALLOC NONNULL(2)
pxy_conn_ctx_new_child(evutil_socket_t fd, pxy_conn_ctx_t *conn)
{
	assert(conn != NULL);

#ifdef DEBUG_PROXY
	log_dbg_level_printf(LOG_DBG_MODE_FINEST, "pxy_conn_ctx_new_child: ENTER fd=%d\n", fd);
#endif /* DEBUG_PROXY */
	pxy_conn_child_ctx_t *ctx = malloc(sizeof(pxy_conn_child_ctx_t));
	if (!ctx) {
		return NULL;
	}
	memset(ctx, 0, sizeof(pxy_conn_child_ctx_t));

	ctx->type = CONN_TYPE_CHILD;
	ctx->fd = fd;
	ctx->conn = conn;

	ctx->protoctx = malloc(sizeof(proto_ctx_t));
	if (!ctx->protoctx) {
		log_err_level_printf(LOG_CRIT, "Error allocating memory\n");
		evutil_closesocket(fd);
		free(ctx);
		return NULL;
	}
	memset(ctx->protoctx, 0, sizeof(proto_ctx_t));
	ctx->proto = pxy_setup_proto_child(ctx);
	if (ctx->proto == PROTO_ERROR) {
		log_err_level_printf(LOG_CRIT, "Error allocating memory\n");
		evutil_closesocket(fd);
		free(ctx->protoctx);
		free(ctx);
		return NULL;
	}

	// @attention Child connections use the parent's event bases, otherwise we would get multithreading issues
	pxy_thrmgr_attach_child(conn);
#ifdef DEBUG_PROXY
	if (OPTS_DEBUG(conn->opts)) {
		log_dbg_printf("%p             pxy_conn_ctx_new_child\n", (void*)ctx);
	}
#endif /* DEBUG_PROXY */
	return ctx;
}

static void NONNULL(1)
pxy_conn_ctx_free_child(pxy_conn_child_ctx_t *ctx)
{
#ifdef DEBUG_PROXY
	log_dbg_level_printf(LOG_DBG_MODE_FINEST, "pxy_conn_ctx_free_child: ENTER fd=%d, conn fd=%d\n", ctx->fd, ctx->conn->fd);
	if (OPTS_DEBUG(ctx->conn->opts)) {
		log_dbg_printf("%p             pxy_conn_ctx_free_child\n",
		                (void*)ctx);
	}
#endif /* DEBUG_PROXY */
	pxy_thrmgr_detach_child(ctx->conn);

	// If the proto doesn't have special args, proto_free() callback is NULL
	if (ctx->protoctx->proto_free) {
		ctx->protoctx->proto_free(ctx);
	}
	free(ctx->protoctx);
	free(ctx);
}

/*
 * Free bufferenvent and close underlying socket properly.
 * For OpenSSL bufferevents, this will shutdown the SSL connection.
 */
void
pxy_bufferevent_free_and_close_fd(struct bufferevent *bev, pxy_conn_ctx_t *ctx)
{
	ctx->protoctx->bufferevent_free_and_close_fd(bev, ctx);
}

static void NONNULL(1,2)
pxy_conn_remove_child(pxy_conn_child_ctx_t *child, pxy_conn_child_ctx_t **head)
{
#ifdef DEBUG_PROXY
	log_dbg_level_printf(LOG_DBG_MODE_FINEST, "pxy_conn_remove_child: ENTER fd=%d\n", child->fd);
#endif /* DEBUG_PROXY */

    if (child->fd == (*head)->fd) {
        *head = (*head)->next;
        return;
    }

    pxy_conn_child_ctx_t *current = (*head)->next;
    pxy_conn_child_ctx_t *previous = *head;
    while (current != NULL && previous != NULL) {
        if (child->fd == current->fd) {
            previous->next = current->next;
            return;
        }
        previous = current;
        current = current->next;
    }
    return;
}

void
pxy_conn_free_child(pxy_conn_child_ctx_t *ctx)
{
	assert(ctx->conn != NULL);

#ifdef DEBUG_PROXY
	log_dbg_level_printf(LOG_DBG_MODE_FINEST, "pxy_conn_free_child: ENTER fd=%d\n", ctx->fd);
#endif /* DEBUG_PROXY */

	pxy_conn_desc_t *dst = &ctx->dst;
	if (dst->bev) {
		pxy_bufferevent_free_and_close_fd(dst->bev, ctx->conn);
		dst->bev = NULL;
	}

	pxy_conn_desc_t *src = &ctx->src;
	if (src->bev) {
		prototcp_bufferevent_free_and_close_fd(src->bev, ctx->conn);
		src->bev = NULL;
	}

	pxy_conn_remove_child(ctx, &ctx->conn->children);
	pxy_conn_ctx_free_child(ctx);
}

void
pxy_conn_ctx_free(pxy_conn_ctx_t *ctx, int by_requestor)
{
#ifdef DEBUG_PROXY
	log_dbg_level_printf(LOG_DBG_MODE_FINEST, "pxy_conn_ctx_free: ENTER fd=%d\n", ctx->fd);
	if (OPTS_DEBUG(ctx->opts)) {
		log_dbg_printf("%p             pxy_conn_ctx_free\n",
		                (void*)ctx);
	}
#endif /* DEBUG_PROXY */
	if (WANT_CONTENT_LOG(ctx) && ctx->logctx) {
		if (log_content_close(&ctx->logctx, by_requestor) == -1) {
			log_err_level_printf(LOG_WARNING, "Content log close failed\n");
		}
	}
	pxy_thrmgr_detach(ctx);
	if (ctx->srchost_str) {
		free(ctx->srchost_str);
	}
	if (ctx->srcport_str) {
		free(ctx->srcport_str);
	}
	if (ctx->dsthost_str) {
		free(ctx->dsthost_str);
	}
	if (ctx->dstport_str) {
		free(ctx->dstport_str);
	}
#ifdef HAVE_LOCAL_PROCINFO
	if (ctx->lproc.exec_path) {
		free(ctx->lproc.exec_path);
	}
	if (ctx->lproc.user) {
		free(ctx->lproc.user);
	}
	if (ctx->lproc.group) {
		free(ctx->lproc.group);
	}
#endif /* HAVE_LOCAL_PROCINFO */
	if (ctx->ev) {
		event_free(ctx->ev);
	}
	if (ctx->header_str) {
		free(ctx->header_str);
	}
	// If the proto doesn't have special args, proto_free() callback is NULL
	if (ctx->protoctx->proto_free) {
		ctx->protoctx->proto_free(ctx);
	}
	free(ctx->protoctx);
	free(ctx);
}

void
pxy_conn_free(pxy_conn_ctx_t *ctx, int by_requestor)
{
	evutil_socket_t fd = ctx->fd;

#ifdef DEBUG_PROXY
	evutil_socket_t child_fd = ctx->child_fd;
	log_dbg_level_printf(LOG_DBG_MODE_FINER, "pxy_conn_free: ENTER fd=%d, child_fd=%d\n", fd, child_fd);
#endif /* DEBUG_PROXY */

	pxy_conn_desc_t *src = &ctx->src;
	if (!src->closed) {
		if (src->bev) {
			pxy_bufferevent_free_and_close_fd(src->bev, ctx);
			src->bev = NULL;
		} else {
#ifdef DEBUG_PROXY
			log_dbg_level_printf(LOG_DBG_MODE_FINE, "pxy_conn_free: evutil_closesocket on NULL src->bev, fd=%d\n", fd);
#endif /* DEBUG_PROXY */
			// @todo src fd may be open, although src.bev is NULL, where do we close the src fd?
			evutil_closesocket(fd);
		}
	}

	pxy_conn_desc_t *srv_dst = &ctx->srv_dst;
	if (srv_dst->bev) {
		pxy_bufferevent_free_and_close_fd(srv_dst->bev, ctx);
		srv_dst->bev = NULL;
	}

	pxy_conn_desc_t *dst = &ctx->dst;
	if (dst->bev) {
		prototcp_bufferevent_free_and_close_fd(dst->bev, ctx);
		dst->bev = NULL;
	}

	// @attention Free the child ctxs asap, we need their fds
	while (ctx->children) {
		pxy_conn_free_child(ctx->children);
	}

	// @attention Parent may be closing before there was any child at all nor was child_evcl ever created
	if (ctx->child_evcl) {
#ifdef DEBUG_PROXY
		log_dbg_level_printf(LOG_DBG_MODE_FINE, "pxy_conn_free: Freeing child_evcl, conn fd=%d, child_fd=%d, cfd=%d\n",
				ctx->fd, ctx->child_fd, ctx->children ? ctx->children->fd : -1);
#endif /* DEBUG_PROXY */
		// @attention child_evcl was created with LEV_OPT_CLOSE_ON_FREE, so do not close ctx->child_fd
		evconnlistener_free(ctx->child_evcl);
		ctx->child_evcl = NULL;
	}

	pxy_conn_ctx_free(ctx, by_requestor);
}

/*
 * Set up a bufferevent structure for either a dst or src connection,
 * optionally with or without SSL.  Sets all callbacks, enables read
 * and write events, but does not call bufferevent_socket_connect().
 *
 * For dst connections, pass -1 as fd.  Pass a pointer to an initialized
 * SSL struct as ssl if the connection should use SSL.
 *
 * Returns pointer to initialized bufferevent structure, as returned
 * by bufferevent_socket_new() or bufferevent_openssl_socket_new().
 */
static struct bufferevent * NONNULL(1)
pxy_bufferevent_setup(pxy_conn_ctx_t *ctx, evutil_socket_t fd, SSL *ssl)
{
#ifdef DEBUG_PROXY
	log_dbg_level_printf(LOG_DBG_MODE_FINEST, "pxy_bufferevent_setup: ENTER fd=%d\n", fd);
#endif /* DEBUG_PROXY */

	struct bufferevent *bev;

	if (ssl) {
		bev = bufferevent_openssl_socket_new(ctx->evbase, fd, ssl,
				((fd == -1) ? BUFFEREVENT_SSL_CONNECTING : BUFFEREVENT_SSL_ACCEPTING), BEV_OPT_DEFER_CALLBACKS);
	} else {
		// @todo Do we really need to defer callbacks? BEV_OPT_DEFER_CALLBACKS seems responsible for the issue with srv_dst: We get writecb sometimes, no eventcb for CONNECTED event
		bev = bufferevent_socket_new(ctx->evbase, fd, BEV_OPT_DEFER_CALLBACKS);
	}
	if (!bev) {
		log_err_level_printf(LOG_CRIT, "Error creating bufferevent socket\n");
		return NULL;
	}
#if LIBEVENT_VERSION_NUMBER >= 0x02010000
	if (ssl) {
#ifdef DEBUG_PROXY
		log_dbg_level_printf(LOG_DBG_MODE_FINEST, "pxy_bufferevent_setup: bufferevent_openssl_set_allow_dirty_shutdown\n");
#endif /* DEBUG_PROXY */
		/* Prevent unclean (dirty) shutdowns to cause error
		 * events on the SSL socket bufferevent. */
		bufferevent_openssl_set_allow_dirty_shutdown(bev, 1);
	}
#endif /* LIBEVENT_VERSION_NUMBER >= 0x02010000 */

	// @attention Do not set callbacks here, srv_dst does not set r cb
	//bufferevent_setcb(bev, pxy_bev_readcb, pxy_bev_writecb, pxy_bev_eventcb, ctx);
	// @todo Should we enable events here?
	//bufferevent_enable(bev, EV_READ|EV_WRITE);

#ifdef DEBUG_PROXY
	if (OPTS_DEBUG(ctx->opts)) {
		log_dbg_printf("            %p pxy_bufferevent_setup\n",
		               (void*)bev);
	}
#endif /* DEBUG_PROXY */
	return bev;
}

struct bufferevent *
pxy_bufferevent_setup_child(pxy_conn_child_ctx_t *ctx, evutil_socket_t fd, SSL *ssl)
{
#ifdef DEBUG_PROXY
	log_dbg_level_printf(LOG_DBG_MODE_FINEST, "pxy_bufferevent_setup_child: ENTER fd=%d\n", fd);
#endif /* DEBUG_PROXY */

	struct bufferevent *bev;

	if (ssl) {
		bev = bufferevent_openssl_socket_new(ctx->conn->evbase, fd, ssl,
				((fd == -1) ? BUFFEREVENT_SSL_CONNECTING : BUFFEREVENT_SSL_ACCEPTING), BEV_OPT_DEFER_CALLBACKS);
	} else {
		bev = bufferevent_socket_new(ctx->conn->evbase, fd, BEV_OPT_DEFER_CALLBACKS);
	}
	if (!bev) {
		log_err_level_printf(LOG_CRIT, "Error creating bufferevent socket\n");
		return NULL;
	}

#if LIBEVENT_VERSION_NUMBER >= 0x02010000
	if (ssl) {
#ifdef DEBUG_PROXY
		log_dbg_level_printf(LOG_DBG_MODE_FINEST, "pxy_bufferevent_setup_child: bufferevent_openssl_set_allow_dirty_shutdown\n");
#endif /* DEBUG_PROXY */
		/* Prevent unclean (dirty) shutdowns to cause error
		 * events on the SSL socket bufferevent. */
		bufferevent_openssl_set_allow_dirty_shutdown(bev, 1);
	}
#endif /* LIBEVENT_VERSION_NUMBER >= 0x02010000 */

	bufferevent_setcb(bev, pxy_bev_readcb_child, pxy_bev_writecb_child, pxy_bev_eventcb_child, ctx);

	// @attention We cannot enable events here, because src events will be deferred until after dst is connected
	//bufferevent_enable(bev, EV_READ|EV_WRITE);

#ifdef DEBUG_PROXY
	if (OPTS_DEBUG(ctx->conn->opts)) {
		log_dbg_printf("            %p pxy_bufferevent_setup_child\n",
		               (void*)bev);
	}
#endif /* DEBUG_PROXY */
	return bev;
}

void
pxy_log_connect_nonhttp(pxy_conn_ctx_t *ctx)
{
	char *msg;
#ifdef HAVE_LOCAL_PROCINFO
	char *lpi = NULL;
#endif /* HAVE_LOCAL_PROCINFO */
	int rv;

#ifdef HAVE_LOCAL_PROCINFO
	if (ctx->opts->lprocinfo) {
		rv = asprintf(&lpi, "lproc:%i:%s:%s:%s",
		              ctx->lproc.pid,
		              STRORDASH(ctx->lproc.user),
		              STRORDASH(ctx->lproc.group),
		              STRORDASH(ctx->lproc.exec_path));
		if ((rv < 0) || !lpi) {
			ctx->enomem = 1;
			goto out;
		}
	} else {
		lpi = "";
	}
#endif /* HAVE_LOCAL_PROCINFO */

	/*
	 * The following ifdef's within asprintf arguments list generates
	 * warnings with -Wembedded-directive on some compilers.
	 * Not fixing the code in order to avoid more code duplication.
	 */

	if (!ctx->src.ssl) {
		rv = asprintf(&msg, "CONN: %s %s %s %s %s"
#ifdef HAVE_LOCAL_PROCINFO
		              " %s"
#endif /* HAVE_LOCAL_PROCINFO */
		              "\n",
		              ctx->proto == PROTO_PASSTHROUGH ? "passthrough" : (ctx->proto == PROTO_POP3 ? "pop3" : (ctx->proto == PROTO_SMTP ? "smtp" : "tcp")),
		              STRORDASH(ctx->srchost_str),
		              STRORDASH(ctx->srcport_str),
		              STRORDASH(ctx->dsthost_str),
		              STRORDASH(ctx->dstport_str)
#ifdef HAVE_LOCAL_PROCINFO
		              , lpi
#endif /* HAVE_LOCAL_PROCINFO */
		             );
	} else {
		rv = asprintf(&msg, "CONN: %s %s %s %s %s "
		              "sni:%s names:%s "
		              "sproto:%s:%s dproto:%s:%s "
		              "origcrt:%s usedcrt:%s"
#ifdef HAVE_LOCAL_PROCINFO
		              " %s"
#endif /* HAVE_LOCAL_PROCINFO */
		              "\n",
		              ctx->proto == PROTO_AUTOSSL ? "autossl" : (ctx->proto == PROTO_POP3S ? "pop3s" : (ctx->proto == PROTO_SMTPS ? "smtps" : "ssl")),
		              STRORDASH(ctx->srchost_str),
		              STRORDASH(ctx->srcport_str),
		              STRORDASH(ctx->dsthost_str),
		              STRORDASH(ctx->dstport_str),
		              STRORDASH(ctx->sslctx->sni),
		              STRORDASH(ctx->sslctx->ssl_names),
		              SSL_get_version(ctx->src.ssl),
		              SSL_get_cipher(ctx->src.ssl),
		              !ctx->srv_dst.closed && ctx->srv_dst.ssl ? SSL_get_version(ctx->srv_dst.ssl):ctx->sslctx->srv_dst_ssl_version,
		              !ctx->srv_dst.closed && ctx->srv_dst.ssl ? SSL_get_cipher(ctx->srv_dst.ssl):ctx->sslctx->srv_dst_ssl_cipher,
		              STRORDASH(ctx->sslctx->origcrtfpr),
		              STRORDASH(ctx->sslctx->usedcrtfpr)
#ifdef HAVE_LOCAL_PROCINFO
		              , lpi
#endif /* HAVE_LOCAL_PROCINFO */
		              );
	}
	if ((rv < 0) || !msg) {
		ctx->enomem = 1;
		goto out;
	}
	if (!ctx->opts->detach) {
		log_err_printf("%s", msg);
	} else if (ctx->opts->statslog) {
		if (log_conn(msg) == -1) {
			log_err_level_printf(LOG_WARNING, "Conn logging failed\n");
		}
	}
	if (ctx->opts->connectlog) {
		if (log_connect_print_free(msg) == -1) {
			free(msg);
			log_err_level_printf(LOG_WARNING, "Connection logging failed\n");
		}
	} else {
		free(msg);
	}
out:
#ifdef HAVE_LOCAL_PROCINFO
	if (lpi && ctx->opts->lprocinfo) {
		free(lpi);
	}
#endif /* HAVE_LOCAL_PROCINFO */
	return;
}

int
pxy_log_content_buf(pxy_conn_ctx_t *ctx, unsigned char *buf, size_t sz, int req)
{
	if (WANT_CONTENT_LOG(ctx->conn)) {
		if (buf) {
			logbuf_t *lb = logbuf_new_alloc(sz, NULL, NULL);
			if (!lb) {
				ctx->conn->enomem = 1;
				return -1;
			}
			memcpy(lb->buf, buf, lb->sz);
			if (log_content_submit(ctx->conn->logctx, lb, req) == -1) {
				logbuf_free(lb);
				log_err_level_printf(LOG_WARNING, "Content log submission failed\n");
				return -1;
			}
		}
	}
	return 0;
}

int
pxy_log_content_inbuf(pxy_conn_ctx_t *ctx, struct evbuffer *inbuf, int req)
{
	if (WANT_CONTENT_LOG(ctx->conn)) {
		size_t sz = evbuffer_get_length(inbuf);
		unsigned char *buf = malloc(sz);
		if (!buf) {
			ctx->conn->enomem = 1;
			return -1;
		}
		if (evbuffer_copyout(inbuf, buf, sz) == -1) {
			return -1;
		}
		if (pxy_log_content_buf(ctx, buf, sz, req) == -1) {
			return -1;
		}
	}
	return 0;
}

int
pxy_prepare_logging_local_procinfo(UNUSED pxy_conn_ctx_t *ctx)
{
#ifdef HAVE_LOCAL_PROCINFO
	if (ctx->opts->lprocinfo) {
		/* fetch process info */
		if (proc_pid_for_addr(&ctx->lproc.pid,
				(struct sockaddr*)&ctx->lproc.srcaddr,
				ctx->lproc.srcaddrlen) == 0 &&
			ctx->lproc.pid != -1 &&
			proc_get_info(ctx->lproc.pid,
						  &ctx->lproc.exec_path,
						  &ctx->lproc.uid,
						  &ctx->lproc.gid) == 0) {
			/* fetch user/group names */
			ctx->lproc.user = sys_user_str(
							ctx->lproc.uid);
			ctx->lproc.group = sys_group_str(
							ctx->lproc.gid);
			if (!ctx->lproc.user ||
				!ctx->lproc.group) {
				ctx->enomem = 1;
				pxy_conn_free(ctx, 1);
				return -1;
			}
		}
	}
#endif /* HAVE_LOCAL_PROCINFO */
	return 0;
}

int
pxy_prepare_logging(pxy_conn_ctx_t *ctx)
{
	/* prepare logging, part 2 */
	if (WANT_CONNECT_LOG(ctx) || WANT_CONTENT_LOG(ctx)) {
		return pxy_prepare_logging_local_procinfo(ctx);
	}
	if (WANT_CONTENT_LOG(ctx)) {
		if (log_content_open(&ctx->logctx, ctx->opts,
							 STRORDASH(ctx->srchost_str), STRORDASH(ctx->srcport_str),
							 STRORDASH(ctx->dsthost_str), STRORDASH(ctx->dstport_str),
#ifdef HAVE_LOCAL_PROCINFO
							 ctx->lproc.exec_path,
							 ctx->lproc.user,
							 ctx->lproc.group
#else /* HAVE_LOCAL_PROCINFO */
							 NULL, NULL, NULL
#endif /* HAVE_LOCAL_PROCINFO */
							) == -1) {
			if (errno == ENOMEM)
				ctx->enomem = 1;
			pxy_conn_free(ctx, 1);
			return -1;
		}
	}
	return 0;
}

static void
pxy_log_dbg_connect_type(pxy_conn_ctx_t *ctx, pxy_conn_desc_t *this)
{
	if (OPTS_DEBUG(ctx->opts)) {
		if (this->ssl) {
			char *keystr;
			/* for SSL, we get two connect events */
			log_dbg_printf("pxy_log_dbg_connect_type: SSL connected to [%s]:%s %s %s\n",
						   STRORDASH(ctx->dsthost_str), STRORDASH(ctx->dstport_str),
						   SSL_get_version(this->ssl), SSL_get_cipher(this->ssl));
			keystr = ssl_ssl_masterkey_to_str(this->ssl);
			if (keystr) {
				log_dbg_print_free(keystr);
			}
		} else {
			/* for TCP, we get only a dst connect event,
			 * since src was already connected from the
			 * beginning; mirror SSL debug output anyway
			 * in order not to confuse anyone who might be
			 * looking closely at the output */
			log_dbg_printf("pxy_log_dbg_connect_type: TCP connected to [%s]:%s\n",
						   STRORDASH(ctx->dsthost_str), STRORDASH(ctx->dstport_str));
			log_dbg_printf("pxy_log_dbg_connect_type: TCP connected from [%s]:%s\n",
						   STRORDASH(ctx->srchost_str), STRORDASH(ctx->srcport_str));
		}
	}
}

void
pxy_log_connect_src(pxy_conn_ctx_t *ctx)
{
	/* log connection if we don't analyze any headers */
	if (!ctx->spec->http && (WANT_CONNECT_LOG(ctx) || ctx->opts->statslog)) {
		pxy_log_connect_nonhttp(ctx);
	}

	if (ctx->src.ssl && ctx->opts->certgendir) {
		/* write SSL certificates to gendir */
		protossl_srccert_write(ctx);
	}

	if (protossl_log_masterkey(ctx, &ctx->src) == -1) {
		return;
	}

	pxy_log_dbg_connect_type(ctx, &ctx->src);
}

void
pxy_log_connect_srv_dst(pxy_conn_ctx_t *ctx)
{
	// @attention srv_dst.bev may be NULL, if its writecb fires first
	if (ctx->srv_dst.bev) {
		/* log connection if we don't analyze any headers */
		if (!ctx->srv_dst.ssl && !ctx->spec->http && (WANT_CONNECT_LOG(ctx) || ctx->opts->statslog)) {
			pxy_log_connect_nonhttp(ctx);
		}

		if (protossl_log_masterkey(ctx, &ctx->srv_dst) == -1) {
			return;
		}

		pxy_log_dbg_connect_type(ctx, &ctx->srv_dst);
	}
}

void
pxy_log_dbg_evbuf_info(UNUSED pxy_conn_ctx_t *ctx, UNUSED pxy_conn_desc_t *this, UNUSED pxy_conn_desc_t *other)
{
#ifdef DEBUG_PROXY
	// Use ctx->conn, because this function is used by child conns too
	if (OPTS_DEBUG(ctx->conn->opts)) {
		log_dbg_printf("evbuffer size at EOF: i:%zu o:%zu i:%zu o:%zu\n",
						evbuffer_get_length(bufferevent_get_input(this->bev)),
						evbuffer_get_length(bufferevent_get_output(this->bev)),
						other->closed ? 0 : evbuffer_get_length(bufferevent_get_input(other->bev)),
						other->closed ? 0 : evbuffer_get_length(bufferevent_get_output(other->bev)));
	}
#endif /* DEBUG_PROXY */
}

void
pxy_log_dbg_disconnect(pxy_conn_ctx_t *ctx)
{
	// On parent connections, ctx->src.ssl is enough to know the type of connection
	/* we only get a single disconnect event here for both connections */
	if (OPTS_DEBUG(ctx->opts)) {
		log_dbg_printf("pxy_log_dbg_disconnect: %s disconnected to [%s]:%s, fd=%d\n",
					   ctx->src.ssl ? "SSL" : "TCP",
					   STRORDASH(ctx->dsthost_str), STRORDASH(ctx->dstport_str), ctx->fd);
		log_dbg_printf("pxy_log_dbg_disconnect: %s disconnected from [%s]:%s, fd=%d\n",
					   ctx->src.ssl ? "SSL" : "TCP",
					   STRORDASH(ctx->srchost_str), STRORDASH(ctx->srcport_str), ctx->fd);
	}
}

void
pxy_log_dbg_disconnect_child(pxy_conn_child_ctx_t *ctx)
{
	// On child connections, ctx->dst.ssl is enough to know the type of connection
	/* we only get a single disconnect event here for both connections */
	if (OPTS_DEBUG(ctx->conn->opts)) {
		log_dbg_printf("pxy_log_dbg_disconnect_child: %s disconnected to [%s]:%s, fd=%d, conn fd=%d\n",
					   ctx->dst.ssl ? "SSL" : "TCP",
					   STRORDASH(ctx->conn->dsthost_str), STRORDASH(ctx->conn->dstport_str), ctx->fd, ctx->conn->fd);
		log_dbg_printf("pxy_log_dbg_disconnect_child: %s disconnected from [%s]:%s, fd=%d, conn fd=%d\n",
					   ctx->dst.ssl ? "SSL" : "TCP",
					   STRORDASH(ctx->conn->srchost_str), STRORDASH(ctx->conn->srcport_str), ctx->fd, ctx->conn->fd);
	}
}

#ifdef HAVE_NETFILTER
/*
 * Copied from:
 * https://github.com/tmux/tmux/blob/master/compat/getdtablecount.c
 */
int
getdtablecount(void)
{
	char path[PATH_MAX];
	glob_t g;
	int n = 0;

	if (snprintf(path, sizeof path, "/proc/%ld/fd/*", (long)getpid()) < 0) {
		log_err_level_printf(LOG_CRIT, "snprintf overflow\n");
		return 0;
	}
	if (glob(path, 0, NULL, &g) == 0)
		n = g.gl_pathc;
	globfree(&g);
	return n;
}
#endif /* HAVE_NETFILTER */

unsigned char *
pxy_malloc_packet(size_t sz, pxy_conn_ctx_t *ctx)
{
	unsigned char *packet = malloc(sz);
	if (!packet) {
		// @todo Should we just set enomem?
		ctx->enomem = 1;
		pxy_conn_free(ctx, 1);
		return NULL;
	}
	return packet;
}

#ifdef DEBUG_PROXY
char *bev_names[] = {
	"src",
	"dst",
	"srv_dst",
	"NULL",
	"UNKWN"
	};

static char *
pxy_get_event_name(struct bufferevent *bev, pxy_conn_ctx_t *ctx)
{
	// XXX: Used by watermark functions only, remove
	if (bev == ctx->src.bev) {
		return bev_names[0];
	} else if (bev == ctx->dst.bev) {
		return bev_names[1];
	} else if (bev == ctx->srv_dst.bev) {
		return bev_names[2];
	} else if (bev == NULL) {
		log_dbg_level_printf(LOG_DBG_MODE_FINE, "pxy_get_event_name: event_name=NULL\n");
		return bev_names[3];
	} else {
		log_dbg_level_printf(LOG_DBG_MODE_FINE, "pxy_get_event_name: event_name=UNKWN\n");
		return bev_names[4];
	}
}
#endif /* DEBUG_PROXY */

void
pxy_set_watermark(struct bufferevent *bev, pxy_conn_ctx_t *ctx, struct bufferevent *other)
{
	if (evbuffer_get_length(bufferevent_get_output(other)) >= OUTBUF_LIMIT) {
#ifdef DEBUG_PROXY
		log_dbg_level_printf(LOG_DBG_MODE_FINE, "pxy_set_watermark: %s, fd=%d\n", pxy_get_event_name(bev, ctx), ctx->fd);
#endif /* DEBUG_PROXY */
		/* temporarily disable data source;
		 * set an appropriate watermark. */
		bufferevent_setwatermark(other, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT);
		bufferevent_disable(bev, EV_READ);
		ctx->thr->set_watermarks++;
	}
}

void
pxy_unset_watermark(struct bufferevent *bev, pxy_conn_ctx_t *ctx, pxy_conn_desc_t *other)
{
	if (other->bev && !(bufferevent_get_enabled(other->bev) & EV_READ)) {
#ifdef DEBUG_PROXY
		log_dbg_level_printf(LOG_DBG_MODE_FINE, "pxy_unset_watermark: %s, fd=%d\n", pxy_get_event_name(bev, ctx), ctx->fd);
#endif /* DEBUG_PROXY */
		/* data source temporarily disabled;
		 * re-enable and reset watermark to 0. */
		bufferevent_setwatermark(bev, EV_WRITE, 0, 0);
		bufferevent_enable(other->bev, EV_READ);
		ctx->thr->unset_watermarks++;
	}
}

void
pxy_discard_inbuf(struct bufferevent *bev)
{
	struct evbuffer *inbuf = bufferevent_get_input(bev);
	size_t inbuf_size = evbuffer_get_length(inbuf);

	log_dbg_printf("Warning: Drained %zu bytes (conn closed)\n", inbuf_size);
	evbuffer_drain(inbuf, inbuf_size);
}

void
pxy_insert_sslproxy_header(pxy_conn_ctx_t *ctx, unsigned char *packet, size_t *packet_size)
{
	// @attention Cannot use string manipulation functions; we are dealing with binary arrays here, not NULL-terminated strings
	if (!ctx->sent_header) {
		memmove(packet + ctx->header_len + 2, packet, *packet_size);
		memcpy(packet, ctx->header_str, ctx->header_len);
		memcpy(packet + ctx->header_len, "\r\n", 2);
		*packet_size+= ctx->header_len + 2;
		ctx->sent_header = 1;
	}
}

void
pxy_remove_sslproxy_header(unsigned char *packet, size_t *packet_size, pxy_conn_child_ctx_t *ctx)
{
	unsigned char *pos = memmem(packet, *packet_size, ctx->conn->header_str, ctx->conn->header_len);
	if (pos) {
		memmove(pos, pos + ctx->conn->header_len + 2, *packet_size - (pos - packet) - (ctx->conn->header_len + 2));
		*packet_size-= ctx->conn->header_len + 2;
#ifdef DEBUG_PROXY
		log_dbg_level_printf(LOG_DBG_MODE_FINER, "pxy_remove_sslproxy_header: REMOVED SSLproxy header, fd=%d\n", ctx->fd);
#endif /* DEBUG_PROXY */
	}
}

/*
 * Callback for accept events on the socket listener bufferevent.
 */
static void
pxy_listener_acceptcb_child(UNUSED struct evconnlistener *listener, evutil_socket_t fd,
                        UNUSED struct sockaddr *peeraddr, UNUSED int peeraddrlen, void *arg)
{
	pxy_conn_ctx_t *conn = arg;

	conn->atime = time(NULL);

#ifdef DEBUG_PROXY
	log_dbg_level_printf(LOG_DBG_MODE_FINEST, "pxy_listener_acceptcb_child: ENTER fd=%d, conn fd=%d, child_fd=%d\n", fd, conn->fd, conn->child_fd);

	char *host, *port;
	if (sys_sockaddr_str(peeraddr, peeraddrlen, &host, &port) == 0) {
		log_dbg_level_printf(LOG_DBG_MODE_FINEST, "pxy_listener_acceptcb_child: Peer addr=[%s]:%s, child fd=%d, conn fd=%d\n", host, port, fd, conn->fd);
		free(host);
		free(port);
	}
#endif /* DEBUG_PROXY */

	int dtable_count = getdtablecount();

#ifdef DEBUG_PROXY
	log_dbg_level_printf(LOG_DBG_MODE_FINEST, "pxy_listener_acceptcb_child: descriptor_table_size=%d, current fd count=%d, reserve=%d, fd=%d\n", descriptor_table_size, dtable_count, FD_RESERVE, fd);
#endif /* DEBUG_PROXY */

	// Close the conn if we are out of file descriptors, or libevent will crash us, @see pxy_conn_setup() for explanation
	if (dtable_count + FD_RESERVE >= descriptor_table_size) {
		errno = EMFILE;
		log_err_level_printf(LOG_CRIT, "Out of file descriptors\n");
		evutil_closesocket(fd);
		pxy_conn_free(conn, 1);
		return;
	}

	pxy_conn_child_ctx_t *ctx = pxy_conn_ctx_new_child(fd, conn);
	if (!ctx) {
		log_err_level_printf(LOG_CRIT, "Error allocating memory\n");
		evutil_closesocket(fd);
		pxy_conn_free(conn, 1);
		return;
	}

	// Prepend child ctx to conn ctx child list
	// @attention If the last child is deleted, the children list may become null again
	ctx->next = conn->children;
	conn->children = ctx;

	conn->child_count++;
	ctx->idx = conn->child_count;

	if (!ctx->conn->addrlen) {
		log_err_level_printf(LOG_CRIT, "Child no target address; aborting connection\n");
		evutil_closesocket(ctx->fd);
		pxy_conn_free(ctx->conn, 1);
		return;
	}

	ctx->src.ssl = NULL;
	ctx->src.bev = pxy_bufferevent_setup_child(ctx, ctx->fd, ctx->src.ssl);
	if (!ctx->src.bev) {
		log_err_level_printf(LOG_CRIT, "Error creating child src\n");
		evutil_closesocket(ctx->fd);
		pxy_conn_free(ctx->conn, 1);
		return;
	}

	ctx->src_fd = bufferevent_getfd(ctx->src.bev);
	ctx->conn->child_src_fd = ctx->src_fd;
	ctx->conn->thr->max_fd = MAX(ctx->conn->thr->max_fd, ctx->src_fd);
	
	// @attention Do not enable src events here yet, they will be enabled after dst connects

	/* create server-side socket and eventbuffer */
	// Children rely on the findings of parent
	ctx->protoctx->connectcb(ctx);

	bufferevent_enable(ctx->dst.bev, EV_READ|EV_WRITE);

	if (OPTS_DEBUG(ctx->conn->opts)) {
		char *host, *port;
		if (sys_sockaddr_str((struct sockaddr *)&ctx->conn->addr, ctx->conn->addrlen, &host, &port) != 0) {
			log_dbg_printf("pxy_listener_acceptcb_child: Connecting to [?]:?\n");
		} else {
			log_dbg_printf("pxy_listener_acceptcb_child: Connecting to [%s]:%s\n", host, port);
			free(host);
			free(port);
		}
	}

	/* initiate connection */
	// @attention No need to check retval here, the eventcb should handle the errors
	bufferevent_socket_connect(ctx->dst.bev, (struct sockaddr *)&ctx->conn->addr, ctx->conn->addrlen);
	
	ctx->dst_fd = bufferevent_getfd(ctx->dst.bev);
	ctx->conn->child_dst_fd = ctx->dst_fd;
	ctx->conn->thr->max_fd = MAX(ctx->conn->thr->max_fd, ctx->dst_fd);
}

int
pxy_setup_child_listener(pxy_conn_ctx_t *ctx)
{
	// @attention Defer child setup and evcl creation until after parent init is complete, otherwise (1) causes multithreading issues (proxy_listener_acceptcb is
	// running on a different thread from the conn, and we only have thrmgr mutex), and (2) we need to clean up less upon errors.
	// Child evcls use the evbase of the parent thread, otherwise we would get multithreading issues.
	if ((ctx->child_fd = privsep_client_opensock_child(ctx->clisock, ctx->spec)) == -1) {
		log_err_level_printf(LOG_CRIT, "Error opening child socket: %s (%i)\n", strerror(errno), errno);
		pxy_conn_free(ctx, 1);
		return -1;
	}
	ctx->thr->max_fd = MAX(ctx->thr->max_fd, ctx->child_fd);

	// @attention Do not pass NULL as user-supplied pointer
	struct evconnlistener *child_evcl = evconnlistener_new(ctx->thr->evbase, pxy_listener_acceptcb_child, ctx, LEV_OPT_CLOSE_ON_FREE, 1024, ctx->child_fd);
	if (!child_evcl) {
		log_err_level_printf(LOG_CRIT, "Error creating child evconnlistener: %s\n", strerror(errno));
#ifdef DEBUG_PROXY
		log_dbg_level_printf(LOG_DBG_MODE_FINER, "pxy_setup_child_listener: Error creating child evconnlistener: %s, fd=%d, child_fd=%d\n", strerror(errno), ctx->fd, ctx->child_fd);
#endif /* DEBUG_PROXY */
		// @attention Cannot call proxy_listener_ctx_free() on child_evcl, child_evcl does not have any ctx with next listener
		// @attention Close child fd separately, because child evcl does not exist yet, hence fd would not be closed by calling pxy_conn_free()
		evutil_closesocket(ctx->child_fd);
		pxy_conn_free(ctx, 1);
		return -1;
	}
	ctx->child_evcl = child_evcl;

	evconnlistener_set_error_cb(child_evcl, proxy_listener_errorcb);
#ifdef DEBUG_PROXY
	log_dbg_level_printf(LOG_DBG_MODE_FINER, "pxy_setup_child_listener: Finished setting up child, fd=%d, NEW child_fd=%d\n", ctx->fd, ctx->child_fd);	
#endif /* DEBUG_PROXY */

	struct sockaddr_in child_listener_addr;
	socklen_t child_listener_len = sizeof(child_listener_addr);

	if (getsockname(ctx->child_fd, (struct sockaddr *)&child_listener_addr, &child_listener_len) < 0) {
		log_err_level_printf(LOG_CRIT, "Error in getsockname: %s\n", strerror(errno));
		// @todo If getsockname() fails, should we really terminate the connection?
		// @attention Do not close the child fd here, because child evcl exists now, hence pxy_conn_free() will close it while freeing child_evcl
		pxy_conn_free(ctx, 1);
		return -1;
	}

	// @attention Children are always listening on an IPv4 loopback address
	char addr[INET_ADDRSTRLEN];
	if (!inet_ntop(AF_INET, &child_listener_addr.sin_addr, addr, INET_ADDRSTRLEN)) {
		pxy_conn_free(ctx, 1);
		return -1;
	}

	// SSLproxy: [127.0.0.1]:34649,[192.168.3.24]:47286,[74.125.206.108]:465,s
	// @todo Port may be less than 5 chars
	// SSLproxy:        +   + [ + addr         + ] + : + p + , + [ + srchost_str              + ] + : + srcport_str              + , + [ + dsthost_str              + ] + : + dstport_str              + , + s
	// SSLPROXY_KEY_LEN + 1 + 1 + strlen(addr) + 1 + 1 + 5 + 1 + 1 + strlen(ctx->srchost_str) + 1 + 1 + strlen(ctx->srcport_str) + 1 + 1 + strlen(ctx->dsthost_str) + 1 + 1 + strlen(ctx->dstport_str) + 1 + 1
	ctx->header_len = SSLPROXY_KEY_LEN + strlen(addr) + strlen(ctx->srchost_str) + strlen(ctx->srcport_str) + strlen(ctx->dsthost_str) + strlen(ctx->dstport_str) + 19;
	// @todo Always check malloc retvals. Should we close the conn if malloc fails?
	// +1 for NULL
	ctx->header_str = malloc(ctx->header_len + 1);
	if (!ctx->header_str) {
		pxy_conn_free(ctx, 1);
		return -1;
	}
	// printf(3): "snprintf() will write at most size-1 of the characters (the size'th character then gets the terminating NULL)"
	// So, +1 for NULL
	snprintf(ctx->header_str, ctx->header_len + 1, "%s [%s]:%u,[%s]:%s,[%s]:%s,%s",
			SSLPROXY_KEY, addr, ntohs(child_listener_addr.sin_port), STRORNONE(ctx->srchost_str), STRORNONE(ctx->srcport_str),
			STRORNONE(ctx->dsthost_str), STRORNONE(ctx->dstport_str), ctx->spec->ssl ? "s":"p");
	return 0;
}

int
pxy_close_conn_end_ifnodata(pxy_conn_desc_t *conn_end, pxy_conn_ctx_t *ctx, bufferevent_free_and_close_fd_func_t free_and_close_fd_func)
{
	/* if the other end is still open and doesn't have data
	 * to send, close it, otherwise its writecb will close
	 * it after writing what's left in the output buffer */
	if (evbuffer_get_length(bufferevent_get_output(conn_end->bev)) == 0) {
#ifdef DEBUG_PROXY
		log_dbg_level_printf(LOG_DBG_MODE_FINEST, "pxy_close_conn_end_ifnodata: evbuffer_get_length(outbuf) == 0, terminate conn, fd=%d\n", ctx->fd);
#endif /* DEBUG_PROXY */
		free_and_close_fd_func(conn_end->bev, ctx);
		conn_end->bev = NULL;
		conn_end->closed = 1;
		return 1;
	}
	return 0;
}

void
pxy_close_dst(pxy_conn_ctx_t *ctx)
{
#ifdef DEBUG_PROXY
	log_dbg_level_printf(LOG_DBG_MODE_FINER, "pxy_close_dst: Closing dst, fd=%d, dst fd=%d\n", ctx->fd, bufferevent_getfd(ctx->dst.bev));
#endif /* DEBUG_PROXY */
	pxy_bufferevent_free_and_close_fd(ctx->dst.bev, ctx);
	ctx->dst.bev = NULL;
	ctx->dst.closed = 1;
}

void
pxy_close_srv_dst(pxy_conn_ctx_t *ctx)
{
	// @attention Free the srv_dst of the conn asap, we don't need it anymore, but we need its fd
#ifdef DEBUG_PROXY
	log_dbg_level_printf(LOG_DBG_MODE_FINER, "pxy_close_srv_dst: Closing srv_dst, fd=%d, srv_dst fd=%d\n", ctx->fd, bufferevent_getfd(ctx->srv_dst.bev));
#endif /* DEBUG_PROXY */
	// So save its ssl info for logging
	if (ctx->srv_dst.ssl) {
		ctx->sslctx->srv_dst_ssl_version = strdup(SSL_get_version(ctx->srv_dst.ssl));
		ctx->sslctx->srv_dst_ssl_cipher = strdup(SSL_get_cipher(ctx->srv_dst.ssl));
	}

	// @attention When both eventcb and writecb for srv_dst are enabled, either eventcb or writecb may get a NULL srv_dst bev, causing a crash with signal 10.
	// So, from this point on, we should check if srv_dst is NULL or not.
	pxy_bufferevent_free_and_close_fd(ctx->srv_dst.bev, ctx);
	ctx->srv_dst.bev = NULL;
	ctx->srv_dst.closed = 1;
}

void
pxy_connect_srv_dst(struct bufferevent *bev, pxy_conn_ctx_t *ctx)
{
	if (!ctx->srv_dst_connected) {
#ifdef DEBUG_PROXY
		log_dbg_level_printf(LOG_DBG_MODE_FINE, "pxy_connect_srv_dst: writecb before connected, fd=%d\n", ctx->fd);
#endif /* DEBUG_PROXY */
		// @attention Sometimes dst write cb fires but not event cb, especially if the listener cb is not finished yet, so the conn stalls.
		// This is a workaround for this error condition, nothing else seems to work.
		// @attention Do not try to free the conn here, since the listener cb may not be finished yet, which causes multithreading issues
		// XXX: Workaround, should find the real cause: BEV_OPT_DEFER_CALLBACKS?
		ctx->protoctx->bev_eventcb(bev, BEV_EVENT_CONNECTED, ctx);
	}
}

void
pxy_disconnect(pxy_conn_ctx_t *ctx, pxy_conn_desc_t *this,
		bufferevent_free_and_close_fd_func_t this_free_and_close_fd_func, pxy_conn_desc_t *other, int is_requestor)
{
	// @attention srv_dst should never reach here unless in passthrough mode, its bev may be NULL
	this->closed = 1;
	this_free_and_close_fd_func(this->bev, ctx);
	this->bev = NULL;
	if (other->closed) {
#ifdef DEBUG_PROXY
		log_dbg_level_printf(LOG_DBG_MODE_FINEST, "pxy_disconnect: other->closed, terminate conn, fd=%d\n", ctx->fd);
#endif /* DEBUG_PROXY */
		pxy_conn_free(ctx, is_requestor);
	}
}

void
pxy_disconnect_child(pxy_conn_child_ctx_t *ctx, pxy_conn_desc_t *this,
		bufferevent_free_and_close_fd_func_t this_free_and_close_fd_func, pxy_conn_desc_t *other)
{
	this->closed = 1;
	this_free_and_close_fd_func(this->bev, ctx->conn);
	this->bev = NULL;
	if (other->closed) {
#ifdef DEBUG_PROXY
		log_dbg_level_printf(LOG_DBG_MODE_FINEST, "pxy_disconnect_child: other->closed, terminate conn, fd=%d, conn fd=%d\n", ctx->fd, ctx->conn->fd);
#endif /* DEBUG_PROXY */
		pxy_conn_free_child(ctx);
	}
}

void
pxy_consume_last_input(struct bufferevent *bev, pxy_conn_ctx_t *ctx)
{
	/* if there is data pending in the closed connection,
	 * handle it here, otherwise it will be lost. */
	if (evbuffer_get_length(bufferevent_get_input(bev))) {
#ifdef DEBUG_PROXY
		log_dbg_level_printf(LOG_DBG_MODE_FINEST, "pxy_consume_last_input: evbuffer_get_length(inbuf) > 0, terminate conn, fd=%d\n", ctx->fd);
#endif /* DEBUG_PROXY */
		ctx->protoctx->bev_readcb(bev, ctx);
	}
}

void
pxy_consume_last_input_child(struct bufferevent *bev, pxy_conn_child_ctx_t *ctx)
{
	/* if there is data pending in the closed connection,
	 * handle it here, otherwise it will be lost. */
	if (evbuffer_get_length(bufferevent_get_input(bev))) {
#ifdef DEBUG_PROXY
		log_dbg_level_printf(LOG_DBG_MODE_FINEST, "pxy_consume_last_input_child: evbuffer_get_length(inbuf) > 0, terminate conn, fd=%d, conn fd=%d\n", ctx->fd, ctx->conn->fd);
#endif /* DEBUG_PROXY */
		ctx->protoctx->bev_readcb(bev, ctx);
	}
}

static int
pxy_check_src_bev(pxy_conn_ctx_t *ctx)
{
	if (!ctx->src.bev) {
		log_err_level_printf(LOG_CRIT, "Error creating src bufferevent\n");
		if (ctx->src.ssl) {
			SSL_free(ctx->src.ssl);
			ctx->src.ssl = NULL;
		}
		pxy_conn_free(ctx, 1);
		return -1;
	}
	return 0;
}

int
pxy_setup_src(pxy_conn_ctx_t *ctx)
{
	ctx->src.bev = pxy_bufferevent_setup(ctx, ctx->fd, ctx->src.ssl);
	return pxy_check_src_bev(ctx);
}

int
pxy_setup_new_src(pxy_conn_ctx_t *ctx)
{
	ctx->src.bev = bufferevent_openssl_filter_new(ctx->evbase, ctx->src.bev, ctx->src.ssl,
			BUFFEREVENT_SSL_ACCEPTING, BEV_OPT_DEFER_CALLBACKS);
	return pxy_check_src_bev(ctx);
}

int
pxy_set_dstaddr(pxy_conn_ctx_t *ctx)
{
	if (sys_sockaddr_str((struct sockaddr *)&ctx->addr, ctx->addrlen, &ctx->dsthost_str, &ctx->dstport_str) != 0) {
		ctx->enomem = 1;
		pxy_conn_free(ctx, 1);
		return -1;
	}
	return 0;
}

int
pxy_setup_dst(pxy_conn_ctx_t *ctx)
{
	ctx->dst.ssl= NULL;
	ctx->dst.bev = pxy_bufferevent_setup(ctx, -1, ctx->dst.ssl);
	if (!ctx->dst.bev) {
		log_err_level_printf(LOG_CRIT, "Error creating parent dst\n");
		evutil_closesocket(ctx->fd);
		pxy_conn_ctx_free(ctx, 1);
		return -1;
	}
	return 0;
}

int
pxy_setup_srv_dst(pxy_conn_ctx_t *ctx)
{
	ctx->srv_dst.bev = pxy_bufferevent_setup(ctx, -1, ctx->srv_dst.ssl);
	if (!ctx->srv_dst.bev) {
		log_err_level_printf(LOG_CRIT, "Error creating srv_dst\n");
		if (ctx->srv_dst.ssl) {
			SSL_free(ctx->srv_dst.ssl);
			ctx->srv_dst.ssl = NULL;
		}
		pxy_conn_free(ctx, 1);
		return -1;
	}
	return 0;
}

/*
 * Callback for read events on the up- and downstream connection bufferevents.
 * Called when there is data ready in the input evbuffer.
 */
void
pxy_bev_readcb(struct bufferevent *bev, void *arg)
{
	pxy_conn_ctx_t *ctx = arg;
	ctx->atime = time(NULL);

	if (!ctx->connected) {
		log_err_level_printf(LOG_CRIT, "pxy_bev_readcb: readcb called when other end not connected - aborting.\n");
		log_exceptcb();
		return;
	}

	ctx->protoctx->bev_readcb(bev, ctx);
}

void
pxy_bev_readcb_child(struct bufferevent *bev, void *arg)
{
	pxy_conn_child_ctx_t *ctx = arg;
	ctx->conn->atime = time(NULL);

	if (!ctx->connected) {
		log_err_level_printf(LOG_CRIT, "pxy_bev_readcb_child: readcb called when other end not connected - aborting.\n");
		log_exceptcb();
		return;
	}

	ctx->protoctx->bev_readcb(bev, ctx);
}

/*
 * Callback for write events on the up- and downstream connection bufferevents.
 * Called when either all data from the output evbuffer has been written,
 * or if the outbuf is only half full again after having been full.
 */
void
pxy_bev_writecb(struct bufferevent *bev, void *arg)
{
	pxy_conn_ctx_t *ctx = arg;
	ctx->atime = time(NULL);
	ctx->protoctx->bev_writecb(bev, ctx);
}

void
pxy_bev_writecb_child(struct bufferevent *bev, void *arg)
{
	pxy_conn_child_ctx_t *ctx = arg;
	ctx->conn->atime = time(NULL);
	ctx->protoctx->bev_writecb(bev, ctx);
}

/*
 * Callback for meta events on the up- and downstream connection bufferevents.
 * Called when EOF has been reached, a connection has been made, and on errors.
 */
void
pxy_bev_eventcb(struct bufferevent *bev, short events, void *arg)
{
	pxy_conn_ctx_t *ctx = arg;
	ctx->atime = time(NULL);
	ctx->protoctx->bev_eventcb(bev, events, arg);
}

void
pxy_bev_eventcb_child(struct bufferevent *bev, short events, void *arg)
{
	pxy_conn_child_ctx_t *ctx = arg;
	ctx->conn->atime = time(NULL);
	ctx->protoctx->bev_eventcb(bev, events, arg);
}

/*
 * Complete the connection.  This gets called after finding out where to
 * connect to.
 */
void
pxy_conn_connect(pxy_conn_ctx_t *ctx)
{
#ifdef DEBUG_PROXY
	log_dbg_level_printf(LOG_DBG_MODE_FINEST, "pxy_conn_connect: ENTER fd=%d\n", ctx->fd);
#endif /* DEBUG_PROXY */
	if (!ctx->addrlen) {
		log_err_level_printf(LOG_CRIT, "No target address; aborting connection\n");
		evutil_closesocket(ctx->fd);
		pxy_conn_ctx_free(ctx, 1);
		return;
	}

	if (OPTS_DEBUG(ctx->opts)) {
		char *host, *port;
		if (sys_sockaddr_str((struct sockaddr *)&ctx->addr,
		                     ctx->addrlen, &host, &port) != 0) {
			log_dbg_printf("Connecting to [?]:?\n");
		} else {
			log_dbg_printf("Connecting to [%s]:%s\n", host, port);
			free(host);
			free(port);
		}
	}

	ctx->protoctx->connectcb(ctx);
	// @attention Do not do anything else with the ctx after connecting socket, otherwise if pxy_bev_eventcb fires on error, such as due to "No route to host",
	// the conn is closed and freed up, and we get multithreading issues, e.g. signal 11. We are on the thrmgr thread. So, just return.
}

/*
 * The src fd is readable.  This is used to sneak-preview the SNI on SSL
 * connections.  If ctx->ev is NULL, it was called manually for a non-SSL
 * connection.  If ctx->passthrough is set, it was called a second time
 * after the first ssl callout failed because of client cert auth.
 */
void
pxy_fd_readcb(evutil_socket_t fd, UNUSED short what, void *arg)
{
	pxy_conn_ctx_t *ctx = arg;
#ifdef DEBUG_PROXY
	log_dbg_level_printf(LOG_DBG_MODE_FINEST, "pxy_fd_readcb: ENTER fd=%d\n", ctx->fd);
#endif /* DEBUG_PROXY */

	ctx->atime = time(NULL);
	ctx->protoctx->fd_readcb(fd, what, arg);
}

/*
 * Callback for accept events on the socket listener bufferevent.
 * Called when a new incoming connection has been accepted.
 * Initiates the connection to the server.  The incoming connection
 * from the client is not being activated until we have a successful
 * connection to the server, because we need the server's certificate
 * in order to set up the SSL session to the client.
 * For consistency, plain TCP works the same way, even if we could
 * start reading from the client while waiting on the connection to
 * the server to connect.
 */
void
pxy_conn_setup(evutil_socket_t fd,
               struct sockaddr *peeraddr, int peeraddrlen,
               pxy_thrmgr_ctx_t *thrmgr,
               proxyspec_t *spec, opts_t *opts,
			   evutil_socket_t clisock)
{
	int dtable_count = getdtablecount();

#ifdef DEBUG_PROXY
	log_dbg_level_printf(LOG_DBG_MODE_FINEST, "pxy_conn_setup: ENTER fd=%d\n", fd);

	char *host, *port;
	if (sys_sockaddr_str(peeraddr, peeraddrlen, &host, &port) == 0) {
		log_dbg_level_printf(LOG_DBG_MODE_FINEST, "pxy_conn_setup: Peer=[%s]:%s, fd=%d\n", host, port, fd);
		free(host);
		free(port);
	}

	log_dbg_level_printf(LOG_DBG_MODE_FINEST, "pxy_conn_setup: descriptor_table_size=%d, current fd count=%d, reserve=%d\n", descriptor_table_size, dtable_count, FD_RESERVE);
#endif /* DEBUG_PROXY */

	// Close the conn if we are out of file descriptors, or libevent will crash us
	// @attention We cannot guess the number of children in a connection at conn setup time. So, FD_RESERVE is just a ball park figure.
	// But what if a connection passes the check below, but eventually tries to create more children than FD_RESERVE allows for? This will crash us the same.
	// Beware, this applies to all current conns, not just the last connection setup.
	// For example, 20x conns pass the check below before creating any children, at which point we reach at the last FD_RESERVE fds,
	// then they all start creating children, which crashes us again.
	// So, no matter how large an FD_RESERVE we choose, there will always be a risk of running out of fds, if we check the number of fds here only.
	// If we are left with less than FD_RESERVE fds, we should not create more children than FD_RESERVE allows for either.
	// Therefore, we check if we are out of fds in proxy_listener_acceptcb_child() and close the conn there too.
	// @attention These checks are expected to slow us further down, but it is critical to avoid a crash in case we run out of fds.
	if (dtable_count + FD_RESERVE >= descriptor_table_size) {
		errno = EMFILE;
		log_err_level_printf(LOG_CRIT, "Out of file descriptors\n");
		evutil_closesocket(fd);
		return;
	}

	/* create per connection state and attach to thread */
	pxy_conn_ctx_t *ctx = pxy_conn_ctx_new(fd, thrmgr, spec, opts, clisock);
	if (!ctx) {
		log_err_level_printf(LOG_CRIT, "Error allocating memory\n");
		evutil_closesocket(fd);
		return;
	}

	ctx->af = peeraddr->sa_family;
	ctx->thr->max_fd = MAX(ctx->thr->max_fd, ctx->fd);

	/* determine original destination of connection */
	if (spec->natlookup) {
		/* NAT engine lookup */
		ctx->addrlen = sizeof(struct sockaddr_storage);
		if (spec->natlookup((struct sockaddr *)&ctx->addr, &ctx->addrlen, fd, peeraddr, peeraddrlen) == -1) {
			log_err_printf("Connection not found in NAT state table, aborting connection\n");
			evutil_closesocket(fd);
			pxy_conn_ctx_free(ctx, 1);
			return;
		}
	} else if (spec->connect_addrlen > 0) {
		/* static forwarding */
		ctx->addrlen = spec->connect_addrlen;
		memcpy(&ctx->addr, &spec->connect_addr, ctx->addrlen);
	} else {
		/* SNI mode */
		if (!ctx->spec->ssl) {
			/* if this happens, the proxyspec parser is broken */
			log_err_printf("SNI mode used for non-SSL connection; aborting connection\n");
			evutil_closesocket(fd);
			pxy_conn_ctx_free(ctx, 1);
			return;
		}
	}

	if (sys_sockaddr_str(peeraddr, peeraddrlen, &ctx->srchost_str, &ctx->srcport_str) != 0) {
		goto memout;
	}

	/* prepare logging, part 1 */
	if (WANT_CONNECT_LOG(ctx) || WANT_CONTENT_LOG(ctx)) {
#ifdef HAVE_LOCAL_PROCINFO
		if (ctx->opts->lprocinfo) {
			memcpy(&ctx->lproc.srcaddr, peeraddr, peeraddrlen);
			ctx->lproc.srcaddrlen = peeraddrlen;
		}
#endif /* HAVE_LOCAL_PROCINFO */
	}

	/* for SSL, defer dst connection setup to initial_readcb */
	if (ctx->spec->ssl) {
		ctx->ev = event_new(ctx->evbase, fd, EV_READ, ctx->protoctx->fd_readcb, ctx);
		if (!ctx->ev)
			goto memout;
		event_add(ctx->ev, NULL);
	} else {
		ctx->protoctx->fd_readcb(fd, 0, ctx);
	}
	return;

memout:
	log_err_level_printf(LOG_CRIT, "Aborting connection setup (out of memory)!\n");
	evutil_closesocket(fd);
	pxy_conn_ctx_free(ctx, 1);
}

/* vim: set noet ft=c: */