From dc900fd653ba223f0d3c1fc8d49be0a191a8bcb4 Mon Sep 17 00:00:00 2001 From: Kefu Chai Date: Tue, 2 Jul 2019 11:04:48 +0800 Subject: [PATCH] crimson/net: print trivial logging using "trace" Signed-off-by: Kefu Chai --- src/crimson/net/Protocol.cc | 2 +- src/crimson/net/ProtocolV1.cc | 14 +++---- src/crimson/net/ProtocolV2.cc | 62 +++++++++++++++--------------- src/crimson/net/SocketMessenger.cc | 2 +- 4 files changed, 40 insertions(+), 40 deletions(-) diff --git a/src/crimson/net/Protocol.cc b/src/crimson/net/Protocol.cc index 3131f568324..3ef6cc9612f 100644 --- a/src/crimson/net/Protocol.cc +++ b/src/crimson/net/Protocol.cc @@ -89,7 +89,7 @@ seastar::future<> Protocol::keepalive() void Protocol::notify_keepalive_ack(utime_t _keepalive_ack) { - logger().debug("{} got keepalive ack {}", conn, _keepalive_ack); + logger().trace("{} got keepalive ack {}", conn, _keepalive_ack); keepalive_ack = _keepalive_ack; write_event(); } diff --git a/src/crimson/net/ProtocolV1.cc b/src/crimson/net/ProtocolV1.cc index e42378e00f7..4601b3460b1 100644 --- a/src/crimson/net/ProtocolV1.cc +++ b/src/crimson/net/ProtocolV1.cc @@ -321,7 +321,7 @@ void ProtocolV1::start_connect(const entity_addr_t& _peer_addr, const entity_type_t& _peer_type) { ceph_assert(state == state_t::none); - logger().debug("{} trigger connecting, was {}", conn, static_cast(state)); + logger().trace("{} trigger connecting, was {}", conn, static_cast(state)); state = state_t::connecting; set_write_state(write_state_t::delay); @@ -600,7 +600,7 @@ void ProtocolV1::start_accept(SocketFRef&& sock, const entity_addr_t& _peer_addr) { ceph_assert(state == state_t::none); - logger().debug("{} trigger accepting, was {}", + logger().trace("{} trigger accepting, was {}", conn, static_cast(state)); state = state_t::accepting; set_write_state(write_state_t::delay); @@ -680,12 +680,12 @@ ceph::bufferlist ProtocolV1::do_sweep_messages( if (unlikely(require_keepalive)) { k.req.stamp = ceph::coarse_real_clock::to_ceph_timespec( ceph::coarse_real_clock::now()); - logger().debug("{} write keepalive2 {}", conn, k.req.stamp.tv_sec); + logger().trace("{} write keepalive2 {}", conn, k.req.stamp.tv_sec); bl.append(create_static(k.req)); } if (unlikely(_keepalive_ack.has_value())) { - logger().debug("{} write keepalive2 ack {}", conn, *_keepalive_ack); + logger().trace("{} write keepalive2 ack {}", conn, *_keepalive_ack); k.ack.stamp = ceph_timespec(*_keepalive_ack); bl.append(create_static(k.ack)); } @@ -733,7 +733,7 @@ seastar::future<> ProtocolV1::handle_keepalive2_ack() .then([this] (auto buf) { auto t = reinterpret_cast(buf.get()); k.ack_stamp = *t; - logger().debug("{} got keepalive2 ack {}", conn, t->tv_sec); + logger().trace("{} got keepalive2 ack {}", conn, t->tv_sec); }); } @@ -860,7 +860,7 @@ seastar::future<> ProtocolV1::handle_tags() void ProtocolV1::execute_open() { - logger().debug("{} trigger open, was {}", conn, static_cast(state)); + logger().trace("{} trigger open, was {}", conn, static_cast(state)); state = state_t::open; set_write_state(write_state_t::open); @@ -897,7 +897,7 @@ void ProtocolV1::execute_open() void ProtocolV1::trigger_close() { - logger().debug("{} trigger closing, was {}", + logger().trace("{} trigger closing, was {}", conn, static_cast(state)); if (state == state_t::accepting) { diff --git a/src/crimson/net/ProtocolV2.cc b/src/crimson/net/ProtocolV2.cc index d6f597fa122..c966d4ba502 100644 --- a/src/crimson/net/ProtocolV2.cc +++ b/src/crimson/net/ProtocolV2.cc @@ -216,7 +216,7 @@ seastar::future ProtocolV2::read_main_preamble() conn, rx_crc, main_preamble.crc); abort_in_fault(); } - logger().debug("{} read main preamble: tag={}, len={}", conn, (int)main_preamble.tag, bl.size()); + logger().trace("{} read main preamble: tag={}, len={}", conn, (int)main_preamble.tag, bl.size()); // currently we do support between 1 and MAX_NUM_SEGMENTS segments if (main_preamble.num_segments < 1 || @@ -235,7 +235,7 @@ seastar::future ProtocolV2::read_main_preamble() rx_segments_data.clear(); for (std::uint8_t idx = 0; idx < main_preamble.num_segments; idx++) { - logger().debug("{} got new segment: len={} align={}", + logger().trace("{} got new segment: len={} align={}", conn, main_preamble.segments[idx].length, main_preamble.segments[idx].alignment); rx_segments_desc.emplace_back(main_preamble.segments[idx]); @@ -257,7 +257,7 @@ seastar::future<> ProtocolV2::read_frame_payload() const auto& cur_rx_desc = rx_segments_desc.at(rx_segments_data.size()); // TODO: create aligned and contiguous buffer from socket if (cur_rx_desc.alignment != segment_t::DEFAULT_ALIGNMENT) { - logger().debug("{} cannot allocate {} aligned buffer at segment desc index {}", + logger().trace("{} cannot allocate {} aligned buffer at segment desc index {}", conn, cur_rx_desc.alignment, rx_segments_data.size()); } // TODO: create aligned and contiguous buffer from socket @@ -265,7 +265,7 @@ seastar::future<> ProtocolV2::read_frame_payload() .then([this] (auto tmp_bl) { bufferlist data; data.append(buffer::create(std::move(tmp_bl))); - logger().debug("{} read frame segment[{}], length={}", + logger().trace("{} read frame segment[{}], length={}", conn, rx_segments_data.size(), data.length()); if (session_stream_handlers.rx) { // TODO @@ -279,7 +279,7 @@ seastar::future<> ProtocolV2::read_frame_payload() ceph_assert(!session_stream_handlers.rx); return read_exactly(FRAME_PLAIN_EPILOGUE_SIZE); }).then([this] (auto bl) { - logger().debug("{} read frame epilogue length={}", conn, bl.size()); + logger().trace("{} read frame epilogue length={}", conn, bl.size()); __u8 late_flags; if (session_stream_handlers.rx) { @@ -296,7 +296,7 @@ seastar::future<> ProtocolV2::read_frame_payload() conn, (unsigned int)idx, expected_crc, calculated_crc); abort_in_fault(); } else { - logger().debug("{} message integrity check success at index {}: crc={}", + logger().trace("{} message integrity check success at index {}: crc={}", conn, (unsigned int)idx, expected_crc); } } @@ -317,7 +317,7 @@ template seastar::future<> ProtocolV2::write_frame(F &frame, bool flush) { auto bl = frame.get_buffer(session_stream_handlers); - logger().debug("{} write frame: tag={}, len={}", conn, + logger().trace("{} write frame: tag={}, len={}", conn, static_cast(frame.tag), bl.length()); if (flush) { return write_flush(std::move(bl)); @@ -333,7 +333,7 @@ void ProtocolV2::trigger_state(state_t _state, write_state_t _write_state, bool conn, get_state_name(state)); ceph_assert(false); } - logger().debug("{} trigger {}, was {}", + logger().trace("{} trigger {}, was {}", conn, get_state_name(_state), get_state_name(state)); state = _state; set_write_state(_write_state); @@ -440,7 +440,7 @@ seastar::future ProtocolV2::banner_exchange() logger().error("{} decode banner payload failed", conn); abort_in_fault(); } - logger().debug("{} supported={} required={}", + logger().trace("{} supported={} required={}", conn, peer_supported_features, peer_required_features); // Check feature bit compatibility @@ -475,7 +475,7 @@ seastar::future ProtocolV2::banner_exchange() }).then([this] { // 6. process peer HelloFrame auto hello = HelloFrame::Decode(rx_segments_data.back()); - logger().debug("{} received hello: peer_type={} peer_addr_for_me={}", + logger().trace("{} received hello: peer_type={} peer_addr_for_me={}", conn, (int)hello.entity_type(), hello.peer_addr()); return seastar::make_ready_future( hello.entity_type(), hello.peer_addr()); @@ -513,7 +513,7 @@ seastar::future<> ProtocolV2::handle_auth_reply() return read_frame_payload().then([this] { // handle_auth_reply_more() logic auto auth_more = AuthReplyMoreFrame::Decode(rx_segments_data.back()); - logger().debug("{} auth reply more len={}", + logger().trace("{} auth reply more len={}", conn, auth_more.auth_payload().length()); ceph_assert(messenger.get_auth_client()); // let execute_connecting() take care of the thrown exception @@ -576,7 +576,7 @@ seastar::future ProtocolV2::process_wait() { return read_frame_payload().then([this] { // handle_wait() logic - logger().debug("{} received WAIT (connection race)", conn); + logger().trace("{} received WAIT (connection race)", conn); WaitFrame::Decode(rx_segments_data.back()); return false; }); @@ -609,7 +609,7 @@ seastar::future ProtocolV2::client_connect() conn.policy.features_required | msgr2_required, flags, client_cookie); - logger().debug("{} sending identification: addrs={} target={} gid={}" + logger().trace("{} sending identification: addrs={} target={} gid={}" " global_seq={} features_supported={} features_required={}" " flags={} cookie={}", conn, messenger.get_myaddrs(), conn.target_addr, @@ -638,7 +638,7 @@ seastar::future ProtocolV2::client_connect() return read_frame_payload().then([this] { // handle_server_ident() logic auto server_ident = ServerIdentFrame::Decode(rx_segments_data.back()); - logger().debug("{} received server identification:" + logger().trace("{} received server identification:" " addrs={} gid={} global_seq={}" " features_supported={} features_required={}" " flags={} cookie={}", @@ -672,7 +672,7 @@ seastar::future ProtocolV2::client_connect() ceph_assert(server_ident.flags() & CEPH_MSG_CONNECT_LOSSY); conn.policy.lossy = server_ident.flags() & CEPH_MSG_CONNECT_LOSSY; // TODO: backoff = utime_t(); - logger().debug("{} connect success {}, lossy={}, features={}", + logger().trace("{} connect success {}, lossy={}, features={}", conn, connect_seq, conn.policy.lossy, conn.features); return dispatcher.ms_handle_connect( @@ -701,7 +701,7 @@ seastar::future ProtocolV2::client_reconnect() global_seq, connect_seq, conn.in_seq); - logger().debug("{} reconnect to session: client_cookie={}" + logger().trace("{} reconnect to session: client_cookie={}" " server_cookie={} gs={} cs={} ms={}", conn, client_cookie, server_cookie, global_seq, connect_seq, conn.in_seq); @@ -742,7 +742,7 @@ seastar::future ProtocolV2::client_reconnect() return read_frame_payload().then([this] { // handle_reconnect_ok() logic auto reconnect_ok = ReconnectOkFrame::Decode(rx_segments_data.back()); - logger().debug("{} received reconnect ok:" + logger().trace("{} received reconnect ok:" "sms={}, lossy={}, features={}", conn, reconnect_ok.msg_seq(), connect_seq, conn.policy.lossy, conn.features); @@ -795,7 +795,7 @@ void ProtocolV2::execute_connecting() } if (messenger.get_myaddrs().empty() || messenger.get_myaddrs().front().is_blank_ip()) { - logger().debug("peer {} says I am {}", conn.target_addr, _peer_addr); + logger().trace("peer {} says I am {}", conn.target_addr, _peer_addr); return messenger.learned_addr(_peer_addr); } else { return seastar::now(); @@ -899,7 +899,7 @@ seastar::future<> ProtocolV2::server_auth() }).then([this] { // handle_auth_request() logic auto request = AuthRequestFrame::Decode(rx_segments_data.back()); - logger().debug("{} got AuthRequest(method={}, preferred_modes={}, payload_len={})", + logger().trace("{} got AuthRequest(method={}, preferred_modes={}, payload_len={})", conn, request.method(), request.preferred_modes(), request.auth_payload().length()); auth_meta->auth_method = request.method(); @@ -925,7 +925,7 @@ seastar::future ProtocolV2::send_wait() seastar::future ProtocolV2::handle_existing_connection(SocketConnectionRef existing) { // handle_existing_connection() logic - logger().debug("{} {}: {}", conn, __func__, *existing); + logger().trace("{} {}: {}", conn, __func__, *existing); ProtocolV2 *exproto = dynamic_cast(existing->protocol.get()); ceph_assert(exproto); @@ -971,7 +971,7 @@ seastar::future ProtocolV2::server_connect() return read_frame_payload().then([this] { // handle_client_ident() logic auto client_ident = ClientIdentFrame::Decode(rx_segments_data.back()); - logger().debug("{} received client identification: addrs={} target={}" + logger().trace("{} received client identification: addrs={} target={}" " gid={} global_seq={} features_supported={}" " features_required={} flags={} cookie={}", conn, client_ident.addrs(), client_ident.target_addr(), @@ -996,7 +996,7 @@ seastar::future ProtocolV2::server_connect() conn.peer_addr.set_type(paddr.get_type()); conn.peer_addr.set_port(paddr.get_port()); conn.peer_addr.set_nonce(paddr.get_nonce()); - logger().debug("{} got paddr={}, conn.peer_addr={}", conn, paddr, conn.peer_addr); + logger().trace("{} got paddr={}, conn.peer_addr={}", conn, paddr, conn.peer_addr); conn.target_addr = conn.peer_addr; peer_name = entity_name_t(conn.get_peer_type(), client_ident.gid()); @@ -1085,7 +1085,7 @@ seastar::future ProtocolV2::server_reconnect() // handle_reconnect() logic auto reconnect = ReconnectFrame::Decode(rx_segments_data.back()); - logger().debug("{} received reconnect: client_cookie={} server_cookie={}" + logger().trace("{} received reconnect: client_cookie={} server_cookie={}" " gs={} cs={} ms={}", conn, reconnect.client_cookie(), reconnect.server_cookie(), reconnect.global_seq(), reconnect.connect_seq(), @@ -1149,14 +1149,14 @@ seastar::future ProtocolV2::server_reconnect() } if (exproto->peer_global_seq > reconnect.global_seq()) { - logger().debug("{} server_reconnect: stale global_seq: sgs={} cgs={}," + logger().trace("{} server_reconnect: stale global_seq: sgs={} cgs={}," " ask client to retry global", conn, exproto->peer_global_seq, reconnect.global_seq()); return send_retry_global(exproto->peer_global_seq); } if (exproto->connect_seq > reconnect.connect_seq()) { - logger().debug("{} server_reconnect: stale connect_seq scs={} ccs={}," + logger().trace("{} server_reconnect: stale connect_seq scs={} ccs={}," " ask client to retry", conn, exproto->connect_seq, reconnect.connect_seq()); return send_retry(exproto->connect_seq); @@ -1203,7 +1203,7 @@ void ProtocolV2::execute_accepting() conn.peer_type = _peer_type; conn.policy = messenger.get_policy(_peer_type); - logger().debug("{} accept of host type {}, lossy={} server={} standby={} resetcheck={}", + logger().trace("{} accept of host type {}, lossy={} server={} standby={} resetcheck={}", conn, (int)_peer_type, conn.policy.lossy, conn.policy.server, conn.policy.standby, conn.policy.resetcheck); @@ -1272,7 +1272,7 @@ seastar::future<> ProtocolV2::finish_auth() conn, actual_tx_sig, sig_frame.signature()); abort_in_fault(); } - logger().debug("{} pre-auth signature success sig_frame.signature()={}", + logger().trace("{} pre-auth signature success sig_frame.signature()={}", conn, sig_frame.signature()); txbuf.clear(); }); @@ -1309,7 +1309,7 @@ seastar::future<> ProtocolV2::send_server_ident() flags, server_cookie); - logger().debug("{} sending server identification: addrs={} gid={}" + logger().trace("{} sending server identification: addrs={} gid={}" " global_seq={} features_supported={} features_required={}" " flags={} cookie={}", conn, messenger.get_myaddrs(), messenger.get_myname().num(), @@ -1413,7 +1413,7 @@ seastar::future<> ProtocolV2::read_message(utime_t throttle_stamp) // XXX: paranoid copy just to avoid oops ceph_msg_header2 current_header = msg_frame.header(); - logger().debug("{} got {} + {} + {} byte message," + logger().trace("{} got {} + {} + {} byte message," " envelope type={} src={} off={} seq={}", conn, msg_frame.front_len(), msg_frame.middle_len(), msg_frame.data_len(), current_header.type, peer_name, @@ -1520,7 +1520,7 @@ void ProtocolV2::execute_ready() if (!cur_msg_size) { return seastar::now(); } - logger().debug("{} wants {} bytes from policy throttler {}/{}", + logger().trace("{} wants {} bytes from policy throttler {}/{}", conn, cur_msg_size, conn.policy.throttler_bytes->get_current(), conn.policy.throttler_bytes->get_max()); @@ -1550,7 +1550,7 @@ void ProtocolV2::execute_ready() auto keepalive_ack_frame = KeepAliveFrameAck::Decode(rx_segments_data.back()); conn.set_last_keepalive_ack( seastar::lowres_system_clock::time_point{keepalive_ack_frame.timestamp()}); - logger().debug("{} got KEEPALIVE_ACK {}", + logger().trace("{} got KEEPALIVE_ACK {}", conn, conn.last_keepalive_ack); }); default: diff --git a/src/crimson/net/SocketMessenger.cc b/src/crimson/net/SocketMessenger.cc index 51cf9ff2963..d386bc5da11 100644 --- a/src/crimson/net/SocketMessenger.cc +++ b/src/crimson/net/SocketMessenger.cc @@ -92,7 +92,7 @@ SocketMessenger::try_bind(const entity_addrvec_t& addrs, return stop_t::yes; }).handle_exception_type([this, max_port, &port] (const std::system_error& e) { ceph_assert(e.code() == error::address_in_use); - logger().debug("{}: try_bind: {} already used", *this, port); + logger().trace("{}: try_bind: {} already used", *this, port); if (port == max_port) { throw e; } -- 2.39.5