This is an automated email from the ASF dual-hosted git repository.
chug pushed a commit to branch main
in repository https://gitbox.apache.org/repos/asf/qpid-dispatch.git
The following commit(s) were added to refs/heads/main by this push:
new 80c685d DISPATCH-2043: TCP adaptor logging improvements
80c685d is described below
commit 80c685d7398b504238066bd5400fed2f5dc26326
Author: Chuck Rolke <c...@apache.org>
AuthorDate: Mon Apr 26 09:25:36 2021 -0400
DISPATCH-2043: TCP adaptor logging improvements
* add connection role to several logs
* in handle_incoming report conn,link,delivery to most logs
This closes #1157
---
src/adaptors/tcp_adaptor.c | 121 +++++++++++++++++++++++----------------------
1 file changed, 61 insertions(+), 60 deletions(-)
diff --git a/src/adaptors/tcp_adaptor.c b/src/adaptors/tcp_adaptor.c
index 2f895ab..9f34403 100644
--- a/src/adaptors/tcp_adaptor.c
+++ b/src/adaptors/tcp_adaptor.c
@@ -275,14 +275,14 @@ static int handle_incoming(qdr_tcp_connection_t *conn,
const char *msg)
// if we don't yet have a reply-to address and credit.
if (conn->ingress && !conn->reply_to) {
qd_log(log, QD_LOG_DEBUG,
- "[C%"PRIu64"][L%"PRIu64"] Waiting for reply-to address before
initiating ingress stream message",
- conn->conn_id, conn->incoming_id);
+ "[C%"PRIu64"][L%"PRIu64"] Waiting for reply-to address before
initiating %s ingress stream message",
+ conn->conn_id, conn->incoming_id,
qdr_tcp_connection_role_name(conn));
return 0;
}
if (!conn->flow_enabled) {
qd_log(log, QD_LOG_DEBUG,
- "[C%"PRIu64"][L%"PRIu64"] Waiting for credit before initiating
ingress stream message",
- conn->conn_id, conn->incoming_id);
+ "[C%"PRIu64"][L%"PRIu64"] Waiting for credit before initiating
%s ingress stream message",
+ conn->conn_id, conn->incoming_id,
qdr_tcp_connection_role_name(conn));
return 0;
}
@@ -301,7 +301,7 @@ static int handle_incoming(qdr_tcp_connection_t *conn,
const char *msg)
qd_compose_insert_string(props, conn->global_id); // subject
qd_compose_insert_string(props, conn->reply_to); // reply-to
qd_log(log, QD_LOG_DEBUG,
- "[C%"PRIu64"][L%"PRIu64"] Initiating ingress stream
incoming link for %s connection to: %s reply: %s",
+ "[C%"PRIu64"][L%"PRIu64"] Initiating listener (ingress)
stream incoming link for %s connection to: %s reply: %s",
conn->conn_id, conn->incoming_id,
qdr_tcp_connection_role_name(conn),
conn->config.address, conn->reply_to);
} else {
@@ -309,8 +309,8 @@ static int handle_incoming(qdr_tcp_connection_t *conn,
const char *msg)
qd_compose_insert_string(props, conn->global_id); // subject
qd_compose_insert_null(props); // reply-to
qd_log(log, QD_LOG_DEBUG,
- "[C%"PRIu64"][L%"PRIu64"] Initiating ingress stream
incoming link for %s connection to: %s",
- conn->conn_id, conn->incoming_id,
qdr_tcp_connection_role_name(conn), conn->reply_to);
+ "[C%"PRIu64"][L%"PRIu64"] Initiating connector (egress)
stream incoming link for connection to: %s",
+ conn->conn_id, conn->incoming_id, conn->reply_to);
}
//qd_compose_insert_null(props); // correlation-id
//qd_compose_insert_null(props); // content-type
@@ -332,17 +332,19 @@ static int handle_incoming(qdr_tcp_connection_t *conn,
const char *msg)
conn->instream = qdr_link_deliver(conn->incoming, msg, 0, false, 0, 0,
0, 0);
qd_log(log, QD_LOG_DEBUG,
- "[C%"PRIu64"][L%"PRIu64"][D%"PRIu32"] Initiating ingress stream
message with 0 bytes",
- conn->conn_id, conn->incoming_id, conn->instream->delivery_id);
+ "[C%"PRIu64"][L%"PRIu64"][D%"PRIu32"] Initiating empty %s
incoming stream message",
+ conn->conn_id, conn->incoming_id, conn->instream->delivery_id,
+ qdr_tcp_connection_role_name(conn));
conn->incoming_started = true;
}
+ qdr_delivery_t *conn_instream = conn->instream;
// Don't read from proton if in Q2 holdoff
if (conn->q2_blocked) {
qd_log(log, QD_LOG_DEBUG,
- "[C%"PRIu64"] handle_incoming q2_blocked for %s connection",
- conn->conn_id, qdr_tcp_connection_role_name(conn));
+ DLV_FMT" handle_incoming q2_blocked for %s connection",
+ DLV_ARGS(conn_instream), qdr_tcp_connection_role_name(conn));
return 0;
}
@@ -363,14 +365,15 @@ static int handle_incoming(qdr_tcp_connection_t *conn,
const char *msg)
qd_message_stream_data_append(qdr_delivery_message(conn->instream),
&buffers, &conn->q2_blocked);
if (conn->q2_blocked) {
// note: unit tests grep for this log!
- qd_log(log, QD_LOG_TRACE,
- "[C%"PRIu64"][L%"PRIu64"] client link blocked on Q2 limit",
- conn->conn_id, conn->incoming_id);
+ qd_log(log, QD_LOG_DEBUG,
+ DLV_FMT" %s client link blocked on Q2 limit",
+ DLV_ARGS(conn_instream),
qdr_tcp_connection_role_name(conn));
+
}
qdr_delivery_continue(tcp_adaptor->core, conn->instream, false);
- qd_log(log, QD_LOG_DEBUG,
- "[C%"PRIu64"][L%"PRIu64"] Continuing message with %i bytes",
- conn->conn_id, conn->incoming_id, count);
+ qd_log(log, QD_LOG_TRACE,
+ DLV_FMT" Continuing %s message with %i bytes",
+ DLV_ARGS(conn_instream), qdr_tcp_connection_role_name(conn),
count);
} else {
assert (DEQ_SIZE(buffers) == 0);
}
@@ -378,8 +381,8 @@ static int handle_incoming(qdr_tcp_connection_t *conn,
const char *msg)
// Close the stream message if read side has closed
if (conn->raw_closed_read) {
qd_log(log, QD_LOG_DEBUG,
- "[C%"PRIu64"][L%"PRIu64"] close instream delivery",
- conn->conn_id, conn->incoming_id);
+ DLV_FMT" close %s instream delivery",
+ DLV_ARGS(conn_instream), qdr_tcp_connection_role_name(conn));
qd_message_set_receive_complete(qdr_delivery_message(conn->instream));
qdr_delivery_continue(tcp_adaptor->core, conn->instream, true);
conn->raw_read_shutdown = true;
@@ -645,19 +648,19 @@ static void
qdr_tcp_connection_ingress_accept(qdr_tcp_connection_t* tc)
{
tc->remote_address = get_address_string(tc->pn_raw_conn);
tc->global_id = get_global_id(tc->config.site_id, tc->remote_address);
- qdr_connection_info_t *info = qdr_connection_info(false, //bool
is_encrypted,
- false, //bool
is_authenticated,
- true, //bool
opened,
- "", //char
*sasl_mechanisms,
- QD_INCOMING,
//qd_direction_t dir,
- tc->remote_address,
//const char *host,
- "", //const char
*ssl_proto,
- "", //const char
*ssl_cipher,
- "", //const char
*user,
- "TcpAdaptor", //const
char *container,
- 0, //pn_data_t
*connection_properties,
- 0, //int
ssl_ssf,
- false, //bool
ssl,
+ qdr_connection_info_t *info = qdr_connection_info(false, //
is_encrypted,
+ false, //
is_authenticated,
+ true, //
opened,
+ "", //
*sasl_mechanisms,
+ QD_INCOMING, //
dir,
+ tc->remote_address, //
*host,
+ "", //
*ssl_proto,
+ "", //
*ssl_cipher,
+ "", //
*user,
+ "TcpAdaptor", //
*container,
+ 0, //
*connection_properties,
+ 0, //
ssl_ssf,
+ false, //
ssl,
"", //
peer router version,
false); //
streaming links
@@ -689,10 +692,10 @@ static void
qdr_tcp_connection_ingress_accept(qdr_tcp_connection_t* tc)
tc->outgoing = qdr_link_first_attach(conn,
QD_OUTGOING,
- dynamic_source, //qdr_terminus_t
*source,
- qdr_terminus(0), //qdr_terminus_t
*target,
- "tcp.ingress.out", //const
char *name,
- 0, //const char
*terminus_addr,
+ dynamic_source, //qdr_terminus_t
*source,
+ qdr_terminus(0), //qdr_terminus_t
*target,
+ "tcp.ingress.out", //const char
*name,
+ 0, //const char
*terminus_addr,
false,
NULL,
&(tc->outgoing_id));
@@ -701,7 +704,7 @@ static void
qdr_tcp_connection_ingress_accept(qdr_tcp_connection_t* tc)
QD_INCOMING,
qdr_terminus(0), //qdr_terminus_t
*source,
target, //qdr_terminus_t
*target,
- "tcp.ingress.in", //const
char *name,
+ "tcp.ingress.in", //const char
*name,
0, //const char
*terminus_addr,
false,
NULL,
@@ -723,14 +726,14 @@ static void handle_connection_event(pn_event_t *e,
qd_server_t *qd_server, void
if (conn->ingress) {
qdr_tcp_connection_ingress_accept(conn);
qd_log(log, QD_LOG_INFO,
- "[C%"PRIu64"] PN_RAW_CONNECTION_CONNECTED Ingress accepted
to %s from %s (global_id=%s)",
+ "[C%"PRIu64"] PN_RAW_CONNECTION_CONNECTED Listener ingress
accepted to %s from %s (global_id=%s)",
conn->conn_id, conn->config.host_port,
conn->remote_address, conn->global_id);
break;
} else {
conn->remote_address = get_address_string(conn->pn_raw_conn);
conn->opened_time = tcp_adaptor->core->uptime_ticks;
qd_log(log, QD_LOG_INFO,
- "[C%"PRIu64"] PN_RAW_CONNECTION_CONNECTED Egress connected
to %s",
+ "[C%"PRIu64"] PN_RAW_CONNECTION_CONNECTED Connector egress
connected to %s",
conn->conn_id, conn->remote_address);
if (!!conn->initial_delivery) {
qdr_tcp_open_server_side_connection(conn);
@@ -741,8 +744,8 @@ static void handle_connection_event(pn_event_t *e,
qd_server_t *qd_server, void
}
}
case PN_RAW_CONNECTION_CLOSED_READ: {
- qd_log(log, QD_LOG_DEBUG, "[C%"PRIu64"][L%"PRIu64"]
PN_RAW_CONNECTION_CLOSED_READ",
- conn->conn_id, conn->incoming_id);
+ qd_log(log, QD_LOG_DEBUG, "[C%"PRIu64"][L%"PRIu64"]
PN_RAW_CONNECTION_CLOSED_READ %s",
+ conn->conn_id, conn->incoming_id,
qdr_tcp_connection_role_name(conn));
sys_mutex_lock(conn->activation_lock);
conn->q2_blocked = false;
conn->raw_closed_read = true;
@@ -752,8 +755,8 @@ static void handle_connection_event(pn_event_t *e,
qd_server_t *qd_server, void
}
case PN_RAW_CONNECTION_CLOSED_WRITE: {
qd_log(log, QD_LOG_DEBUG,
- "[C%"PRIu64"] PN_RAW_CONNECTION_CLOSED_WRITE",
- conn->conn_id);
+ "[C%"PRIu64"] PN_RAW_CONNECTION_CLOSED_WRITE %s",
+ conn->conn_id, qdr_tcp_connection_role_name(conn));
sys_mutex_lock(conn->activation_lock);
conn->raw_closed_write = true;
sys_mutex_unlock(conn->activation_lock);
@@ -761,8 +764,8 @@ static void handle_connection_event(pn_event_t *e,
qd_server_t *qd_server, void
}
case PN_RAW_CONNECTION_DISCONNECTED: {
qd_log(log, QD_LOG_INFO,
- "[C%"PRIu64"] PN_RAW_CONNECTION_DISCONNECTED",
- conn->conn_id);
+ "[C%"PRIu64"] PN_RAW_CONNECTION_DISCONNECTED %s",
+ conn->conn_id, qdr_tcp_connection_role_name(conn));
sys_mutex_lock(conn->activation_lock);
conn->pn_raw_conn = 0;
sys_mutex_unlock(conn->activation_lock);
@@ -771,16 +774,16 @@ static void handle_connection_event(pn_event_t *e,
qd_server_t *qd_server, void
}
case PN_RAW_CONNECTION_NEED_WRITE_BUFFERS: {
qd_log(log, QD_LOG_DEBUG,
- "[C%"PRIu64"] PN_RAW_CONNECTION_NEED_WRITE_BUFFERS",
- conn->conn_id);
+ "[C%"PRIu64"] PN_RAW_CONNECTION_NEED_WRITE_BUFFERS %s",
+ conn->conn_id, qdr_tcp_connection_role_name(conn));
while (qdr_connection_process(conn->qdr_conn)) {}
handle_outgoing(conn);
break;
}
case PN_RAW_CONNECTION_NEED_READ_BUFFERS: {
qd_log(log, QD_LOG_DEBUG,
- "[C%"PRIu64"] PN_RAW_CONNECTION_NEED_READ_BUFFERS",
- conn->conn_id);
+ "[C%"PRIu64"] PN_RAW_CONNECTION_NEED_READ_BUFFERS %s",
+ conn->conn_id, qdr_tcp_connection_role_name(conn));
while (qdr_connection_process(conn->qdr_conn)) {}
if (conn->incoming_started) {
grant_read_buffers(conn);
@@ -790,16 +793,16 @@ static void handle_connection_event(pn_event_t *e,
qd_server_t *qd_server, void
}
case PN_RAW_CONNECTION_WAKE: {
qd_log(log, QD_LOG_DEBUG,
- "[C%"PRIu64"] PN_RAW_CONNECTION_WAKE",
- conn->conn_id);
+ "[C%"PRIu64"] PN_RAW_CONNECTION_WAKE %s",
+ conn->conn_id, qdr_tcp_connection_role_name(conn));
if (sys_atomic_set(&conn->q2_restart, 0)) {
sys_mutex_lock(conn->activation_lock);
conn->q2_blocked = false;
sys_mutex_unlock(conn->activation_lock);
// note: unit tests grep for this log!
qd_log(log, QD_LOG_TRACE,
- "[C%"PRIu64"] client link unblocked from Q2 limit",
- conn->conn_id);
+ "[C%"PRIu64"] %s client link unblocked from Q2 limit",
+ conn->conn_id, qdr_tcp_connection_role_name(conn));
handle_incoming(conn, "PNRC_WAKE after Q2 unblock");
}
while (qdr_connection_process(conn->qdr_conn)) {}
@@ -807,8 +810,8 @@ static void handle_connection_event(pn_event_t *e,
qd_server_t *qd_server, void
}
case PN_RAW_CONNECTION_READ: {
qd_log(log, QD_LOG_DEBUG,
- "[C%"PRIu64"] PN_RAW_CONNECTION_READ Event ",
- conn->conn_id);
+ "[C%"PRIu64"] PN_RAW_CONNECTION_READ %s Event ",
+ conn->conn_id, qdr_tcp_connection_role_name(conn));
int read = 0;
if (conn->incoming_started) {
// Streaming message exists. Process read normally.
@@ -835,8 +838,8 @@ static void handle_connection_event(pn_event_t *e,
qd_server_t *qd_server, void
conn->last_out_time = tcp_adaptor->core->uptime_ticks;
conn->bytes_out += written;
qd_log(log, QD_LOG_DEBUG,
- "[C%"PRIu64"] PN_RAW_CONNECTION_WRITTEN
pn_raw_connection_take_written_buffers wrote %zu bytes. Total written %"PRIu64"
bytes",
- conn->conn_id, written, conn->bytes_out);
+ "[C%"PRIu64"] PN_RAW_CONNECTION_WRITTEN %s
pn_raw_connection_take_written_buffers wrote %zu bytes. Total written %"PRIu64"
bytes",
+ conn->conn_id, qdr_tcp_connection_role_name(conn), written,
conn->bytes_out);
while (qdr_connection_process(conn->qdr_conn)) {}
break;
}
@@ -1243,7 +1246,7 @@ static void qdr_tcp_second_attach(void *context,
qdr_link_t *link,
qd_log(tcp_adaptor->log_source, QD_LOG_DEBUG,
"[C%"PRIu64"][L%"PRIu64"] %s qdr_tcp_second_attach",
tc->conn_id, tc->incoming_id,
- qdr_tcp_quadrant_id(tc, link));
+ qdr_tcp_quadrant_id(tc, link));
}
} else {
qd_log(tcp_adaptor->log_source, QD_LOG_ERROR, "qdr_tcp_second_attach:
no link context");
@@ -1382,8 +1385,6 @@ static uint64_t qdr_tcp_deliver(void *context, qdr_link_t
*link, qdr_delivery_t
false,
NULL,
&(tc->incoming_id));
- assert(tc);
- assert(tc->incoming);
qd_log(tcp_adaptor->log_source, QD_LOG_DEBUG,
"[C%"PRIu64"][L%"PRIu64"] %s Created link to %s",
tc->conn_id, tc->incoming->identity,
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscr...@qpid.apache.org
For additional commands, e-mail: commits-h...@qpid.apache.org
