DECLARE_TEST(error, output) {
#if BUILD_ENABLE_LOG
error_handler_fn handler_error = error_handler();
log_handler_fn handler_log = log_handler();
string_const_t shortmsg = string_const(STRING_CONST("Short message with prefix"));
string_const_t longmsg = string_const(STRING_CONST("Longer message which should be output without a prefix"));
error_set_handler(ignore_error_handler);
log_set_handler(log_verify_handler);
log_enable_stdout(false);
EXPECT_EQ(log_stdout(), false);
log_warn(HASH_TEST, WARNING_SUSPICIOUS, STRING_ARGS(shortmsg));
log_enable_stdout(true);
EXPECT_EQ(log_stdout(), true);
EXPECT_EQ(_last_log_context, HASH_TEST);
EXPECT_EQ(_last_log_severity, ERRORLEVEL_WARNING);
EXPECT_GE(_last_log_length, shortmsg.length);
EXPECT_NE(string_find_string(_last_log_msg, _last_log_length, STRING_ARGS(shortmsg), 0), STRING_NPOS);
EXPECT_GT(string_find_string(_last_log_msg, _last_log_length, STRING_ARGS(shortmsg), 0), 0);
EXPECT_NE(string_find_string(_last_log_msg, _last_log_length, STRING_CONST("WARNING [suspicious]"), 0), STRING_NPOS);
_last_log_context = 0;
_last_log_severity = ERRORLEVEL_NONE;
_last_log_msg = nullptr;
_last_log_length = 0;
log_enable_stdout(false);
log_warn(HASH_TEST, (warning_t)0x1000, STRING_ARGS(shortmsg));
log_enable_stdout(true);
EXPECT_EQ(_last_log_context, HASH_TEST);
EXPECT_EQ(_last_log_severity, ERRORLEVEL_WARNING);
EXPECT_GE(_last_log_length, shortmsg.length);
EXPECT_NE(string_find_string(_last_log_msg, _last_log_length, STRING_ARGS(shortmsg), 0), STRING_NPOS);
EXPECT_GT(string_find_string(_last_log_msg, _last_log_length, STRING_ARGS(shortmsg), 0), 0);
EXPECT_NE(string_find_string(_last_log_msg, _last_log_length, STRING_CONST("WARNING [4096]"), 0), STRING_NPOS);
_last_log_context = 0;
_last_log_severity = ERRORLEVEL_NONE;
_last_log_msg = nullptr;
_last_log_length = 0;
log_enable_prefix(false);
log_enable_stdout(false);
log_warn(HASH_TEST, WARNING_SYSTEM_CALL_FAIL, STRING_ARGS(longmsg));
log_enable_stdout(true);
log_enable_prefix(true);
EXPECT_EQ(_last_log_context, HASH_TEST);
EXPECT_EQ(_last_log_severity, ERRORLEVEL_WARNING);
EXPECT_NE(string_find_string(_last_log_msg, _last_log_length, STRING_ARGS(longmsg), 0), STRING_NPOS);
EXPECT_GT(string_find_string(_last_log_msg, _last_log_length, STRING_ARGS(longmsg), 0), 0);
_last_log_context = 0;
_last_log_severity = ERRORLEVEL_NONE;
_last_log_msg = nullptr;
_last_log_length = 0;
log_enable_stdout(false);
log_error(HASH_TEST, ERROR_DEPRECATED, STRING_ARGS(shortmsg));
log_enable_stdout(true);
EXPECT_EQ(_last_log_context, HASH_TEST);
EXPECT_EQ(_last_log_severity, ERRORLEVEL_ERROR);
EXPECT_GE(_last_log_length, shortmsg.length);
EXPECT_NE(string_find_string(_last_log_msg, _last_log_length, STRING_ARGS(shortmsg), 0), STRING_NPOS);
EXPECT_GT(string_find_string(_last_log_msg, _last_log_length, STRING_ARGS(shortmsg), 0), 0);
EXPECT_NE(string_find_string(_last_log_msg, _last_log_length, STRING_CONST("ERROR [deprecated]"), 0), STRING_NPOS);
_last_log_context = 0;
_last_log_severity = ERRORLEVEL_NONE;
_last_log_msg = nullptr;
_last_log_length = 0;
log_enable_stdout(false);
log_error(HASH_TEST, (error_t)0x1000, STRING_ARGS(shortmsg));
log_enable_stdout(true);
EXPECT_EQ(_last_log_context, HASH_TEST);
EXPECT_EQ(_last_log_severity, ERRORLEVEL_ERROR);
EXPECT_GE(_last_log_length, shortmsg.length);
EXPECT_NE(string_find_string(_last_log_msg, _last_log_length, STRING_ARGS(shortmsg), 0), STRING_NPOS);
EXPECT_GT(string_find_string(_last_log_msg, _last_log_length, STRING_ARGS(shortmsg), 0), 0);
EXPECT_NE(string_find_string(_last_log_msg, _last_log_length, STRING_CONST("ERROR [4096]"), 0), STRING_NPOS);
_last_log_context = 0;
_last_log_severity = ERRORLEVEL_NONE;
_last_log_msg = nullptr;
_last_log_length = 0;
log_enable_prefix(false);
log_enable_stdout(false);
log_error(HASH_TEST, ERROR_INVALID_VALUE, STRING_ARGS(longmsg));
log_enable_stdout(true);
log_enable_prefix(true);
EXPECT_EQ(_last_log_context, HASH_TEST);
EXPECT_EQ(_last_log_severity, ERRORLEVEL_ERROR);
EXPECT_NE(string_find_string(_last_log_msg, _last_log_length, STRING_ARGS(longmsg), 0), STRING_NPOS);
EXPECT_GT(string_find_string(_last_log_msg, _last_log_length, STRING_ARGS(longmsg), 0), 0);
_last_log_context = 0;
_last_log_severity = ERRORLEVEL_NONE;
_last_log_msg = nullptr;
_last_log_length = 0;
log_enable_stdout(false);
log_panic(HASH_TEST, ERROR_DEPRECATED, STRING_ARGS(shortmsg));
log_enable_stdout(true);
EXPECT_EQ(_last_log_context, HASH_TEST);
EXPECT_EQ(_last_log_severity, ERRORLEVEL_PANIC);
EXPECT_GE(_last_log_length, shortmsg.length);
EXPECT_NE(string_find_string(_last_log_msg, _last_log_length, STRING_ARGS(shortmsg), 0), STRING_NPOS);
EXPECT_GT(string_find_string(_last_log_msg, _last_log_length, STRING_ARGS(shortmsg), 0), 0);
EXPECT_NE(string_find_string(_last_log_msg, _last_log_length, STRING_CONST("PANIC [deprecated]"), 0), STRING_NPOS);
_last_log_context = 0;
_last_log_severity = ERRORLEVEL_NONE;
_last_log_msg = nullptr;
_last_log_length = 0;
log_enable_stdout(false);
log_panic(HASH_TEST, (error_t)0x1000, STRING_ARGS(shortmsg));
log_enable_stdout(true);
EXPECT_EQ(_last_log_context, HASH_TEST);
EXPECT_EQ(_last_log_severity, ERRORLEVEL_PANIC);
EXPECT_GE(_last_log_length, shortmsg.length);
EXPECT_NE(string_find_string(_last_log_msg, _last_log_length, STRING_ARGS(shortmsg), 0), STRING_NPOS);
EXPECT_GT(string_find_string(_last_log_msg, _last_log_length, STRING_ARGS(shortmsg), 0), 0);
EXPECT_NE(string_find_string(_last_log_msg, _last_log_length, STRING_CONST("PANIC [4096]"), 0), STRING_NPOS);
_last_log_context = 0;
_last_log_severity = ERRORLEVEL_NONE;
_last_log_msg = nullptr;
_last_log_length = 0;
log_enable_prefix(false);
log_enable_stdout(false);
log_panic(HASH_TEST, ERROR_INVALID_VALUE, STRING_ARGS(longmsg));
log_enable_stdout(true);
log_enable_prefix(true);
EXPECT_EQ(_last_log_context, HASH_TEST);
EXPECT_EQ(_last_log_severity, ERRORLEVEL_PANIC);
EXPECT_NE(string_find_string(_last_log_msg, _last_log_length, STRING_ARGS(longmsg), 0), STRING_NPOS);
EXPECT_GT(string_find_string(_last_log_msg, _last_log_length, STRING_ARGS(longmsg), 0), 0);
# if BUILD_ENABLE_ERROR_CONTEXT
error_context_push(STRING_CONST("one"), STRING_CONST("dataone"));
error_context_push(STRING_CONST("two"), STRING_CONST("datatwo"));
error_context_push(STRING_CONST("three"), STRING_CONST("datathree"));
_last_log_context = 0;
_last_log_severity = ERRORLEVEL_NONE;
_last_log_msg = nullptr;
_last_log_length = 0;
log_enable_stdout(false);
log_error_context(HASH_TEST, ERRORLEVEL_INFO);
log_enable_stdout(true);
error_context_pop();
error_context_pop();
error_context_pop();
EXPECT_SIZEEQ(string_find_string(_last_log_msg, _last_log_length, STRING_CONST("When one: dataone"), 0), STRING_NPOS);
EXPECT_SIZEEQ(string_find_string(_last_log_msg, _last_log_length, STRING_CONST("When two: datatwo"), 0), STRING_NPOS);
EXPECT_SIZENE(string_find_string(_last_log_msg, _last_log_length, STRING_CONST("When three: datathree"), 0), STRING_NPOS);
# endif
log_set_handler(handler_log);
error_set_handler(handler_error);
#endif
return 0;
}
static rstatus_t
proxy_accept(struct context *ctx, struct conn *p)
{
rstatus_t status;
struct conn *c;
int sd;
struct sockaddr_storage addr;
socklen_t addr_len;
ASSERT(p->proxy && !p->client);
ASSERT(p->sd > 0);
ASSERT(p->recv_active && p->recv_ready);
for (;;) {
sd = accept(p->sd, NULL, NULL);
if (sd < 0) {
if (errno == EINTR) {
log_debug(LOG_VERB, "accept on p %d not ready - eintr", p->sd);
continue;
}
if (errno == EAGAIN || errno == EWOULDBLOCK || errno == ECONNABORTED) {
log_debug(LOG_VERB, "accept on p %d not ready - eagain", p->sd);
p->recv_ready = 0;
return NC_OK;
}
/*
* FIXME: On EMFILE or ENFILE mask out IN event on the proxy; mask
* it back in when some existing connection gets closed
*/
/*
* Workaround of https://github.com/twitter/twemproxy/issues/97
* Just ignore EMFILE/ENFILE, return NC_OK will enable the server
* continue to run instead of close the server socket
*/
if (errno == EMFILE || errno == ENFILE) {
log_crit("accept on p %d failed: %s", p->sd,
strerror(errno));
p->recv_ready = 0;
log_crit("connections status: rlimit nofile %d, "
"used connections: %d, max client connections %d, "
"curr client connections %d", ctx->rlimit_nofile,
conn_ncurr(), ctx->max_ncconn, conn_ncurr_cconn());
/* Since we maintain a safe max_ncconn and check
* it after every accept, we should not reach here.
* So we will panic after this log */
log_panic("HIT MAX OPEN FILES, IT SHOULD NOT HAPPEN. ABORT.");
return NC_OK;
}
log_error("accept on p %d failed: %s", p->sd, strerror(errno));
return NC_ERROR;
}
addr_len = sizeof(addr);
if (getsockname(sd, (struct sockaddr *)&addr, &addr_len)) {
log_error("getsockname on p %d failed: %s", p->sd, strerror(errno));
close(sd);
continue;
}
break;
}
if (conn_ncurr_cconn() >= ctx->max_ncconn) {
stats_pool_incr(ctx, p->owner, rejected_connections);
log_crit("client connections %d exceed limit %d",
conn_ncurr_cconn(), ctx->max_ncconn);
status = close(sd);
if (status < 0) {
log_error("close c %d failed, ignored: %s", sd, strerror(errno));
}
return NC_OK;
}
c = conn_get(p->owner, true, p->redis);
if (c == NULL) {
log_error("get conn for c %d from p %d failed: %s", sd, p->sd,
strerror(errno));
status = close(sd);
if (status < 0) {
log_error("close c %d failed, ignored: %s", sd, strerror(errno));
}
return NC_ENOMEM;
}
c->sd = sd;
c->family = addr.ss_family;
c->addrlen = addr_len;
c->ss = addr;
c->addr = (struct sockaddr *)&c->ss;
stats_pool_incr(ctx, c->owner, client_connections);
status = nc_set_nonblocking(c->sd);
if (status < 0) {
log_error("set nonblock on c %d from p %d failed: %s", c->sd, p->sd,
strerror(errno));
c->close(ctx, c);
return status;
}
if (p->family == AF_INET || p->family == AF_INET6) {
status = nc_set_tcpnodelay(c->sd);
if (status < 0) {
log_warn("set tcpnodelay on c %d from p %d failed, ignored: %s",
c->sd, p->sd, strerror(errno));
}
}
status = event_add_conn(ctx->evb, c);
if (status < 0) {
log_error("event add conn from p %d failed: %s", p->sd,
strerror(errno));
c->close(ctx, c);
return status;
}
log_notice("accepted c %d on p %d from '%s'", c->sd, p->sd,
nc_unresolve_peer_desc(c->sd));
return NC_OK;
}
