diff --git a/src/http.c b/src/http.c index 6b7acd2..da396a8 100644 --- a/src/http.c +++ b/src/http.c @@ -2,6 +2,7 @@ #include "server.h" #include "worker.h" #include "client.h" +#include "slog.h" #include #include @@ -98,7 +99,12 @@ http_response_cleanup(struct http_response *r, int fd, int success) { free(r->out); if(!r->keep_alive || !success) { /* Close fd is client doesn't support Keep-Alive. */ - fprintf(stderr, "http_response_cleanup: keep_alive=%d, success=%d -> closing\n", r->keep_alive, success); + if (r->w && slog_enabled(r->w->s, WEBDIS_TRACE)) { + char format[] = "http_response_cleanup: keep_alive=%d, success=%d -> closing"; + char cleanup_msg[sizeof(format)]; + snprintf(cleanup_msg, sizeof(cleanup_msg), format, r->keep_alive ? 1 : 0, success ? 1: 0); + slog(r->w->s, WEBDIS_TRACE, cleanup_msg, 0); + } close(fd); } @@ -125,8 +131,19 @@ http_can_write(int fd, short event, void *p) { if(ret > 0) r->sent += ret; - fprintf(stderr, "http_can_write: ret=%d, r->out_sz=%lu, r->sent=%d\n", - ret, r->out_sz, r->sent); + if (r->w && slog_enabled(r->w->s, WEBDIS_TRACE)) { /* trace logs */ + char format[] = "http_can_write: wrote %d, remaining=%lu, total sent=%d"; + size_t contents_sz = snprintf(NULL, 0, format, ret, r->out_sz - r->sent, r->sent); + char *contents_msg = calloc(contents_sz + 1, 1); + if (contents_msg) { + snprintf(contents_msg, contents_sz + 1, format, ret, r->out_sz - r->sent, r->sent); + slog(r->w->s, WEBDIS_TRACE, contents_msg, contents_sz); + free(contents_msg); + } else { + slog(r->w->s, WEBDIS_ERROR, "Failed allocation in http_can_write", 0); + } + } + if(ret <= 0 || r->out_sz - r->sent == 0) { /* error or done */ http_response_cleanup(r, fd, (int)r->out_sz == r->sent ? 1 : 0); } else { /* reschedule write */ diff --git a/src/websocket.c b/src/websocket.c index 687fbfe..c8482f6 100644 --- a/src/websocket.c +++ b/src/websocket.c @@ -6,6 +6,7 @@ #include "worker.h" #include "pool.h" #include "http.h" +#include "slog.h" /* message parsers */ #include "formats/json.h" @@ -219,13 +220,13 @@ ws_execute(struct http_client *c, const char *frame, size_t frame_len) { } static struct ws_msg * -ws_msg_new() { - fprintf(stderr, "------------ NEW -----------\n"); +ws_msg_new(struct server *s) { + slog(s, WEBDIS_TRACE, "ws_msg_new", 0); return calloc(1, sizeof(struct ws_msg)); } static void -ws_msg_add(struct ws_msg *m, const char *p, size_t psz, const unsigned char *mask) { +ws_msg_add(struct server *s, struct ws_msg *m, const char *p, size_t psz, const unsigned char *mask) { /* add data to frame */ size_t i; @@ -236,22 +237,35 @@ ws_msg_add(struct ws_msg *m, const char *p, size_t psz, const unsigned char *mas for(i = 0; i < psz && mask; ++i) { m->payload[m->payload_sz + i] = (unsigned char)p[i] ^ mask[i%4]; } - fprintf(stderr, "CONTENTS=[%.*s] (%lu)\n", (int)psz, m->payload, psz); + if (slog_enabled(s, WEBDIS_TRACE)) { + char format[] = "ws_msg_add: %lu bytes, mask_enabled=%c"; + char mask_enabled = mask ? 'Y' : 'N'; + + size_t contents_sz = snprintf(NULL, 0, format, psz, mask_enabled); + char *contents_msg = calloc(contents_sz + 1, 1); + if (contents_msg) { + snprintf(contents_msg, contents_sz + 1, format, psz, mask_enabled); + slog(s, WEBDIS_TRACE, contents_msg, contents_sz); + free(contents_msg); + } else { + slog(s, WEBDIS_ERROR, "Failed allocation in ws_msg_add", 0); + } + } /* save new size */ m->payload_sz += psz; } static void -ws_msg_free(struct ws_msg **m) { - fprintf(stderr, "------------ /FREE -----------\n"); +ws_msg_free(struct server *s, struct ws_msg **m) { + slog(s, WEBDIS_TRACE, "ws_msg_free", 0); free((*m)->payload); free(*m); *m = NULL; } static enum ws_state -ws_parse_data(const char *frame, size_t sz, struct ws_msg **msg) { +ws_parse_data(struct server *s, const char *frame, size_t sz, struct ws_msg **msg) { int has_mask; uint64_t len; @@ -264,15 +278,30 @@ ws_parse_data(const char *frame, size_t sz, struct ws_msg **msg) { } has_mask = frame[1] & 0x80 ? 1:0; - fprintf(stderr, "has_mask=%d\n", has_mask); + if (slog_enabled(s, WEBDIS_TRACE)) { + char log_mask[]= "ws_parse_data: has_mask=?"; + log_mask[sizeof(log_mask)-2] = has_mask ? 'Y' : 'N'; /* -1 for \0 and -1 again for last char */ + slog(s, WEBDIS_TRACE, log_mask, sizeof(log_mask)-1); + } /* get payload length */ len = frame[1] & 0x7f; /* remove leftmost bit */ - fprintf(stderr, "len=%llu\n", len); + + if (slog_enabled(s, WEBDIS_TRACE)) { /* log length */ + char format[] = "ws_parse_data: payload length = %llu bytes"; + size_t contents_sz = snprintf(NULL, 0, format, len); + char *contents_msg = calloc(contents_sz + 1, 1); + if (contents_msg) { + snprintf(contents_msg, contents_sz + 1, format, len); + slog(s, WEBDIS_TRACE, contents_msg, contents_sz); + free(contents_msg); + } else { + slog(s, WEBDIS_ERROR, "Failed allocation in ws_parse_data", 0); + } + } if(len <= 125) { /* data starts right after the mask */ p = frame + 2 + (has_mask ? 4 : 0); if(has_mask) memcpy(&mask, frame + 2, sizeof(mask)); - if (has_mask) fprintf(stderr, "mask= %02x %02x %02x %02x\n", mask[0], mask[1], mask[2], mask[3]); } else if(len == 126) { uint16_t sz16; memcpy(&sz16, frame + 2, sizeof(uint16_t)); @@ -293,15 +322,15 @@ ws_parse_data(const char *frame, size_t sz, struct ws_msg **msg) { } if(!*msg) - *msg = ws_msg_new(); - ws_msg_add(*msg, p, len, has_mask ? mask : NULL); + *msg = ws_msg_new(s); + ws_msg_add(s, *msg, p, len, has_mask ? mask : NULL); (*msg)->total_sz += len + (p - frame); if(frame[0] & 0x80) { /* FIN bit set */ - fprintf(stderr, "FIN bit: SET\n"); + slog(s, WEBDIS_TRACE, "ws_parse_data: FIN bit set", 0); return WS_MSG_COMPLETE; } else { - fprintf(stderr, "FIN bit: NOT SET\n"); + slog(s, WEBDIS_TRACE, "ws_parse_data: FIN bit not set", 0); return WS_READING; /* need more data */ } } @@ -315,32 +344,43 @@ ws_add_data(struct http_client *c) { enum ws_state state; - state = ws_parse_data(c->buffer, c->sz, &c->frame); + state = ws_parse_data(c->s, c->buffer, c->sz, &c->frame); while(state == WS_MSG_COMPLETE) { int ret = ws_execute(c, c->frame->payload, c->frame->payload_sz); - fprintf(stderr, "ws_execute returned %d\n", ret); + if (slog_enabled(c->s, WEBDIS_TRACE)) { + char format[] = "ws_add_data: ws_execute(payload_sz=%lu) returned %d"; + + size_t contents_sz = snprintf(NULL, 0, format, c->frame->payload_sz, ret); + char *contents_msg = calloc(contents_sz + 1, 1); + if (contents_msg) { + snprintf(contents_msg, contents_sz + 1, format, c->frame->payload_sz, ret); + slog(c->s, WEBDIS_TRACE, contents_msg, contents_sz); + free(contents_msg); + } else { + slog(c->s, WEBDIS_ERROR, "Failed allocation in ws_add_data", 0); + } + } /* remove frame from client buffer */ http_client_remove_data(c, c->frame->total_sz); /* free frame and set back to NULL */ - ws_msg_free(&c->frame); + ws_msg_free(c->s, &c->frame); if(ret != 0) { /* can't process frame. */ + slog(c->s, WEBDIS_WARNING, "ws_add_data: ws_execute failed", 0); return WS_ERROR; } - fprintf(stderr, "Calling ws_parse_data again...\n"); - state = ws_parse_data(c->buffer, c->sz, &c->frame); - fprintf(stderr, "ws_parse_data returned %d\n", (int)state); + slog(c->s, WEBDIS_TRACE, "ws_add_data: calling ws_parse_data again", 0); + state = ws_parse_data(c->s, c->buffer, c->sz, &c->frame); } return state; } int ws_reply(struct cmd *cmd, const char *p, size_t sz) { - fprintf(stderr, "ws_reply: '%.*s' (%lu bytes)\n", (int)sz, p, sz); char *frame = malloc(sz + 8); /* create frame by prepending header */ size_t frame_sz = 0; struct http_response *r; @@ -375,7 +415,7 @@ ws_reply(struct cmd *cmd, const char *p, size_t sz) { /* send WS frame */ r = http_response_init(cmd->w, 0, NULL); - if (1 || cmd_is_subscribe(cmd)) { + if (cmd_is_subscribe(cmd)) { r->keep_alive = 1; } @@ -385,6 +425,20 @@ ws_reply(struct cmd *cmd, const char *p, size_t sz) { r->out = frame; r->out_sz = frame_sz; r->sent = 0; + + if (slog_enabled(cmd->w->s, WEBDIS_TRACE)) { + char format[] = "ws_reply: response is %lu bytes, frame is %lu"; + size_t contents_sz = snprintf(NULL, 0, format, sz, frame_sz); + char *contents_msg = calloc(contents_sz + 1, 1); + if (contents_msg) { + snprintf(contents_msg, contents_sz + 1, format, sz, frame_sz); + slog(cmd->w->s, WEBDIS_TRACE, contents_msg, contents_sz); + free(contents_msg); + } else { + slog(cmd->w->s, WEBDIS_ERROR, "Failed allocation in ws_reply", 0); + } + } + http_schedule_write(cmd->fd, r); return 0; diff --git a/src/worker.c b/src/worker.c index 1d5b838..747c5ff 100644 --- a/src/worker.c +++ b/src/worker.c @@ -35,13 +35,13 @@ worker_new(struct server *s) { void worker_can_read(int fd, short event, void *p) { - fprintf(stderr, "worker_can_read\n"); struct http_client *c = p; int ret, nparsed; (void)fd; (void)event; + slog(c->w->s, WEBDIS_TRACE, "worker_can_read", 0); ret = http_client_read(c); if(ret <= 0) { if((client_error_t)ret == CLIENT_DISCONNECTED) { @@ -87,11 +87,11 @@ worker_can_read(int fd, short event, void *p) { } if(c->broken) { /* terminate client */ - fprintf(stderr, "c->broken: http_client_free()\n"); + slog(c->s, WEBDIS_TRACE, "worker_can_read: c->broken, calling http_client_free", 0); http_client_free(c); } else { /* start monitoring input again */ - fprintf(stderr, "worker_monitor_input()\n"); + slog(c->s, WEBDIS_TRACE, "worker_can_read: calling worker_monitor_input again", 0); worker_monitor_input(c); } }