# HG changeset patch
# User Olaf Wintermann <olaf.wintermann@gmail.com>
# Date 1726262344 -7200
# Node ID e35829a3a6d85720a33565d728f9319706389123
# Parent  b036ccad4b49f0fe5fa656bd4d8e4c78d8d00999
add sessionhandler debug logging

diff -r b036ccad4b49 -r e35829a3a6d8 src/server/daemon/httplistener.c
--- a/src/server/daemon/httplistener.c	Sat Aug 24 22:37:12 2024 +0200
+++ b/src/server/daemon/httplistener.c	Fri Sep 13 23:19:04 2024 +0200
@@ -47,6 +47,7 @@
 #include <stdio.h>
 #include <stdlib.h>
 
+#include <openssl/rand.h> /* RAND_bytes, connection id */
 
 #include <cx/hash_map.h>
 
@@ -652,12 +653,16 @@
         
         // create Connection object
         Connection *conn = malloc(sizeof(Connection));
+        uint32_t conn_id;
+        RAND_bytes((unsigned char*)&conn->id, sizeof(conn->id));
+        conn->id <<= 16;
         conn->address = ca;
         conn->addr_type = addr_type;
         conn->fd = clientfd;
         conn->listener = ls;
         conn->ssl_accepted = 0;
         conn->ssl_error = 0;
+        log_ereport(LOG_DEBUG, "trace reqid: %016llx connection accepted", (unsigned long long int)conn->id);
         if(socket_ssl) {
             // SSL connections are always non-blocking 
             // set socket non blocking
@@ -666,6 +671,7 @@
                 flags = 0;
             }
             if(fcntl(conn->fd, F_SETFL, flags | O_NONBLOCK)) {
+                log_ereport(LOG_DEBUG, "trace reqid: %016llx connection destroyed | fcntl error", (unsigned long long int)conn->id);
                 log_ereport(LOG_FAILURE, "acceptor: fcntl failed: %s", strerror(errno));
                 close(clientfd);
                 free(conn);
@@ -680,6 +686,7 @@
                     conn->write = connection_ssl_write;
                     conn->close = connection_ssl_close;
                 } else {
+                    log_ereport(LOG_DEBUG, "trace reqid: %016llx connection destroyed | SSL init error", (unsigned long long int)conn->id);
                     log_ereport(LOG_FAILURE, "acceptor: %p listener: %p SSL_new() failed", acceptor, acceptor->listener);
                     free(conn);
                     close(clientfd);
diff -r b036ccad4b49 -r e35829a3a6d8 src/server/daemon/httprequest.c
--- a/src/server/daemon/httprequest.c	Sat Aug 24 22:37:12 2024 +0200
+++ b/src/server/daemon/httprequest.c	Fri Sep 13 23:19:04 2024 +0200
@@ -146,6 +146,8 @@
 }
 
 int nsapi_start_request(HTTPRequest *request, threadpool_t *thrpool, EventHandler *ev, pool_handle_t *pool) {
+    log_ereport(LOG_DEBUG, "trace reqid: %016llx nsapi_start_request", (unsigned long long int)request->connection->id);
+    
     // create nsapi data structures
     NSAPISession *sn = nsapisession_create(pool);
     if(sn == NULL) {
@@ -514,6 +516,8 @@
  */
 
 int nsapi_handle_request(NSAPISession *sn, NSAPIRequest *rq) {
+    log_ereport(LOG_DEBUG, "trace reqid: %016llx nsapi_handle_request", (unsigned long long int)sn->connection->id);
+    
     int r = REQ_NOACTION;
     do {
         switch(rq->phase) {
@@ -617,6 +621,8 @@
     rq->finished = TRUE;
     request_free_resources(sn, rq);
     
+    log_ereport(LOG_DEBUG, "trace reqid: %016llx nsapi_finish_request", (unsigned long long int)sn->connection->id);
+    
     WSBool read_stream_eof = httpstream_eof(sn->sn.csd);
     if(!read_stream_eof) {
         log_ereport(LOG_WARN, "request input stream not closed");
@@ -661,6 +667,7 @@
          * unref it
          */
     } else {
+        log_ereport(LOG_DEBUG, "trace reqid: %016llx connection destroyed | keep_alive failed", (unsigned long long int)sn->connection->id);
         connection_destroy(sn->connection);
     }
     
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);
diff -r b036ccad4b49 -r e35829a3a6d8 src/server/daemon/sessionhandler.h
--- a/src/server/daemon/sessionhandler.h	Sat Aug 24 22:37:12 2024 +0200
+++ b/src/server/daemon/sessionhandler.h	Fri Sep 13 23:19:04 2024 +0200
@@ -60,6 +60,7 @@
 typedef enum ConnectionAddrType ConnectionAddrType;
 
 struct _connection {
+    uint64_t             id;
     int                  fd;
     ConnectionAddr       address;
     ConnectionAddrType   addr_type;