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