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.

Clean-up
This commit is contained in:
Soner Tari 2017-07-10 17:26:58 +03:00
parent 590a693998
commit 85875be00f
2 changed files with 32 additions and 26 deletions

View File

@ -1235,7 +1235,7 @@ bufferevent_free_and_close_fd(struct bufferevent *bev, pxy_conn_ctx_t *ctx)
}
#endif /* DEBUG_PROXY */
// @todo Check if we need to NULL all cbs.
// @todo Check if we need to NULL all cbs?
// @see https://stackoverflow.com/questions/31688709/knowing-all-callbacks-have-run-with-libevent-and-bufferevent-free
//bufferevent_setcb(bev, NULL, NULL, NULL, NULL);
bufferevent_free(bev); /* does not free SSL unless the option
@ -2405,7 +2405,7 @@ pxy_bev_readcb(struct bufferevent *bev, void *arg)
free(header_head);
free(header_tail);
} else {
log_dbg_level_printf(LOG_DBG_MODE_FINE, ">>>>>,,,,,,,,,,,,,,,,,,,,,,, pxy_bev_readcb: No CRNL in packet\n");
log_dbg_level_printf(LOG_DBG_MODE_FINE, ">>>>>,,,,,,,,,,,,,,,,,,,,,,, pxy_bev_readcb: No CRLF in packet\n");
packet_size-= custom_field_len;
packet_size++;
}
@ -2883,15 +2883,22 @@ pxy_bev_writecb(struct bufferevent *bev, void *arg)
// @attention Get the mctx pointer now, because we may need to free it after freeing ctx
proxy_conn_meta_ctx_t *mctx = ctx->mctx;
log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>>+++++++++++++++++++++++++++++++++++ pxy_bev_writecb: ENTER fd=%d, fd2=%d\n", mctx->fd, mctx->child_fd);
char *event_name = pxy_get_event_name(bev, ctx);
log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>>+++++++++++++++++++++++++++++++++++ pxy_bev_writecb: ENTER %s fd=%d, fd2=%d, cfd=%d\n", event_name, mctx->fd, mctx->child_fd, ctx->fd);
if (bev==ctx->dst.bev) {
// @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.
// XXX: Workaround, should find the real cause
log_dbg_level_printf(LOG_DBG_MODE_FINE, ">>>>>+++++++++++++++++++++++++++++++++++ pxy_bev_writecb: pxy_all_conn_free %s fd=%d, fd2=%d, cfd=%d <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< DST W CB B4 CONNECTED\n", event_name, mctx->fd, mctx->child_fd, ctx->fd);
pxy_all_conn_free(mctx);
return;
}
int rv = 0;
mctx->access_time = time(NULL);
char *event_name = pxy_get_event_name(bev, ctx);
log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>>+++++++++++++++++++++++++++++++++++ pxy_bev_writecb: %s, %d\n", event_name, ctx->fd);
if ((bev==ctx->src.bev) || (bev==ctx->e2src.bev)) {
pxy_conn_desc_t *this = (bev==ctx->src.bev) ? &ctx->src : &ctx->e2src;
pxy_conn_desc_t *other = (bev==ctx->src.bev) ? &ctx->e2src : &ctx->src;
@ -2940,15 +2947,14 @@ pxy_bev_writecb_child(struct bufferevent *bev, void *arg)
// @attention Get the mctx pointer now, because we may need to free it after freeing ctx
proxy_conn_meta_ctx_t *mctx = ctx->mctx;
log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>>??????????????????????????? pxy_bev_writecb_child: ENTER fd=%d, fd2=%d\n", mctx->fd, mctx->child_fd);
char *event_name = pxy_get_event_name(bev, ctx);
log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>>??????????????????????????? pxy_bev_writecb_child: ENTER %s fd=%d, fd2=%d, cfd=%d\n", event_name, mctx->fd, mctx->child_fd, ctx->fd);
int rv = 0;
mctx->access_time = time(NULL);
char *event_name = pxy_get_event_name(bev, ctx);
log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>>??????????????????????????? pxy_bev_writecb_child: %s, %d\n", event_name, ctx->fd);
pxy_conn_desc_t *this = (bev==ctx->e2dst.bev) ? &ctx->e2dst : &ctx->dst;
pxy_conn_desc_t *other = (bev==ctx->e2dst.bev) ? &ctx->dst : &ctx->e2dst;
void (*this_free_and_close_fd_func)(struct bufferevent *, pxy_conn_ctx_t *) = (bev==ctx->e2dst.bev) ? &bufferevent_free_and_close_fd_nonssl : &bufferevent_free_and_close_fd;
@ -3360,12 +3366,12 @@ pxy_bev_eventcb_child(struct bufferevent *bev, short events, void *arg)
evutil_closesocket(ctx->fd);
other->closed = 1;
} else if (!other->closed) {
log_dbg_level_printf(LOG_DBG_MODE_FINE, ">>>>>=================================== pxy_bev_eventcb_child: !other->closed <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< CONN TERM\n");
log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>>=================================== pxy_bev_eventcb_child: !other->closed <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< CONN TERM\n");
struct evbuffer *inbuf, *outbuf;
inbuf = bufferevent_get_input(bev);
outbuf = bufferevent_get_output(other->bev);
if (evbuffer_get_length(inbuf) > 0) {
log_dbg_level_printf(LOG_DBG_MODE_FINE, ">>>>>=================================== pxy_bev_eventcb_child: evbuffer_get_length(inbuf) > 0 <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< CONN TERM\n");
log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>>=================================== pxy_bev_eventcb_child: evbuffer_get_length(inbuf) > 0 <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< CONN TERM\n");
pxy_bev_readcb_child(bev, ctx);
} else {
/* if the other end is still open and doesn't
@ -3373,7 +3379,7 @@ pxy_bev_eventcb_child(struct bufferevent *bev, short events, void *arg)
* writecb will close it after writing what's
* left in the output buffer. */
if (evbuffer_get_length(outbuf) == 0) {
log_dbg_level_printf(LOG_DBG_MODE_FINE, ">>>>>=================================== pxy_bev_eventcb_child: evbuffer_get_length(inbuf) == 0 <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< CONN TERM\n");
log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>>=================================== pxy_bev_eventcb_child: evbuffer_get_length(inbuf) == 0 <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< CONN TERM\n");
other_free_and_close_fd_func(other->bev, ctx);
other->bev = NULL;
other->closed = 1;
@ -3458,11 +3464,11 @@ pxy_conn_connect(pxy_conn_ctx_t *ctx)
return;
}
// @attention Do not enable r/w cbs for dst: (1) We do nothing in those cbs for dst and (2) sometimes write cb fires before event cb,
// especially if this listener cb is not finished yet, then event cb never fires, so the conn stalls. Not enabling those cbs seems to solve the problem.
// @todo Why does event cb not fire? Why does not enabling r/w cbs solve the problem?
//log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>> pxy_conn_connect: <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< bufferevent_enable(ctx->dst.bev)\n");
//bufferevent_enable(ctx->dst.bev, EV_READ|EV_WRITE);
// @attention Sometimes dst write cb fires but not event cb, especially if this listener cb is not finished yet, so the conn stalls.
// @todo Why does event cb not fire sometimes?
log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>> pxy_conn_connect: <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< bufferevent_enable(ctx->dst.bev)\n");
bufferevent_enable(ctx->dst.bev, EV_READ|EV_WRITE);
//bufferevent_setcb(ctx->dst.bev, NULL, NULL, pxy_bev_eventcb, ctx);
if (OPTS_DEBUG(ctx->opts)) {
char *host, *port;

View File

@ -356,7 +356,7 @@ pxy_thrmgr_detach(pxy_thrmgr_ctx_t *ctx, int thridx, proxy_conn_meta_ctx_t *mctx
if (!mctx->child_list) {
pxy_thrmgr_remove_mctx(mctx, &mctx->thr->mctx_list);
} else {
log_dbg_level_printf(LOG_DBG_MODE_FINE, ">>>>> pxy_thrmgr_detach(): parent ctx has an active child, will not remove from the list, fd=%d, fd2=%d <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<\n",
log_dbg_level_printf(LOG_DBG_MODE_FINER, ">>>>> pxy_thrmgr_detach(): parent ctx has an active child, will not remove from the list, fd=%d, fd2=%d <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<\n",
mctx->fd, mctx->child_fd);
}
@ -381,10 +381,10 @@ pxy_thrmgr_detach_child(pxy_thrmgr_ctx_t *ctx, int thridx, proxy_conn_meta_ctx_t
pxy_thrmgr_remove_mctx(mctx, &mctx->thr->mctx_list);
} else {
if (mctx->parent_ctx) {
log_dbg_level_printf(LOG_DBG_MODE_FINE, ">>>>> pxy_thrmgr_detach_child(): child ctx has an active parent, will not remove from the list, fd=%d, fd2=%d <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<\n",
log_dbg_level_printf(LOG_DBG_MODE_FINER, ">>>>> pxy_thrmgr_detach_child(): child ctx has an active parent, will not remove from the list, fd=%d, fd2=%d <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<\n",
mctx->fd, mctx->child_fd);
} else if (mctx->child_list) {
log_dbg_level_printf(LOG_DBG_MODE_FINE, ">>>>> pxy_thrmgr_detach_child(): conn has 1+ active child, will not remove from the list, fd=%d, fd2=%d <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<\n",
log_dbg_level_printf(LOG_DBG_MODE_FINER, ">>>>> pxy_thrmgr_detach_child(): conn has 1+ active child, will not remove from the list, fd=%d, fd2=%d <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<\n",
mctx->fd, mctx->child_fd);
}
}
@ -399,7 +399,7 @@ void
pxy_thrmgr_print_child_info(pxy_conn_child_info_t *info, int thridx, int count)
{
assert(info != NULL);
log_dbg_level_printf(LOG_DBG_MODE_FINE, ">>> .......... pxy_thrmgr_print_child_info(): thr=%d, cont=%d, e2dst=%d, dst2=%d, c=%d-%d, ci=%d\n",
log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>> .......... pxy_thrmgr_print_child_info(): thr=%d, cont=%d, e2dst=%d, dst2=%d, c=%d-%d, ci=%d\n",
thridx, count, info->e2dst_fd, info->dst2_fd, info->e2dst_eof, info->dst2_eof, info->child_idx);
if (info->next) {
pxy_thrmgr_print_child_info(info->next, thridx, count);
@ -409,9 +409,9 @@ pxy_thrmgr_print_child_info(pxy_conn_child_info_t *info, int thridx, int count)
void
pxy_thrmgr_print_thr_info(pxy_thr_ctx_t *ctx)
{
log_dbg_level_printf(LOG_DBG_MODE_FINE, ">>>>>---------------------- pxy_thrmgr_print_thr_info(): ENTER\n");
log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>>---------------------- pxy_thrmgr_print_thr_info(): ENTER\n");
log_dbg_level_printf(LOG_DBG_MODE_FINE, ">>> pxy_thrmgr_print_thr_info(): thr=%d, load=%lu\n", ctx->thridx, ctx->load);
log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>> pxy_thrmgr_print_thr_info(): thr=%d, load=%lu\n", ctx->thridx, ctx->load);
if (ctx->mctx_list) {
time_t now = time(NULL);
@ -422,11 +422,11 @@ pxy_thrmgr_print_thr_info(pxy_thr_ctx_t *ctx)
char *host, *port;
if (mctx->addrlen == 0 || (sys_sockaddr_str((struct sockaddr *)&mctx->addr, mctx->addrlen, &host, &port) != 0)) {
log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>> pxy_thrmgr_print_thr_info(): Cannot get host:port: thr=%d, cont=%d, fd=%d, fd2=%d\n", ctx->thridx, count, mctx->fd, mctx->child_fd);
log_dbg_level_printf(LOG_DBG_MODE_FINE, ">>> pxy_thrmgr_print_thr_info(): thr=%d, cont=%d, fd=%d, fd2=%d, src=%d, e2src=%d, dst=%d, e2dst=%d, dst2=%d, p=%d-%d-%d c=%d-%d, init=%d, pe=%d ce=%d tcc=%d, time=%lld\n",
log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>> pxy_thrmgr_print_thr_info(): thr=%d, cont=%d, fd=%d, fd2=%d, src=%d, e2src=%d, dst=%d, e2dst=%d, dst2=%d, p=%d-%d-%d c=%d-%d, init=%d, pe=%d ce=%d tcc=%d, time=%lld\n",
ctx->thridx, count, mctx->fd, mctx->child_fd, mctx->src_fd, mctx->e2src_fd, mctx->dst_fd, mctx->e2dst_fd, mctx->dst2_fd,
mctx->src_eof, mctx->e2src_eof, mctx->dst_eof, mctx->e2dst_eof, mctx->dst2_eof, mctx->initialized, mctx->parent_ctx ? 1:0, mctx->child_list ? 1:0, mctx->child_count,(long int) now - mctx->access_time);
} else {
log_dbg_level_printf(LOG_DBG_MODE_FINE, ">>> pxy_thrmgr_print_thr_info(): thr=%d, cont=%d, fd=%d, fd2=%d, src=%d, e2src=%d, dst=%d, e2dst=%d, dst2=%d, p=%d-%d-%d c=%d-%d, init=%d, pe=%d ce=%d tcc=%d, time=%lld, addr=%s:%s\n",
log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>> pxy_thrmgr_print_thr_info(): thr=%d, cont=%d, fd=%d, fd2=%d, src=%d, e2src=%d, dst=%d, e2dst=%d, dst2=%d, p=%d-%d-%d c=%d-%d, init=%d, pe=%d ce=%d tcc=%d, time=%lld, addr=%s:%s\n",
ctx->thridx, count, mctx->fd, mctx->child_fd, mctx->src_fd, mctx->e2src_fd, mctx->dst_fd, mctx->e2dst_fd, mctx->dst2_fd,
mctx->src_eof, mctx->e2src_eof, mctx->dst_eof, mctx->e2dst_eof, mctx->dst2_eof, mctx->initialized, mctx->parent_ctx ? 1:0, mctx->child_list ? 1:0, mctx->child_count, (long int) now - mctx->access_time, host ? host : "?", port ? port : "?");
free(host);