lsquic_ev_log.c revision 10c492f0 
1/* Copyright (c) 2017 - 2018 LiteSpeed Technologies Inc.  See LICENSE. */
2#ifndef WIN32
3#include <arpa/inet.h>
4#else
5#include <vc_compat.h>
6#endif
7#include <errno.h>
8#include <inttypes.h>
9#include <stdlib.h>
10#include <string.h>
11#include <sys/queue.h>
12
13#include "lsquic.h"
14#include "lsquic_types.h"
15#include "lsquic_int_types.h"
16#include "lsquic_packet_common.h"
17#include "lsquic_packet_in.h"
18#include "lsquic_packet_out.h"
19#include "lsquic_parse.h"
20#include "lsquic_frame_common.h"
21#include "lsquic_frame_reader.h"
22#include "lsquic_ev_log.h"
23
24#define LSQUIC_LOGGER_MODULE LSQLM_EVENT
25#include "lsquic_logger.h"
26
27
28/*  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^  */
29/*  ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||  */
30/* Messages that do not include connection ID go above this point */
31
32#define LSQUIC_LOG_CONN_ID cid
33#define LCID(...) LSQ_LOG2(LSQ_LOG_DEBUG, __VA_ARGS__)   /* LCID: log with CID */
34
35/* Messages that are to include connection ID go below this point */
36/*  ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||  */
37/*  VVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVV  */
38
39void
40lsquic_ev_log_packet_in (lsquic_cid_t cid, const lsquic_packet_in_t *packet_in)
41{
42        LCID("packet in: %"PRIu64, packet_in->pi_packno);
43}
44
45
46void
47lsquic_ev_log_ack_frame_in (lsquic_cid_t cid, const struct ack_info *acki)
48{
49    size_t sz;
50    char *buf;
51
52    if ((buf = acki2str(acki, &sz)))
53    {
54        LCID("ACK frame in: %.*s", (int) sz, buf);
55        free(buf);
56    }
57}
58
59
60void
61lsquic_ev_log_stream_frame_in (lsquic_cid_t cid,
62                                        const struct stream_frame *frame)
63{
64    LCID("STREAM frame in: stream %u; offset %"PRIu64"; size %"PRIu16
65        "; fin: %d", frame->stream_id, frame->data_frame.df_offset,
66        frame->data_frame.df_size, (int) frame->data_frame.df_fin);
67}
68
69
70void
71lsquic_ev_log_stop_waiting_frame_in (lsquic_cid_t cid, lsquic_packno_t least)
72{
73    LCID("STOP_WAITING frame in: least unacked packno %"PRIu64, least);
74}
75
76
77void
78lsquic_ev_log_window_update_frame_in (lsquic_cid_t cid, uint32_t stream_id,
79                                                            uint64_t offset)
80{
81    LCID("WINDOW_UPDATE frame in: stream %"PRIu32"; offset %"PRIu64,
82        stream_id, offset);
83}
84
85
86void
87lsquic_ev_log_blocked_frame_in (lsquic_cid_t cid, uint32_t stream_id)
88{
89    LCID("BLOCKED frame in: stream %"PRIu32, stream_id);
90}
91
92
93void
94lsquic_ev_log_connection_close_frame_in (lsquic_cid_t cid,
95                    uint32_t error_code, int reason_len, const char *reason)
96{
97    LCID("CONNECTION_CLOSE frame in: error code %"PRIu32", reason: %.*s",
98        error_code, reason_len, reason);
99}
100
101
102void
103lsquic_ev_log_goaway_frame_in (lsquic_cid_t cid, uint32_t error_code,
104                    uint32_t stream_id, int reason_len, const char *reason)
105{
106    LCID("GOAWAY frame in: error code %"PRIu32", stream %"PRIu32
107        ", reason: %.*s", error_code, stream_id, reason_len, reason);
108}
109
110
111void
112lsquic_ev_log_rst_stream_frame_in (lsquic_cid_t cid, uint32_t stream_id,
113                                        uint64_t offset, uint32_t error_code)
114{
115    LCID("RST_FRAME frame in: error code %"PRIu32", stream %"PRIu32
116        ", offset: %"PRIu64, error_code, stream_id, offset);
117}
118
119
120void
121lsquic_ev_log_padding_frame_in (lsquic_cid_t cid, size_t len)
122{
123    LCID("PADDING frame in of %zd bytes", len);
124}
125
126
127void
128lsquic_ev_log_ping_frame_in (lsquic_cid_t cid)
129{
130    LCID("PING frame in");
131}
132
133
134void
135lsquic_ev_log_packet_created (lsquic_cid_t cid,
136                                const struct lsquic_packet_out *packet_out)
137{
138    LCID("created packet %"PRIu64"; flags: version=%d, nonce=%d, conn_id=%d",
139        packet_out->po_packno,
140        !!(packet_out->po_flags & PO_VERSION),
141        !!(packet_out->po_flags & PO_NONCE),
142        !!(packet_out->po_flags & PO_CONN_ID));
143}
144
145
146void
147lsquic_ev_log_packet_sent (lsquic_cid_t cid,
148                                const struct lsquic_packet_out *packet_out)
149{
150    char frames[lsquic_frame_types_str_sz];
151    if (lsquic_packet_out_verneg(packet_out))
152        LCID("sent version negotiation packet, size %hu",
153                                                    packet_out->po_data_sz);
154    else if (lsquic_packet_out_pubres(packet_out))
155        LCID("sent public reset packet, size %hu", packet_out->po_data_sz);
156    else
157        LCID("sent packet %"PRIu64", size %hu, frame types: %s",
158            packet_out->po_packno, packet_out->po_enc_data_sz,
159                /* Frame types is a list of different frames types contained
160                 * in the packet, no more.  Count and order of frames is not
161                 * printed.
162                 */
163                lsquic_frame_types_to_str(frames, sizeof(frames),
164                                                packet_out->po_frame_types));
165}
166
167
168void
169lsquic_ev_log_packet_not_sent (lsquic_cid_t cid,
170                                const struct lsquic_packet_out *packet_out)
171{
172    char frames[lsquic_frame_types_str_sz];
173    LCID("unsent packet %"PRIu64", size %hu, frame types: %s",
174        packet_out->po_packno, packet_out->po_enc_data_sz,
175            /* Frame types is a list of different frames types contained in
176             * the packet, no more.  Count and order of frames is not printed.
177             */
178            lsquic_frame_types_to_str(frames, sizeof(frames),
179                                                packet_out->po_frame_types));
180}
181
182
183void
184lsquic_ev_log_http_headers_in (lsquic_cid_t cid, int is_server,
185                                        const struct uncompressed_headers *uh)
186{
187    const char *cr, *p;
188
189    if (uh->uh_flags & UH_PP)
190        LCID("read push promise; stream %"PRIu32", promised stream %"PRIu32,
191            uh->uh_stream_id, uh->uh_oth_stream_id);
192    else
193        LCID("read %s headers; stream: %"PRIu32", depends on stream: %"PRIu32
194            ", weight: %hu, exclusive: %d, fin: %d",
195            is_server ? "request" : "response",
196            uh->uh_stream_id, uh->uh_oth_stream_id, uh->uh_weight,
197            (int) uh->uh_exclusive, !!(uh->uh_flags & UH_FIN));
198
199    for (p = uh->uh_headers; p < uh->uh_headers + uh->uh_size; p = cr + 2)
200    {
201        cr = strchr(p, '\r');
202        if (cr && cr > p)
203            LCID("  %.*s", (int) (cr - p), p);
204        else
205            break;
206    }
207}
208
209
210void
211lsquic_ev_log_action_stream_frame (lsquic_cid_t cid,
212    const struct parse_funcs *pf, const unsigned char *buf, size_t bufsz,
213    const char *what)
214{
215    struct stream_frame frame;
216    int len;
217
218    len = pf->pf_parse_stream_frame(buf, bufsz, &frame);
219    if (len > 0)
220        LCID("%s STREAM frame: stream %"PRIu32", offset: %"PRIu64
221            ", size: %"PRIu16", fin: %d", what, frame.stream_id,
222            frame.data_frame.df_offset, frame.data_frame.df_size,
223            frame.data_frame.df_fin);
224    else
225        LSQ_LOG2(LSQ_LOG_WARN, "cannot parse STREAM frame");
226}
227
228
229void
230lsquic_ev_log_generated_ack_frame (lsquic_cid_t cid, const struct parse_funcs *pf,
231                                   const unsigned char *ack_buf, size_t ack_buf_sz)
232{
233    struct ack_info acki;
234    size_t sz;
235    char *buf;
236    int len;
237
238    len = pf->pf_parse_ack_frame(ack_buf, ack_buf_sz, &acki);
239    if (len < 0)
240    {
241        LSQ_LOG2(LSQ_LOG_WARN, "cannot parse ACK frame");
242        return;
243    }
244
245    if ((buf = acki2str(&acki, &sz)))
246    {
247        LCID("generated ACK frame: %.*s", (int) sz, buf);
248        free(buf);
249    }
250}
251
252
253void
254lsquic_ev_log_generated_stop_waiting_frame (lsquic_cid_t cid,
255                                            lsquic_packno_t lunack)
256{
257    LCID("generated STOP_WAITING frame; least unacked: %"PRIu64, lunack);
258}
259
260
261void
262lsquic_ev_log_generated_http_headers (lsquic_cid_t cid, uint32_t stream_id,
263                    int is_server, const struct http_prio_frame *prio_frame,
264                    const struct lsquic_http_headers *headers)
265{
266    uint32_t dep_stream_id;
267    int exclusive, i;
268    unsigned short weight;
269
270    if (is_server)
271        LCID("generated HTTP response HEADERS for stream %"PRIu32, stream_id);
272    else
273    {
274        memcpy(&dep_stream_id, prio_frame->hpf_stream_id, 4);
275        dep_stream_id = htonl(dep_stream_id);
276        exclusive = dep_stream_id >> 31;
277        dep_stream_id &= ~(1 << 31);
278        weight = prio_frame->hpf_weight + 1;
279        LCID("generated HTTP request HEADERS for stream %"PRIu32
280            ", dep stream: %"PRIu32", weight: %hu, exclusive: %d", stream_id,
281            dep_stream_id, weight, exclusive);
282    }
283
284    for (i = 0; i < headers->count; ++i)
285        LCID("  %.*s: %.*s",
286            (int)    headers->headers[i].name.iov_len,
287            (char *) headers->headers[i].name.iov_base,
288            (int)    headers->headers[i].value.iov_len,
289            (char *) headers->headers[i].value.iov_base);
290}
291
292
293void
294lsquic_ev_log_generated_http_push_promise (lsquic_cid_t cid,
295                            uint32_t stream_id, uint32_t promised_stream_id,
296                            const struct lsquic_http_headers *headers,
297                            const struct lsquic_http_headers *extra_headers)
298{
299    int i;
300
301    LCID("generated HTTP PUSH_PROMISE for stream %"PRIu32"; promised stream %"
302        PRIu32, stream_id, promised_stream_id);
303
304    for (i = 0; i < headers->count; ++i)
305        LCID("  %.*s: %.*s",
306            (int)    headers->headers[i].name.iov_len,
307            (char *) headers->headers[i].name.iov_base,
308            (int)    headers->headers[i].value.iov_len,
309            (char *) headers->headers[i].value.iov_base);
310
311    if (extra_headers)
312        for (i = 0; i < extra_headers->count; ++i)
313            LCID("  %.*s: %.*s",
314                (int)    extra_headers->headers[i].name.iov_len,
315                (char *) extra_headers->headers[i].name.iov_base,
316                (int)    extra_headers->headers[i].value.iov_len,
317                (char *) extra_headers->headers[i].value.iov_base);
318}
319
320
321