Skip to content

Commit

Permalink
implement per-point logging in userspace
Browse files Browse the repository at this point in the history
  • Loading branch information
@kazuho
kazuho committed Nov 25, 2024
1 parent d13ff3b commit 2debf2a
Show file tree
Hide file tree
Showing 2 changed files with 156 additions and 46 deletions.
72 changes: 49 additions & 23 deletions include/picotls.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1386,35 +1386,40 @@ uint64_t ptls_decode_quicint(const uint8_t **src, const uint8_t *end);
ptls_decode_assert_block_close((src), end); \
} while (0)

#define PTLS_LOG__DO_LOG(module, type, block) \
#define PTLS_LOG__DO_LOG(module, name, block) \
do { \
int ptlslog_skip = 0; \
char smallbuf[128]; \
ptls_buffer_t ptlslogbuf; \
ptls_buffer_init(&ptlslogbuf, smallbuf, sizeof(smallbuf)); \
PTLS_LOG__DO_PUSH_SAFESTR("{\"module\":\"" PTLS_TO_STR(module) "\",\"type\":\"" PTLS_TO_STR(type) "\""); \
PTLS_LOG__DO_PUSH_SAFESTR("{\"module\":\"" PTLS_TO_STR(module) "\",\"type\":\"" PTLS_TO_STR(name) "\""); \
do { \
block \
} while (0); \
PTLS_LOG__DO_PUSH_SAFESTR("}\n"); \
if (!ptlslog_skip) \
ptls_log__do_write(&ptlslogbuf); \
ptls_log__do_write(&logpoint, &ptlslogbuf); \
ptls_buffer_dispose(&ptlslogbuf); \
} while (0)

#define PTLS_LOG(module, type, block) \
#define PTLS_LOG_DEFINE_POINT(_module, _name, _var) \
static struct st_ptls_log_point_t _var = {.name = PTLS_TO_STR(_module) ":" PTLS_TO_STR(_name)}

#define PTLS_LOG(module, name, block) \
do { \
if (!ptls_log.is_active) \
PTLS_LOG_DEFINE_POINT(module, name); \
if (ptls_log__active_connections(&logpoint) == 0) \
break; \
PTLS_LOG__DO_LOG((module), (type), (block)); \
} while (0)

#define PTLS_LOG_CONN(type, tls, block) \
#define PTLS_LOG_CONN(name, tls, block) \
do { \
PTLS_LOG_DEFINE_POINT(picotls, name, logpoint); \
ptls_t *_tls = (tls); \
if (!ptls_log.is_active || ptls_skip_tracing(_tls)) \
if (!ptls_log_point_is_active(&logpoint) || ptls_skip_tracing(_tls)) \
break; \
PTLS_LOG__DO_LOG(picotls, type, { \
PTLS_LOG__DO_LOG(picotls, name, { \
PTLS_LOG_ELEMENT_PTR(tls, _tls); \
do { \
block \
Expand Down Expand Up @@ -1461,14 +1466,14 @@ uint64_t ptls_decode_quicint(const uint8_t **src, const uint8_t *end);
#define PTLS_LOG_APPDATA_ELEMENT_UNSAFESTR(name, value, value_len) \
do { \
size_t _len = (value_len); \
if (ptls_log.include_appdata) \
if (ptls_log_include_appdata) \
PTLS_LOG_ELEMENT_UNSAFESTR(name, value, _len); \
PTLS_LOG_ELEMENT__DO_UNSIGNED(name, "_len", _len); \
} while (0)
#define PTLS_LOG_APPDATA_ELEMENT_HEXDUMP(name, value, value_len) \
do { \
size_t _len = (value_len); \
if (ptls_log.include_appdata) \
if (ptls_log_include_appdata) \
PTLS_LOG_ELEMENT_HEXDUMP(name, value, _len); \
PTLS_LOG_ELEMENT__DO_UNSIGNED(name, "_len", _len); \
} while (0)
Expand Down Expand Up @@ -1513,26 +1518,40 @@ uint64_t ptls_decode_quicint(const uint8_t **src, const uint8_t *end);
} \
} while (0)

/**
* User API is exposed only when logging is supported by the platform.
*/
typedef struct st_ptls_log_t {
unsigned is_active : 1;
unsigned include_appdata : 1;
} ptls_log_t;
struct st_ptls_log_point_t {
/**
* name of the log point (`module:type`)
*/
const char *name;
/**
* bit array of connections (1 is active)
*/
uint32_t active_conns;
/**
* link list of log points, see `logctx::points`
*/
struct st_ptls_log_point_t *next;
};

extern volatile unsigned ptls_log_include_appdata;

void ptls_log__init_point(struct st_ptls_log_point_t *point);
static int ptls_log_point_is_active(struct st_ptls_log_point_t *point);

#if PTLS_HAVE_LOG
extern volatile ptls_log_t ptls_log;
/**
* Returns the number of log events that were unable to be emitted.
*/
size_t ptls_log_num_lost(void);
/**
* Registers an fd to the logger. A registered fd is automatically closed and removed if it is invalidated.
*
*/
int ptls_log_add_fd(int fd);
#else
static const ptls_log_t ptls_log = {0};
/**
* Registers an fd to the logger. A registered fd is automatically closed and removed when it is closed by the peer.
* @param points list of points being logged, in the form of p1\0p2\0\0 (i.e., concatenated list of C strings with an empty string
* marking the end). An empty list means attach to all.
*/
int ptls_log_add_fd(int fd, const char *points);
#endif

static int ptls_log__do_push_safestr(ptls_buffer_t *buf, const char *s);
Expand All @@ -1543,7 +1562,7 @@ int ptls_log__do_push_signed32(ptls_buffer_t *buf, int32_t v);
int ptls_log__do_push_signed64(ptls_buffer_t *buf, int64_t v);
int ptls_log__do_push_unsigned32(ptls_buffer_t *buf, uint32_t v);
int ptls_log__do_push_unsigned64(ptls_buffer_t *buf, uint64_t v);
void ptls_log__do_write(const ptls_buffer_t *buf);
void ptls_log__do_write(struct st_ptls_log_point_t *point, const ptls_buffer_t *buf);

/**
* create a client object to handle new TLS connection
Expand Down Expand Up @@ -1919,6 +1938,13 @@ inline ptls_t *ptls_new(ptls_context_t *ctx, int is_server)
return is_server ? ptls_server_new(ctx) : ptls_client_new(ctx);
}

inline int ptls_log_point_is_active(struct st_ptls_log_point_t *point)
{
if (point->next == NULL)
ptls_log__init_point(point);
return point->active_conns > 0;
}

inline ptls_iovec_t ptls_iovec_init(const void *p, size_t len)
{
/* avoid the "return (ptls_iovec_t){(uint8_t *)p, len};" construct because it requires C99
Expand Down
130 changes: 107 additions & 23 deletions lib/picotls.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -6820,12 +6820,33 @@ int ptls_log__do_push_unsigned64(ptls_buffer_t *buf, uint64_t v)

#if PTLS_HAVE_LOG

volatile ptls_log_t ptls_log = {};
volatile unsigned ptls_log_include_appdata = 0;

static struct {
int *fds;
size_t num_fds;
/**
* list of connections; the slot is connected if points != NULL
*/
struct {
/**
* file descriptor
*/
int fd;
/**
* see `ptls_log_add_fd`
*/
char *points;
} conns[sizeof(((struct st_ptls_log_point_t *)NULL)->active_conns) * 8];
/**
* counts the number of writes that failed
*/
size_t num_lost;
/**
* anchor of the single-linked list of log points; the tail refers to itself (i.e., point->next == point)
*/
struct st_ptls_log_point_t *points;
/**
*
*/
pthread_mutex_t mutex;
} logctx = {.mutex = PTHREAD_MUTEX_INITIALIZER};

Expand All @@ -6834,53 +6855,116 @@ size_t ptls_log_num_lost(void)
return logctx.num_lost;
}

int ptls_log_add_fd(int fd)
static int is_traced(struct st_ptls_log_point_t *point, const char *list)
{
if (list[0] == '\0')
return 1;

for (const char *s = list; s[0] != '\0'; s += strlen(s) + 1)
if (strcmp(point->name, s) == 0)
return 1;
return 0;
}

void ptls_log__init_point(struct st_ptls_log_point_t *point)
{
pthread_mutex_lock(&logctx.mutex);

/* setup active bitmap */
for (size_t slot = 0; slot < PTLS_ELEMENTSOF(logctx.conns); ++slot)
if (logctx.conns[slot].points != NULL && is_traced(point, logctx.conns[slot].points))
point->active_conns = (uint32_t)1 << slot;

/* register to the linked list */
point->next = logctx.points != NULL ? logctx.points : point;
logctx.points = point;

pthread_mutex_unlock(&logctx.mutex);
}

int ptls_log_add_fd(int fd, const char *_points)
{
char *points;

{ /* duplicate the list of log points */
const char *in_tail;
for (in_tail = _points; in_tail[0] != '\0'; in_tail += strlen(in_tail) + 1)
;
++in_tail;
if ((points = malloc(in_tail - _points)) == NULL)
return PTLS_ERROR_NO_MEMORY;
memcpy(points, _points, in_tail - _points);
}

int ret;

pthread_mutex_lock(&logctx.mutex);

int *newfds;
if ((newfds = realloc(logctx.fds, sizeof(logctx.fds[0]) * (logctx.num_fds + 1))) == NULL) {
/* find slot, or return if not available */
size_t slot_index;
for (slot_index = 0; slot_index < PTLS_ELEMENTSOF(logctx.conns); ++slot_index)
if (logctx.conns[slot_index].points == NULL)
break;
if (slot_index == PTLS_ELEMENTSOF(logctx.conns)) {
ret = PTLS_ERROR_NO_MEMORY;
goto Exit;
}
logctx.fds = newfds;
logctx.fds[logctx.num_fds++] = fd;
ptls_log.is_active = 1;

/* setup the slot */
logctx.conns[slot_index].fd = fd;
logctx.conns[slot_index].points = points;

/* update the known event slots */
for (struct st_ptls_log_point_t *point = logctx.points;; point = point->next) {
if (is_traced(point, points))
point->active_conns |= (uint32_t)1 << slot_index;
if (point->next == point)
break;
}

ret = 0; /* success */

Exit:
pthread_mutex_unlock(&logctx.mutex);
if (ret != 0)
free(points);
return ret;
}

#endif

void ptls_log__do_write(const ptls_buffer_t *buf)
void ptls_log__do_write(struct st_ptls_log_point_t *point, const ptls_buffer_t *buf)
{
#if PTLS_HAVE_LOG
pthread_mutex_lock(&logctx.mutex);

for (size_t fd_index = 0; fd_index < logctx.num_fds;) {
ssize_t ret;
while ((ret = write(logctx.fds[fd_index], buf->base, buf->off)) == -1 && errno == EINTR)
uint32_t conns = point->active_conns;

for (size_t slot = 0; conns != 0; ++slot, conns >>= 1) {
if ((conns & 1) == 0)
continue;
conns &= ~1;

assert(logctx.conns[slot].fd != -1);
ssize_t wret;
while ((wret = write(logctx.conns[slot].fd, buf->base, buf->off)) == -1 && errno == EINTR)
;
if (ret == buf->off) {
if (wret == buf->off) {
/* success */
++fd_index;
} else if (ret > 0 || (ret == -1 && (errno == EAGAIN || errno == EWOULDBLOCK))) {
} else if (wret > 0 || (wret == -1 && (errno == EAGAIN || errno == EWOULDBLOCK))) {
/* partial write or buffer full */
++logctx.num_lost;
++fd_index;
} else {
/* write error; close and remove that fd from array */
close(logctx.fds[fd_index]);
logctx.fds[fd_index] = logctx.fds[logctx.num_fds - 1];
--logctx.num_fds;
if (logctx.num_fds == 0)
ptls_log.is_active = 0;
/* write error; close and unregister the connection */
close(logctx.conns[slot].fd);
logctx.conns[slot].fd = -1;
free(logctx.conns[slot].points);
logctx.conns[slot].points = NULL;
for (struct st_ptls_log_point_t *point = logctx.points;; point = point->next) {
point->active_conns &= ~((uint32_t)1 << slot);
if (point == point->next)
break;
}
}
}

Expand Down

0 comments on commit 2debf2a

Please sign in to comment.