Skip to content

Commit

Permalink
[logger] switch to draft-ietf-quic-qlog-main-schema-01
Browse files Browse the repository at this point in the history
  • Loading branch information
@jlaine
jlaine committed Oct 28, 2021
1 parent bf7f409 commit 65b534a
Show file tree
Hide file tree
Showing 6 changed files with 171 additions and 159 deletions.
49 changes: 17 additions & 32 deletions examples/interop.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -136,13 +136,10 @@ async def test_version_negotiation(server: Server, configuration: QuicConfigurat
await protocol.ping()

# check log
for stamp, category, event, data in configuration.quic_logger.to_dict()[
"traces"
][0]["events"]:
for event in configuration.quic_logger.to_dict()["traces"][0]["events"]:
if (
category == "transport"
and event == "packet_received"
and data["packet_type"] == "version_negotiation"
event["name"] == "transport:packet_received"
and event["data"]["packet_type"] == "version_negotiation"
):
server.result |= Result.V

Expand All @@ -167,13 +164,10 @@ async def test_retry(server: Server, configuration: QuicConfiguration):
await protocol.ping()

# check log
for stamp, category, event, data in configuration.quic_logger.to_dict()[
"traces"
][0]["events"]:
for event in configuration.quic_logger.to_dict()["traces"][0]["events"]:
if (
category == "transport"
and event == "packet_received"
and data["packet_type"] == "retry"
event["name"] == "transport:packet_received"
and event["data"]["packet_type"] == "retry"
):
server.result |= Result.S

Expand Down Expand Up @@ -362,15 +356,12 @@ async def test_nat_rebinding(server: Server, configuration: QuicConfiguration):

# check log
path_challenges = 0
for stamp, category, event, data in configuration.quic_logger.to_dict()[
"traces"
][0]["events"]:
for event in configuration.quic_logger.to_dict()["traces"][0]["events"]:
if (
category == "transport"
and event == "packet_received"
and data["packet_type"] == "1RTT"
event["name"] == "transport:packet_received"
and event["data"]["packet_type"] == "1RTT"
):
for frame in data["frames"]:
for frame in event["data"]["frames"]:
if frame["frame_type"] == "path_challenge":
path_challenges += 1
if not path_challenges:
Expand Down Expand Up @@ -398,18 +389,14 @@ async def test_address_mobility(server: Server, configuration: QuicConfiguration

# check log
path_challenges = 0
for stamp, category, event, data in configuration.quic_logger.to_dict()[
"traces"
][0]["events"]:
for event in configuration.quic_logger.to_dict()["traces"][0]["events"]:
if (
category == "transport"
and event == "packet_received"
and data["packet_type"] == "1RTT"
event["name"] == "transport:packet_received"
and event["data"]["packet_type"] == "1RTT"
):
for frame in data["frames"]:
for frame in event["data"]["frames"]:
if frame["frame_type"] == "path_challenge":
path_challenges += 1

if not path_challenges:
protocol._quic._logger.warning("No PATH_CHALLENGE received")
else:
Expand All @@ -425,11 +412,9 @@ async def test_spin_bit(server: Server, configuration: QuicConfiguration):

# check log
spin_bits = set()
for stamp, category, event, data in configuration.quic_logger.to_dict()[
"traces"
][0]["events"]:
if category == "connectivity" and event == "spin_bit_updated":
spin_bits.add(data["state"])
for event in configuration.quic_logger.to_dict()["traces"][0]["events"]:
if event["name"] == "connectivity:spin_bit_updated":
spin_bits.add(event["data"]["state"])
if len(spin_bits) == 2:
server.result |= Result.P

Expand Down
58 changes: 11 additions & 47 deletions src/aioquic/h3/connection.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -178,44 +178,6 @@ def parse_settings(data: bytes) -> Dict[int, int]:
return dict(settings)


def qlog_encode_data_frame(byte_length: int, stream_id: int) -> Dict:
return {
"byte_length": str(byte_length),
"frame": {"frame_type": "data"},
"stream_id": str(stream_id),
}


def qlog_encode_headers(headers: Headers) -> List[Dict]:
return [
{"name": h[0].decode("utf8"), "value": h[1].decode("utf8")} for h in headers
]


def qlog_encode_headers_frame(
byte_length: int, headers: Headers, stream_id: int
) -> Dict:
return {
"byte_length": str(byte_length),
"frame": {"frame_type": "headers", "headers": qlog_encode_headers(headers)},
"stream_id": str(stream_id),
}


def qlog_encode_push_promise_frame(
byte_length: int, headers: Headers, push_id: int, stream_id: int
) -> Dict:
return {
"byte_length": str(byte_length),
"frame": {
"frame_type": "push_promise",
"headers": qlog_encode_headers(headers),
"push_id": str(push_id),
},
"stream_id": str(stream_id),
}


def validate_headers(
headers: Headers,
allowed_pseudo_headers: FrozenSet[bytes],
Expand Down Expand Up @@ -474,7 +436,9 @@ def send_data(self, stream_id: int, data: bytes, end_stream: bool) -> None:
self._quic_logger.log_event(
category="http",
event="frame_created",
data=qlog_encode_data_frame(byte_length=len(data), stream_id=stream_id),
data=self._quic_logger.encode_http3_data_frame(
length=len(data), stream_id=stream_id
),
)

self._quic.send_stream_data(
Expand Down Expand Up @@ -507,8 +471,8 @@ def send_headers(
self._quic_logger.log_event(
category="http",
event="frame_created",
data=qlog_encode_headers_frame(
byte_length=len(frame_data), headers=headers, stream_id=stream_id
data=self._quic_logger.encode_http3_headers_frame(
length=len(frame_data), headers=headers, stream_id=stream_id
),
)

Expand Down Expand Up @@ -653,8 +617,8 @@ def _handle_request_or_push_frame(
self._quic_logger.log_event(
category="http",
event="frame_parsed",
data=qlog_encode_headers_frame(
byte_length=stream.blocked_frame_size
data=self._quic_logger.encode_http3_headers_frame(
length=stream.blocked_frame_size
if frame_data is None
else len(frame_data),
headers=headers,
Expand Down Expand Up @@ -692,8 +656,8 @@ def _handle_request_or_push_frame(
self._quic_logger.log_event(
category="http",
event="frame_parsed",
data=qlog_encode_push_promise_frame(
byte_length=len(frame_data),
data=self._quic_logger.encode_http3_push_promise_frame(
length=len(frame_data),
headers=headers,
push_id=push_id,
stream_id=stream.stream_id,
Expand Down Expand Up @@ -857,8 +821,8 @@ def _receive_request_or_push_data(
self._quic_logger.log_event(
category="http",
event="frame_parsed",
data=qlog_encode_data_frame(
byte_length=stream.frame_size, stream_id=stream.stream_id
data=self._quic_logger.encode_http3_data_frame(
length=stream.frame_size, stream_id=stream.stream_id
),
)

Expand Down
60 changes: 40 additions & 20 deletions src/aioquic/quic/connection.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -80,6 +80,7 @@
]
STREAM_FLAGS = 0x07
STREAM_COUNT_MAX = 0x1000000000000000
UDP_HEADER_SIZE = 8

NetworkAddress = Any

Expand Down Expand Up @@ -574,18 +575,18 @@ def datagrams_to_send(self, now: float) -> List[Tuple[bytes, NetworkAddress]]:
category="transport",
event="packet_sent",
data={
"packet_type": self._quic_logger.packet_type(
packet.packet_type
),
"frames": packet.quic_logger_frames,
"header": {
"packet_number": str(packet.packet_number),
"packet_size": packet.sent_bytes,
"packet_number": packet.packet_number,
"packet_type": self._quic_logger.packet_type(
packet.packet_type
),
"scid": dump_cid(self.host_cid)
if is_long_header(packet.packet_type)
else "",
"dcid": dump_cid(self._peer_cid.cid),
},
"frames": packet.quic_logger_frames,
"raw": {"length": packet.sent_bytes},
},
)

Expand All @@ -596,15 +597,23 @@ def datagrams_to_send(self, now: float) -> List[Tuple[bytes, NetworkAddress]]:
# return datagrams to send and the destination network address
ret = []
for datagram in datagrams:
byte_length = len(datagram)
network_path.bytes_sent += byte_length
payload_length = len(datagram)
network_path.bytes_sent += payload_length
ret.append((datagram, network_path.addr))

if self._quic_logger is not None:
self._quic_logger.log_event(
category="transport",
event="datagrams_sent",
data={"byte_length": byte_length, "count": 1},
data={
"count": 1,
"raw": [
{
"length": UDP_HEADER_SIZE + payload_length,
"payload_length": payload_length,
}
],
},
)
return ret

Expand Down Expand Up @@ -692,10 +701,19 @@ def receive_datagram(self, data: bytes, addr: NetworkAddress, now: float) -> Non

# log datagram
if self._quic_logger is not None:
payload_length = len(data)
self._quic_logger.log_event(
category="transport",
event="datagrams_received",
data={"byte_length": len(data), "count": 1},
data={
"count": 1,
"raw": [
{
"length": UDP_HEADER_SIZE + payload_length,
"payload_length": payload_length,
}
],
},
)

# for servers, arm the idle timeout on the first datagram
Expand Down Expand Up @@ -743,12 +761,13 @@ def receive_datagram(self, data: bytes, addr: NetworkAddress, now: float) -> Non
category="transport",
event="packet_received",
data={
"packet_type": "version_negotiation",
"frames": [],
"header": {
"packet_type": "version_negotiation",
"scid": dump_cid(header.source_cid),
"dcid": dump_cid(header.destination_cid),
},
"frames": [],
"raw": {"length": buf.tell() - start_off},
},
)
if self._version in versions:
Expand Down Expand Up @@ -807,12 +826,13 @@ def receive_datagram(self, data: bytes, addr: NetworkAddress, now: float) -> Non
category="transport",
event="packet_received",
data={
"packet_type": "retry",
"frames": [],
"header": {
"packet_type": "retry",
"scid": dump_cid(header.source_cid),
"dcid": dump_cid(header.destination_cid),
},
"frames": [],
"raw": {"length": buf.tell() - start_off},
},
)

Expand Down Expand Up @@ -902,16 +922,16 @@ def receive_datagram(self, data: bytes, addr: NetworkAddress, now: float) -> Non
category="transport",
event="packet_received",
data={
"packet_type": self._quic_logger.packet_type(
header.packet_type
),
"frames": quic_logger_frames,
"header": {
"packet_number": str(packet_number),
"packet_size": end_off - start_off,
"packet_number": packet_number,
"packet_type": self._quic_logger.packet_type(
header.packet_type
),
"dcid": dump_cid(header.destination_cid),
"scid": dump_cid(header.source_cid),
},
"frames": quic_logger_frames,
"raw": {"length": end_off - start_off},
},
)

Expand Down
Loading

0 comments on commit 65b534a

Please sign in to comment.