diff -r b036ccad4b49 -r e35829a3a6d8 src/server/daemon/sessionhandler.c --- a/src/server/daemon/sessionhandler.c Sat Aug 24 22:37:12 2024 +0200 +++ b/src/server/daemon/sessionhandler.c Fri Sep 13 23:19:04 2024 +0200 @@ -258,6 +258,8 @@ } void evt_enq_conn(SessionHandler *handler, Connection *conn) { + log_ereport(LOG_DEBUG, "trace reqid: %016llx enqueue connection", (unsigned long long int)conn->id); + Event *start_request = malloc(sizeof(Event)); if(!start_request) { connection_destroy(conn); @@ -273,6 +275,7 @@ EventHttpIO *io = evt_req_init(handler, conn); if(!io) { + log_ereport(LOG_DEBUG, "trace reqid: %016llx connection destroyed | evt_req_init failed", (unsigned long long int)conn->id); connection_destroy(conn); free(start_request); free(event); @@ -299,6 +302,7 @@ start_request->finish = ev_free_event; start_request->error = 0; if(event_send(ev, start_request)) { + log_ereport(LOG_DEBUG, "trace reqid: %016llx connection destroyed | event_send failed", (unsigned long long int)conn->id); log_ereport(LOG_FAILURE, "Cannot start request timeout: event_send failed"); evt_request_error(ev, event); free(start_request); @@ -375,8 +379,11 @@ EventHttpIO *io = event->cookie; Connection *conn = io->request->connection; + log_ereport(LOG_DEBUG, "trace reqid: %016llx ssl accept", (unsigned long long int)conn->id); + int ret = SSL_accept(conn->ssl); if(ret <= 0) { + log_ereport(LOG_DEBUG, "trace reqid: %016llx ssl accept | error", (unsigned long long int)conn->id); int error = SSL_get_error(conn->ssl, ret); char *errstr; switch(error) { @@ -421,21 +428,28 @@ conn, buf->inbuf + buf->pos, buf->maxsize - buf->pos); + + log_ereport(LOG_DEBUG, "trace reqid: %016llx request input | r=%d", (unsigned long long int)conn->id, r); + if(r <= 0) { if(conn->ssl) { // SSL specific error handling switch(conn->ssl_error) { case SSL_ERROR_WANT_READ: { event->events = EVENT_POLLIN; + log_ereport(LOG_DEBUG, "trace reqid: %016llx request input | ssl want read", (unsigned long long int)conn->id); return 1; } case SSL_ERROR_WANT_WRITE: { event->events = EVENT_POLLOUT; + log_ereport(LOG_DEBUG, "trace reqid: %016llx request input | ssl want write", (unsigned long long int)conn->id); return 1; } } } + log_ereport(LOG_DEBUG, "trace reqid: %016llx request input | error", (unsigned long long int)conn->id); + event->finish = evt_request_error; io->error = 1; return 0; @@ -446,6 +460,8 @@ buf->cursize += r; state = http_parser_process(parser); if(state == 2) { + log_ereport(LOG_DEBUG, "trace reqid: %016llx request input | http parser error", (unsigned long long int)conn->id); + // parse error fatal_error(request, 400); log_ereport(LOG_VERBOSE, "http parser: bad request"); @@ -459,6 +475,7 @@ * we need more data -> return 1 to tell the event handler to * continue polling */ + log_ereport(LOG_DEBUG, "trace reqid: %016llx request input | event_pollin", (unsigned long long int)conn->id); event->events = EVENT_POLLIN; return 1; } @@ -472,12 +489,14 @@ } if (fcntl(request->connection->fd, F_SETFL, flags & ~O_NONBLOCK) != 0) { // just close the connection if fcntl fails + log_ereport(LOG_DEBUG, "trace reqid: %016llx request input | fcntl error", (unsigned long long int)conn->id); event->finish = evt_request_error; io->error = 3; return 0; } if(!http_parser_validate(parser)) { + log_ereport(LOG_DEBUG, "trace reqid: %016llx request input | http parser validate error", (unsigned long long int)conn->id); log_ereport(LOG_FAILURE, "http_parser_validate failed"); fatal_error(request, 400); event->finish = evt_request_error; @@ -498,6 +517,8 @@ HttpParser *parser = io->parser; HTTPRequest *request = io->request; + log_ereport(LOG_DEBUG, "trace reqid: %016llx request finish", (unsigned long long int)request->connection->id); + // remove timeout if(io->watch.intdata) { ev_watchlist_remove(h, &io->watch); @@ -505,6 +526,7 @@ int r = handle_request(request, NULL, h); if(r != 0) { + log_ereport(LOG_DEBUG, "trace reqid: %016llx request finish | handle_request failed", (unsigned long long int)request->connection->id); connection_destroy(request->connection); free(request->netbuf->inbuf); free(request->netbuf); @@ -554,6 +576,9 @@ } void evt_keep_alive(SessionHandler *handler, Connection *conn) { + log_ereport(LOG_DEBUG, "trace reqid: %016llx keep alive", (unsigned long long int)conn->id); + + conn->id++; Event *event = malloc(sizeof(Event)); if(!event) { connection_destroy(conn); @@ -567,6 +592,7 @@ EventHandler *ev = ev_instance(((EventSessionHandler*)handler)->eventhandler); if(event_send(ev, event)) { + log_ereport(LOG_DEBUG, "trace reqid: %016llx connection destroyed | keep_alive event error", (unsigned long long int)conn->id); log_ereport(LOG_FAILURE, "Keep-Alive: ev_send failed"); connection_destroy(conn); free(event); @@ -605,6 +631,7 @@ ioevent->finish = ev_free_event; ioevent->cookie = keepalive; if(ev_pollin(h, conn->fd, ioevent) != 0) { + log_ereport(LOG_DEBUG, "trace reqid: %016llx connection destroyed | keep_alive_enqueue", (unsigned long long int)conn->id); log_ereport(LOG_FAILURE, "Cannot enqueue connection"); ev_watchlist_remove(h, keepalive); connection_destroy(conn); @@ -626,6 +653,7 @@ // prepare http io EventHttpIO *io = evt_req_init(conn->session_handler, conn); if(!io) { + log_ereport(LOG_DEBUG, "trace reqid: %016llx connection destroyed | keep alive input", (unsigned long long int)conn->id); connection_destroy(conn); return 0; } @@ -647,6 +675,7 @@ log_ereport(LOG_FAILURE, "sessionhandler: keep-alive timeout: cannot remove poll"); } + log_ereport(LOG_DEBUG, "trace reqid: %016llx connection destroyed | keep_alive timeout", (unsigned long long int)conn->id); connection_destroy(conn); free(ioevent); free(item);