[njs] Modules: improved debug log.

[Dmitry Volyntsev]

details:   https://hg.nginx.org/njs/rev/1ac5ae749ae1
branches:  
changeset: 2197:1ac5ae749ae1
user:      Dmitry Volyntsev <xeioex at nginx.com>
date:      Fri Sep 08 17:13:19 2023 -0700
description:
Modules: improved debug log.

1) Ensuring that consistent prefixes are used:
"http js" in HTTP module and "stream js" in Stream module.
2) Added debug for every event/callback handler entrance.
3) Added debug with a method name for every JS call.

diffstat:

 nginx/ngx_http_js_module.c   |  12 ++++++++++++
 nginx/ngx_stream_js_module.c |  16 +++++++++++-----
 2 files changed, 23 insertions(+), 5 deletions(-)

diffs (97 lines):

diff -r 947f3b18dde4 -r 1ac5ae749ae1 nginx/ngx_http_js_module.c
--- a/nginx/ngx_http_js_module.c	Fri Sep 08 17:52:07 2023 -0700
+++ b/nginx/ngx_http_js_module.c	Fri Sep 08 17:13:19 2023 -0700
@@ -1075,6 +1075,9 @@ ngx_http_js_header_filter(ngx_http_reque
         return ngx_http_next_header_filter(r);
     }
 
+    ngx_log_debug0(NGX_LOG_DEBUG_HTTP, r->connection->log, 0,
+                   "http js header filter");
+
     rc = ngx_http_js_init_vm(r, ngx_http_js_request_proto_id);
 
     if (rc == NGX_ERROR || rc == NGX_DECLINED) {
@@ -1086,6 +1089,9 @@ ngx_http_js_header_filter(ngx_http_reque
     ctx->filter = 1;
     pending = njs_vm_pending(ctx->vm);
 
+    ngx_log_debug1(NGX_LOG_DEBUG_HTTP, r->connection->log, 0,
+                   "http js header call \"%V\"", &jlcf->header_filter);
+
     rc = ngx_js_call(ctx->vm, &jlcf->header_filter, r->connection->log,
                      &ctx->request, 1);
 
@@ -1127,6 +1133,9 @@ ngx_http_js_body_filter(ngx_http_request
         return ngx_http_next_body_filter(r, in);
     }
 
+    ngx_log_debug0(NGX_LOG_DEBUG_HTTP, r->connection->log, 0,
+                   "http js body filter");
+
     rc = ngx_http_js_init_vm(r, ngx_http_js_request_proto_id);
 
     if (rc == NGX_ERROR || rc == NGX_DECLINED) {
@@ -1183,6 +1192,9 @@ ngx_http_js_body_filter(ngx_http_request
 
             pending = njs_vm_pending(ctx->vm);
 
+            ngx_log_debug1(NGX_LOG_DEBUG_HTTP, c->log, 0,
+                           "http js body call \"%V\"", &jlcf->body_filter);
+
             rc = ngx_js_call(ctx->vm, &jlcf->body_filter, c->log, &arguments[0],
                              3);
 
diff -r 947f3b18dde4 -r 1ac5ae749ae1 nginx/ngx_stream_js_module.c
--- a/nginx/ngx_stream_js_module.c	Fri Sep 08 17:52:07 2023 -0700
+++ b/nginx/ngx_stream_js_module.c	Fri Sep 08 17:13:19 2023 -0700
@@ -722,6 +722,9 @@ ngx_stream_js_phase_handler(ngx_stream_s
         return NGX_DECLINED;
     }
 
+    ngx_log_debug0(NGX_LOG_DEBUG_STREAM, s->connection->log, 0,
+                   "stream js phase handler");
+
     rc = ngx_stream_js_init_vm(s, ngx_stream_js_session_proto_id);
     if (rc != NGX_OK) {
         return rc;
@@ -729,9 +732,6 @@ ngx_stream_js_phase_handler(ngx_stream_s
 
     c = s->connection;
 
-    ngx_log_debug1(NGX_LOG_DEBUG_STREAM, c->log, 0,
-                   "stream js phase call \"%V\"", name);
-
     ctx = ngx_stream_get_module_ctx(s, ngx_stream_js_module);
 
     if (!ctx->in_progress) {
@@ -742,6 +742,9 @@ ngx_stream_js_phase_handler(ngx_stream_s
 
         ctx->status = NGX_ERROR;
 
+        ngx_log_debug1(NGX_LOG_DEBUG_STREAM, c->log, 0,
+                       "stream js phase call \"%V\"", name);
+
         rc = ngx_js_call(ctx->vm, name, c->log, &ctx->args[0], 1);
 
         if (rc == NGX_ERROR) {
@@ -816,6 +819,9 @@ ngx_stream_js_body_filter(ngx_stream_ses
     ctx = ngx_stream_get_module_ctx(s, ngx_stream_js_module);
 
     if (!ctx->filter) {
+        ngx_log_debug1(NGX_LOG_DEBUG_STREAM, c->log, 0,
+                       "stream js filter call \"%V\"" , &jscf->filter);
+
         rc = ngx_js_call(ctx->vm, &jscf->filter, c->log, &ctx->args[0], 1);
 
         if (rc == NGX_ERROR) {
@@ -1899,8 +1905,8 @@ ngx_stream_js_periodic_handler(ngx_event
 
     if (c != NULL) {
         ngx_log_error(NGX_LOG_ERR, c->log, 0,
-                      "js periodic \"%V\" is already running, killing previous "
-                      "instance", &periodic->method);
+                      "stream js periodic \"%V\" is already running, killing "
+                      "previous instance", &periodic->method);
 
         ngx_stream_js_periodic_finalize(c->data, NGX_ERROR);
     }