mirror of
https://github.com/oxen-io/lokinet
synced 2023-12-14 06:53:00 +01:00
change llarp/quic log statements to new format with category
This commit is contained in:
Thomas Winget
parent
7fb36782dc
commit
80b74ad97d
|
|
@ -12,6 +12,8 @@
|
|||
|
||||
namespace llarp::quic
|
||||
{
|
||||
static auto logcat = log::Cat("quic");
|
||||
|
||||
Client::Client(EndpointBase& ep, const SockAddr& remote, uint16_t pseudo_port) : Endpoint{ep}
|
||||
{
|
||||
default_stream_buffer_size =
|
||||
|
|
@ -35,7 +37,7 @@ namespace llarp::quic
|
|||
// - key_update_timer
|
||||
|
||||
Path path{local_addr, remote};
|
||||
llarp::LogDebug("Connecting to ", remote);
|
||||
log::debug(logcat, "Connecting to {}", remote);
|
||||
|
||||
auto conn = std::make_shared<Connection>(*this, ConnectionID::random(), path, tunnel_port);
|
||||
conn->io_ready();
|
||||
|
|
|
|||
|
|
@ -25,6 +25,8 @@ extern "C"
|
|||
|
||||
namespace llarp::quic
|
||||
{
|
||||
static auto logcat = log::Cat("quic");
|
||||
|
||||
ConnectionID::ConnectionID(const uint8_t* cid, size_t length)
|
||||
{
|
||||
assert(length <= max_size());
|
||||
|
|
@ -57,7 +59,7 @@ namespace llarp::quic
|
|||
int
|
||||
client_initial(ngtcp2_conn* conn_, void* user_data)
|
||||
{
|
||||
LogTrace("######################", __func__);
|
||||
log::trace(logcat, "{} called", __PRETTY_FUNCTION__);
|
||||
|
||||
// Initialization the connection and send our transport parameters to the server. This will
|
||||
// put the connection into NGTCP2_CS_CLIENT_WAIT_HANDSHAKE state.
|
||||
|
|
@ -66,7 +68,7 @@ namespace llarp::quic
|
|||
int
|
||||
recv_client_initial(ngtcp2_conn* conn_, const ngtcp2_cid* dcid, void* user_data)
|
||||
{
|
||||
LogTrace("######################", __func__);
|
||||
log::trace(logcat, "{} called", __PRETTY_FUNCTION__);
|
||||
|
||||
// New incoming connection from a client: our server connection starts out here in state
|
||||
// NGTCP2_CS_SERVER_INITIAL, but we should immediately get into recv_crypto_data because the
|
||||
|
|
@ -90,14 +92,14 @@ namespace llarp::quic
|
|||
void* user_data)
|
||||
{
|
||||
std::basic_string_view data{rawdata, rawdatalen};
|
||||
LogTrace("Receiving crypto data @ level ", crypto_level, " ", buffer_printer{data});
|
||||
log::trace(logcat, "Receiving crypto data @ level {} {}", crypto_level, buffer_printer{data});
|
||||
|
||||
auto& conn = *static_cast<Connection*>(user_data);
|
||||
switch (crypto_level)
|
||||
{
|
||||
case NGTCP2_CRYPTO_LEVEL_EARLY:
|
||||
// We don't currently use or support 0rtt
|
||||
LogWarn("Invalid EARLY crypto level");
|
||||
log::warning(logcat, "Invalid EARLY crypto level");
|
||||
return FAIL;
|
||||
|
||||
case NGTCP2_CRYPTO_LEVEL_INITIAL:
|
||||
|
|
@ -136,7 +138,9 @@ namespace llarp::quic
|
|||
// Check that we received the above as expected
|
||||
if (data != handshake_magic)
|
||||
{
|
||||
LogWarn("Invalid handshake crypto frame from client: did not find expected magic");
|
||||
log::warning(
|
||||
logcat,
|
||||
"Invalid handshake crypto frame from client: did not find expected magic");
|
||||
return NGTCP2_ERR_CALLBACK_FAILURE;
|
||||
}
|
||||
}
|
||||
|
|
@ -150,7 +154,7 @@ namespace llarp::quic
|
|||
break;
|
||||
|
||||
default:
|
||||
LogWarn("Unhandled crypto_level ", crypto_level);
|
||||
log::warning(logcat, "Unhandled crypto_level {}", crypto_level);
|
||||
return FAIL;
|
||||
}
|
||||
conn.io_ready();
|
||||
|
|
@ -168,8 +172,8 @@ namespace llarp::quic
|
|||
const uint8_t* ad,
|
||||
size_t adlen)
|
||||
{
|
||||
LogTrace("######################", __func__);
|
||||
LogTrace("Lengths: ", plaintextlen, "+", noncelen, "+", adlen);
|
||||
log::trace(logcat, "{} called", __PRETTY_FUNCTION__);
|
||||
log::trace(logcat, "Lengths: {}+{}+{}", plaintextlen, noncelen, adlen);
|
||||
if (dest != plaintext)
|
||||
std::memmove(dest, plaintext, plaintextlen);
|
||||
return 0;
|
||||
|
|
@ -186,8 +190,8 @@ namespace llarp::quic
|
|||
const uint8_t* ad,
|
||||
size_t adlen)
|
||||
{
|
||||
LogTrace("######################", __func__);
|
||||
LogTrace("Lengths: ", ciphertextlen, "+", noncelen, "+", adlen);
|
||||
log::trace(logcat, "{} called", __PRETTY_FUNCTION__);
|
||||
log::trace(logcat, "Lengths: {}+{}+{}", ciphertextlen, noncelen, adlen);
|
||||
if (dest != ciphertext)
|
||||
std::memmove(dest, ciphertext, ciphertextlen);
|
||||
return 0;
|
||||
|
|
@ -199,7 +203,7 @@ namespace llarp::quic
|
|||
const ngtcp2_crypto_cipher_ctx* hp_ctx,
|
||||
const uint8_t* sample)
|
||||
{
|
||||
LogTrace("######################", __func__);
|
||||
log::trace(logcat, "{} called", __PRETTY_FUNCTION__);
|
||||
memset(dest, 0, NGTCP2_HP_MASKLEN);
|
||||
return 0;
|
||||
}
|
||||
|
|
@ -214,7 +218,7 @@ namespace llarp::quic
|
|||
void* user_data,
|
||||
void* stream_user_data)
|
||||
{
|
||||
LogTrace("######################", __func__);
|
||||
log::trace(logcat, "{} called", __PRETTY_FUNCTION__);
|
||||
return static_cast<Connection*>(user_data)->stream_receive(
|
||||
{stream_id},
|
||||
{reinterpret_cast<const std::byte*>(data), datalen},
|
||||
|
|
@ -230,15 +234,15 @@ namespace llarp::quic
|
|||
void* user_data,
|
||||
void* stream_user_data)
|
||||
{
|
||||
LogTrace("######################", __func__);
|
||||
LogTrace("Ack [", offset, ",", offset + datalen, ")");
|
||||
log::trace(logcat, "{} called", __PRETTY_FUNCTION__);
|
||||
log::trace(logcat, "Ack [{},{})", offset, offset + datalen);
|
||||
return static_cast<Connection*>(user_data)->stream_ack({stream_id}, datalen);
|
||||
}
|
||||
|
||||
int
|
||||
stream_open(ngtcp2_conn* conn, int64_t stream_id, void* user_data)
|
||||
{
|
||||
LogTrace("######################", __func__);
|
||||
log::trace(logcat, "{} called", __PRETTY_FUNCTION__);
|
||||
return static_cast<Connection*>(user_data)->stream_opened({stream_id});
|
||||
}
|
||||
int
|
||||
|
|
@ -250,7 +254,7 @@ namespace llarp::quic
|
|||
void* user_data,
|
||||
void* stream_user_data)
|
||||
{
|
||||
LogTrace("######################", __func__);
|
||||
log::trace(logcat, "{} called", __PRETTY_FUNCTION__);
|
||||
static_cast<Connection*>(user_data)->stream_closed({stream_id}, app_error_code);
|
||||
return 0;
|
||||
}
|
||||
|
|
@ -259,15 +263,15 @@ namespace llarp::quic
|
|||
int
|
||||
recv_retry(ngtcp2_conn* conn, const ngtcp2_pkt_hd* hd, void* user_data)
|
||||
{
|
||||
LogTrace("######################", __func__);
|
||||
LogError("FIXME UNIMPLEMENTED ", __func__);
|
||||
log::trace(logcat, "{} called", __PRETTY_FUNCTION__);
|
||||
log::error(logcat, "FIXME UNIMPLEMENTED {}", __PRETTY_FUNCTION__);
|
||||
// FIXME
|
||||
return 0;
|
||||
}
|
||||
int
|
||||
extend_max_local_streams_bidi(ngtcp2_conn* conn_, uint64_t max_streams, void* user_data)
|
||||
{
|
||||
LogTrace("######################", __func__);
|
||||
log::trace(logcat, "{} called", __PRETTY_FUNCTION__);
|
||||
auto& conn = *static_cast<Connection*>(user_data);
|
||||
if (conn.on_stream_available)
|
||||
if (uint64_t left = ngtcp2_conn_get_streams_bidi_left(conn); left > 0)
|
||||
|
|
@ -279,7 +283,7 @@ namespace llarp::quic
|
|||
void
|
||||
rand(uint8_t* dest, size_t destlen, const ngtcp2_rand_ctx* rand_ctx)
|
||||
{
|
||||
LogTrace("######################", __func__);
|
||||
log::trace(logcat, "{} called", __PRETTY_FUNCTION__);
|
||||
randombytes_buf(dest, destlen);
|
||||
}
|
||||
|
||||
|
|
@ -287,7 +291,7 @@ namespace llarp::quic
|
|||
get_new_connection_id(
|
||||
ngtcp2_conn* conn_, ngtcp2_cid* cid_, uint8_t* token, size_t cidlen, void* user_data)
|
||||
{
|
||||
LogTrace("######################", __func__);
|
||||
log::trace(logcat, "{} called", __PRETTY_FUNCTION__);
|
||||
|
||||
auto& conn = *static_cast<Connection*>(user_data);
|
||||
auto cid = conn.make_alias_id(cidlen);
|
||||
|
|
@ -295,8 +299,9 @@ namespace llarp::quic
|
|||
*cid_ = cid;
|
||||
|
||||
conn.endpoint.make_stateless_reset_token(cid, token);
|
||||
LogDebug(
|
||||
"make stateless reset token ",
|
||||
log::debug(
|
||||
logcat,
|
||||
"make stateless reset token {}",
|
||||
oxenc::to_hex(token, token + NGTCP2_STATELESS_RESET_TOKENLEN));
|
||||
|
||||
return 0;
|
||||
|
|
@ -304,8 +309,8 @@ namespace llarp::quic
|
|||
int
|
||||
remove_connection_id(ngtcp2_conn* conn, const ngtcp2_cid* cid, void* user_data)
|
||||
{
|
||||
LogTrace("######################", __func__);
|
||||
LogError("FIXME UNIMPLEMENTED ", __func__);
|
||||
log::trace(logcat, "{} called", __PRETTY_FUNCTION__);
|
||||
log::error(logcat, "FIXME UNIMPLEMENTED {}", __PRETTY_FUNCTION__);
|
||||
// FIXME
|
||||
return 0;
|
||||
}
|
||||
|
|
@ -337,7 +342,7 @@ namespace llarp::quic
|
|||
va_list ap;
|
||||
va_start(ap, fmt);
|
||||
if (vsnprintf(buf.data(), buf.size(), fmt, ap) >= 0)
|
||||
LogTrace(fmt::format("{}", buf.data()));
|
||||
log::trace(logcat, "{}", buf.data());
|
||||
va_end(ap);
|
||||
}
|
||||
#endif
|
||||
|
|
@ -365,10 +370,11 @@ namespace llarp::quic
|
|||
|
||||
retransmit_timer = loop->resource<uvw::TimerHandle>();
|
||||
retransmit_timer->on<uvw::TimerEvent>([this](auto&, auto&) {
|
||||
LogTrace("Retransmit timer fired!");
|
||||
log::trace(logcat, "Retransmit timer fired!");
|
||||
if (auto rv = ngtcp2_conn_handle_expiry(*this, get_timestamp()); rv != 0)
|
||||
{
|
||||
LogWarn("expiry handler invocation returned an error: ", ngtcp2_strerror(rv));
|
||||
log::warning(
|
||||
logcat, "expiry handler invocation returned an error: {}", ngtcp2_strerror(rv));
|
||||
endpoint.close_connection(*this, ngtcp2_err_infer_quic_transport_error_code(rv), false);
|
||||
}
|
||||
else
|
||||
|
|
@ -419,7 +425,7 @@ namespace llarp::quic
|
|||
tparams.max_idle_timeout = std::chrono::nanoseconds(IDLE_TIMEOUT).count();
|
||||
tparams.active_connection_id_limit = 8;
|
||||
|
||||
LogDebug("Done basic connection initialization");
|
||||
log::debug(logcat, "Done basic connection initialization");
|
||||
|
||||
return result;
|
||||
}
|
||||
|
|
@ -456,7 +462,7 @@ namespace llarp::quic
|
|||
|
||||
tparams.original_dcid = header.dcid;
|
||||
|
||||
LogDebug("original_dcid is now set to ", ConnectionID(tparams.original_dcid));
|
||||
log::debug(logcat, "original_dcid is now set to {}", ConnectionID(tparams.original_dcid));
|
||||
|
||||
settings.token = header.token;
|
||||
|
||||
|
|
@ -465,7 +471,7 @@ namespace llarp::quic
|
|||
tparams.stateless_reset_token_present = 1;
|
||||
|
||||
ngtcp2_conn* connptr;
|
||||
LogDebug("server_new, path=", path);
|
||||
log::debug(logcat, "server_new, path={}", path);
|
||||
if (auto rv = ngtcp2_conn_server_new(
|
||||
&connptr,
|
||||
&dest_cid,
|
||||
|
|
@ -481,7 +487,7 @@ namespace llarp::quic
|
|||
throw std::runtime_error{"Failed to initialize server connection: "s + ngtcp2_strerror(rv)};
|
||||
conn.reset(connptr);
|
||||
|
||||
LogDebug("Created new server conn ", base_cid);
|
||||
log::debug(logcat, "Created new server conn {}", base_cid);
|
||||
}
|
||||
|
||||
Connection::Connection(
|
||||
|
|
@ -518,7 +524,7 @@ namespace llarp::quic
|
|||
throw std::runtime_error{"Failed to initialize client connection: "s + ngtcp2_strerror(rv)};
|
||||
conn.reset(connptr);
|
||||
|
||||
LogDebug("Created new client conn ", scid);
|
||||
log::debug(logcat, "Created new client conn {}", scid);
|
||||
}
|
||||
|
||||
Connection::~Connection()
|
||||
|
|
@ -541,9 +547,9 @@ namespace llarp::quic
|
|||
void
|
||||
Connection::on_io_ready()
|
||||
{
|
||||
LogTrace(__func__);
|
||||
log::trace(logcat, "{} called", __PRETTY_FUNCTION__);
|
||||
flush_streams();
|
||||
LogTrace("done ", __func__);
|
||||
log::trace(logcat, "{} finished", __PRETTY_FUNCTION__);
|
||||
}
|
||||
|
||||
void
|
||||
|
|
@ -554,33 +560,35 @@ namespace llarp::quic
|
|||
|
||||
send_pkt_info = {};
|
||||
|
||||
auto add_stream_data =
|
||||
[&](StreamID stream_id, const ngtcp2_vec* datav, size_t datalen, uint32_t flags = 0) {
|
||||
std::array<ngtcp2_ssize, 2> result;
|
||||
auto& [nwrite, consumed] = result;
|
||||
if (!ts)
|
||||
ts = get_timestamp();
|
||||
auto add_stream_data = [&](StreamID stream_id,
|
||||
const ngtcp2_vec* datav,
|
||||
size_t datalen,
|
||||
uint32_t flags = 0) {
|
||||
std::array<ngtcp2_ssize, 2> result;
|
||||
auto& [nwrite, consumed] = result;
|
||||
if (!ts)
|
||||
ts = get_timestamp();
|
||||
|
||||
LogTrace(
|
||||
"send_buffer size=", send_buffer.size(), ", datalen=", datalen, ", flags=", flags);
|
||||
nwrite = ngtcp2_conn_writev_stream(
|
||||
conn.get(),
|
||||
&path.path,
|
||||
&send_pkt_info,
|
||||
u8data(send_buffer),
|
||||
send_buffer.size(),
|
||||
&consumed,
|
||||
NGTCP2_WRITE_STREAM_FLAG_MORE | flags,
|
||||
stream_id.id,
|
||||
datav,
|
||||
datalen,
|
||||
*ts);
|
||||
return result;
|
||||
};
|
||||
log::trace(
|
||||
logcat, "send_buffer size={}, datalen={}, flags={}", send_buffer.size(), datalen, flags);
|
||||
nwrite = ngtcp2_conn_writev_stream(
|
||||
conn.get(),
|
||||
&path.path,
|
||||
&send_pkt_info,
|
||||
u8data(send_buffer),
|
||||
send_buffer.size(),
|
||||
&consumed,
|
||||
NGTCP2_WRITE_STREAM_FLAG_MORE | flags,
|
||||
stream_id.id,
|
||||
datav,
|
||||
datalen,
|
||||
*ts);
|
||||
return result;
|
||||
};
|
||||
|
||||
auto send_packet = [&](auto nwrite) -> bool {
|
||||
send_buffer_size = nwrite;
|
||||
LogTrace("Sending ", send_buffer_size, "B packet");
|
||||
log::trace(logcat, "Sending {}B packet", send_buffer_size);
|
||||
|
||||
auto sent = send();
|
||||
if (sent.blocked())
|
||||
|
|
@ -592,11 +600,11 @@ namespace llarp::quic
|
|||
send_buffer_size = 0;
|
||||
if (!sent)
|
||||
{
|
||||
LogWarn("I/O error while trying to send packet: ", sent.str());
|
||||
log::warning(logcat, "I/O error while trying to send packet: {}", sent.str());
|
||||
// FIXME: disconnect?
|
||||
return false;
|
||||
}
|
||||
LogTrace("packet away!");
|
||||
log::trace(logcat, "packet away!");
|
||||
return true;
|
||||
};
|
||||
|
||||
|
|
@ -630,14 +638,15 @@ namespace llarp::quic
|
|||
buf_sizes += '+';
|
||||
buf_sizes += std::to_string(b.size());
|
||||
}
|
||||
LogDebug("Sending ", buf_sizes.empty() ? "no" : buf_sizes, " data for ", stream.id());
|
||||
log::debug(
|
||||
logcat, "Sending {} data for {}", buf_sizes.empty() ? "no" : buf_sizes, stream.id());
|
||||
}
|
||||
#endif
|
||||
|
||||
uint32_t extra_flags = 0;
|
||||
if (stream.is_closing && !stream.sent_fin)
|
||||
{
|
||||
LogDebug("Sending FIN");
|
||||
log::debug(logcat, "Sending FIN");
|
||||
extra_flags |= NGTCP2_WRITE_STREAM_FLAG_FIN;
|
||||
stream.sent_fin = true;
|
||||
}
|
||||
|
|
@ -648,18 +657,22 @@ namespace llarp::quic
|
|||
|
||||
auto [nwrite, consumed] =
|
||||
add_stream_data(stream.id(), vecs.data(), vecs.size(), extra_flags);
|
||||
LogTrace(
|
||||
"add_stream_data for stream ", stream.id(), " returned [", nwrite, ",", consumed, "]");
|
||||
log::trace(
|
||||
logcat,
|
||||
"add_stream_data for stream {} returned [{},{}]",
|
||||
stream.id(),
|
||||
nwrite,
|
||||
consumed);
|
||||
|
||||
if (nwrite > 0)
|
||||
{
|
||||
if (consumed >= 0)
|
||||
{
|
||||
LogTrace("consumed ", consumed, " bytes from stream ", stream.id());
|
||||
log::trace(logcat, "consumed {} bytes from stream {}", consumed, stream.id());
|
||||
stream.wrote(consumed);
|
||||
}
|
||||
|
||||
LogTrace("Sending stream data packet");
|
||||
log::trace(logcat, "Sending stream data packet");
|
||||
if (!send_packet(nwrite))
|
||||
return;
|
||||
++stream_packets;
|
||||
|
|
@ -670,15 +683,19 @@ namespace llarp::quic
|
|||
switch (nwrite)
|
||||
{
|
||||
case 0:
|
||||
LogTrace(
|
||||
"Done stream writing to ",
|
||||
stream.id(),
|
||||
" (either stream is congested or we have nothing else to send right now)");
|
||||
log::trace(
|
||||
logcat,
|
||||
"Done stream writing to {} (either stream is congested or we have nothing else to "
|
||||
"send right now)",
|
||||
stream.id());
|
||||
assert(consumed <= 0);
|
||||
break;
|
||||
case NGTCP2_ERR_WRITE_MORE:
|
||||
LogTrace(
|
||||
"consumed ", consumed, " bytes from stream ", stream.id(), " and have space left");
|
||||
log::trace(
|
||||
logcat,
|
||||
"consumed {} bytes from stream {} and have space left",
|
||||
consumed,
|
||||
stream.id());
|
||||
stream.wrote(consumed);
|
||||
if (stream.unsent() > 0)
|
||||
{
|
||||
|
|
@ -688,14 +705,15 @@ namespace llarp::quic
|
|||
}
|
||||
break;
|
||||
case NGTCP2_ERR_STREAM_DATA_BLOCKED:
|
||||
LogDebug("cannot add to stream ", stream.id(), " right now: stream is blocked");
|
||||
log::debug(logcat, "cannot add to stream {} right now: stream is blocked", stream.id());
|
||||
break;
|
||||
case NGTCP2_ERR_STREAM_SHUT_WR:
|
||||
LogDebug("cannot write to ", stream.id(), ": stream is shut down");
|
||||
log::debug(logcat, "cannot write to {}: stream is shut down", stream.id());
|
||||
break;
|
||||
default:
|
||||
assert(consumed <= 0);
|
||||
LogWarn("Error writing to stream ", stream.id(), ": ", ngtcp2_strerror(nwrite));
|
||||
log::warning(
|
||||
logcat, "Error writing to stream {}: {}", stream.id(), ngtcp2_strerror(nwrite));
|
||||
break;
|
||||
}
|
||||
it = strs.erase(it);
|
||||
|
|
@ -707,28 +725,29 @@ namespace llarp::quic
|
|||
for (;;)
|
||||
{
|
||||
auto [nwrite, consumed] = add_stream_data(StreamID{}, nullptr, 0);
|
||||
LogTrace("add_stream_data for non-stream returned [", nwrite, ",", consumed, "]");
|
||||
log::trace(logcat, "add_stream_data for non-stream returned [{},{}]", nwrite, consumed);
|
||||
assert(consumed <= 0);
|
||||
if (nwrite == NGTCP2_ERR_WRITE_MORE)
|
||||
{
|
||||
LogTrace("Writing non-stream data, and have space left");
|
||||
log::trace(logcat, "Writing non-stream data, and have space left");
|
||||
continue;
|
||||
}
|
||||
if (nwrite < 0)
|
||||
{
|
||||
LogWarn("Error writing non-stream data: ", ngtcp2_strerror(nwrite));
|
||||
log::warning(logcat, "Error writing non-stream data: {}", ngtcp2_strerror(nwrite));
|
||||
break;
|
||||
}
|
||||
if (nwrite == 0)
|
||||
{
|
||||
LogTrace("Nothing else to write for non-stream data for now (or we are congested)");
|
||||
log::trace(
|
||||
logcat, "Nothing else to write for non-stream data for now (or we are congested)");
|
||||
ngtcp2_conn_stat cstat;
|
||||
ngtcp2_conn_get_conn_stat(*this, &cstat);
|
||||
LogTrace("Current unacked bytes in flight: ", cstat.bytes_in_flight);
|
||||
log::trace(logcat, "Current unacked bytes in flight: {}", cstat.bytes_in_flight);
|
||||
break;
|
||||
}
|
||||
|
||||
LogTrace("Sending non-stream data packet");
|
||||
log::trace(logcat, "Sending non-stream data packet");
|
||||
if (!send_packet(nwrite))
|
||||
return;
|
||||
}
|
||||
|
|
@ -742,7 +761,7 @@ namespace llarp::quic
|
|||
auto exp = ngtcp2_conn_get_expiry(*this);
|
||||
if (exp == std::numeric_limits<decltype(exp)>::max())
|
||||
{
|
||||
LogTrace("no retransmit currently needed");
|
||||
log::trace(logcat, "no retransmit currently needed");
|
||||
retransmit_timer->stop();
|
||||
return;
|
||||
}
|
||||
|
|
@ -752,7 +771,7 @@ namespace llarp::quic
|
|||
0ms,
|
||||
std::chrono::duration_cast<std::chrono::milliseconds>(
|
||||
expiry - get_time().time_since_epoch()));
|
||||
LogDebug("Next retransmit in ", expires_in.count(), "ms");
|
||||
log::debug(logcat, "Next retransmit in {}ms", expires_in.count());
|
||||
retransmit_timer->stop();
|
||||
retransmit_timer->start(expires_in, 0ms);
|
||||
}
|
||||
|
|
@ -760,11 +779,11 @@ namespace llarp::quic
|
|||
int
|
||||
Connection::stream_opened(StreamID id)
|
||||
{
|
||||
LogDebug("New stream ", id);
|
||||
log::debug(logcat, "New stream {}", id);
|
||||
auto* serv = server();
|
||||
if (!serv)
|
||||
{
|
||||
LogWarn("We are a client, incoming streams are not accepted");
|
||||
log::warning(logcat, "We are a client, incoming streams are not accepted");
|
||||
return NGTCP2_ERR_CALLBACK_FAILURE;
|
||||
}
|
||||
|
||||
|
|
@ -775,7 +794,7 @@ namespace llarp::quic
|
|||
good = serv->stream_open_callback(*stream, tunnel_port);
|
||||
if (!good)
|
||||
{
|
||||
LogDebug("stream_open_callback returned failure, dropping stream ", id);
|
||||
log::debug(logcat, "stream_open_callback returned failure, dropping stream {}", id);
|
||||
ngtcp2_conn_shutdown_stream(*this, id.id, 1);
|
||||
io_ready();
|
||||
return NGTCP2_ERR_CALLBACK_FAILURE;
|
||||
|
|
@ -783,7 +802,7 @@ namespace llarp::quic
|
|||
|
||||
[[maybe_unused]] auto [it, ins] = streams.emplace(id, std::move(stream));
|
||||
assert(ins);
|
||||
LogDebug("Created new incoming stream ", id);
|
||||
log::debug(logcat, "Created new incoming stream {}", id);
|
||||
return 0;
|
||||
}
|
||||
|
||||
|
|
@ -792,7 +811,10 @@ namespace llarp::quic
|
|||
{
|
||||
auto str = get_stream(id);
|
||||
if (!str->data_callback)
|
||||
LogDebug("Dropping incoming data on stream ", str->id(), ": stream has no data callback set");
|
||||
log::debug(
|
||||
logcat,
|
||||
"Dropping incoming data on stream {}: stream has no data callback set",
|
||||
str->id());
|
||||
else
|
||||
{
|
||||
bool good = false;
|
||||
|
|
@ -803,20 +825,19 @@ namespace llarp::quic
|
|||
}
|
||||
catch (const std::exception& e)
|
||||
{
|
||||
LogWarn(
|
||||
"Stream ",
|
||||
log::warning(
|
||||
logcat,
|
||||
"Stream {} data callback raised exception ({}); closing stream with app code {}",
|
||||
str->id(),
|
||||
" data callback raised exception (",
|
||||
e.what(),
|
||||
"); closing stream with app code ",
|
||||
STREAM_ERROR_EXCEPTION);
|
||||
}
|
||||
catch (...)
|
||||
{
|
||||
LogWarn(
|
||||
"Stream ",
|
||||
log::warning(
|
||||
logcat,
|
||||
"Stream {} data callback raised an unknown exception; closing stream with app code {}",
|
||||
str->id(),
|
||||
" data callback raised an unknown exception; closing stream with app code ",
|
||||
STREAM_ERROR_EXCEPTION);
|
||||
}
|
||||
if (!good)
|
||||
|
|
@ -827,7 +848,7 @@ namespace llarp::quic
|
|||
}
|
||||
if (fin)
|
||||
{
|
||||
LogTrace("Stream ", str->id(), " closed by remote");
|
||||
log::trace(logcat, "Stream {} closed by remote", str->id());
|
||||
// Don't cleanup here; stream_closed is going to be called right away to deal with that
|
||||
}
|
||||
else
|
||||
|
|
@ -842,7 +863,7 @@ namespace llarp::quic
|
|||
Connection::stream_closed(StreamID id, uint64_t app_code)
|
||||
{
|
||||
assert(ngtcp2_is_bidi_stream(id.id));
|
||||
LogDebug(id, " closed with code ", app_code);
|
||||
log::debug(logcat, "{} closed with code {}", id, app_code);
|
||||
auto it = streams.find(id);
|
||||
if (it == streams.end())
|
||||
return;
|
||||
|
|
@ -851,14 +872,14 @@ namespace llarp::quic
|
|||
stream.is_closing = stream.is_shutdown = true;
|
||||
if (!was_closing && stream.close_callback)
|
||||
{
|
||||
LogDebug("Invoke stream close callback");
|
||||
log::debug(logcat, "Invoke stream close callback");
|
||||
std::optional<uint64_t> code;
|
||||
if (app_code != 0)
|
||||
code = app_code;
|
||||
stream.close_callback(stream, code);
|
||||
}
|
||||
|
||||
LogDebug("Erasing stream ", id, " from ", (void*)it->second.get());
|
||||
log::debug(logcat, "Erasing stream {} from {}", id, (void*)it->second.get());
|
||||
streams.erase(it);
|
||||
|
||||
if (!ngtcp2_conn_is_local_stream(*this, id.id))
|
||||
|
|
@ -961,7 +982,7 @@ namespace llarp::quic
|
|||
{
|
||||
if (data.substr(0, handshake_magic.size()) != handshake_magic)
|
||||
{
|
||||
LogWarn("Invalid initial crypto frame: did not find expected magic prefix");
|
||||
log::warning(logcat, "Invalid initial crypto frame: did not find expected magic prefix");
|
||||
return NGTCP2_ERR_CALLBACK_FAILURE;
|
||||
}
|
||||
data.remove_prefix(handshake_magic.size());
|
||||
|
|
@ -981,7 +1002,7 @@ namespace llarp::quic
|
|||
// in a second callback to handle them).
|
||||
if (!data.empty())
|
||||
{
|
||||
LogWarn("Invalid initial crypto frame: unexpected post-magic data found");
|
||||
log::warning(logcat, "Invalid initial crypto frame: unexpected post-magic data found");
|
||||
return NGTCP2_ERR_CALLBACK_FAILURE;
|
||||
}
|
||||
}
|
||||
|
|
@ -1073,20 +1094,20 @@ namespace llarp::quic
|
|||
{
|
||||
if (data.substr(0, lokinet_metadata_code.size()) != lokinet_metadata_code)
|
||||
{
|
||||
LogWarn("transport params did not begin with expected lokinet metadata");
|
||||
log::warning(logcat, "transport params did not begin with expected lokinet metadata");
|
||||
return NGTCP2_ERR_TRANSPORT_PARAM;
|
||||
}
|
||||
auto [meta_len, meta_len_bytes] = decode_varint(data.substr(lokinet_metadata_code.size()));
|
||||
if (meta_len_bytes == 0)
|
||||
{
|
||||
LogWarn("transport params lokinet metadata has truncated size");
|
||||
log::warning(logcat, "transport params lokinet metadata has truncated size");
|
||||
return NGTCP2_ERR_MALFORMED_TRANSPORT_PARAM;
|
||||
}
|
||||
std::string_view lokinet_metadata{
|
||||
reinterpret_cast<const char*>(
|
||||
data.substr(lokinet_metadata_code.size() + meta_len_bytes).data()),
|
||||
static_cast<std::size_t>(meta_len)};
|
||||
LogDebug("Received bencoded lokinet metadata: ", buffer_printer{lokinet_metadata});
|
||||
log::debug(logcat, "Received bencoded lokinet metadata: {}", buffer_printer{lokinet_metadata});
|
||||
|
||||
uint16_t port;
|
||||
try
|
||||
|
|
@ -1095,20 +1116,20 @@ namespace llarp::quic
|
|||
// '#' contains the port the client wants us to forward to
|
||||
if (!meta.skip_until("#"))
|
||||
{
|
||||
LogWarn("transport params # (port) is missing but required");
|
||||
log::warning(logcat, "transport params # (port) is missing but required");
|
||||
return NGTCP2_ERR_TRANSPORT_PARAM;
|
||||
}
|
||||
port = meta.consume_integer<uint16_t>();
|
||||
if (port == 0)
|
||||
{
|
||||
LogWarn("transport params tunnel port (#) is invalid: 0 is not permitted");
|
||||
log::warning(logcat, "transport params tunnel port (#) is invalid: 0 is not permitted");
|
||||
return NGTCP2_ERR_TRANSPORT_PARAM;
|
||||
}
|
||||
LogDebug("decoded lokinet tunnel port = ", port);
|
||||
log::debug(logcat, "decoded lokinet tunnel port = {}", port);
|
||||
}
|
||||
catch (const oxenc::bt_deserialize_invalid& c)
|
||||
{
|
||||
LogWarn("transport params lokinet metadata is invalid: ", c.what());
|
||||
log::warning(logcat, "transport params lokinet metadata is invalid: {}", c.what());
|
||||
return NGTCP2_ERR_TRANSPORT_PARAM;
|
||||
}
|
||||
|
||||
|
|
@ -1123,7 +1144,8 @@ namespace llarp::quic
|
|||
// Make sure the server reflected the proper port
|
||||
if (tunnel_port != port)
|
||||
{
|
||||
LogWarn("server returned invalid port; expected ", tunnel_port, ", got ", port);
|
||||
log::warning(
|
||||
logcat, "server returned invalid port; expected {}, got {}", tunnel_port, port);
|
||||
return NGTCP2_ERR_TRANSPORT_PARAM;
|
||||
}
|
||||
}
|
||||
|
|
@ -1134,14 +1156,19 @@ namespace llarp::quic
|
|||
: NGTCP2_TRANSPORT_PARAMS_TYPE_ENCRYPTED_EXTENSIONS;
|
||||
|
||||
auto rv = ngtcp2_decode_transport_params(¶ms, exttype, data.data(), data.size());
|
||||
LogDebug("Decode transport params ", rv == 0 ? "success" : "fail: "s + ngtcp2_strerror(rv));
|
||||
LogTrace("params orig dcid = ", ConnectionID(params.original_dcid));
|
||||
LogTrace("params init scid = ", ConnectionID(params.initial_scid));
|
||||
log::debug(
|
||||
logcat,
|
||||
"Decode transport params {}",
|
||||
rv == 0 ? "success" : "fail: "s + ngtcp2_strerror(rv));
|
||||
log::trace(logcat, "params orig dcid = {}", ConnectionID(params.original_dcid));
|
||||
log::trace(logcat, "params init scid = {}", ConnectionID(params.initial_scid));
|
||||
if (rv == 0)
|
||||
{
|
||||
rv = ngtcp2_conn_set_remote_transport_params(*this, ¶ms);
|
||||
LogDebug(
|
||||
"Set remote transport params ", rv == 0 ? "success" : "fail: "s + ngtcp2_strerror(rv));
|
||||
log::debug(
|
||||
logcat,
|
||||
"Set remote transport params {}",
|
||||
rv == 0 ? "success" : "fail: "s + ngtcp2_strerror(rv));
|
||||
}
|
||||
|
||||
if (rv != 0)
|
||||
|
|
@ -1214,7 +1241,7 @@ namespace llarp::quic
|
|||
conn_buffer.clear();
|
||||
return nwrite;
|
||||
}
|
||||
LogDebug("encoded transport params: ", buffer_printer{conn_buffer});
|
||||
log::debug(logcat, "encoded transport params: {}", buffer_printer{conn_buffer});
|
||||
return ngtcp2_conn_submit_crypto_data(*this, level, u8data(conn_buffer), conn_buffer.size());
|
||||
}
|
||||
|
||||
|
|
|
|||
|
|
@ -22,6 +22,8 @@ extern "C"
|
|||
|
||||
namespace llarp::quic
|
||||
{
|
||||
static auto logcat = log::Cat("quic");
|
||||
|
||||
Endpoint::Endpoint(EndpointBase& ep) : service_endpoint{ep}
|
||||
{
|
||||
randombytes_buf(static_secret.data(), static_secret.size());
|
||||
|
|
@ -31,7 +33,7 @@ namespace llarp::quic
|
|||
expiry_timer->on<uvw::TimerEvent>([this](const auto&, auto&) { check_timeouts(); });
|
||||
expiry_timer->start(250ms, 250ms);
|
||||
|
||||
LogDebug("Created QUIC endpoint");
|
||||
log::debug(logcat, "Created QUIC endpoint");
|
||||
}
|
||||
|
||||
Endpoint::~Endpoint()
|
||||
|
|
@ -57,30 +59,30 @@ namespace llarp::quic
|
|||
|
||||
Packet pkt{Path{local, src}, data, ngtcp2_pkt_info{.ecn = ecn}};
|
||||
|
||||
LogTrace("[", pkt.path, ",ecn=", pkt.info.ecn, "]: received ", data.size(), " bytes");
|
||||
log::trace(logcat, "[{},ecn={}]: received {} bytes", pkt.path, pkt.info.ecn, data.size());
|
||||
|
||||
handle_packet(pkt);
|
||||
|
||||
LogTrace("Done handling packet");
|
||||
log::trace(logcat, "Done handling packet");
|
||||
}
|
||||
|
||||
void
|
||||
Endpoint::handle_packet(const Packet& p)
|
||||
{
|
||||
LogTrace("Handling incoming quic packet: ", buffer_printer{p.data});
|
||||
log::trace(logcat, "Handling incoming quic packet: {}", buffer_printer{p.data});
|
||||
auto maybe_dcid = handle_packet_init(p);
|
||||
if (!maybe_dcid)
|
||||
return;
|
||||
auto& dcid = *maybe_dcid;
|
||||
|
||||
// See if we have an existing connection already established for it
|
||||
LogTrace("Incoming connection id ", dcid);
|
||||
log::trace(logcat, "Incoming connection id {}", dcid);
|
||||
auto [connptr, alias] = get_conn(dcid);
|
||||
if (!connptr)
|
||||
{
|
||||
if (alias)
|
||||
{
|
||||
LogDebug("Incoming packet QUIC CID is an expired alias; dropping");
|
||||
log::debug(logcat, "Incoming packet QUIC CID is an expired alias; dropping");
|
||||
return;
|
||||
}
|
||||
connptr = accept_initial_connection(p);
|
||||
|
|
@ -88,9 +90,9 @@ namespace llarp::quic
|
|||
return;
|
||||
}
|
||||
if (alias)
|
||||
LogTrace("CID is alias for primary CID ", connptr->base_cid);
|
||||
log::trace(logcat, "CID is alias for primary CID {}", connptr->base_cid);
|
||||
else
|
||||
LogTrace("CID is primary CID");
|
||||
log::trace(logcat, "CID is primary CID");
|
||||
|
||||
handle_conn_packet(*connptr, p);
|
||||
}
|
||||
|
|
@ -115,13 +117,13 @@ namespace llarp::quic
|
|||
}
|
||||
if (rv != 0)
|
||||
{
|
||||
LogWarn("QUIC packet header decode failed: ", ngtcp2_strerror(rv));
|
||||
log::warning(logcat, "QUIC packet header decode failed: {}", ngtcp2_strerror(rv));
|
||||
return std::nullopt;
|
||||
}
|
||||
|
||||
if (vi.dcid_len > ConnectionID::max_size())
|
||||
{
|
||||
LogWarn("Internal error: destination ID is longer than should be allowed");
|
||||
log::warning(logcat, "Internal error: destination ID is longer than should be allowed");
|
||||
return std::nullopt;
|
||||
}
|
||||
|
||||
|
|
@ -132,13 +134,13 @@ namespace llarp::quic
|
|||
{
|
||||
if (ngtcp2_conn_is_in_closing_period(conn))
|
||||
{
|
||||
LogDebug("Connection is in closing period, dropping");
|
||||
log::debug(logcat, "Connection is in closing period, dropping");
|
||||
close_connection(conn);
|
||||
return;
|
||||
}
|
||||
if (conn.draining)
|
||||
{
|
||||
LogDebug("Connection is draining, dropping");
|
||||
log::debug(logcat, "Connection is draining, dropping");
|
||||
// "draining" state means we received a connection close and we're keeping the
|
||||
// connection alive just to catch (and discard) straggling packets that arrive
|
||||
// out of order w.r.t to connection close.
|
||||
|
|
@ -147,24 +149,24 @@ namespace llarp::quic
|
|||
|
||||
if (auto result = read_packet(p, conn); !result)
|
||||
{
|
||||
LogWarn("Read packet failed! ", ngtcp2_strerror(result.error_code));
|
||||
log::warning(logcat, "Read packet failed! {}", ngtcp2_strerror(result.error_code));
|
||||
}
|
||||
|
||||
// FIXME - reset idle timer?
|
||||
LogTrace("Done with incoming packet");
|
||||
log::trace(logcat, "Done with incoming packet");
|
||||
}
|
||||
|
||||
io_result
|
||||
Endpoint::read_packet(const Packet& p, Connection& conn)
|
||||
{
|
||||
LogTrace("Reading packet from ", p.path);
|
||||
log::trace(logcat, "Reading packet from {}", p.path);
|
||||
auto rv =
|
||||
ngtcp2_conn_read_pkt(conn, p.path, &p.info, u8data(p.data), p.data.size(), get_timestamp());
|
||||
|
||||
if (rv == 0)
|
||||
conn.io_ready();
|
||||
else
|
||||
LogWarn("read pkt error: ", ngtcp2_strerror(rv));
|
||||
log::warning(logcat, "read pkt error: {}", ngtcp2_strerror(rv));
|
||||
|
||||
if (rv == NGTCP2_ERR_DRAINING)
|
||||
start_draining(conn);
|
||||
|
|
@ -188,11 +190,12 @@ namespace llarp::quic
|
|||
if (service_endpoint.SendToOrQueue(
|
||||
to, llarp_buffer_t{outgoing.data(), outgoing.size()}, service::ProtocolType::QUIC))
|
||||
{
|
||||
LogTrace("[", to, "]: sent ", buffer_printer{outgoing});
|
||||
log::trace(logcat, "[{}]: sent {}", to, buffer_printer{outgoing});
|
||||
}
|
||||
else
|
||||
{
|
||||
LogDebug("Failed to send to quic endpoint ", to, "; was sending ", outgoing.size(), "B");
|
||||
log::debug(
|
||||
logcat, "Failed to send to quic endpoint {}; was sending {}B", to, outgoing.size());
|
||||
}
|
||||
return {};
|
||||
}
|
||||
|
|
@ -218,7 +221,8 @@ namespace llarp::quic
|
|||
versions.data(),
|
||||
versions.size());
|
||||
if (nwrote < 0)
|
||||
LogWarn("Failed to construct version negotiation packet: ", ngtcp2_strerror(nwrote));
|
||||
log::warning(
|
||||
logcat, "Failed to construct version negotiation packet: {}", ngtcp2_strerror(nwrote));
|
||||
if (nwrote <= 0)
|
||||
return;
|
||||
|
||||
|
|
@ -229,7 +233,7 @@ namespace llarp::quic
|
|||
Endpoint::close_connection(
|
||||
Connection& conn, uint64_t code, bool application, std::string_view close_reason)
|
||||
{
|
||||
LogDebug("Closing connection ", conn.base_cid);
|
||||
log::debug(logcat, "Closing connection {}", conn.base_cid);
|
||||
if (!conn.closing)
|
||||
{
|
||||
conn.conn_buffer.resize(max_pkt_size_v4);
|
||||
|
|
@ -252,8 +256,9 @@ namespace llarp::quic
|
|||
get_timestamp());
|
||||
if (written <= 0)
|
||||
{
|
||||
LogWarn(
|
||||
"Failed to write connection close packet: ",
|
||||
log::warning(
|
||||
logcat,
|
||||
"Failed to write connection close packet: {}",
|
||||
written < 0 ? ngtcp2_strerror(written) : "unknown error: closing is 0 bytes??");
|
||||
return;
|
||||
}
|
||||
|
|
@ -267,10 +272,10 @@ namespace llarp::quic
|
|||
|
||||
if (auto sent = send_packet(conn.path.remote, conn.conn_buffer, 0); not sent)
|
||||
{
|
||||
LogWarn(
|
||||
"Failed to send packet: ",
|
||||
log::warning(
|
||||
logcat,
|
||||
"Failed to send packet: {}; removing connection {}",
|
||||
strerror(sent.error_code),
|
||||
"; removing connection ",
|
||||
conn.base_cid);
|
||||
delete_conn(conn.base_cid);
|
||||
return;
|
||||
|
|
@ -285,7 +290,7 @@ namespace llarp::quic
|
|||
{
|
||||
if (conn.draining)
|
||||
return;
|
||||
LogDebug("Putting ", conn.base_cid, " into draining mode");
|
||||
log::debug(logcat, "Putting {} into draining mode", conn.base_cid);
|
||||
conn.draining = true;
|
||||
// Recommended draining time is 3*Probe Timeout
|
||||
draining.emplace(conn.base_cid, get_time() + ngtcp2_conn_get_pto(conn) * 3 * 1ns);
|
||||
|
|
@ -305,7 +310,7 @@ namespace llarp::quic
|
|||
{
|
||||
if (std::holds_alternative<primary_conn_ptr>(it->second))
|
||||
cleanup = true;
|
||||
LogDebug("Deleting connection ", it->first);
|
||||
log::debug(logcat, "Deleting connection {}", it->first);
|
||||
conns.erase(it);
|
||||
}
|
||||
draining.pop();
|
||||
|
|
@ -344,12 +349,12 @@ namespace llarp::quic
|
|||
auto it = conns.find(cid);
|
||||
if (it == conns.end())
|
||||
{
|
||||
LogDebug("Cannot delete connection ", cid, ": cid not found");
|
||||
log::debug(logcat, "Cannot delete connection {}: cid not found", cid);
|
||||
return false;
|
||||
}
|
||||
|
||||
bool primary = std::holds_alternative<primary_conn_ptr>(it->second);
|
||||
LogDebug("Deleting ", primary ? "primary" : "alias", " connection ", cid);
|
||||
log::debug(logcat, "Deleting {} connection {}", primary ? "primary" : "alias", cid);
|
||||
conns.erase(it);
|
||||
if (primary)
|
||||
clean_alias_conns();
|
||||
|
|
@ -378,7 +383,7 @@ namespace llarp::quic
|
|||
cid = ConnectionID::random(cid_length);
|
||||
inserted = conns.emplace(cid, conn.weak_from_this()).second;
|
||||
}
|
||||
LogDebug("Created cid ", cid, " alias for ", conn.base_cid);
|
||||
log::debug(logcat, "Created cid {} alias for {}", cid, conn.base_cid);
|
||||
return cid;
|
||||
}
|
||||
|
||||
|
|
|
|||
|
|
@ -5,6 +5,8 @@
|
|||
|
||||
namespace llarp::quic
|
||||
{
|
||||
static auto logcat = log::Cat("quic");
|
||||
|
||||
// Cranks a value to "11", i.e. set it to its maximum
|
||||
template <typename T>
|
||||
void
|
||||
|
|
@ -41,7 +43,7 @@ namespace llarp::quic
|
|||
void
|
||||
NullCrypto::server_initial(Connection& conn)
|
||||
{
|
||||
LogDebug("Server initial null crypto setup");
|
||||
log::debug(logcat, "Server initial null crypto setup");
|
||||
ngtcp2_conn_set_initial_crypto_ctx(conn, &null_ctx);
|
||||
ngtcp2_conn_install_initial_key(
|
||||
conn,
|
||||
|
|
|
|||
|
|
@ -11,10 +11,12 @@
|
|||
|
||||
namespace llarp::quic
|
||||
{
|
||||
static auto logcat = log::Cat("quic");
|
||||
|
||||
std::shared_ptr<Connection>
|
||||
Server::accept_initial_connection(const Packet& p)
|
||||
{
|
||||
LogDebug("Accepting new connection");
|
||||
log::debug(logcat, "Accepting new connection");
|
||||
|
||||
// This is a new incoming connection
|
||||
ngtcp2_pkt_hd hd;
|
||||
|
|
@ -22,14 +24,14 @@ namespace llarp::quic
|
|||
|
||||
if (rv == -1)
|
||||
{ // Invalid packet
|
||||
LogWarn("Invalid packet received, length=", p.data.size());
|
||||
LogTrace("packet body: ", buffer_printer{p.data});
|
||||
log::warning(logcat, "Invalid packet received, length={}", p.data.size());
|
||||
log::trace(logcat, "packet body: {}", buffer_printer{p.data});
|
||||
return nullptr;
|
||||
}
|
||||
|
||||
if (rv == 1)
|
||||
{ // Invalid/unexpected version, send a version negotiation
|
||||
LogDebug("Invalid/unsupported version; sending version negotiation");
|
||||
log::debug(logcat, "Invalid/unsupported version; sending version negotiation");
|
||||
send_version_negotiation(
|
||||
version_info{hd.version, hd.dcid.data, hd.dcid.datalen, hd.scid.data, hd.scid.datalen},
|
||||
p.path.remote);
|
||||
|
|
@ -38,14 +40,15 @@ namespace llarp::quic
|
|||
|
||||
if (hd.type == NGTCP2_PKT_0RTT)
|
||||
{
|
||||
LogWarn("Received 0-RTT packet, which shouldn't happen in our implementation; dropping");
|
||||
log::warning(
|
||||
logcat, "Received 0-RTT packet, which shouldn't happen in our implementation; dropping");
|
||||
return nullptr;
|
||||
}
|
||||
|
||||
if (hd.type == NGTCP2_PKT_INITIAL && hd.token.len)
|
||||
{
|
||||
// This is a normal QUIC thing, but we don't do it:
|
||||
LogWarn("Unexpected token in initial packet");
|
||||
log::warning(logcat, "Unexpected token in initial packet");
|
||||
}
|
||||
|
||||
// create and store Connection
|
||||
|
|
|
|||
|
|
@ -43,6 +43,8 @@
|
|||
|
||||
namespace llarp::quic
|
||||
{
|
||||
static auto logcat = log::Cat("quic");
|
||||
|
||||
std::string
|
||||
StreamID::ToString() const
|
||||
{
|
||||
|
|
@ -71,7 +73,7 @@ namespace llarp::quic
|
|||
|
||||
Stream::~Stream()
|
||||
{
|
||||
LogTrace("Destroying stream ", stream_id);
|
||||
log::trace(logcat, "Destroying stream {}", stream_id);
|
||||
if (avail_trigger)
|
||||
{
|
||||
avail_trigger->close();
|
||||
|
|
@ -124,26 +126,24 @@ namespace llarp::quic
|
|||
auto data_split = data.begin() + (buffer.size() - wpos);
|
||||
std::copy(data.begin(), data_split, buffer.begin() + wpos);
|
||||
std::copy(data_split, data.end(), buffer.begin());
|
||||
LogTrace(
|
||||
"Wrote ",
|
||||
log::trace(
|
||||
logcat,
|
||||
"Wrote {} bytes to buffer ranges [{},)+[0,{})",
|
||||
data.size(),
|
||||
" bytes to buffer ranges [",
|
||||
wpos,
|
||||
",",
|
||||
buffer.size(),
|
||||
")+[0,",
|
||||
data.end() - data_split,
|
||||
")");
|
||||
data.end() - data_split);
|
||||
}
|
||||
else
|
||||
{
|
||||
// No wrap needs, it fits before the end:
|
||||
std::copy(data.begin(), data.end(), buffer.begin() + wpos);
|
||||
LogTrace(
|
||||
"Wrote ", data.size(), " bytes to buffer range [", wpos, ",", wpos + data.size(), ")");
|
||||
log::trace(
|
||||
logcat, "Wrote {} bytes to buffer range [{},{})", data.size(), wpos, wpos + data.size());
|
||||
}
|
||||
size += data.size();
|
||||
LogTrace("New stream buffer: ", size, "/", buffer.size(), " bytes beginning at ", start);
|
||||
log::trace(
|
||||
logcat, "New stream buffer: {}/{} bytes beginning at {}", size, buffer.size(), start);
|
||||
conn.io_ready();
|
||||
return true;
|
||||
}
|
||||
|
|
@ -177,7 +177,7 @@ namespace llarp::quic
|
|||
//
|
||||
assert(bytes <= unacked_size && unacked_size <= size);
|
||||
|
||||
LogTrace("Acked ", bytes, " bytes of ", unacked_size, "/", size, " unacked/total");
|
||||
log::trace(logcat, "Acked {} bytes of {}/{} unacked/total", bytes, unacked_size, size);
|
||||
|
||||
unacked_size -= bytes;
|
||||
size -= bytes;
|
||||
|
|
@ -308,7 +308,7 @@ namespace llarp::quic
|
|||
// [ áaarrrrrr ] or [rr áaar]
|
||||
// to:
|
||||
// [ áaaaaarrr ] or [aa áaaa]
|
||||
LogTrace("wrote ", bytes, ", unsent=", unsent());
|
||||
log::trace(logcat, "wrote {}, unsent={}", bytes, unsent());
|
||||
assert(bytes <= unsent());
|
||||
unacked_size += bytes;
|
||||
}
|
||||
|
|
@ -316,20 +316,21 @@ namespace llarp::quic
|
|||
void
|
||||
Stream::close(std::optional<uint64_t> error_code)
|
||||
{
|
||||
LogDebug(
|
||||
"Closing ",
|
||||
log::debug(
|
||||
logcat,
|
||||
"Closing {} {}",
|
||||
stream_id,
|
||||
error_code ? " immediately with code " + std::to_string(*error_code) : " gracefully");
|
||||
|
||||
if (is_shutdown)
|
||||
LogDebug("Stream is already shutting down");
|
||||
log::debug(logcat, "Stream is already shutting down");
|
||||
else if (error_code)
|
||||
{
|
||||
is_closing = is_shutdown = true;
|
||||
ngtcp2_conn_shutdown_stream(conn, stream_id.id, *error_code);
|
||||
}
|
||||
else if (is_closing)
|
||||
LogDebug("Stream is already closing");
|
||||
log::debug(logcat, "Stream is already closing");
|
||||
else
|
||||
is_closing = true;
|
||||
|
||||
|
|
|
|||
|
|
@ -16,6 +16,8 @@ namespace llarp::quic
|
|||
{
|
||||
namespace
|
||||
{
|
||||
static auto logcat = log::Cat("quic");
|
||||
|
||||
// Takes data from the tcp connection and pushes it down the quic tunnel
|
||||
void
|
||||
on_outgoing_data(uvw::DataEvent& event, uvw::TCPHandle& client)
|
||||
|
|
@ -24,21 +26,23 @@ namespace llarp::quic
|
|||
assert(stream);
|
||||
std::string_view data{event.data.get(), event.length};
|
||||
auto peer = client.peer();
|
||||
LogTrace(peer.ip, ":", peer.port, " → lokinet ", buffer_printer{data});
|
||||
log::trace(logcat, "{}:{} → lokinet {}", peer.ip, peer.port, buffer_printer{data});
|
||||
// Steal the buffer from the DataEvent's unique_ptr<char[]>:
|
||||
stream->append_buffer(reinterpret_cast<const std::byte*>(event.data.release()), event.length);
|
||||
if (stream->used() >= tunnel::PAUSE_SIZE)
|
||||
{
|
||||
LogDebug(
|
||||
"quic tunnel is congested (have ",
|
||||
stream->used(),
|
||||
" bytes in flight); pausing local tcp connection reads");
|
||||
log::debug(
|
||||
logcat,
|
||||
"quic tunnel is congested (have {} bytes in flight); pausing local tcp connection "
|
||||
"reads",
|
||||
stream->used());
|
||||
client.stop();
|
||||
stream->when_available([](Stream& s) {
|
||||
auto client = s.data<uvw::TCPHandle>();
|
||||
if (s.used() < tunnel::PAUSE_SIZE)
|
||||
{
|
||||
LogDebug("quic tunnel is no longer congested; resuming tcp connection reading");
|
||||
log::debug(
|
||||
logcat, "quic tunnel is no longer congested; resuming tcp connection reading");
|
||||
client->read();
|
||||
return true;
|
||||
}
|
||||
|
|
@ -47,7 +51,7 @@ namespace llarp::quic
|
|||
}
|
||||
else
|
||||
{
|
||||
LogDebug("Queued ", event.length, " bytes");
|
||||
log::debug(logcat, "Queued {} bytes", event.length);
|
||||
}
|
||||
}
|
||||
|
||||
|
|
@ -62,7 +66,7 @@ namespace llarp::quic
|
|||
|
||||
std::string_view data{reinterpret_cast<const char*>(bdata.data()), bdata.size()};
|
||||
auto peer = tcp->peer();
|
||||
LogTrace(peer.ip, ":", peer.port, " ← lokinet ", buffer_printer{data});
|
||||
log::trace(logcat, "{}:{} ← lokinet {}", peer.ip, peer.port, buffer_printer{data});
|
||||
|
||||
if (data.empty())
|
||||
return;
|
||||
|
|
@ -85,7 +89,7 @@ namespace llarp::quic
|
|||
{
|
||||
if (auto tcp = st.data<uvw::TCPHandle>())
|
||||
{
|
||||
LogTrace("Closing TCP connection");
|
||||
log::trace(logcat, "Closing TCP connection");
|
||||
tcp->close();
|
||||
}
|
||||
};
|
||||
|
|
@ -103,7 +107,10 @@ namespace llarp::quic
|
|||
// This fires sometime after we call `close()` to signal that the close is done.
|
||||
if (auto stream = c.data<Stream>())
|
||||
{
|
||||
LogInfo("Local TCP connection closed, closing associated quic stream ", stream->id());
|
||||
log::info(
|
||||
logcat,
|
||||
"Local TCP connection closed, closing associated quic stream {}",
|
||||
stream->id());
|
||||
stream->close();
|
||||
stream->data(nullptr);
|
||||
}
|
||||
|
|
@ -111,20 +118,17 @@ namespace llarp::quic
|
|||
});
|
||||
tcp.on<uvw::EndEvent>([](auto&, uvw::TCPHandle& c) {
|
||||
// This fires on eof, most likely because the other side of the TCP connection closed it.
|
||||
LogInfo("EOF on connection to ", c.peer().ip, ":", c.peer().port);
|
||||
log::info(logcat, "EOF on connection to {}:{}", c.peer().ip, c.peer().port);
|
||||
c.close();
|
||||
});
|
||||
tcp.on<uvw::ErrorEvent>([](const uvw::ErrorEvent& e, uvw::TCPHandle& tcp) {
|
||||
LogError(
|
||||
"ErrorEvent[",
|
||||
log::error(
|
||||
logcat,
|
||||
"ErrorEvent[{}:{}] on connection with {}:{}, shutting down quic stream",
|
||||
e.name(),
|
||||
": ",
|
||||
e.what(),
|
||||
"] on connection with ",
|
||||
tcp.peer().ip,
|
||||
":",
|
||||
tcp.peer().port,
|
||||
", shutting down quic stream");
|
||||
tcp.peer().port);
|
||||
if (auto stream = tcp.data<Stream>())
|
||||
{
|
||||
stream->close(tunnel::ERROR_TCP);
|
||||
|
|
@ -147,7 +151,7 @@ namespace llarp::quic
|
|||
void
|
||||
initial_client_data_handler(uvw::TCPHandle& client, Stream& stream, bstring_view bdata)
|
||||
{
|
||||
LogTrace("initial client handler; data: ", buffer_printer{bdata});
|
||||
log::trace(logcat, "initial client handler; data: {}", buffer_printer{bdata});
|
||||
if (bdata.empty())
|
||||
return;
|
||||
client.clear(); // Clear these initial event handlers: we either set up the proper ones, or
|
||||
|
|
@ -164,14 +168,15 @@ namespace llarp::quic
|
|||
bdata.remove_prefix(1);
|
||||
stream.data_callback(stream, std::move(bdata));
|
||||
}
|
||||
LogTrace("starting client reading");
|
||||
log::trace(logcat, "starting client reading");
|
||||
}
|
||||
else
|
||||
{
|
||||
LogWarn(
|
||||
"Remote connection returned invalid initial byte (0x",
|
||||
oxenc::to_hex(bdata.begin(), bdata.begin() + 1),
|
||||
"); dropping connection");
|
||||
log::warning(
|
||||
logcat,
|
||||
"Remote connection returned invalid initial byte (0x{}); dropping "
|
||||
"connection",
|
||||
oxenc::to_hex(bdata.begin(), bdata.begin() + 1));
|
||||
stream.close(tunnel::ERROR_BAD_INIT);
|
||||
client.close();
|
||||
}
|
||||
|
|
@ -187,14 +192,14 @@ namespace llarp::quic
|
|||
uvw::TCPHandle& client, Stream& /*stream*/, std::optional<uint64_t> error_code)
|
||||
{
|
||||
if (error_code && *error_code == tunnel::ERROR_CONNECT)
|
||||
LogDebug("Remote TCP connection failed, closing local connection");
|
||||
log::debug(logcat, "Remote TCP connection failed, closing local connection");
|
||||
else
|
||||
LogWarn(
|
||||
"Stream connection closed ",
|
||||
error_code ? "with error " + std::to_string(*error_code) : "gracefully",
|
||||
"; closing local TCP connection.");
|
||||
log::warning(
|
||||
logcat,
|
||||
"Stream connection closed {}; closing local TCP connection.",
|
||||
error_code ? "with error " + std::to_string(*error_code) : "gracefully");
|
||||
auto peer = client.peer();
|
||||
LogDebug("Closing connection to ", peer.ip, ":", peer.port);
|
||||
log::debug(logcat, "Closing connection to {}:{}", peer.ip, peer.port);
|
||||
client.clear();
|
||||
if (error_code)
|
||||
client.close();
|
||||
|
|
@ -208,7 +213,7 @@ namespace llarp::quic
|
|||
{
|
||||
// Cleanup callback to clear out closed tunnel connections
|
||||
service_endpoint_.Loop()->call_every(500ms, timer_keepalive_, [this] {
|
||||
LogTrace("Checking quic tunnels for finished connections");
|
||||
log::trace(logcat, "Checking quic tunnels for finished connections");
|
||||
for (auto ctit = client_tunnels_.begin(); ctit != client_tunnels_.end();)
|
||||
{
|
||||
// Clear any accepted connections that have been closed:
|
||||
|
|
@ -220,7 +225,7 @@ namespace llarp::quic
|
|||
// stop the TCP connection when the quic side gets congested.
|
||||
if (not *it or not(*it)->data())
|
||||
{
|
||||
LogDebug("Cleanup up closed outgoing tunnel on quic:", port);
|
||||
log::debug(logcat, "Cleanup up closed outgoing tunnel on quic:{}", port);
|
||||
it = ct.conns.erase(it);
|
||||
}
|
||||
else
|
||||
|
|
@ -231,13 +236,13 @@ namespace llarp::quic
|
|||
// destroy the whole thing.
|
||||
if (ct.conns.empty() and (not ct.tcp or not ct.tcp->active()))
|
||||
{
|
||||
LogDebug("All sockets closed on quic:", port, ", destroying tunnel data");
|
||||
log::debug(logcat, "All sockets closed on quic:{}, destroying tunnel data", port);
|
||||
ctit = client_tunnels_.erase(ctit);
|
||||
}
|
||||
else
|
||||
++ctit;
|
||||
}
|
||||
LogTrace("Done quic tunnel cleanup check");
|
||||
log::trace(logcat, "Done quic tunnel cleanup check");
|
||||
});
|
||||
}
|
||||
|
||||
|
|
@ -254,7 +259,8 @@ namespace llarp::quic
|
|||
auto remote = service_endpoint_.GetEndpointWithConvoTag(conn.path.remote);
|
||||
if (!remote)
|
||||
{
|
||||
LogWarn("Received new stream open from invalid/unknown convo tag, dropping stream");
|
||||
log::warning(
|
||||
logcat, "Received new stream open from invalid/unknown convo tag, dropping stream");
|
||||
return false;
|
||||
}
|
||||
|
||||
|
|
@ -262,12 +268,13 @@ namespace llarp::quic
|
|||
auto tunnel_to = allow_connection(lokinet_addr, port);
|
||||
if (not tunnel_to)
|
||||
return false;
|
||||
LogInfo("quic stream from ", lokinet_addr, " to ", port, " tunnelling to ", *tunnel_to);
|
||||
log::info(
|
||||
logcat, "quic stream from {} to {} tunnelling to {}", lokinet_addr, port, *tunnel_to);
|
||||
|
||||
auto tcp = get_loop()->resource<uvw::TCPHandle>();
|
||||
auto error_handler = tcp->once<uvw::ErrorEvent>(
|
||||
[&stream, to = *tunnel_to](const uvw::ErrorEvent&, uvw::TCPHandle&) {
|
||||
LogWarn("Failed to connect to ", to, ", shutting down quic stream");
|
||||
log::warning(logcat, "Failed to connect to {}, shutting down quic stream", to);
|
||||
stream.close(tunnel::ERROR_CONNECT);
|
||||
});
|
||||
|
||||
|
|
@ -281,16 +288,16 @@ namespace llarp::quic
|
|||
auto stream = streamw.lock();
|
||||
if (!stream)
|
||||
{
|
||||
LogWarn(
|
||||
"Connected to TCP ",
|
||||
log::warning(
|
||||
logcat,
|
||||
"Connected to TCP {}:{} but quic stream has gone away; close/resetting local TCP "
|
||||
"connection",
|
||||
peer.ip,
|
||||
":",
|
||||
peer.port,
|
||||
" but quic stream has gone away; close/resetting local TCP connection");
|
||||
peer.port);
|
||||
tcp.close();
|
||||
return;
|
||||
}
|
||||
LogDebug("Connected to ", peer.ip, ":", peer.port, " for quic ", stream->id());
|
||||
log::debug(logcat, "Connected to {}:{} for quic {}", peer.ip, peer.port, stream->id());
|
||||
// Set up the data stream forwarding (which also clears these initial handlers).
|
||||
install_stream_forwarding(tcp, *stream);
|
||||
assert(stream->used() == 0);
|
||||
|
|
@ -324,7 +331,7 @@ namespace llarp::quic
|
|||
TunnelManager::listen(SockAddr addr)
|
||||
{
|
||||
return listen([addr](std::string_view, uint16_t p) -> std::optional<SockAddr> {
|
||||
LogInfo("try accepting ", addr.getPort());
|
||||
log::info(logcat, "try accepting {}", addr.getPort());
|
||||
if (p == addr.getPort())
|
||||
return addr;
|
||||
return std::nullopt;
|
||||
|
|
@ -349,19 +356,20 @@ namespace llarp::quic
|
|||
}
|
||||
catch (const std::exception& e)
|
||||
{
|
||||
LogWarn(
|
||||
"Incoming quic connection from ",
|
||||
log::warning(
|
||||
logcat,
|
||||
"Incoming quic connection from {} to {} denied via exception ({})",
|
||||
lokinet_addr,
|
||||
" to ",
|
||||
port,
|
||||
" denied via exception (",
|
||||
e.what(),
|
||||
")");
|
||||
e.what());
|
||||
return std::nullopt;
|
||||
}
|
||||
}
|
||||
LogWarn(
|
||||
"Incoming quic connection from ", lokinet_addr, " to ", port, " declined by all handlers");
|
||||
log::warning(
|
||||
logcat,
|
||||
"Incoming quic connection from {} to {} declined by all handlers",
|
||||
lokinet_addr,
|
||||
port);
|
||||
return std::nullopt;
|
||||
}
|
||||
|
||||
|
|
@ -413,12 +421,12 @@ namespace llarp::quic
|
|||
auto it = client_tunnels_.find(pseudo_port);
|
||||
if (it == client_tunnels_.end())
|
||||
{
|
||||
LogDebug("QUIC tunnel to ", addr, " closed before ", step_name, " finished");
|
||||
log::debug(logcat, "QUIC tunnel to {} closed before {} finished", addr, step_name);
|
||||
return false;
|
||||
}
|
||||
if (!step_success)
|
||||
{
|
||||
LogWarn("QUIC tunnel to ", addr, " failed during ", step_name, "; aborting tunnel");
|
||||
log::warning(logcat, "QUIC tunnel to {} failed during {}; aborting tunnel", addr, step_name);
|
||||
it->second.tcp->close();
|
||||
if (it->second.open_cb)
|
||||
it->second.open_cb(false);
|
||||
|
|
@ -494,7 +502,7 @@ namespace llarp::quic
|
|||
"Unable to open an outgoing quic connection: too many existing connections"};
|
||||
(next_pseudo_port_ = pport)++;
|
||||
|
||||
LogInfo("Bound TCP tunnel ", saddr, " for quic client :", pport);
|
||||
log::info(logcat, "Bound TCP tunnel {} for quic client :{}", saddr, pport);
|
||||
|
||||
// We are emplacing into client_tunnels_ here: beyond this point we must not throw until we
|
||||
// return (or if we do, make sure we remove this row from client_tunnels_ first).
|
||||
|
|
@ -591,7 +599,7 @@ namespace llarp::quic
|
|||
auto conn = tunnel.client->get_connection();
|
||||
|
||||
conn->on_stream_available = [this, id = row.first](Connection&) {
|
||||
LogDebug("QUIC connection :", id, " established; streams now available");
|
||||
log::debug(logcat, "QUIC connection :{} established; streams now available", id);
|
||||
if (auto it = client_tunnels_.find(id); it != client_tunnels_.end())
|
||||
flush_pending_incoming(it->second);
|
||||
};
|
||||
|
|
@ -626,11 +634,11 @@ namespace llarp::quic
|
|||
}
|
||||
catch (const std::exception& e)
|
||||
{
|
||||
LogWarn("Opening quic stream failed: ", e.what());
|
||||
log::warning(logcat, "Opening quic stream failed: {}", e.what());
|
||||
tcp_client->close();
|
||||
}
|
||||
|
||||
LogTrace("Set up new stream");
|
||||
log::trace(logcat, "Set up new stream");
|
||||
conn.io_ready();
|
||||
}
|
||||
}
|
||||
|
|
@ -640,7 +648,7 @@ namespace llarp::quic
|
|||
{
|
||||
if (buf.sz <= 4)
|
||||
{
|
||||
LogWarn("invalid quic packet: packet size (", buf.sz, ") too small");
|
||||
log::warning(logcat, "invalid quic packet: packet size ({}) too small", buf.sz);
|
||||
return;
|
||||
}
|
||||
auto type = static_cast<std::byte>(buf.base[0]);
|
||||
|
|
@ -654,26 +662,26 @@ namespace llarp::quic
|
|||
quic::Endpoint* ep = nullptr;
|
||||
if (type == CLIENT_TO_SERVER)
|
||||
{
|
||||
LogTrace("packet is client-to-server from client pport ", pseudo_port);
|
||||
log::trace(logcat, "packet is client-to-server from client pport {}", pseudo_port);
|
||||
// Client-to-server: the header port is the return port
|
||||
remote.setPort(pseudo_port);
|
||||
if (!server_)
|
||||
{
|
||||
LogWarn("Dropping incoming quic packet to server: no listeners");
|
||||
log::warning(logcat, "Dropping incoming quic packet to server: no listeners");
|
||||
return;
|
||||
}
|
||||
ep = server_.get();
|
||||
}
|
||||
else if (type == SERVER_TO_CLIENT)
|
||||
{
|
||||
LogTrace("packet is server-to-client to client pport ", pseudo_port);
|
||||
log::trace(logcat, "packet is server-to-client to client pport {}", pseudo_port);
|
||||
// Server-to-client: the header port tells us which client tunnel this is going to
|
||||
if (auto it = client_tunnels_.find(pseudo_port); it != client_tunnels_.end())
|
||||
ep = it->second.client.get();
|
||||
|
||||
if (not ep)
|
||||
{
|
||||
LogWarn("Incoming quic packet to invalid/closed client; dropping");
|
||||
log::warning(logcat, "Incoming quic packet to invalid/closed client; dropping");
|
||||
return;
|
||||
}
|
||||
|
||||
|
|
@ -682,17 +690,18 @@ namespace llarp::quic
|
|||
if (auto conn = static_cast<quic::Client&>(*ep).get_connection())
|
||||
{
|
||||
remote.setPort(conn->path.remote.port());
|
||||
LogTrace("remote port is ", remote.getPort());
|
||||
log::trace(logcat, "remote port is {}", remote.getPort());
|
||||
}
|
||||
else
|
||||
{
|
||||
LogWarn("Incoming quic to a quic::Client without an active quic::Connection; dropping");
|
||||
log::warning(
|
||||
logcat, "Incoming quic to a quic::Client without an active quic::Connection; dropping");
|
||||
return;
|
||||
}
|
||||
}
|
||||
else
|
||||
{
|
||||
LogWarn("Invalid incoming quic packet type ", type, "; dropping packet");
|
||||
log::warning(logcat, "Invalid incoming quic packet type {}; dropping packet", type);
|
||||
return;
|
||||
}
|
||||
ep->receive_packet(remote, ecn, data);
|
||||
|
|
|
|||
Loading…
Reference in a new issue