improve logging + HTTP on_finish should always be called for cleanup.

facil-io · Oct 20, 2024 · 3fa871a · 3fa871a
1 parent ced8ee5
commit 3fa871a
Show file tree

Hide file tree

Showing 7 changed files with 141 additions and 55 deletions.
diff --git a/LICENSE b/LICENSE
@@ -1,6 +1,6 @@
 MIT License
 
-Copyright (c) 2019-2023 Boaz Segev
+Copyright (c) 2019-2024 Boaz Segev
 
 Permission is hereby granted, free of charge, to any person obtaining a copy
 of this software and associated documentation files (the "Software"), to deal

diff --git a/fio-stl.h b/fio-stl.h
@@ -33236,7 +33236,7 @@ SFUNC uint16_t fio_srv_workers(int workers) {
     workers = (int)(cores / (0 - workers));
     workers += !workers;
   }
-  return workers;
+  return (uint16_t)workers;
 }
 
 /** Adds `workers` amount of workers to the root server process. */
@@ -37984,7 +37984,7 @@ FIO_SFUNC fio_str_info_s fio_http_date(uint64_t now_in_seconds) {
   static uint64_t date_buf_val;
   if (date_buf_val == now_in_seconds)
     return FIO_STR_INFO2(date_buf, date_len);
-  date_len = fio_time2rfc7231(date_buf, now_in_seconds);
+  date_len = fio_time2log(date_buf, now_in_seconds);
   date_buf[date_len] = 0;
   date_buf_val = now_in_seconds;
   return FIO_STR_INFO2(date_buf, date_len);
@@ -39857,6 +39857,34 @@ SFUNC int fio_http_send_error_response(fio_http_s *h, size_t status) {
 HTTP Logging
 ***************************************************************************** */
 
+SFUNC void fio___http_write_pid(fio_str_info_s *dest) {
+  static int last_pid = 0;
+  static char buf[64];
+  static size_t len = 0;
+#ifdef H___FIO_SERVER___H
+  int pid = fio_srv_pid();
+#else
+  int pid = fio_thread_getpid();
+#endif
+  if (last_pid != pid)
+    goto rewrite;
+copy:
+  if (len)
+    FIO_MEMCPY(dest->buf + dest->len, buf, len);
+  dest->len += len;
+  return;
+rewrite:
+  len = 0;
+  buf[len++] = '[';
+  if (pid > 0) {
+    size_t d = fio_digits10u((uint64_t)pid);
+    fio_ltoa10u(buf + 1, (uint64_t)pid, d);
+    len += d;
+  }
+  buf[len++] = ']';
+  last_pid = pid;
+  goto copy;
+}
 /** Logs an HTTP (response) to STDOUT. */
 SFUNC void fio_http_write_log(fio_http_s *h) {
   FIO_STR_INFO_TMP_VAR(buf, 1023);
@@ -39865,14 +39893,17 @@ SFUNC void fio_http_write_log(fio_http_s *h) {
   time_start = h->received_at;
   time_end = fio_http_get_timestump();
   fio_str_info_s date = fio_http_date(time_end / FIO___HTTP_TIME_DIV);
+  fio___http_write_pid(&buf);
+  buf.buf[buf.len++] = ' ';
   fio_http_from(&buf, h);
-  FIO_MEMCPY(buf.buf + buf.len, " - - [", 6);
-  FIO_MEMCPY(buf.buf + buf.len + 6, date.buf, date.len);
+  FIO_MEMCPY(buf.buf + buf.len, " - - ", 5);
+  FIO_MEMCPY(buf.buf + buf.len + 5, date.buf, date.len);
   buf.len += date.len + 6;
+  buf.buf[buf.len++] = ' ';
+  buf.buf[buf.len++] = '\"';
   fio_string_write2(
       &buf,
       NULL,
-      FIO_STRING_WRITE_STR2((const char *)"] \"", 3),
       FIO_STRING_WRITE_STR_INFO(fio_keystr_info(&h->method)),
       FIO_STRING_WRITE_STR2((const char *)" ", 1),
       FIO_STRING_WRITE_STR_INFO(fio_keystr_info(&h->path)),
@@ -42976,6 +43007,7 @@ FIO_SFUNC void fio___http_controller_http1_send_headers(fio_http_s *h) {
                       FIO_STRING_WRITE_STR2(status.buf, status.len),
                       FIO_STRING_WRITE_STR2("\r\n", 2));
   }
+
   /* write headers */
   fio_http_response_header_each(h, fio_http1___write_header_callback, &buf);
   /* write cookies */
@@ -43395,9 +43427,12 @@ FIO_SFUNC void fio___websocket_on_close(void *udata) {
   fio___http_connection_s *c = (fio___http_connection_s *)udata;
   c->io = NULL;
   fio_bstr_free(c->state.ws.msg);
-  fio_http_status_set(c->h, (size_t)(c->state.ws.code));
-  c->settings->on_close(c->h);
-  fio_http_free(c->h);
+  if (c->h) {
+    fio_http_status_set(c->h, (size_t)(c->state.ws.code));
+    c->settings->on_close(c->h);
+    c->settings->on_finish(c->h);
+    fio_http_free(c->h);
+  }
   fio___http_connection_free(c);
 }
 
@@ -43570,19 +43605,6 @@ SFUNC int fio_http_websocket_write(fio_http_s *h,
 WebSocket Controller
 ***************************************************************************** */
 
-FIO_SFUNC void fio___http_controller_ws_on_finish_task(void *h_, void *ignr_) {
-  fio_http_s *h = (fio_http_s *)h_;
-  fio___http_connection_s *c = (fio___http_connection_s *)fio_http_cdata(h);
-  fio_protocol_set(c->io, NULL); /* make zombie, timeout will clear it. */
-  fio___http_connection_free(c);
-  (void)ignr_;
-}
-
-/** called once a request / response had finished */
-FIO_SFUNC void fio___http_controller_ws_on_finish(fio_http_s *h) {
-  fio_srv_defer(fio___http_controller_ws_on_finish_task, (void *)(h), NULL);
-}
-
 /* Called by the HTTP handle for each body chunk (or to finish a response). */
 FIO_SFUNC void fio___http_controller_ws_write_body(fio_http_s *h,
                                                    fio_http_write_args_s args) {
@@ -43752,9 +43774,12 @@ FIO_SFUNC void fio___sse_on_close(void *udata) {
   fio___http_connection_s *c = (fio___http_connection_s *)udata;
   FIO_LOG_DDEBUG2("(%d) SSE connection closed for %p", fio_srv_pid(), c->io);
   c->io = NULL;
-  c->settings->on_close(c->h);
   fio_bstr_free(c->state.sse.data);
-  fio_http_free(c->h);
+  if (c->h) {
+    c->settings->on_close(c->h);
+    c->settings->on_finish(c->h);
+    fio_http_free(c->h);
+  }
   fio___http_connection_free(c);
 }
 
@@ -43785,6 +43810,26 @@ FIO_SFUNC void fio___http_controller_on_destroyed_task(void *c_, void *ignr_) {
   (void)ignr_;
 }
 
+FIO_SFUNC void fio___http_controller_http1_on_finish_client_task(void *c_,
+                                                                 void *h_) {
+  fio___http_connection_s *c = (fio___http_connection_s *)c_;
+  fio_http_s *h = (fio_http_s *)h_;
+  c->settings->on_finish(h);
+  fio_http_free(h);
+  fio___http_connection_free(c);
+}
+
+FIO_SFUNC void fio___http_controller_http1_on_finish_client(fio_http_s *h) {
+  fio___http_connection_s *c = (fio___http_connection_s *)fio_http_cdata(h);
+  /* on_finish should be called after the `on_close` or after on_http */
+  if (!fio_http_is_upgraded(h)) {
+    /* on_finish always manually called here */
+    fio_srv_defer(fio___http_controller_http1_on_finish_client_task,
+                  (void *)fio___http_connection_dup(c),
+                  (void *)fio_http_dup(h));
+  }
+}
+
 /** Called when an HTTP handle is freed. */
 FIO_SFUNC void fio__http_controller_on_destroyed(fio_http_s *h) {
   if (!(fio_http_is_upgraded(h) | fio_http_is_finished(h))) {
@@ -43900,7 +43945,7 @@ fio___http_controller_get(fio___http_protocol_selector_e s, int is_client) {
     if (is_client) {
       r = (fio_http_controller_s){
           .on_destroyed = fio__http_controller_on_destroyed_client,
-          // .on_finish = fio___http_controller_http1_on_finish_client,
+          .on_finish = fio___http_controller_http1_on_finish_client,
           .close_io = fio___http_default_close,
           .get_fd = fio___http_controller_get_fd,
       };
@@ -43926,7 +43971,6 @@ fio___http_controller_get(fio___http_protocol_selector_e s, int is_client) {
     r = (fio_http_controller_s){
         .on_destroyed = fio__http_controller_on_destroyed2,
         .write_body = fio___http_controller_ws_write_body,
-        .on_finish = fio___http_controller_ws_on_finish,
         .close_io = fio___http_default_close,
         .get_fd = fio___http_controller_get_fd,
     };
@@ -43935,7 +43979,6 @@ fio___http_controller_get(fio___http_protocol_selector_e s, int is_client) {
     r = (fio_http_controller_s){
         .on_destroyed = fio__http_controller_on_destroyed2,
         .write_body = fio___http_controller_sse_write_body,
-        .on_finish = fio___http_controller_ws_on_finish,
         .close_io = fio___http_default_close,
         .get_fd = fio___http_controller_get_fd,
     };

diff --git a/fio-stl.md b/fio-stl.md
@@ -9398,7 +9398,7 @@ The internal Pub/Sub Letter Exchange Protocol imposes the following limitations
 
 * Empty messages (no numerical filters, no channel, no message payload, no flags) are ignored.
 
-* Subscriptions match delivery interests by both channel name (or pattern) and a numerical filter.
+* Subscriptions match delivery matches by both channel name (or pattern) and the numerical filter.
 
 ### Subscriptions - Receiving Messages
 

diff --git a/fio-stl/400 server.h b/fio-stl/400 server.h
@@ -1926,7 +1926,7 @@ SFUNC uint16_t fio_srv_workers(int workers) {
     workers = (int)(cores / (0 - workers));
     workers += !workers;
   }
-  return workers;
+  return (uint16_t)workers;
 }
 
 /** Adds `workers` amount of workers to the root server process. */

diff --git a/fio-stl/420 pubsub.md b/fio-stl/420 pubsub.md
@@ -24,7 +24,7 @@ The internal Pub/Sub Letter Exchange Protocol imposes the following limitations
 
 * Empty messages (no numerical filters, no channel, no message payload, no flags) are ignored.
 
-* Subscriptions match delivery interests by both channel name (or pattern) and a numerical filter.
+* Subscriptions match delivery matches by both channel name (or pattern) and the numerical filter.
 
 ### Subscriptions - Receiving Messages
 

diff --git a/fio-stl/431 http handle.h b/fio-stl/431 http handle.h
@@ -878,7 +878,7 @@ FIO_SFUNC fio_str_info_s fio_http_date(uint64_t now_in_seconds) {
   static uint64_t date_buf_val;
   if (date_buf_val == now_in_seconds)
     return FIO_STR_INFO2(date_buf, date_len);
-  date_len = fio_time2rfc7231(date_buf, now_in_seconds);
+  date_len = fio_time2log(date_buf, now_in_seconds);
   date_buf[date_len] = 0;
   date_buf_val = now_in_seconds;
   return FIO_STR_INFO2(date_buf, date_len);
@@ -2751,6 +2751,34 @@ SFUNC int fio_http_send_error_response(fio_http_s *h, size_t status) {
 HTTP Logging
 ***************************************************************************** */
 
+SFUNC void fio___http_write_pid(fio_str_info_s *dest) {
+  static int last_pid = 0;
+  static char buf[64];
+  static size_t len = 0;
+#ifdef H___FIO_SERVER___H
+  int pid = fio_srv_pid();
+#else
+  int pid = fio_thread_getpid();
+#endif
+  if (last_pid != pid)
+    goto rewrite;
+copy:
+  if (len)
+    FIO_MEMCPY(dest->buf + dest->len, buf, len);
+  dest->len += len;
+  return;
+rewrite:
+  len = 0;
+  buf[len++] = '[';
+  if (pid > 0) {
+    size_t d = fio_digits10u((uint64_t)pid);
+    fio_ltoa10u(buf + 1, (uint64_t)pid, d);
+    len += d;
+  }
+  buf[len++] = ']';
+  last_pid = pid;
+  goto copy;
+}
 /** Logs an HTTP (response) to STDOUT. */
 SFUNC void fio_http_write_log(fio_http_s *h) {
   FIO_STR_INFO_TMP_VAR(buf, 1023);
@@ -2759,14 +2787,17 @@ SFUNC void fio_http_write_log(fio_http_s *h) {
   time_start = h->received_at;
   time_end = fio_http_get_timestump();
   fio_str_info_s date = fio_http_date(time_end / FIO___HTTP_TIME_DIV);
+  fio___http_write_pid(&buf);
+  buf.buf[buf.len++] = ' ';
   fio_http_from(&buf, h);
-  FIO_MEMCPY(buf.buf + buf.len, " - - [", 6);
-  FIO_MEMCPY(buf.buf + buf.len + 6, date.buf, date.len);
+  FIO_MEMCPY(buf.buf + buf.len, " - - ", 5);
+  FIO_MEMCPY(buf.buf + buf.len + 5, date.buf, date.len);
   buf.len += date.len + 6;
+  buf.buf[buf.len++] = ' ';
+  buf.buf[buf.len++] = '\"';
   fio_string_write2(
       &buf,
       NULL,
-      FIO_STRING_WRITE_STR2((const char *)"] \"", 3),
       FIO_STRING_WRITE_STR_INFO(fio_keystr_info(&h->method)),
       FIO_STRING_WRITE_STR2((const char *)" ", 1),
       FIO_STRING_WRITE_STR_INFO(fio_keystr_info(&h->path)),

diff --git a/fio-stl/439 http.h b/fio-stl/439 http.h
@@ -1435,6 +1435,7 @@ FIO_SFUNC void fio___http_controller_http1_send_headers(fio_http_s *h) {
                       FIO_STRING_WRITE_STR2(status.buf, status.len),
                       FIO_STRING_WRITE_STR2("\r\n", 2));
   }
+
   /* write headers */
   fio_http_response_header_each(h, fio_http1___write_header_callback, &buf);
   /* write cookies */
@@ -1854,9 +1855,12 @@ FIO_SFUNC void fio___websocket_on_close(void *udata) {
   fio___http_connection_s *c = (fio___http_connection_s *)udata;
   c->io = NULL;
   fio_bstr_free(c->state.ws.msg);
-  fio_http_status_set(c->h, (size_t)(c->state.ws.code));
-  c->settings->on_close(c->h);
-  fio_http_free(c->h);
+  if (c->h) {
+    fio_http_status_set(c->h, (size_t)(c->state.ws.code));
+    c->settings->on_close(c->h);
+    c->settings->on_finish(c->h);
+    fio_http_free(c->h);
+  }
   fio___http_connection_free(c);
 }
 
@@ -2029,19 +2033,6 @@ SFUNC int fio_http_websocket_write(fio_http_s *h,
 WebSocket Controller
 ***************************************************************************** */
 
-FIO_SFUNC void fio___http_controller_ws_on_finish_task(void *h_, void *ignr_) {
-  fio_http_s *h = (fio_http_s *)h_;
-  fio___http_connection_s *c = (fio___http_connection_s *)fio_http_cdata(h);
-  fio_protocol_set(c->io, NULL); /* make zombie, timeout will clear it. */
-  fio___http_connection_free(c);
-  (void)ignr_;
-}
-
-/** called once a request / response had finished */
-FIO_SFUNC void fio___http_controller_ws_on_finish(fio_http_s *h) {
-  fio_srv_defer(fio___http_controller_ws_on_finish_task, (void *)(h), NULL);
-}
-
 /* Called by the HTTP handle for each body chunk (or to finish a response). */
 FIO_SFUNC void fio___http_controller_ws_write_body(fio_http_s *h,
                                                    fio_http_write_args_s args) {
@@ -2211,9 +2202,12 @@ FIO_SFUNC void fio___sse_on_close(void *udata) {
   fio___http_connection_s *c = (fio___http_connection_s *)udata;
   FIO_LOG_DDEBUG2("(%d) SSE connection closed for %p", fio_srv_pid(), c->io);
   c->io = NULL;
-  c->settings->on_close(c->h);
   fio_bstr_free(c->state.sse.data);
-  fio_http_free(c->h);
+  if (c->h) {
+    c->settings->on_close(c->h);
+    c->settings->on_finish(c->h);
+    fio_http_free(c->h);
+  }
   fio___http_connection_free(c);
 }
 
@@ -2244,6 +2238,26 @@ FIO_SFUNC void fio___http_controller_on_destroyed_task(void *c_, void *ignr_) {
   (void)ignr_;
 }
 
+FIO_SFUNC void fio___http_controller_http1_on_finish_client_task(void *c_,
+                                                                 void *h_) {
+  fio___http_connection_s *c = (fio___http_connection_s *)c_;
+  fio_http_s *h = (fio_http_s *)h_;
+  c->settings->on_finish(h);
+  fio_http_free(h);
+  fio___http_connection_free(c);
+}
+
+FIO_SFUNC void fio___http_controller_http1_on_finish_client(fio_http_s *h) {
+  fio___http_connection_s *c = (fio___http_connection_s *)fio_http_cdata(h);
+  /* on_finish should be called after the `on_close` or after on_http */
+  if (!fio_http_is_upgraded(h)) {
+    /* on_finish always manually called here */
+    fio_srv_defer(fio___http_controller_http1_on_finish_client_task,
+                  (void *)fio___http_connection_dup(c),
+                  (void *)fio_http_dup(h));
+  }
+}
+
 /** Called when an HTTP handle is freed. */
 FIO_SFUNC void fio__http_controller_on_destroyed(fio_http_s *h) {
   if (!(fio_http_is_upgraded(h) | fio_http_is_finished(h))) {
@@ -2359,7 +2373,7 @@ fio___http_controller_get(fio___http_protocol_selector_e s, int is_client) {
     if (is_client) {
       r = (fio_http_controller_s){
           .on_destroyed = fio__http_controller_on_destroyed_client,
-          // .on_finish = fio___http_controller_http1_on_finish_client,
+          .on_finish = fio___http_controller_http1_on_finish_client,
           .close_io = fio___http_default_close,
           .get_fd = fio___http_controller_get_fd,
       };
@@ -2385,7 +2399,6 @@ fio___http_controller_get(fio___http_protocol_selector_e s, int is_client) {
     r = (fio_http_controller_s){
         .on_destroyed = fio__http_controller_on_destroyed2,
         .write_body = fio___http_controller_ws_write_body,
-        .on_finish = fio___http_controller_ws_on_finish,
         .close_io = fio___http_default_close,
         .get_fd = fio___http_controller_get_fd,
     };
@@ -2394,7 +2407,6 @@ fio___http_controller_get(fio___http_protocol_selector_e s, int is_client) {
     r = (fio_http_controller_s){
         .on_destroyed = fio__http_controller_on_destroyed2,
         .write_body = fio___http_controller_sse_write_body,
-        .on_finish = fio___http_controller_ws_on_finish,
         .close_io = fio___http_default_close,
         .get_fd = fio___http_controller_get_fd,
     };