diff --git a/pxyconn.c b/pxyconn.c index c98d0ad..0c8a20a 100644 --- a/pxyconn.c +++ b/pxyconn.c @@ -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; diff --git a/pxythrmgr.c b/pxythrmgr.c index 7f79332..6399829 100644 --- a/pxythrmgr.c +++ b/pxythrmgr.c @@ -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);