From f93afbf95fcd73ca9a7835ffdf5adbe0787b07c4 Mon Sep 17 00:00:00 2001 From: Francis Deslauriers Date: Mon, 8 Nov 2021 10:06:37 -0500 Subject: [PATCH] src.ctf.lttng-live: Add debug statements and comments Signed-off-by: Francis Deslauriers Change-Id: I55395dfc4ba2b5aa5eacd092c22fd88059a9ea24 Reviewed-on: https://review.lttng.org/c/babeltrace/+/6652 Tested-by: jenkins Reviewed-by: Philippe Proulx --- src/plugins/ctf/lttng-live/lttng-live.c | 101 ++++++++-- src/plugins/ctf/lttng-live/metadata.c | 3 +- .../ctf/lttng-live/viewer-connection.c | 185 ++++++++++++++---- 3 files changed, 239 insertions(+), 50 deletions(-) diff --git a/src/plugins/ctf/lttng-live/lttng-live.c b/src/plugins/ctf/lttng-live/lttng-live.c index 629ff9a5..91e312f2 100644 --- a/src/plugins/ctf/lttng-live/lttng-live.c +++ b/src/plugins/ctf/lttng-live/lttng-live.c @@ -357,12 +357,12 @@ enum lttng_live_iterator_status lttng_live_iterator_next_check_stream_state( } /* - * For active no data stream, fetch next data. It can be either: - * - quiescent: need to put it in the prio heap at quiescent end - * timestamp, - * - have data: need to wire up first event into the prio heap, - * - have no data on this stream at this point: need to retry (AGAIN) or - * return EOF. + * For active no data stream, fetch next index. As a result of that it can + * become either: + * - quiescent: won't have events for a bit, + * - have data: need to get that data and produce the event, + * - have no data on this stream at this point: need to retry (AGAIN) or return + * EOF. */ static enum lttng_live_iterator_status lttng_live_iterator_next_handle_one_no_data_stream( @@ -377,23 +377,31 @@ enum lttng_live_iterator_status lttng_live_iterator_next_handle_one_no_data_stre if (lttng_live_stream->trace->metadata_stream_state == LTTNG_LIVE_METADATA_STREAM_STATE_NEEDED) { + BT_COMP_LOGD("Need to get an update for the metadata stream before proceeding further with this stream: " + "stream-name=\"%s\"", lttng_live_stream->name->str); ret = LTTNG_LIVE_ITERATOR_STATUS_CONTINUE; goto end; } + if (lttng_live_stream->trace->session->new_streams_needed) { + BT_COMP_LOGD("Need to get an update of all streams before proceeding further with this stream: " + "stream-name=\"%s\"", lttng_live_stream->name->str); ret = LTTNG_LIVE_ITERATOR_STATUS_CONTINUE; goto end; } + if (lttng_live_stream->state != LTTNG_LIVE_STREAM_ACTIVE_NO_DATA && lttng_live_stream->state != LTTNG_LIVE_STREAM_QUIESCENT_NO_DATA) { goto end; } ret = lttng_live_get_next_index(lttng_live_msg_iter, lttng_live_stream, - &index); + &index); if (ret != LTTNG_LIVE_ITERATOR_STATUS_OK) { goto end; } + BT_ASSERT_DBG(lttng_live_stream->state != LTTNG_LIVE_STREAM_EOF); + if (lttng_live_stream->state == LTTNG_LIVE_STREAM_QUIESCENT) { uint64_t last_inact_ts = lttng_live_stream->last_inactivity_ts, curr_inact_ts = lttng_live_stream->current_inactivity_ts; @@ -407,9 +415,19 @@ enum lttng_live_iterator_status lttng_live_iterator_next_handle_one_no_data_stre } goto end; } + lttng_live_stream->base_offset = index.offset; lttng_live_stream->offset = index.offset; lttng_live_stream->len = index.packet_size / CHAR_BIT; + + BT_COMP_LOGD("Setting live stream reading info: stream-name=\"%s\", " + "viewer-stream-id=%" PRIu64 ", stream-base-offset=%" PRIu64 + ", stream-offset=%" PRIu64 ", stream-len=%" PRIu64, + lttng_live_stream->name->str, + lttng_live_stream->viewer_stream_id, + lttng_live_stream->base_offset, + lttng_live_stream->offset, lttng_live_stream->len); + end: if (ret == LTTNG_LIVE_ITERATOR_STATUS_OK) { ret = lttng_live_iterator_next_check_stream_state(lttng_live_stream); @@ -434,11 +452,9 @@ enum lttng_live_iterator_status lttng_live_get_session( enum lttng_live_iterator_status status; uint64_t trace_idx; - BT_COMP_LOGD("Updating all streams for session: " - "session-id=%"PRIu64", session-name=\"%s\"", - session->id, session->session_name->str); - if (!session->attached) { + BT_COMP_LOGD("Attach to session: session-id=%" PRIu64, + session->id); enum lttng_live_viewer_status attach_status = lttng_live_session_attach(session, lttng_live_msg_iter->self_msg_iter); @@ -461,12 +477,17 @@ enum lttng_live_iterator_status lttng_live_get_session( } } + BT_COMP_LOGD("Updating all streams and metadata for session: " + "session-id=%" PRIu64 ", session-name=\"%s\"", + session->id, session->session_name->str); + status = lttng_live_session_get_new_streams(session, lttng_live_msg_iter->self_msg_iter); if (status != LTTNG_LIVE_ITERATOR_STATUS_OK && status != LTTNG_LIVE_ITERATOR_STATUS_END) { goto end; } + trace_idx = 0; while (trace_idx < session->traces->len) { struct lttng_live_trace *trace = @@ -490,6 +511,11 @@ enum lttng_live_iterator_status lttng_live_get_session( goto end; } } + + /* + * Now that we have the metadata we can initialize the downstream + * iterator. + */ status = lttng_live_lazy_msg_init(session, lttng_live_msg_iter->self_msg_iter); @@ -501,16 +527,23 @@ static void lttng_live_force_new_streams_and_metadata(struct lttng_live_msg_iter *lttng_live_msg_iter) { uint64_t session_idx, trace_idx; + bt_logging_level log_level = lttng_live_msg_iter->log_level; + bt_self_component *self_comp = lttng_live_msg_iter->self_comp; for (session_idx = 0; session_idx < lttng_live_msg_iter->sessions->len; session_idx++) { struct lttng_live_session *session = g_ptr_array_index(lttng_live_msg_iter->sessions, session_idx); + BT_COMP_LOGD("Force marking session as needing new streams: " + "session-id=%" PRIu64, session->id); session->new_streams_needed = true; for (trace_idx = 0; trace_idx < session->traces->len; trace_idx++) { struct lttng_live_trace *trace = g_ptr_array_index(session->traces, trace_idx); + BT_COMP_LOGD("Force marking trace metadata state as needing an update: " + "session-id=%" PRIu64 ", trace-id=%" PRIu64, + session->id, trace->id); BT_ASSERT(trace->metadata_stream_state != LTTNG_LIVE_METADATA_STREAM_STATE_CLOSED); @@ -612,6 +645,11 @@ enum lttng_live_iterator_status emit_inactivity_message( BT_ASSERT(stream_iter->trace->clock_class); + BT_COMP_LOGD("Emitting inactivity message for stream: ctf-stream-id=%" PRIu64 + ", viewer-stream-id=%" PRIu64 ", timestamp=%" PRIu64, + stream_iter->ctf_stream_class_id, + stream_iter->viewer_stream_id, timestamp); + msg = bt_message_message_iterator_inactivity_create( lttng_live_msg_iter->self_msg_iter, stream_iter->trace->clock_class, timestamp); @@ -643,6 +681,10 @@ enum lttng_live_iterator_status lttng_live_iterator_next_handle_one_quiescent_st return LTTNG_LIVE_ITERATOR_STATUS_OK; } + /* + * Check if we already sent an inactivty message downstream for this + * `current_inactivity_ts` value. + */ if (lttng_live_stream->current_inactivity_ts == lttng_live_stream->last_inactivity_ts) { lttng_live_stream->state = LTTNG_LIVE_STREAM_QUIESCENT_NO_DATA; @@ -775,6 +817,8 @@ enum lttng_live_iterator_status lttng_live_iterator_next_handle_one_active_data_ g_ptr_array_index(lttng_live_msg_iter->sessions, session_idx); if (session->new_streams_needed) { + BT_COMP_LOGD("Need an update for streams: " + "session-id=%" PRIu64, session->id); ret = LTTNG_LIVE_ITERATOR_STATUS_CONTINUE; goto end; } @@ -783,6 +827,9 @@ enum lttng_live_iterator_status lttng_live_iterator_next_handle_one_active_data_ struct lttng_live_trace *trace = g_ptr_array_index(session->traces, trace_idx); if (trace->metadata_stream_state == LTTNG_LIVE_METADATA_STREAM_STATE_NEEDED) { + BT_COMP_LOGD("Need an update for metadata stream: " + "session-id=%" PRIu64 ", trace-id=%" PRIu64, + session->id, trace->id); ret = LTTNG_LIVE_ITERATOR_STATUS_CONTINUE; goto end; } @@ -840,6 +887,11 @@ enum lttng_live_iterator_status lttng_live_iterator_close_stream( LTTNG_LIVE_ITERATOR_STATUS_OK; bt_logging_level log_level = lttng_live_msg_iter->log_level; bt_self_component *self_comp = lttng_live_msg_iter->self_comp; + + BT_COMP_LOGD("Closing live stream iterator: stream-name=\"%s\", " + "viewer-stream-id=%" PRIu64, stream_iter->name->str, + stream_iter->viewer_stream_id); + /* * The viewer has hung up on us so we are closing the stream. The * `ctf_msg_iter` should simply realize that it needs to close the @@ -923,8 +975,9 @@ enum lttng_live_iterator_status lttng_live_iterator_next_msg_on_stream( bt_self_component *self_comp = lttng_live_msg_iter->self_comp; enum lttng_live_iterator_status live_status; - BT_COMP_LOGD("Finding the next message for stream iterator: " - "stream-name=\"%s\"", stream_iter->name->str); + BT_COMP_LOGD("Advancing live stream iterator until next message if possible: " + "stream-name=\"%s\", viewer-stream-id=%" PRIu64, + stream_iter->name->str, stream_iter->viewer_stream_id); if (stream_iter->has_stream_hung_up) { /* @@ -939,14 +992,19 @@ enum lttng_live_iterator_status lttng_live_iterator_next_msg_on_stream( retry: LTTNG_LIVE_LOGD_STREAM_ITER(stream_iter); + + /* + * Make sure we have the most recent metadata and possibly some new + * streams. + */ live_status = lttng_live_iterator_handle_new_streams_and_metadata( lttng_live_msg_iter); if (live_status != LTTNG_LIVE_ITERATOR_STATUS_OK) { goto end; } + live_status = lttng_live_iterator_next_handle_one_no_data_stream( lttng_live_msg_iter, stream_iter); - if (live_status != LTTNG_LIVE_ITERATOR_STATUS_OK) { if (live_status == LTTNG_LIVE_ITERATOR_STATUS_END) { /* @@ -958,6 +1016,7 @@ retry: } goto end; } + live_status = lttng_live_iterator_next_handle_one_quiescent_stream( lttng_live_msg_iter, stream_iter, curr_msg); if (live_status != LTTNG_LIVE_ITERATOR_STATUS_OK) { @@ -975,9 +1034,15 @@ retry: end: if (live_status == LTTNG_LIVE_ITERATOR_STATUS_CONTINUE) { + BT_COMP_LOGD("Ask the relay daemon for an updated view of the data and metadata streams"); goto retry; } + BT_COMP_LOGD("Returning from advancing live stream iterator: status=%s" + "stream-name=\"%s\", viewer-stream-id=%" PRIu64, + lttng_live_iterator_status_string(live_status), + stream_iter->name->str, stream_iter->viewer_stream_id); + return live_status; } @@ -1090,11 +1155,10 @@ enum lttng_live_iterator_status next_stream_iterator_for_trace( while (!stream_iter->current_msg) { const bt_message *msg = NULL; int64_t curr_msg_ts_ns = INT64_MAX; + stream_iter_status = lttng_live_iterator_next_msg_on_stream( lttng_live_msg_iter, stream_iter, &msg); - BT_COMP_LOGD("live stream iterator returned status :%s", - lttng_live_iterator_status_string(stream_iter_status)); if (stream_iter_status == LTTNG_LIVE_ITERATOR_STATUS_END) { stream_iter_is_ended = true; break; @@ -1106,6 +1170,11 @@ enum lttng_live_iterator_status next_stream_iterator_for_trace( BT_ASSERT_DBG(msg); + BT_COMP_LOGD("Live stream iterator returned message: msg-type=%s" + "stream-name=\"%s\", viewer-stream-id=%" PRIu64, + bt_common_message_type_string(bt_message_get_type(msg)), + stream_iter->name->str, stream_iter->viewer_stream_id); + /* * Get the timestamp in nanoseconds from origin of this * messsage. diff --git a/src/plugins/ctf/lttng-live/metadata.c b/src/plugins/ctf/lttng-live/metadata.c index 3edeb76d..711f3ca5 100644 --- a/src/plugins/ctf/lttng-live/metadata.c +++ b/src/plugins/ctf/lttng-live/metadata.c @@ -114,7 +114,8 @@ enum lttng_live_iterator_status lttng_live_metadata_update( bt_self_component *self_comp = trace->self_comp; enum lttng_live_get_one_metadata_status metadata_status; - BT_COMP_LOGD("Updating metadata for trace: trace-id=%"PRIu64, trace->id); + BT_COMP_LOGD("Updating metadata for trace: session-id=%" PRIu64 + ", trace-id=%" PRIu64, session->id, trace->id); /* No metadata stream yet. */ if (!metadata) { diff --git a/src/plugins/ctf/lttng-live/viewer-connection.c b/src/plugins/ctf/lttng-live/viewer-connection.c index a821431e..c3b5ca1b 100644 --- a/src/plugins/ctf/lttng-live/viewer-connection.c +++ b/src/plugins/ctf/lttng-live/viewer-connection.c @@ -62,6 +62,86 @@ do { \ _msg ": %s" _fmt, bt_socket_errormsg(), ##__VA_ARGS__); \ } while (0) +static +const char *lttng_viewer_command_string(enum lttng_viewer_command cmd) +{ + switch (cmd){ + case LTTNG_VIEWER_CONNECT: + return "CONNECT"; + case LTTNG_VIEWER_LIST_SESSIONS: + return "LIST_SESSIONS"; + case LTTNG_VIEWER_ATTACH_SESSION: + return "ATTACH_SESSION"; + case LTTNG_VIEWER_GET_NEXT_INDEX: + return "GET_NEXT_INDEX"; + case LTTNG_VIEWER_GET_PACKET: + return "GET_PACKET"; + case LTTNG_VIEWER_GET_METADATA: + return "GET_METADATA"; + case LTTNG_VIEWER_GET_NEW_STREAMS: + return "GET_NEW_STREAMS"; + case LTTNG_VIEWER_CREATE_SESSION: + return "CREATE_SESSION"; + case LTTNG_VIEWER_DETACH_SESSION: + return "DETACH_SESSION"; + } + + bt_common_abort(); +} + +static +const char *lttng_viewer_next_index_return_code_string( + enum lttng_viewer_next_index_return_code code) +{ + switch (code) { + case LTTNG_VIEWER_INDEX_OK: + return "INDEX_OK"; + case LTTNG_VIEWER_INDEX_RETRY: + return "INDEX_RETRY"; + case LTTNG_VIEWER_INDEX_HUP: + return "INDEX_HUP"; + case LTTNG_VIEWER_INDEX_ERR: + return "INDEX_ERR"; + case LTTNG_VIEWER_INDEX_INACTIVE: + return "INDEX_INACTIVE"; + case LTTNG_VIEWER_INDEX_EOF: + return "INDEX_EOF"; + } + + bt_common_abort(); +} + +static +const char *lttng_viewer_get_packet_return_code_string( + enum lttng_viewer_get_packet_return_code code) +{ + switch (code) { + case LTTNG_VIEWER_GET_PACKET_OK: + return "GET_PACKET_OK"; + case LTTNG_VIEWER_GET_PACKET_RETRY: + return "GET_PACKET_RETRY"; + case LTTNG_VIEWER_GET_PACKET_ERR: + return "GET_PACKET_ERR"; + case LTTNG_VIEWER_GET_PACKET_EOF: + return "GET_PACKET_EOF"; + } + + bt_common_abort(); +}; + +static +const char *lttng_viewer_seek_string(enum lttng_viewer_seek seek) +{ + switch (seek) { + case LTTNG_VIEWER_SEEK_BEGINNING: + return "SEEK_BEGINNING"; + case LTTNG_VIEWER_SEEK_LAST: + return "SEEK_LAST"; + } + + bt_common_abort(); +} + static inline enum lttng_live_iterator_status viewer_status_to_live_iterator_status( enum lttng_live_viewer_status viewer_status) @@ -73,9 +153,9 @@ enum lttng_live_iterator_status viewer_status_to_live_iterator_status( return LTTNG_LIVE_ITERATOR_STATUS_AGAIN; case LTTNG_LIVE_VIEWER_STATUS_ERROR: return LTTNG_LIVE_ITERATOR_STATUS_ERROR; - default: - bt_common_abort(); } + + bt_common_abort(); } static inline @@ -89,9 +169,9 @@ enum ctf_msg_iter_medium_status viewer_status_to_ctf_msg_iter_medium_status( return CTF_MSG_ITER_MEDIUM_STATUS_AGAIN; case LTTNG_LIVE_VIEWER_STATUS_ERROR: return CTF_MSG_ITER_MEDIUM_STATUS_ERROR; - default: - bt_common_abort(); } + + bt_common_abort(); } static inline @@ -330,9 +410,9 @@ enum lttng_live_viewer_status lttng_live_handshake( char cmd_buf[cmd_buf_len]; BT_COMP_OR_COMP_CLASS_LOGD(self_comp, self_comp_class, - "Handshaking with the Relay: " - "major-version=%u, minor-version=%u", - LTTNG_LIVE_MAJOR, LTTNG_LIVE_MINOR); + "Handshaking with the relay daemon: cmd=%s, major-version=%u, minor-version=%u", + lttng_viewer_command_string(LTTNG_VIEWER_CONNECT), LTTNG_LIVE_MAJOR, + LTTNG_LIVE_MINOR); cmd.cmd = htobe32(LTTNG_VIEWER_CONNECT); cmd.data_size = htobe64((uint64_t) sizeof(connect)); @@ -786,6 +866,9 @@ bt_component_class_query_method_status live_viewer_connection_list_sessions( goto error; } + BT_LOGD("Requesting list of sessions: cmd=%s", + lttng_viewer_command_string(LTTNG_VIEWER_LIST_SESSIONS)); + cmd.cmd = htobe32(LTTNG_VIEWER_LIST_SESSIONS); cmd.data_size = htobe64((uint64_t) 0); cmd.cmd_version = htobe32(0); @@ -863,7 +946,8 @@ enum lttng_live_viewer_status lttng_live_query_session_ids( bt_self_component_class *self_comp_class = viewer_connection->self_comp_class; - BT_COMP_LOGD("Asking the Relay for the list of sessions"); + BT_COMP_LOGD("Asking the relay daemon for the list of sessions: cmd=%s", + lttng_viewer_command_string(LTTNG_VIEWER_LIST_SESSIONS)); cmd.cmd = htobe32(LTTNG_VIEWER_LIST_SESSIONS); cmd.data_size = htobe64((uint64_t) 0); @@ -937,7 +1021,8 @@ enum lttng_live_viewer_status lttng_live_create_viewer_session( viewer_connection->self_comp_class; BT_COMP_OR_COMP_CLASS_LOGD(self_comp, self_comp_class, - "Creating a viewer session"); + "Creating a viewer session: cmd=%s", + lttng_viewer_command_string(LTTNG_VIEWER_CREATE_SESSION)); cmd.cmd = htobe32(LTTNG_VIEWER_CREATE_SESSION); cmd.data_size = htobe64((uint64_t) 0); @@ -990,7 +1075,7 @@ enum lttng_live_viewer_status receive_streams(struct lttng_live_session *session lttng_live_msg_iter->viewer_connection; bt_self_component *self_comp = viewer_connection->self_comp; - BT_COMP_LOGI("Getting %" PRIu32 " new streams:", stream_count); + BT_COMP_LOGI("Getting %" PRIu32 " new streams", stream_count); for (i = 0; i < stream_count; i++) { struct lttng_viewer_stream stream; struct lttng_live_stream_iterator *live_stream; @@ -1059,7 +1144,11 @@ enum lttng_live_viewer_status lttng_live_session_attach( const size_t cmd_buf_len = sizeof(cmd) + sizeof(rq); char cmd_buf[cmd_buf_len]; - BT_COMP_LOGD("Attaching to session: session-id=%"PRIu64, session_id); + BT_COMP_LOGD("Attaching to session: cmd=%s, session-id=%" PRIu64 + ", seek=%s", + lttng_viewer_command_string(LTTNG_VIEWER_ATTACH_SESSION), + session_id, + lttng_viewer_seek_string(LTTNG_VIEWER_SEEK_LAST)); cmd.cmd = htobe32(LTTNG_VIEWER_ATTACH_SESSION); cmd.data_size = htobe64((uint64_t) sizeof(rq)); @@ -1168,6 +1257,10 @@ enum lttng_live_viewer_status lttng_live_session_detach( return 0; } + BT_COMP_LOGD("Detaching from session: cmd=%s, session-id=%" PRIu64, + lttng_viewer_command_string(LTTNG_VIEWER_DETACH_SESSION), + session_id); + cmd.cmd = htobe32(LTTNG_VIEWER_DETACH_SESSION); cmd.data_size = htobe64((uint64_t) sizeof(rq)); cmd.cmd_version = htobe32(0); @@ -1243,8 +1336,9 @@ enum lttng_live_get_one_metadata_status lttng_live_get_one_metadata_packet( const size_t cmd_buf_len = sizeof(cmd) + sizeof(rq); char cmd_buf[cmd_buf_len]; - BT_COMP_LOGD("Requesting new metadata for trace: " - "trace-id=%"PRIu64", metadata-stream-id=%"PRIu64, + BT_COMP_LOGD("Requesting new metadata for trace:" + "cmd=%s, trace-id=%" PRIu64 ", metadata-stream-id=%" PRIu64, + lttng_viewer_command_string(LTTNG_VIEWER_GET_METADATA), trace->id, metadata->stream_id); rq.stream_id = htobe64(metadata->stream_id); @@ -1365,11 +1459,15 @@ static void lttng_live_need_new_streams(struct lttng_live_msg_iter *lttng_live_msg_iter) { uint64_t session_idx; + struct live_viewer_connection *viewer_connection = + lttng_live_msg_iter->viewer_connection; for (session_idx = 0; session_idx < lttng_live_msg_iter->sessions->len; session_idx++) { struct lttng_live_session *session = - g_ptr_array_index(lttng_live_msg_iter->sessions, session_idx); + g_ptr_array_index(lttng_live_msg_iter->sessions, session_idx); + BT_COMP_LOGD("Marking session as needing new streams: " + "session-id=%" PRIu64, session->id); session->new_streams_needed = true; } } @@ -1393,14 +1491,14 @@ enum lttng_live_iterator_status lttng_live_get_next_index( char cmd_buf[cmd_buf_len]; uint32_t flags, rp_status; - BT_COMP_LOGD("Requesting next index for stream: " - "stream-id=%"PRIu64, stream->viewer_stream_id); - + BT_COMP_LOGD("Requesting next index for stream: cmd=%s, " + "viewer-stream-id=%" PRIu64, + lttng_viewer_command_string(LTTNG_VIEWER_GET_NEXT_INDEX), + stream->viewer_stream_id); cmd.cmd = htobe32(LTTNG_VIEWER_GET_NEXT_INDEX); cmd.data_size = htobe64((uint64_t) sizeof(rq)); cmd.cmd_version = htobe32(0); - memset(&rq, 0, sizeof(rq)); rq.stream_id = htobe64(stream->viewer_stream_id); @@ -1411,6 +1509,7 @@ enum lttng_live_iterator_status lttng_live_get_next_index( */ memcpy(cmd_buf, &cmd, sizeof(cmd)); memcpy(cmd_buf + sizeof(cmd), &rq, sizeof(rq)); + viewer_status = lttng_live_send(viewer_connection, &cmd_buf, cmd_buf_len); if (viewer_status != LTTNG_LIVE_VIEWER_STATUS_OK) { viewer_handle_send_status(self_comp, NULL, @@ -1428,12 +1527,14 @@ enum lttng_live_iterator_status lttng_live_get_next_index( flags = be32toh(rp.flags); rp_status = be32toh(rp.status); + BT_COMP_LOGD("Received response from relay daemon: cmd=%s, response=%s", + lttng_viewer_command_string(LTTNG_VIEWER_GET_NEXT_INDEX), + lttng_viewer_next_index_return_code_string(rp_status)); switch (rp_status) { case LTTNG_VIEWER_INDEX_INACTIVE: { uint64_t ctf_stream_class_id; - BT_COMP_LOGD("Received get_next_index response: inactive"); memset(index, 0, sizeof(struct packet_index)); index->ts_cycles.timestamp_end = be64toh(rp.timestamp_end); stream->current_inactivity_ts = index->ts_cycles.timestamp_end; @@ -1452,7 +1553,6 @@ enum lttng_live_iterator_status lttng_live_get_next_index( { uint64_t ctf_stream_class_id; - BT_COMP_LOGD("Received get_next_index response: OK"); lttng_index_to_packet_index(&rp, index); ctf_stream_class_id = be64toh(rp.stream_id); if (stream->ctf_stream_class_id != -1ULL) { @@ -1465,24 +1565,27 @@ enum lttng_live_iterator_status lttng_live_get_next_index( stream->state = LTTNG_LIVE_STREAM_ACTIVE_DATA; if (flags & LTTNG_VIEWER_FLAG_NEW_METADATA) { - BT_COMP_LOGD("Received get_next_index response: new metadata needed"); + BT_COMP_LOGD("Marking trace as needing new metadata: " + "response=%s, response-flag=NEW_METADATA, trace-id=%" PRIu64, + lttng_viewer_next_index_return_code_string(rp_status), + trace->id); trace->metadata_stream_state = LTTNG_LIVE_METADATA_STREAM_STATE_NEEDED; } if (flags & LTTNG_VIEWER_FLAG_NEW_STREAM) { - BT_COMP_LOGD("Received get_next_index response: new streams needed"); + BT_COMP_LOGD("Marking all sessions as possibly needing new streams: " + "response=%s, response-flag=NEW_STREAM", + lttng_viewer_next_index_return_code_string(rp_status)); lttng_live_need_new_streams(lttng_live_msg_iter); } status = LTTNG_LIVE_ITERATOR_STATUS_OK; break; } case LTTNG_VIEWER_INDEX_RETRY: - BT_COMP_LOGD("Received get_next_index response: retry"); memset(index, 0, sizeof(struct packet_index)); stream->state = LTTNG_LIVE_STREAM_ACTIVE_NO_DATA; status = LTTNG_LIVE_ITERATOR_STATUS_AGAIN; goto end; case LTTNG_VIEWER_INDEX_HUP: - BT_COMP_LOGD("Received get_next_index response: stream hung up"); memset(index, 0, sizeof(struct packet_index)); index->offset = EOF; stream->state = LTTNG_LIVE_STREAM_EOF; @@ -1490,7 +1593,6 @@ enum lttng_live_iterator_status lttng_live_get_next_index( status = LTTNG_LIVE_ITERATOR_STATUS_END; break; case LTTNG_VIEWER_INDEX_ERR: - BT_COMP_LOGD("Received get_next_index response: error"); memset(index, 0, sizeof(struct packet_index)); stream->state = LTTNG_LIVE_STREAM_ACTIVE_NO_DATA; status = LTTNG_LIVE_ITERATOR_STATUS_ERROR; @@ -1529,8 +1631,11 @@ enum ctf_msg_iter_medium_status lttng_live_get_stream_bytes( char cmd_buf[cmd_buf_len]; uint32_t flags, rp_status; - BT_COMP_LOGD("lttng_live_get_stream_bytes: offset=%" PRIu64 ", req_len=%" PRIu64, + BT_COMP_LOGD("Requesting data from stream: cmd=%s, " + "offset=%" PRIu64 ", request-len=%" PRIu64, + lttng_viewer_command_string(LTTNG_VIEWER_GET_PACKET), offset, req_len); + cmd.cmd = htobe32(LTTNG_VIEWER_GET_PACKET); cmd.data_size = htobe64((uint64_t) sizeof(rq)); cmd.cmd_version = htobe32(0); @@ -1547,6 +1652,7 @@ enum ctf_msg_iter_medium_status lttng_live_get_stream_bytes( */ memcpy(cmd_buf, &cmd, sizeof(cmd)); memcpy(cmd_buf + sizeof(cmd), &rq, sizeof(rq)); + viewer_status = lttng_live_send(viewer_connection, &cmd_buf, cmd_buf_len); if (viewer_status != LTTNG_LIVE_VIEWER_STATUS_OK) { viewer_handle_send_status(self_comp, NULL, @@ -1564,30 +1670,40 @@ enum ctf_msg_iter_medium_status lttng_live_get_stream_bytes( flags = be32toh(rp.flags); rp_status = be32toh(rp.status); + BT_COMP_LOGD("Received response from relay daemon: cmd=%s, response=%s", + lttng_viewer_command_string(LTTNG_VIEWER_GET_PACKET), + lttng_viewer_get_packet_return_code_string(rp_status)); switch (rp_status) { case LTTNG_VIEWER_GET_PACKET_OK: req_len = be32toh(rp.len); - BT_COMP_LOGD("Received get_data_packet response: Ok, " - "packet size : %" PRIu64 "", req_len); + BT_COMP_LOGD("Got packet from relay daemon: response=%s, packet-len=%" PRIu64 "", + lttng_viewer_get_packet_return_code_string(rp_status), + req_len); status = CTF_MSG_ITER_MEDIUM_STATUS_OK; break; case LTTNG_VIEWER_GET_PACKET_RETRY: /* Unimplemented by relay daemon */ - BT_COMP_LOGD("Received get_data_packet response: retry"); status = CTF_MSG_ITER_MEDIUM_STATUS_AGAIN; goto end; case LTTNG_VIEWER_GET_PACKET_ERR: if (flags & LTTNG_VIEWER_FLAG_NEW_METADATA) { - BT_COMP_LOGD("get_data_packet: new metadata needed, try again later"); + BT_COMP_LOGD("Marking trace as needing new metadata: " + "response=%s, response-flag=NEW_METADATA, trace-id=%" PRIu64, + lttng_viewer_next_index_return_code_string(rp_status), + trace->id); trace->metadata_stream_state = LTTNG_LIVE_METADATA_STREAM_STATE_NEEDED; } if (flags & LTTNG_VIEWER_FLAG_NEW_STREAM) { - BT_COMP_LOGD("get_data_packet: new streams needed, try again later"); + BT_COMP_LOGD("Marking all sessions as possibly needing new streams: " + "response=%s, response-flag=NEW_STREAM", + lttng_viewer_next_index_return_code_string(rp_status)); lttng_live_need_new_streams(lttng_live_msg_iter); } if (flags & (LTTNG_VIEWER_FLAG_NEW_METADATA | LTTNG_VIEWER_FLAG_NEW_STREAM)) { status = CTF_MSG_ITER_MEDIUM_STATUS_AGAIN; + BT_COMP_LOGD("Reply with any one flags set means we should retry: response=%s", + lttng_viewer_get_packet_return_code_string(rp_status)); goto end; } BT_COMP_LOGE_APPEND_CAUSE(self_comp, @@ -1654,8 +1770,10 @@ enum lttng_live_iterator_status lttng_live_session_get_new_streams( goto end; } - BT_COMP_LOGD("Requesting new streams for session: " - "session-id=%"PRIu64, session->id); + BT_COMP_LOGD("Requesting new streams for session: cmd=%s" + "session-id=%" PRIu64, + lttng_viewer_command_string(LTTNG_VIEWER_GET_NEW_STREAMS), + session->id); cmd.cmd = htobe32(LTTNG_VIEWER_GET_NEW_STREAMS); cmd.data_size = htobe64((uint64_t) sizeof(rq)); @@ -1671,6 +1789,7 @@ enum lttng_live_iterator_status lttng_live_session_get_new_streams( */ memcpy(cmd_buf, &cmd, sizeof(cmd)); memcpy(cmd_buf + sizeof(cmd), &rq, sizeof(rq)); + viewer_status = lttng_live_send(viewer_connection, &cmd_buf, cmd_buf_len); if (viewer_status != LTTNG_LIVE_VIEWER_STATUS_OK) { viewer_handle_send_status(self_comp, NULL, -- 2.34.1