Repository: qpid-dispatch Updated Branches: refs/heads/master cdc71d475 -> 7affc254f
NO-JIRA: Improved message logging - Quote string-like values using proton conventions: "string", b"binary", :"symbol" - Omit fields absent in message, fix comma-separation of fields. - Add link source & target address to message logs. - Move the word "Sent" or "Received" to the front of the log message. - Remove useless "max" parameter of print_field, print_parsed_field It was only ever passed the value MAXINT. Project: http://git-wip-us.apache.org/repos/asf/qpid-dispatch/repo Commit: http://git-wip-us.apache.org/repos/asf/qpid-dispatch/commit/7affc254 Tree: http://git-wip-us.apache.org/repos/asf/qpid-dispatch/tree/7affc254 Diff: http://git-wip-us.apache.org/repos/asf/qpid-dispatch/diff/7affc254 Branch: refs/heads/master Commit: 7affc254f01130621f9ba64ffb6d770fae921ec7 Parents: c48e55c Author: Alan Conway <acon...@redhat.com> Authored: Thu Jun 28 22:39:25 2018 -0400 Committer: Alan Conway <acon...@redhat.com> Committed: Thu Jun 28 23:12:27 2018 -0400 ---------------------------------------------------------------------- src/message.c | 195 +++++++++------------- src/router_node.c | 44 ++--- src/server.c | 4 +- tests/system_tests_log_message_components.py | 50 +++--- 4 files changed, 135 insertions(+), 158 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/qpid-dispatch/blob/7affc254/src/message.c ---------------------------------------------------------------------- diff --git a/src/message.c b/src/message.c index 0553719..9c71b79 100644 --- a/src/message.c +++ b/src/message.c @@ -130,10 +130,28 @@ static void format_time(pn_timestamp_t epoch_time, char *format, char *buffer, s } /** - * Tries to print the string representation of the parsed field content based on the tag of the parsed field. - * Some tag types have not been dealt with. Add code as and when required. + * Print the bytes of a parsed_field as characters, with pre/post quotes. */ -static void print_parsed_field(qd_parsed_field_t *parsed_field, char **begin, char *end, int max) +static void print_parsed_field_string(qd_parsed_field_t *parsed_field, + const char *pre, const char *post, + char **begin, char *end) { + qd_iterator_t *i = qd_parse_raw(parsed_field); + if (i) { + aprintf(begin, end, "%s", pre); + while (end - *begin > 1 && !qd_iterator_end(i)) { + char c = qd_iterator_octet(i); + quote(&c, 1, begin, end); + } + aprintf(begin, end, "%s", post); + } +} + +/** + * Tries to print the string representation of the parsed field content based on + * the tag of the parsed field. Some tag types have not been dealt with. Add + * code as and when required. + */ +static void print_parsed_field(qd_parsed_field_t *parsed_field, char **begin, char *end) { uint8_t tag = qd_parse_tag(parsed_field); switch (tag) { @@ -188,18 +206,13 @@ static void print_parsed_field(qd_parsed_field_t *parsed_field, char **begin, ch //qd_iterator_t* iter = qd_message_field_iterator(msg, field); qd_iterator_t *iter = qd_parse_raw(parsed_field); - for (int j = 0; !qd_iterator_end(iter) && j < max; ++j) { - char byte = qd_iterator_octet(iter); - if (timestamp_length > 0) { - // Gather the timestamp bytes into the timestamp_bytes array, so we process them later into time. - timestamp_bytes[--timestamp_length] = byte; - } + while (!qd_iterator_end(iter) && timestamp_length > 0) { + timestamp_bytes[--timestamp_length] = qd_iterator_octet(iter); } - memcpy(&creation_timestamp, timestamp_bytes, 8); if (creation_timestamp > 0) { format_time(creation_timestamp, "%Y-%m-%d %H:%M:%S.%%03lu %z", creation_time, 100); - aprintf(begin, end, "%s", creation_time); + aprintf(begin, end, "\"%s\"", creation_time); } break; } @@ -222,24 +235,19 @@ static void print_parsed_field(qd_parsed_field_t *parsed_field, char **begin, ch case QD_AMQP_VBIN8: case QD_AMQP_VBIN32: + print_parsed_field_string(parsed_field, "b\"", "\"", begin, end); + break; + case QD_AMQP_STR8_UTF8: case QD_AMQP_STR32_UTF8: + print_parsed_field_string(parsed_field, "\"", "\"", begin, end); + break; + case QD_AMQP_SYM8: - case QD_AMQP_SYM32: { - qd_iterator_t *raw_iter = qd_parse_raw(parsed_field); - if (raw_iter) { - int len = qd_iterator_length(raw_iter); - char str_val[len]; - int i=0; - - while (!qd_iterator_end(raw_iter)) { - str_val[i] = qd_iterator_octet(raw_iter); - i++; - } - quote(str_val, len, begin, end); - } + case QD_AMQP_SYM32: + print_parsed_field_string(parsed_field, ":\"", "\"", begin, end); break; - } + case QD_AMQP_MAP8: case QD_AMQP_MAP32: { uint32_t count = qd_parse_sub_count(parsed_field); @@ -248,14 +256,15 @@ static void print_parsed_field(qd_parsed_field_t *parsed_field, char **begin, ch } for (uint32_t idx = 0; idx < count; idx++) { qd_parsed_field_t *sub_key = qd_parse_sub_key(parsed_field, idx); - // The keys of this map are restricted to be of type string (which excludes the possibility of a null key) - print_parsed_field(sub_key, begin, end, max); + // The keys of this map are restricted to be of type string + // (which excludes the possibility of a null key) + print_parsed_field(sub_key, begin, end); aprintf(begin, end, "%s", "="); qd_parsed_field_t *sub_value = qd_parse_sub_value(parsed_field, idx); - print_parsed_field(sub_value, begin, end, max); + print_parsed_field(sub_value, begin, end); if ((idx + 1) < count) aprintf(begin, end, "%s", ", "); @@ -274,7 +283,7 @@ static void print_parsed_field(qd_parsed_field_t *parsed_field, char **begin, ch } for (uint32_t idx = 0; idx < count; idx++) { qd_parsed_field_t *sub_value = qd_parse_sub_value(parsed_field, idx); - print_parsed_field(sub_value, begin, end, max); + print_parsed_field(sub_value, begin, end); if ((idx + 1) < count) aprintf(begin, end, "%s", ", "); } @@ -290,100 +299,58 @@ static void print_parsed_field(qd_parsed_field_t *parsed_field, char **begin, ch } } -static void print_field(qd_message_t *msg, int field, int max, char *pre, char *post, - char **begin, char *end) +/* Print field if enabled by log bits, leading comma if !*first */ +static void print_field( + qd_message_t *msg, int field, const char *name, + qd_log_bits flags, bool *first, char **begin, char *end) { - qd_iterator_t* iter = 0; - - - // TODO - Need to discuss this. I have a question. - if (field == QD_FIELD_APPLICATION_PROPERTIES) { - iter = qd_message_field_iterator(msg, field); - } - else { - iter = qd_message_field_iterator_typed(msg, field); - } - - aprintf(begin, end, "%s", pre); - - if (!iter) { - aprintf(begin, end, "%s", post); - return; - } - + if (is_log_component_enabled(flags, name)) { + qd_iterator_t* iter = (field == QD_FIELD_APPLICATION_PROPERTIES) ? + qd_message_field_iterator(msg, field) : + qd_message_field_iterator_typed(msg, field); + if (iter) { qd_parsed_field_t *parsed_field = qd_parse(iter); - - // If there is a problem with parsing a field, just return - if (!qd_parse_ok(parsed_field)) { - aprintf(begin, end, "%s", post); - qd_iterator_free(iter); - qd_parse_free(parsed_field); - return; + if (qd_parse_ok(parsed_field)) { + if (*first) { + *first = false; + aprintf(begin, end, "%s=", name); + } else { + aprintf(begin, end, ", %s=", name); + } + print_parsed_field(parsed_field, begin, end); } - - print_parsed_field(parsed_field, begin, end, max); - - aprintf(begin, end, "%s", post); - qd_iterator_free(iter); qd_parse_free(parsed_field); + qd_iterator_free(iter); + } + } } static const char REPR_END[] = "}\0"; -char* qd_message_repr(qd_message_t *msg, char* buffer, size_t len, qd_log_bits log_message) { - if (log_message == 0) - return 0; - - if (qd_message_check(msg, QD_DEPTH_APPLICATION_PROPERTIES)) { - char *begin = buffer; - char *end = buffer + len - sizeof(REPR_END); /* Save space for ending */ - - aprintf(&begin, end, "Message{", msg); - - if (is_log_component_enabled(log_message, "message-id")) - print_field(msg, QD_FIELD_MESSAGE_ID, INT_MAX, "message-id='", "'", &begin, end); - - if (is_log_component_enabled(log_message, "user-id")) - print_field(msg, QD_FIELD_USER_ID, INT_MAX, ", user-id='", "'", &begin, end); - - if (is_log_component_enabled(log_message, "to")) - print_field(msg, QD_FIELD_TO, INT_MAX, ", to='", "'", &begin, end); - - if (is_log_component_enabled(log_message, "subject")) - print_field(msg, QD_FIELD_SUBJECT, INT_MAX, ", subject='", "'", &begin, end); - - if (is_log_component_enabled(log_message, "reply-to")) - print_field(msg, QD_FIELD_REPLY_TO, INT_MAX, ", reply-to='", "'", &begin, end); - - if (is_log_component_enabled(log_message, "correlation-id")) - print_field(msg, QD_FIELD_CORRELATION_ID, INT_MAX, ", correlation-id='", "'", &begin, end); - - if (is_log_component_enabled(log_message, "content-type")) - print_field(msg, QD_FIELD_CONTENT_TYPE, INT_MAX, ", content-type='", "'", &begin, end); - - if (is_log_component_enabled(log_message, "content-encoding")) - print_field(msg, QD_FIELD_CONTENT_ENCODING, INT_MAX, ", content-encoding='", "'", &begin, end); - - if (is_log_component_enabled(log_message, "absolute-expiry-time")) - print_field(msg, QD_FIELD_ABSOLUTE_EXPIRY_TIME, INT_MAX, ", absolute-expiry-time='", "'", &begin, end); - - if (is_log_component_enabled(log_message, "creation-time")) - print_field(msg, QD_FIELD_CREATION_TIME, INT_MAX, ", creation-time='", "'", &begin, end); - - if (is_log_component_enabled(log_message, "group-id")) - print_field(msg, QD_FIELD_GROUP_ID, INT_MAX, ", group-id='", "'", &begin, end); - - if (is_log_component_enabled(log_message, "group-sequence")) - print_field(msg, QD_FIELD_GROUP_SEQUENCE, INT_MAX, ", group-sequence='", "'", &begin, end); - - if (is_log_component_enabled(log_message, "reply-to-group-id")) - print_field(msg, QD_FIELD_REPLY_TO_GROUP_ID, INT_MAX, ", reply-to-group-id='", "'", &begin, end); - - if (is_log_component_enabled(log_message, "app-properties")) - print_field(msg, QD_FIELD_APPLICATION_PROPERTIES, INT_MAX, ", application properties=", "", &begin, end); - - aprintf(&begin, end, "%s", REPR_END); /* We saved space at the beginning. */ +char* qd_message_repr(qd_message_t *msg, char* buffer, size_t len, qd_log_bits flags) { + if (flags == 0 || !qd_message_check(msg, QD_DEPTH_APPLICATION_PROPERTIES)) { + return NULL; } + char *begin = buffer; + char *end = buffer + len - sizeof(REPR_END); /* Save space for ending */ + bool first = true; + aprintf(&begin, end, "Message{", msg); + print_field(msg, QD_FIELD_MESSAGE_ID, "message-id", flags, &first, &begin, end); + print_field(msg, QD_FIELD_USER_ID, "user-id", flags, &first, &begin, end); + print_field(msg, QD_FIELD_TO, "to", flags, &first, &begin, end); + print_field(msg, QD_FIELD_SUBJECT, "subject", flags, &first, &begin, end); + print_field(msg, QD_FIELD_REPLY_TO, "reply-to", flags, &first, &begin, end); + print_field(msg, QD_FIELD_CORRELATION_ID, "correlation-id", flags, &first, &begin, end); + print_field(msg, QD_FIELD_CONTENT_TYPE, "content-type", flags, &first, &begin, end); + print_field(msg, QD_FIELD_CONTENT_ENCODING, "content-encoding", flags, &first, &begin, end); + print_field(msg, QD_FIELD_ABSOLUTE_EXPIRY_TIME, "absolute-expiry-time", flags, &first, &begin, end); + print_field(msg, QD_FIELD_CREATION_TIME, "creation-time", flags, &first, &begin, end); + print_field(msg, QD_FIELD_GROUP_ID, "group-id", flags, &first, &begin, end); + print_field(msg, QD_FIELD_GROUP_SEQUENCE, "group-sequence", flags, &first, &begin, end); + print_field(msg, QD_FIELD_REPLY_TO_GROUP_ID, "reply-to-group-id", flags, &first, &begin, end); + print_field(msg, QD_FIELD_APPLICATION_PROPERTIES, "app-properties", flags, &first, &begin, end); + + aprintf(&begin, end, "%s", REPR_END); /* We saved space at the beginning. */ return buffer; } http://git-wip-us.apache.org/repos/asf/qpid-dispatch/blob/7affc254/src/router_node.c ---------------------------------------------------------------------- diff --git a/src/router_node.c b/src/router_node.c index fd45435..e1fd9ee 100644 --- a/src/router_node.c +++ b/src/router_node.c @@ -264,6 +264,27 @@ static qd_iterator_t *router_annotate_message(qd_router_t *router, return ingress_iter; } +static void log_link_message(qd_connection_t *conn, pn_link_t *pn_link, qd_message_t *msg) +{ + if (!conn || !pn_link || !msg) return; + const qd_server_config_t *cf = qd_connection_config(conn); + if (!cf) return; + char buf[qd_message_repr_len()]; + const char *msg_str = qd_message_aborted(msg) ? + "aborted message" : qd_message_repr(msg, buf, sizeof(buf), cf->log_bits); + if (msg_str) { + const char *src = pn_terminus_get_address(pn_link_source(pn_link)); + const char *tgt = pn_terminus_get_address(pn_link_target(pn_link)); + qd_log(qd_message_log_source(), QD_LOG_TRACE, + "[%"PRIu64"]: %s %s on link '%s' (%s -> %s)", + qd_connection_connection_id(conn), + pn_link_is_sender(pn_link) ? "Sent" : "Received", + msg_str, + pn_link_name(pn_link), + src ? src : "", + tgt ? tgt : ""); + } +} /** * Inbound Delivery Handler @@ -278,7 +299,6 @@ static void AMQP_rx_handler(void* context, qd_link_t *link) return; qdr_link_t *rlink = (qdr_link_t*) qd_link_get_context(link); qd_connection_t *conn = qd_link_connection(link); - const qd_server_config_t *cf = qd_connection_config(conn); qdr_delivery_t *delivery = qdr_node_delivery_qdr_from_pn(pnd); // @@ -288,24 +308,7 @@ static void AMQP_rx_handler(void* context, qd_link_t *link) bool receive_complete = qd_message_receive_complete(msg); if (receive_complete) { - if (!qd_message_aborted(msg)) { - // Since the entire message has been received, we can print out its contents to the log if necessary. - if (cf->log_message) { - char repr[qd_message_repr_len()]; - char* message_repr = qd_message_repr((qd_message_t*)msg, - repr, - sizeof(repr), - cf->log_bits); - if (message_repr) { - qd_log(qd_message_log_source(), QD_LOG_TRACE, "Link %s received %s", - pn_link_name(pn_link), - message_repr); - } - } - } else { - qd_log(qd_message_log_source(), QD_LOG_TRACE, "Link '%s' received aborted message", - pn_link_name(pn_link)); - } + log_link_message(conn, pn_link, msg); // // The entire message has been received and we are ready to consume the delivery by calling pn_link_advance(). @@ -1362,6 +1365,8 @@ static uint64_t CORE_link_deliver(void *context, qdr_link_t *link, qdr_delivery_ { qd_router_t *router = (qd_router_t*) context; qd_link_t *qlink = (qd_link_t*) qdr_link_get_context(link); + qd_connection_t *qconn = qd_link_connection(qlink); + uint64_t update = 0; if (!qlink) @@ -1453,6 +1458,7 @@ static uint64_t CORE_link_deliver(void *context, qdr_link_t *link, qdr_delivery_ pn_delivery_settle(pdlv); } } + log_link_message(qconn, plink, msg_out); } return update; } http://git-wip-us.apache.org/repos/asf/qpid-dispatch/blob/7affc254/src/server.c ---------------------------------------------------------------------- diff --git a/src/server.c b/src/server.c index f065be3..ae3b22b 100644 --- a/src/server.c +++ b/src/server.c @@ -1299,7 +1299,9 @@ const qd_server_config_t *qd_connection_config(const qd_connection_t *conn) { if (conn->listener) return &conn->listener->config; - return &conn->connector->config; + if (conn->connector) + return &conn->connector->config; + return NULL; } http://git-wip-us.apache.org/repos/asf/qpid-dispatch/blob/7affc254/tests/system_tests_log_message_components.py ---------------------------------------------------------------------- diff --git a/tests/system_tests_log_message_components.py b/tests/system_tests_log_message_components.py index c497839..59f34ba 100644 --- a/tests/system_tests_log_message_components.py +++ b/tests/system_tests_log_message_components.py @@ -80,23 +80,23 @@ class RouterMessageLogTestAll(RouterMessageLogTestBase): everything_ok = False logs = json.loads(self.run_qdmanage("get-log")) - for log in logs: - if log[0] == u'MESSAGE': - if "message-id='123455'" in log[2]: - self.assertTrue("user-id='testuser'" in log[2]) - self.assertTrue("subject='test-subject'" in log[2]) - self.assertTrue("reply-to='hello_world'" in log[2]) - self.assertTrue("correlation-id='89'" in log[2]) - self.assertTrue("content-type='text/html; charset=utf-8'" in log[2]) - self.assertTrue("content-encoding='gzip, deflate'" in log[2]) - self.assertTrue("group-id='group1', group-sequence='0', reply-to-group-id='group0'" in log[2]) - self.assertTrue("application properties={app-property=[10, 20, 30], some-other=O_one}" in log[2]) - self.assertTrue("creation-time='2017-02-22" in log[2]) - self.assertTrue("10:23.883" in log[2]) - - everything_ok = True - - self.assertTrue(everything_ok) + message_logs = [log for log in logs if log[0] == u'MESSAGE'] + self.assertTrue(message_logs) + test_message = [log for log in message_logs if "message-id=\"123455\"" in log[2]] + self.assertTrue(2 == len(test_message), message_logs) # Sent and Received + self.assertIn('Received', test_message[0][2]) + self.assertIn('Sent', test_message[1][2]) + for log in test_message: + self.assertIn('user-id=b"testuser"', log[2]) + self.assertIn('subject="test-subject"', log[2]) + self.assertIn('reply-to="hello_world"', log[2]) + self.assertIn('correlation-id=89', log[2]) + self.assertIn('content-type=:"text/html; charset=utf-8"', log[2]) + self.assertIn('content-encoding=:"gzip, deflate"', log[2]) + self.assertIn('group-id="group1", group-sequence=0, reply-to-group-id="group0"', log[2]) + self.assertIn('app-properties={"app-property"=[10, 20, 30], "some-other"=:"O_one"}', log[2]) + self.assertIn('creation-time="2017-02-22', log[2]) + self.assertIn('10:23.883', log[2]) class RouterMessageLogTestNone(RouterMessageLogTestBase): """System tests to check log messages emitted by router""" @@ -144,7 +144,7 @@ class RouterMessageLogTestSome(RouterMessageLogTestBase): ('router', {'mode': 'standalone', 'id': 'QDR'}), # logMessage has been deprecated. We are using it here so we can make sure that it is still # backward compatible. - ('listener', {'port': cls.tester.get_port(), 'logMessage': 'message-id,user-id,subject,reply-to'}), + ('listener', {'port': cls.tester.get_port(), 'logMessage': 'user-id,subject,reply-to'}), ('address', {'prefix': 'closest', 'distribution': 'closest'}), ('address', {'prefix': 'spread', 'distribution': 'balanced'}), @@ -163,12 +163,14 @@ class RouterMessageLogTestSome(RouterMessageLogTestBase): everything_ok = False logs = json.loads(self.run_qdmanage("get-log")) - for log in logs: - if log[0] == u'MESSAGE': - if u"received Message{message-id='123455', user-id='testuser', subject='test-subject', reply-to='hello_world'}" in log[2]: - everything_ok = True - - self.assertTrue(everything_ok) + message_logs = [log for log in logs if log[0] == u'MESSAGE'] + self.assertTrue(message_logs) + test_message = [log for log in message_logs if + u'Received Message{user-id=b"testuser", subject="test-subject", reply-to="hello_world"}' in log[2]] + self.assertTrue(test_message, message_logs) + test_message = [log for log in message_logs if + u'Sent Message{user-id=b"testuser", subject="test-subject", reply-to="hello_world"}' in log[2]] + self.assertTrue(test_message, message_logs) class LogMessageTest(MessagingHandler): def __init__(self, address): --------------------------------------------------------------------- To unsubscribe, e-mail: commits-unsubscr...@qpid.apache.org For additional commands, e-mail: commits-h...@qpid.apache.org
