Do not call topmost callback functions directly, use them in bufferevent setup only, otherwise can possibly cause double free of ctx

Run preexec and postexec logging and/or stats code when calling interface callback functions directly, they are mostly called in edge cases, but otherwise we would miss related logs and/or stats

protoautossl.c

@@ -563,7 +563,10 @@ protoautossl_bev_eventcb_connected_dst_child(UNUSED struct bufferevent *bev, pxy
 		log_dbg_level_printf(LOG_DBG_MODE_FINER, "protoautossl_bev_eventcb_connected_dst_child: clienthello_found src inbuf len > 0, calling pxy_bev_readcb_child for src, child fd=%d, fd=%d\n", ctx->fd, ctx->conn->fd);
 #endif /* DEBUG_PROXY */
 
-		pxy_bev_readcb_child(ctx->src.bev, ctx);
+		if (pxy_bev_readcb_preexec_logging_and_stats_child(bev, ctx) == -1) {
+			return;
+		}
+		ctx->protoctx->bev_readcb(ctx->src.bev, ctx);
 	}
 }
 

protopassthrough.c

@@ -192,7 +192,9 @@ protopassthrough_bev_writecb_srvdst(struct bufferevent *bev, pxy_conn_ctx_t *ctx
 #endif /* DEBUG_PROXY */
 
 	if (!ctx->srvdst_connected) {
-		pxy_connect_srvdst(bev, ctx);
+		if (pxy_connect_srvdst(bev, ctx) == -1) {
+			return;
+		}
 	}
 
 	if (ctx->src.closed) {
@@ -277,7 +279,9 @@ protopassthrough_bev_eventcb_eof_src(struct bufferevent *bev, pxy_conn_ctx_t *ct
 		log_dbg_level_printf(LOG_DBG_MODE_FINEST, "protopassthrough_bev_eventcb_eof_src: !other->closed, terminate conn, fd=%d\n", ctx->fd);
 #endif /* DEBUG_PROXY */
 
-		pxy_try_consume_last_input(bev, ctx);
+		if (pxy_try_consume_last_input(bev, ctx) == -1) {
+			return;
+		}
 		pxy_try_close_conn_end(&ctx->srvdst, ctx, &prototcp_bufferevent_free_and_close_fd);
 	}
 
@@ -304,7 +308,9 @@ protopassthrough_bev_eventcb_eof_srvdst(struct bufferevent *bev, pxy_conn_ctx_t
 		log_dbg_level_printf(LOG_DBG_MODE_FINEST, "protopassthrough_bev_eventcb_eof_srvdst: !other->closed, terminate conn, fd=%d\n", ctx->fd);
 #endif /* DEBUG_PROXY */
 
-		pxy_try_consume_last_input(bev, ctx);
+		if (pxy_try_consume_last_input(bev, ctx) == -1) {
+			return;
+		}
 		pxy_try_close_conn_end(&ctx->src, ctx, &prototcp_bufferevent_free_and_close_fd);
 	}
 

prototcp.c

@@ -391,7 +391,7 @@ prototcp_bev_writecb_src(struct bufferevent *bev, pxy_conn_ctx_t *ctx)
 	pxy_try_unset_watermark(bev, ctx, &ctx->dst);
 }
 
-static void NONNULL(1,2)
+static int NONNULL(1,2)
 prototcp_connect_dst(struct bufferevent *bev, pxy_conn_ctx_t *ctx)
 {
 #ifdef DEBUG_PROXY
@@ -403,6 +403,8 @@ prototcp_connect_dst(struct bufferevent *bev, pxy_conn_ctx_t *ctx)
 	// @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);
+
+	return pxy_bev_eventcb_postexec_logging_and_stats(bev, BEV_EVENT_CONNECTED, ctx);
 }
 
 static void NONNULL(1)
@@ -413,7 +415,9 @@ prototcp_bev_writecb_dst(struct bufferevent *bev, pxy_conn_ctx_t *ctx)
 #endif /* DEBUG_PROXY */
 
 	if (!ctx->dst_connected) {
-		prototcp_connect_dst(bev, ctx);
+		if (prototcp_connect_dst(bev, ctx) == -1) {
+			return;
+		}
 	}
 
 	if (ctx->src.closed) {
@@ -473,6 +477,8 @@ prototcp_connect_dst_child(struct bufferevent *bev, pxy_conn_child_ctx_t *ctx)
 	// @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);
+
+	pxy_bev_eventcb_postexec_stats_child(BEV_EVENT_CONNECTED, ctx);
 }
 
 static void NONNULL(1)
@@ -611,7 +617,9 @@ prototcp_bev_eventcb_eof_src(struct bufferevent *bev, pxy_conn_ctx_t *ctx)
 		log_dbg_level_printf(LOG_DBG_MODE_FINEST, "prototcp_bev_eventcb_eof_src: !other->closed, terminate conn, fd=%d\n", ctx->fd);
 #endif /* DEBUG_PROXY */
 
-		pxy_try_consume_last_input(bev, ctx);
+		if (pxy_try_consume_last_input(bev, ctx) == -1) {
+			return;
+		}
 		pxy_try_close_conn_end(&ctx->dst, ctx, &prototcp_bufferevent_free_and_close_fd);
 	}
 
@@ -638,7 +646,9 @@ prototcp_bev_eventcb_eof_dst(struct bufferevent *bev, pxy_conn_ctx_t *ctx)
 		log_dbg_level_printf(LOG_DBG_MODE_FINEST, "prototcp_bev_eventcb_eof_dst: !other->closed, terminate conn, fd=%d\n", ctx->fd);
 #endif /* DEBUG_PROXY */
 
-		pxy_try_consume_last_input(bev, ctx);
+		if (pxy_try_consume_last_input(bev, ctx) == -1) {
+			return;
+		}
 		pxy_try_close_conn_end(&ctx->src, ctx, ctx->protoctx->bufferevent_free_and_close_fd);
 	}
 
@@ -746,7 +756,9 @@ prototcp_bev_eventcb_eof_src_child(struct bufferevent *bev, pxy_conn_child_ctx_t
 		log_dbg_level_printf(LOG_DBG_MODE_FINEST, "prototcp_bev_eventcb_eof_src_child: !other->closed, terminate conn, child fd=%d, fd=%d\n", ctx->fd, ctx->conn->fd);
 #endif /* DEBUG_PROXY */
 
-		pxy_try_consume_last_input_child(bev, ctx);
+		if (pxy_try_consume_last_input_child(bev, ctx) == -1) {
+			return;
+		}
 		pxy_try_close_conn_end(&ctx->dst, ctx->conn, ctx->protoctx->bufferevent_free_and_close_fd);
 	}
 
@@ -774,7 +786,9 @@ prototcp_bev_eventcb_eof_dst_child(struct bufferevent *bev, pxy_conn_child_ctx_t
 		log_dbg_level_printf(LOG_DBG_MODE_FINEST, "prototcp_bev_eventcb_eof_dst_child: !other->closed, terminate conn, child fd=%d, fd=%d\n", ctx->fd, ctx->conn->fd);
 #endif /* DEBUG_PROXY */
 
-		pxy_try_consume_last_input_child(bev, ctx);
+		if (pxy_try_consume_last_input_child(bev, ctx) == -1) {
+			return;
+		}
 		pxy_try_close_conn_end(&ctx->src, ctx->conn, &prototcp_bufferevent_free_and_close_fd);
 	}
 

pxyconn.c

@@ -1146,7 +1146,7 @@ pxy_try_close_conn_end(pxy_conn_desc_t *conn_end, pxy_conn_ctx_t *ctx, buffereve
 	return 0;
 }
 
-void
+int
 pxy_connect_srvdst(struct bufferevent *bev, pxy_conn_ctx_t *ctx)
 {
 #ifdef DEBUG_PROXY
@@ -1158,6 +1158,8 @@ pxy_connect_srvdst(struct bufferevent *bev, pxy_conn_ctx_t *ctx)
 	// @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);
+
+	return pxy_bev_eventcb_postexec_logging_and_stats(bev, BEV_EVENT_CONNECTED, ctx);
 }
 
 void
@@ -1197,7 +1199,7 @@ pxy_try_disconnect_child(pxy_conn_child_ctx_t *ctx, pxy_conn_desc_t *this,
 	}
 }
 
-void
+int
 pxy_try_consume_last_input(struct bufferevent *bev, pxy_conn_ctx_t *ctx)
 {
 	/* if there is data pending in the closed connection,
@@ -1207,11 +1209,15 @@ pxy_try_consume_last_input(struct bufferevent *bev, pxy_conn_ctx_t *ctx)
 		log_dbg_level_printf(LOG_DBG_MODE_FINE, "pxy_try_consume_last_input: evbuffer_get_length(inbuf) > 0, terminate conn, fd=%d\n", ctx->fd);
 #endif /* DEBUG_PROXY */
 
+		if (pxy_bev_readcb_preexec_logging_and_stats(bev, ctx) == -1) {
+			return -1;
+		}
 		ctx->protoctx->bev_readcb(bev, ctx);
 	}
+	return 0;
 }
 
-void
+int
 pxy_try_consume_last_input_child(struct bufferevent *bev, pxy_conn_child_ctx_t *ctx)
 {
 	/* if there is data pending in the closed connection,
@@ -1221,8 +1227,12 @@ pxy_try_consume_last_input_child(struct bufferevent *bev, pxy_conn_child_ctx_t *
 		log_dbg_level_printf(LOG_DBG_MODE_FINE, "pxy_try_consume_last_input_child: evbuffer_get_length(inbuf) > 0, terminate conn, child fd=%d, fd=%d\n", ctx->fd, ctx->conn->fd);
 #endif /* DEBUG_PROXY */
 
+		if (pxy_bev_readcb_preexec_logging_and_stats_child(bev, ctx) == -1) {
+			return -1;
+		}
 		ctx->protoctx->bev_readcb(bev, ctx);
 	}
+	return 0;
 }
 
 int
@@ -1237,15 +1247,9 @@ pxy_set_dstaddr(pxy_conn_ctx_t *ctx)
 	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)
+int
+pxy_bev_readcb_preexec_logging_and_stats(struct bufferevent *bev, pxy_conn_ctx_t *ctx)
 {
-	pxy_conn_ctx_t *ctx = arg;
-
 	if (bev == ctx->src.bev || bev == ctx->dst.bev) {
 		struct evbuffer *inbuf = bufferevent_get_input(bev);
 		size_t inbuf_size = evbuffer_get_length(inbuf);
@@ -1259,10 +1263,25 @@ pxy_bev_readcb(struct bufferevent *bev, void *arg)
 		if (ctx->proto != PROTO_PASSTHROUGH) {
 			// HTTP content logging at this point may record certain headers twice, if we have not seen all header lines yet
 			if (pxy_log_content_inbuf(ctx, inbuf, (bev == ctx->src.bev)) == -1) {
-				goto memout;
+				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;
+
+	if (pxy_bev_readcb_preexec_logging_and_stats(bev, ctx) == -1) {
+		goto memout;
+	}
 
 	if (!ctx->connected) {
 		log_err_level_printf(LOG_CRIT, "pxy_bev_readcb: readcb called when not connected - aborting.\n");
@@ -1284,11 +1303,9 @@ memout:
 	}
 }
 
-void
-pxy_bev_readcb_child(struct bufferevent *bev, void *arg)
+int
+pxy_bev_readcb_preexec_logging_and_stats_child(struct bufferevent *bev, pxy_conn_child_ctx_t *ctx)
 {
-	pxy_conn_child_ctx_t *ctx = arg;
-
 	struct evbuffer *inbuf = bufferevent_get_input(bev);
 	size_t inbuf_size = evbuffer_get_length(inbuf);
 
@@ -1300,9 +1317,20 @@ pxy_bev_readcb_child(struct bufferevent *bev, void *arg)
 
 	if (ctx->proto != PROTO_PASSTHROUGH) {
 		if (pxy_log_content_inbuf((pxy_conn_ctx_t *)ctx, inbuf, (bev == ctx->src.bev)) == -1) {
-			goto memout;
+			return -1;
 		}
 	}
+	return 0;
+}
+
+void
+pxy_bev_readcb_child(struct bufferevent *bev, void *arg)
+{
+	pxy_conn_child_ctx_t *ctx = arg;
+
+	if (pxy_bev_readcb_preexec_logging_and_stats_child(bev, ctx) == -1) {
+		goto memout;
+	}
 
 	if (!ctx->connected) {
 		log_err_level_printf(LOG_CRIT, "pxy_bev_readcb_child: readcb called when not connected - aborting.\n");
@@ -1375,26 +1403,11 @@ pxy_bev_writecb_child(struct bufferevent *bev, void *arg)
 	}
 }
 
-/*
- * 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)
+int
+pxy_bev_eventcb_postexec_logging_and_stats(struct bufferevent *bev, short events, pxy_conn_ctx_t *ctx)
 {
-	pxy_conn_ctx_t *ctx = arg;
-
-	ctx->atime = time(NULL);
-
-	if (events & BEV_EVENT_ERROR) {
-		log_err_printf("Client-side BEV_EVENT_ERROR\n");
-		ctx->thr->errors++;
-	}
-
-	ctx->protoctx->bev_eventcb(bev, events, arg);
-
 	if (ctx->term || ctx->enomem) {
-		goto out;
+		return -1;
 	}
 
 	if (events & BEV_EVENT_CONNECTED) {
@@ -1405,7 +1418,7 @@ pxy_bev_eventcb(struct bufferevent *bev, short events, void *arg)
 				pxy_log_connect_src(ctx);
 			} else if (ctx->connected) {
 				if (pxy_prepare_logging(ctx) == -1) {
-					goto out;
+					return -1;
 				}
 				// Doesn't log connect if proto is http, http proto does its own connect logging
 				pxy_log_connect_srvdst(ctx);
@@ -1424,8 +1437,29 @@ pxy_bev_eventcb(struct bufferevent *bev, short events, void *arg)
 			}
 		}
 	}
+	return 0;
+}
+
+/*
+ * 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);
+
+	if (events & BEV_EVENT_ERROR) {
+		log_err_printf("Client-side BEV_EVENT_ERROR\n");
+		ctx->thr->errors++;
+	}
+
+	ctx->protoctx->bev_eventcb(bev, events, arg);
+
+	pxy_bev_eventcb_postexec_logging_and_stats(bev, events, ctx);
 
-out:
 	// Logging functions may set term or enomem too
 	if (ctx->term) {
 		pxy_conn_free(ctx, ctx->term_requestor);
@@ -1438,6 +1472,14 @@ out:
 	}
 }
 
+void
+pxy_bev_eventcb_postexec_stats_child(short events, pxy_conn_child_ctx_t *ctx)
+{
+	if (events & BEV_EVENT_CONNECTED) {
+		ctx->conn->thr->max_fd = MAX(ctx->conn->thr->max_fd, MAX(bufferevent_getfd(ctx->src.bev), bufferevent_getfd(ctx->dst.bev)));
+	}
+}
+
 void
 pxy_bev_eventcb_child(struct bufferevent *bev, short events, void *arg)
 {
@@ -1468,9 +1510,7 @@ pxy_bev_eventcb_child(struct bufferevent *bev, short events, void *arg)
 		return;
 	}
 
-	if (events & BEV_EVENT_CONNECTED) {
-		ctx->conn->thr->max_fd = MAX(ctx->conn->thr->max_fd, MAX(bufferevent_getfd(ctx->src.bev), bufferevent_getfd(ctx->dst.bev)));
-	}
+	pxy_bev_eventcb_postexec_stats_child(events, ctx);
 }
 
 /*

pxyconn.h

@@ -321,8 +321,8 @@ int pxy_try_close_conn_end(pxy_conn_desc_t *, pxy_conn_ctx_t *, bufferevent_free
 void pxy_try_disconnect(pxy_conn_ctx_t *, pxy_conn_desc_t *, bufferevent_free_and_close_fd_func_t, pxy_conn_desc_t *, int) NONNULL(1,2,3,4);
 void pxy_try_disconnect_child(pxy_conn_child_ctx_t *, pxy_conn_desc_t *, bufferevent_free_and_close_fd_func_t, pxy_conn_desc_t *) NONNULL(1,2,3,4);
 
-void pxy_try_consume_last_input(struct bufferevent *, pxy_conn_ctx_t *) NONNULL(1,2);
-void pxy_try_consume_last_input_child(struct bufferevent *, pxy_conn_child_ctx_t *) NONNULL(1,2);
+int pxy_try_consume_last_input(struct bufferevent *, pxy_conn_ctx_t *) NONNULL(1,2);
+int pxy_try_consume_last_input_child(struct bufferevent *, pxy_conn_child_ctx_t *) NONNULL(1,2);
 void pxy_discard_inbuf(struct bufferevent *) NONNULL(1);
 
 void pxy_conn_ctx_free(pxy_conn_ctx_t *, int) NONNULL(1);
@@ -331,14 +331,20 @@ void pxy_conn_term(pxy_conn_ctx_t *, int) NONNULL(1);
 void pxy_conn_term_child(pxy_conn_child_ctx_t *) NONNULL(1);
 void pxy_conn_free_children(pxy_conn_ctx_t *) NONNULL(1);
 
-void pxy_connect_srvdst(struct bufferevent *, pxy_conn_ctx_t *) NONNULL(1,2);
+int pxy_connect_srvdst(struct bufferevent *, pxy_conn_ctx_t *) NONNULL(1,2);
 
 int pxy_setup_child_listener(pxy_conn_ctx_t *) NONNULL(1);
 
+int pxy_bev_readcb_preexec_logging_and_stats(struct bufferevent *, pxy_conn_ctx_t *) NONNULL(1,2);
+int pxy_bev_eventcb_postexec_logging_and_stats(struct bufferevent *, short , pxy_conn_ctx_t *) NONNULL(1,3);
+
 void pxy_bev_readcb(struct bufferevent *, void *);
 void pxy_bev_writecb(struct bufferevent *, void *);
 void pxy_bev_eventcb(struct bufferevent *, short, void *);
 
+int pxy_bev_readcb_preexec_logging_and_stats_child(struct bufferevent *, pxy_conn_child_ctx_t *) NONNULL(1,2);
+void pxy_bev_eventcb_postexec_stats_child(short, pxy_conn_child_ctx_t *) NONNULL(2);
+
 void pxy_bev_readcb_child(struct bufferevent *, void *);
 void pxy_bev_writecb_child(struct bufferevent *, void *);
 void pxy_bev_eventcb_child(struct bufferevent *, short, void *);