aos/network: fix up logging, especially VLOG
Make it so that VLOG(1) is not overwhelming and mostly
shows us changes related to association changes.
Also show more useful messages that tell us more about
what is going on by including per-connection information.
Change-Id: I079a849afd63da03ba2e76a6c3f631455ed7e480
Signed-off-by: James Kuszmaul <james.kuszmaul@bluerivertech.com>
diff --git a/aos/network/message_bridge_client_lib.cc b/aos/network/message_bridge_client_lib.cc
index 9001cce..b2bf1e4 100644
--- a/aos/network/message_bridge_client_lib.cc
+++ b/aos/network/message_bridge_client_lib.cc
@@ -38,6 +38,9 @@
const Connection *connection =
configuration::ConnectionToNode(channel, my_node);
if (connection != nullptr) {
+ VLOG(1) << "Channel " << channel->name()->string_view() << " "
+ << channel->type()->string_view() << " mapped to stream "
+ << stream_to_channel.size() + kControlStreams();
stream_to_channel.emplace_back(channel_index);
}
}
@@ -171,6 +174,8 @@
case SCTP_SHUTDOWN_COMP:
case SCTP_CANT_STR_ASSOC: {
NodeDisconnected();
+ VLOG(1) << "Disconnect from " << message->PeerAddress() << " on "
+ << sac->sac_assoc_id;
} break;
case SCTP_RESTART:
LOG(FATAL) << "Never seen this before.";
@@ -188,15 +193,18 @@
}
void SctpClientConnection::SendConnect() {
- VLOG(1) << "Sending Connect";
// Try to send the connect message. If that fails, retry.
if (client_.Send(kConnectStream(),
std::string_view(reinterpret_cast<const char *>(
connect_message_.span().data()),
connect_message_.span().size()),
0)) {
+ VLOG(1) << "Connect to " << remote_node_->hostname()->string_view()
+ << " succeeded.";
ScheduleConnectTimeout();
} else {
+ VLOG(1) << "Connect to " << remote_node_->hostname()->string_view()
+ << " failed.";
NodeDisconnected();
}
}
@@ -225,7 +233,7 @@
const RemoteData *remote_data =
flatbuffers::GetSizePrefixedRoot<RemoteData>(message->data());
- VLOG(1) << "Got a message of size " << message->size;
+ VLOG(2) << "Got a message of size " << message->size;
CHECK_EQ(message->size, flatbuffers::GetPrefixedSize(message->data()) +
sizeof(flatbuffers::uoffset_t));
{
@@ -306,14 +314,14 @@
}
}
- VLOG(1) << "Received data of length " << message->size << " from "
+ VLOG(2) << "Received data of length " << message->size << " from "
<< message->PeerAddress();
- if (VLOG_IS_ON(1)) {
+ if (VLOG_IS_ON(2)) {
client_.LogSctpStatus(message->header.rcvinfo.rcv_assoc_id);
}
- VLOG(2) << "\tSNDRCV (stream=" << message->header.rcvinfo.rcv_sid
+ VLOG(3) << "\tSNDRCV (stream=" << message->header.rcvinfo.rcv_sid
<< " ssn=" << message->header.rcvinfo.rcv_ssn
<< " tsn=" << message->header.rcvinfo.rcv_tsn << " flags=0x"
<< std::hex << message->header.rcvinfo.rcv_flags << std::dec
diff --git a/aos/network/message_bridge_server_lib.cc b/aos/network/message_bridge_server_lib.cc
index 7c0e468..de30af1 100644
--- a/aos/network/message_bridge_server_lib.cc
+++ b/aos/network/message_bridge_server_lib.cc
@@ -31,7 +31,7 @@
const Context &context) {
flatbuffers::FlatBufferBuilder fbb(channel_->max_size() + 100);
fbb.ForceDefaults(true);
- VLOG(1) << "Found " << peers_.size() << " peers on channel "
+ VLOG(2) << "Found " << peers_.size() << " peers on channel "
<< channel_->name()->string_view() << " "
<< channel_->type()->string_view() << " size " << context.size;
@@ -93,10 +93,10 @@
VLOG(1)
<< "No clients, rejecting. TODO(austin): do backup logging to disk";
} else {
- VLOG(1) << "TODO(austin): backup log to disk if this fails eventually";
+ VLOG(2) << "TODO(austin): backup log to disk if this fails eventually";
}
} else {
- VLOG(1) << "Not bothering to track this message since nobody cares.";
+ VLOG(2) << "Not bothering to track this message since nobody cares.";
}
// TODO(austin): Limit the size of this queue. Flush messages to disk
@@ -195,16 +195,23 @@
int ChannelState::NodeConnected(
const Node *node, sctp_assoc_t assoc_id, int stream, SctpServer *server,
aos::monotonic_clock::time_point monotonic_now) {
- VLOG(1) << "Connected to assoc_id: " << assoc_id << " for stream " << stream;
+ VLOG(1) << "Channel " << channel_->name()->string_view() << " "
+ << channel_->type()->string_view() << " mapped to stream " << stream
+ << " for node " << node->name()->string_view() << " assoc_id "
+ << assoc_id;
for (ChannelState::Peer &peer : peers_) {
if (peer.connection->name()->string_view() == node->name()->string_view()) {
// There's a peer already connected. Disconnect them and take over.
if (peer.sac_assoc_id != 0) {
if (peer.sac_assoc_id == assoc_id) {
- LOG(WARNING) << "Reconnecting with the same ID, something got lost";
+ LOG(WARNING) << "Node " << node->name()->string_view()
+ << " reconnecting on " << assoc_id
+ << "with the same ID, something got lost";
} else {
- LOG(WARNING) << "Peer " << peer.sac_assoc_id
- << " already connected, aborting old connection.";
+ LOG(WARNING) << "Node " << node->name()->string_view() << " "
+ << " already connected on " << peer.sac_assoc_id
+ << "aborting old connection and switching to "
+ << assoc_id;
server->Abort(peer.sac_assoc_id);
}
}
@@ -429,13 +436,15 @@
switch (sac->sac_state) {
case SCTP_COMM_UP:
NodeConnected(sac->sac_assoc_id);
- VLOG(1) << "Peer connected";
+ VLOG(1) << "Received up from " << message->PeerAddress() << " on "
+ << sac->sac_assoc_id;
break;
case SCTP_COMM_LOST:
case SCTP_SHUTDOWN_COMP:
case SCTP_CANT_STR_ASSOC:
NodeDisconnected(sac->sac_assoc_id);
- VLOG(1) << "Disconnect";
+ VLOG(1) << "Disconnect from " << message->PeerAddress() << " on "
+ << sac->sac_assoc_id << " state " << sac->sac_state;
break;
case SCTP_RESTART:
LOG(FATAL) << "Never seen this before.";
@@ -449,7 +458,7 @@
}
void MessageBridgeServer::HandleData(const Message *message) {
- VLOG(1) << "Received data of length " << message->size;
+ VLOG(2) << "Received data of length " << message->size;
if (message->header.rcvinfo.rcv_sid == kConnectStream()) {
// Control channel!
@@ -479,7 +488,6 @@
connect->node(), message->header.rcvinfo.rcv_assoc_id,
channel_index, &server_, monotonic_now);
CHECK_NE(node_index, -1);
-
matched = true;
break;
}
@@ -502,6 +510,9 @@
->Get(node_index)
->name()
->string_view();
+ if (VLOG_IS_ON(1)) {
+ message->LogRcvInfo();
+ }
} else if (message->header.rcvinfo.rcv_sid == kTimestampStream()) {
// Message delivery
const logger::MessageHeader *message_header =
@@ -518,10 +529,15 @@
message->header.rcvinfo.rcv_ssn,
absl::Span<const uint8_t>(message->data(), message->size),
message->partial_deliveries, &server_status_);
- }
-
- if (VLOG_IS_ON(1)) {
+ if (VLOG_IS_ON(2)) {
+ message->LogRcvInfo();
+ }
+ } else {
message->LogRcvInfo();
+ // TODO(sarah.newman): add some versioning concept such that if this was a
+ // fatal error, we would never get here.
+ LOG_FIRST_N(ERROR, 20) << "Unexpected stream id "
+ << message->header.rcvinfo.rcv_sid;
}
}
diff --git a/aos/network/sctp_lib.cc b/aos/network/sctp_lib.cc
index 5bc1b37..21c0b78 100644
--- a/aos/network/sctp_lib.cc
+++ b/aos/network/sctp_lib.cc
@@ -23,7 +23,7 @@
namespace {
const char *sac_state_tbl[] = {"COMMUNICATION_UP", "COMMUNICATION_LOST",
"RESTART", "SHUTDOWN_COMPLETE",
- "CANT_START_ASSOCICATION"};
+ "CANT_START_ASSOCIATION"};
typedef union {
struct sctp_initmsg init;
@@ -285,7 +285,7 @@
if (sockaddr_remote) {
outmsg.msg_name = &*sockaddr_remote;
outmsg.msg_namelen = sizeof(*sockaddr_remote);
- VLOG(1) << "Sending to " << Address(*sockaddr_remote);
+ VLOG(2) << "Sending to " << Address(*sockaddr_remote);
} else {
outmsg.msg_namelen = 0;
}
@@ -328,7 +328,7 @@
return false;
}
CHECK_EQ(static_cast<ssize_t>(data.size()), size);
- VLOG(1) << "Sent " << data.size();
+ VLOG(2) << "Sent " << data.size();
return true;
}
@@ -444,7 +444,7 @@
memcpy(partial_message->mutable_data() + partial_message->size,
result->data(), result->size);
++partial_message->partial_deliveries;
- VLOG(1) << "Merged fragment of " << result->size << " after "
+ VLOG(2) << "Merged fragment of " << result->size << " after "
<< partial_message->size << ", had "
<< partial_message->partial_deliveries
<< ", for: " << result->header.rcvinfo.rcv_sid << ","
@@ -472,7 +472,7 @@
return result;
}
if (partial_message_iterator == partial_messages_.end()) {
- VLOG(1) << "Starting fragment for: " << result->header.rcvinfo.rcv_sid
+ VLOG(2) << "Starting fragment for: " << result->header.rcvinfo.rcv_sid
<< "," << result->header.rcvinfo.rcv_ssn << ","
<< result->header.rcvinfo.rcv_assoc_id;
// Need to record this as the first fragment.
diff --git a/aos/network/timestamp_filter.cc b/aos/network/timestamp_filter.cc
index 87133d1..8d84adf 100644
--- a/aos/network/timestamp_filter.cc
+++ b/aos/network/timestamp_filter.cc
@@ -86,7 +86,7 @@
void TimestampFilter::Sample(aos::monotonic_clock::time_point monotonic_now,
chrono::nanoseconds sample_ns) {
- VLOG(1) << " " << this << " Sample at " << monotonic_now << " is "
+ VLOG(2) << " " << this << " Sample at " << monotonic_now << " is "
<< sample_ns.count() << "ns, Base is " << base_offset_.count();
CHECK_GE(monotonic_now, last_time_)
<< ": " << this << " Being asked to filter backwards in time!";
@@ -165,7 +165,7 @@
time_contribution_ = time_contribution;
}
- VLOG(1) << " " << this << " filter sample is " << offset_;
+ VLOG(2) << " " << this << " filter sample is " << offset_;
}
}
@@ -283,7 +283,7 @@
void ClippedAverageFilter::FwdSet(
aos::monotonic_clock::time_point monotonic_now,
chrono::nanoseconds sample_ns) {
- VLOG(1) << "Fwd Set";
+ VLOG(2) << "Fwd Set";
fwd_.Set(monotonic_now, sample_ns);
Update(monotonic_now, &last_fwd_time_);
}
@@ -324,7 +324,7 @@
void ClippedAverageFilter::RevSet(
aos::monotonic_clock::time_point monotonic_now,
chrono::nanoseconds sample_ns) {
- VLOG(1) << "Rev set";
+ VLOG(2) << "Rev set";
rev_.Set(monotonic_now, sample_ns);
Update(monotonic_now, &last_rev_time_);
}
@@ -420,7 +420,7 @@
const double hard_max = fwd_.offset();
const double hard_min = -rev_.offset();
const double average = (hard_max + hard_min) / 2.0;
- VLOG(1) << this << " Max(fwd) " << hard_max << " min(rev) " << hard_min;
+ VLOG(2) << this << " Max(fwd) " << hard_max << " min(rev) " << hard_min;
// We don't want to clip the offset to the hard min/max. We really want to
// keep it within a band around the middle. ratio of 0.3 means stay within
// +- 0.15 of the middle of the hard min and max.
@@ -455,7 +455,7 @@
(offset_velocity_ -
(fwd_.filtered_velocity() - rev_.filtered_velocity()) / 2.0);
- VLOG(1) << this << " last time " << offset_;
+ VLOG(2) << this << " last time " << offset_;
}
*last_time = monotonic_now;
diff --git a/aos/network/timestamp_filter.h b/aos/network/timestamp_filter.h
index b51fe2f..2ed98da 100644
--- a/aos/network/timestamp_filter.h
+++ b/aos/network/timestamp_filter.h
@@ -57,7 +57,7 @@
void set_base_offset(std::chrono::nanoseconds base_offset);
double offset() const {
- VLOG(1) << " " << this << " offset " << offset_;
+ VLOG(2) << " " << this << " offset " << offset_;
return offset_;
}