From: Mike Stepanek (mstepane) <mstepane@cisco.com>
Date: Tue, 7 Sep 2021 15:52:14 +0000 (+0000)
Subject: Merge pull request #3039 in SNORT/snort3 from ~OSHUMEIK/snort3:js_trace to master
X-Git-Tag: 3.1.12.0~2
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=15531511f135134a3be33d33e34acca8e5b70250;p=thirdparty%2Fsnort3.git

Merge pull request #3039 in SNORT/snort3 from ~OSHUMEIK/snort3:js_trace to master

Squashed commit of the following:

commit e3a3e9bdb3fe9939334474775fc323bf38280fad
Author: Oleksii Shumeiko <oshumeik@cisco.com>
Date:   Fri Aug 20 18:07:16 2021 +0300

    http_inspect: enable traces for JS Normalizer

    This presents Trace framework to NHI.
    Dev/User documentation updated with config option description and
    trace verbosity levels.
---

diff --git a/doc/user/http_inspect.txt b/doc/user/http_inspect.txt
index 3f08584de..53a913b8a 100755
--- a/doc/user/http_inspect.txt
+++ b/doc/user/http_inspect.txt
@@ -335,6 +335,35 @@ server. Due to this potential evasion tactic, the HTTP inspector will not cut ov
 it sees any early client-to-server traffic, but will continue normal HTTP processing of the flow
 regardless of the eventual server response.
 
+==== Trace messages
+
+When a user needs help to sort out things going on inside HTTP inspector, Trace module becomes handy.
+
+    $ snort --help-module trace | grep http_inspect
+
+Messages for the enhanced JavaScript Normalizer follow
+(more verbosity available in debug build):
+
+===== trace.module.http_inspect.js_proc
+
+Messages from script processing flow and their verbosity levels:
+
+1. Script opening tag location.
+
+2. Attributes of the detected script.
+
+3. Return codes from Normalizer.
+
+===== trace.module.http_inspect.js_dump
+
+Script data dump and verbosity levels:
+
+1. script_data buffer as it is passed to detection.
+
+2. Current script in normalized form.
+
+3. Current script as it is passed to Normalizer.
+
 ==== Detection rules
 
 http_inspect parses HTTP messages into their components and makes them
diff --git a/src/service_inspectors/http_inspect/dev_notes.txt b/src/service_inspectors/http_inspect/dev_notes.txt
index 305ab6dd6..f19f0a0d4 100755
--- a/src/service_inspectors/http_inspect/dev_notes.txt
+++ b/src/service_inspectors/http_inspect/dev_notes.txt
@@ -251,9 +251,6 @@ though the already-processed data remains in the output buffer.
 Enhanced Normalizer supports scripts over multiple PDUs.
 So, if the script is not ended, Normalizer's context is saved in HttpFlowData.
 The script continuation will be processed with the saved context.
-This has some limitations, like:
- * split in the middle of the identifier will result in two identifiers in the output
- * "<script" or "</script>" sequences split over two PDU will not be detected
 
 In order to support Script Detection feature for inline scripts, Normalizer ensures
 that after reaching the script end (legitimate closing tag or bad token),
@@ -416,3 +413,27 @@ developer to get it right.
 The test tool is designed for single-threaded operation only.
 
 The test tool is only available when compiled with REG_TEST.
+
+NHI has some trace messages available. Trace options follow:
+
+* trace.module.http_inspect.js_proc turns on messages from script processing flow.
++
+Verbosity levels:
++
+1. Script opening tag detected (available in release build)
+2. Attributes of detected script (available in release build)
+3. Normalizer return code (available in release build)
+4. Contexts management (debug build only)
+5. Parser states (debug build only)
+6. Input stream states (debug build only)
+
+* trace.module.http_inspect.js_dump dumps script data from processing layers.
++
+Verbosity levels:
++
+1. script_data buffer as it is being passed to detection (available in release build)
+2. Current normalized script (available in release build)
+3. Payload passed to Normalizer (available in release build)
+4. Temporary buffer (debug build only)
+5. Matched token (debug build only)
+6. Identifier substitution (debug build only)
diff --git a/src/service_inspectors/http_inspect/http_enum.h b/src/service_inspectors/http_inspect/http_enum.h
index 5dd0af5c6..043cc23e2 100755
--- a/src/service_inspectors/http_inspect/http_enum.h
+++ b/src/service_inspectors/http_inspect/http_enum.h
@@ -22,6 +22,12 @@
 
 #include <cstdint>
 
+enum
+{
+    TRACE_JS_PROC = 0,
+    TRACE_JS_DUMP
+};
+
 namespace HttpEnums
 {
 static const int MAX_OCTETS = 63780;
diff --git a/src/service_inspectors/http_inspect/http_flow_data.cc b/src/service_inspectors/http_inspect/http_flow_data.cc
index 7778a0155..977d79675 100644
--- a/src/service_inspectors/http_inspect/http_flow_data.cc
+++ b/src/service_inspectors/http_inspect/http_flow_data.cc
@@ -24,6 +24,7 @@
 #include "http_flow_data.h"
 
 #include "decompress/file_decomp.h"
+#include "main/snort_debug.h"
 #include "service_inspectors/http2_inspect/http2_flow_data.h"
 #include "utils/js_identifier_ctx.h"
 #include "utils/js_normalizer.h"
@@ -96,11 +97,17 @@ HttpFlowData::~HttpFlowData()
     {
         update_deallocations(js_ident_ctx->size());
         delete js_ident_ctx;
+
+        debug_log(4, http_trace, TRACE_JS_PROC, nullptr,
+            "js_ident_ctx deleted\n");
     }
     if (js_normalizer)
     {
         update_deallocations(JSNormalizer::size());
         delete js_normalizer;
+
+        debug_log(4, http_trace, TRACE_JS_PROC, nullptr,
+            "js_normalizer deleted\n");
     }
 #endif
 
@@ -240,7 +247,11 @@ void HttpFlowData::garbage_collect()
 void HttpFlowData::reset_js_ident_ctx()
 {
     if (js_ident_ctx)
+    {
         js_ident_ctx->reset();
+        debug_log(4, http_trace, TRACE_JS_PROC, nullptr,
+            "js_ident_ctx reset\n");
+    }
 }
 
 snort::JSNormalizer& HttpFlowData::acquire_js_ctx(int32_t ident_depth, size_t norm_depth,
@@ -253,11 +264,18 @@ snort::JSNormalizer& HttpFlowData::acquire_js_ctx(int32_t ident_depth, size_t no
     {
         js_ident_ctx = new JSIdentifierCtx(ident_depth);
         update_allocations(js_ident_ctx->size());
+
+        debug_logf(4, http_trace, TRACE_JS_PROC, nullptr,
+            "js_ident_ctx created (ident_depth %d)\n", ident_depth);
     }
 
     js_normalizer = new JSNormalizer(*js_ident_ctx, norm_depth, max_template_nesting);
     update_allocations(JSNormalizer::size());
 
+    debug_logf(4, http_trace, TRACE_JS_PROC, nullptr,
+        "js_normalizer created (norm_depth %zd, max_template_nesting %d)\n",
+        norm_depth, max_template_nesting);
+
     return *js_normalizer;
 }
 
@@ -269,6 +287,9 @@ void HttpFlowData::release_js_ctx()
     update_deallocations(JSNormalizer::size());
     delete js_normalizer;
     js_normalizer = nullptr;
+
+    debug_log(4, http_trace, TRACE_JS_PROC, nullptr,
+        "js_normalizer deleted\n");
 }
 #else
 void HttpFlowData::reset_js_ident_ctx() {}
diff --git a/src/service_inspectors/http_inspect/http_js_norm.cc b/src/service_inspectors/http_inspect/http_js_norm.cc
index e371d5f41..3b110bdfa 100644
--- a/src/service_inspectors/http_inspect/http_js_norm.cc
+++ b/src/service_inspectors/http_inspect/http_js_norm.cc
@@ -23,6 +23,7 @@
 
 #include "http_js_norm.h"
 
+#include "main/snort_debug.h"
 #include "utils/js_normalizer.h"
 #include "utils/safec.h"
 #include "utils/util_jsnorm.h"
@@ -33,19 +34,48 @@
 using namespace HttpEnums;
 using namespace snort;
 
+static const char* jsret_codes[] =
+{
+    "end of stream",
+    "script ended",
+    "script continues",
+    "opening tag",
+    "closing tag",
+    "bad token",
+    "identifier overflow",
+    "template nesting overflow",
+    "unknown"
+};
+
+static const char* ret2str(JSTokenizer::JSRet ret)
+{
+    ret = ret < JSTokenizer::JSRet::MAX ? ret : JSTokenizer::JSRet::MAX;
+    return jsret_codes[ret];
+}
+
 static inline JSTokenizer::JSRet js_normalize(JSNormalizer& ctx, const char* const end,
     const char* dst_end, const char*& ptr, char*& dst)
 {
+    trace_logf(3, http_trace, TRACE_JS_DUMP, nullptr,
+        "original[%zu]: %.*s\n", end - ptr, static_cast<int>(end - ptr), ptr);
+
     auto ret = ctx.normalize(ptr, end - ptr, dst, dst_end - dst);
-    auto next = ctx.get_src_next();
+    auto src_next = ctx.get_src_next();
+    auto dst_next = ctx.get_dst_next();
 
-    if (next > ptr)
-        HttpModule::increment_peg_counts(PEG_JS_BYTES, next - ptr);
+    trace_logf(3, http_trace, TRACE_JS_PROC, nullptr,
+        "normalizer returned with %d '%s'\n", ret, ret2str(ret));
+
+    trace_logf(2, http_trace, TRACE_JS_DUMP, nullptr,
+        "normalized[%zu]: %.*s\n", dst_next - dst, static_cast<int>(dst_next - dst), dst);
+
+    if (src_next > ptr)
+        HttpModule::increment_peg_counts(PEG_JS_BYTES, src_next - ptr);
     else
-        next = end; // Normalizer has failed, thus aborting the remaining input
+        src_next = end; // Normalizer has failed, thus aborting the remaining input
 
-    ptr = next;
-    dst = ctx.get_dst_next();
+    ptr = src_next;
+    dst = dst_next;
 
     return ret;
 }
@@ -123,6 +153,12 @@ void HttpJsNorm::enhanced_external_normalize(const Field& input, Field& output,
 
     while (ptr < end)
     {
+        trace_logf(1, http_trace, TRACE_JS_PROC, nullptr,
+            "external script at %zd offset\n", ptr - (const char*)input.start());
+
+        trace_logf(2, http_trace, TRACE_JS_PROC, nullptr,
+            "script %s\n", alive_ctx(ssn) ? "continues" : "starts");
+
         if (!buffer)
         {
             auto len = end - ptr; // not more than the remaining raw data
@@ -176,7 +212,12 @@ void HttpJsNorm::enhanced_external_normalize(const Field& input, Field& output,
     }
 
     if (buffer)
+    {
         output.set(dst - buffer, (const uint8_t*)buffer, true);
+
+        trace_logf(1, http_trace, TRACE_JS_DUMP, nullptr,
+            "script_data[%zu]: %.*s\n", dst - buffer, static_cast<int>(dst - buffer), buffer);
+    }
 }
 
 void HttpJsNorm::enhanced_inline_normalize(const Field& input, Field& output,
@@ -214,6 +255,15 @@ void HttpJsNorm::enhanced_inline_normalize(const Field& input, Field& output,
                 ptr = sctx.next;
             }
 
+            trace_logf(1, http_trace, TRACE_JS_PROC, nullptr,
+                "opening tag at %zd offset\n", ptr - (const char*)input.start());
+
+            trace_logf(2, http_trace, TRACE_JS_PROC, nullptr,
+                "script attributes [%s, %s, %s]\n",
+                sctx.is_shortened ? "shortened form" : "full form",
+                sctx.is_javascript ? "JavaScript type" : "unknown type",
+                sctx.is_external ? "external source" : "inline");
+
             if (sctx.is_shortened)
             {
                 *infractions += INF_JS_SHORTENED_TAG;
@@ -303,7 +353,12 @@ void HttpJsNorm::enhanced_inline_normalize(const Field& input, Field& output,
         ssn->release_js_ctx();
 
     if (buffer)
+    {
         output.set(dst - buffer, (const uint8_t*)buffer, true);
+
+        trace_logf(1, http_trace, TRACE_JS_DUMP, nullptr,
+            "script_data[%zu]: %.*s\n", dst - buffer, static_cast<int>(dst - buffer), buffer);
+    }
 }
 
 void HttpJsNorm::legacy_normalize(const Field& input, Field& output, HttpInfractions* infractions,
diff --git a/src/service_inspectors/http_inspect/http_module.cc b/src/service_inspectors/http_inspect/http_module.cc
index 69ec5f1fa..b090fbf64 100755
--- a/src/service_inspectors/http_inspect/http_module.cc
+++ b/src/service_inspectors/http_inspect/http_module.cc
@@ -24,6 +24,7 @@
 #include "http_module.h"
 
 #include "log/messages.h"
+#include "trace/trace.h"
 
 #include "http_enum.h"
 #include "http_js_norm.h"
@@ -173,6 +174,25 @@ ProfileStats* HttpModule::get_profile() const
 
 THREAD_LOCAL PegCount HttpModule::peg_counts[PEG_COUNT_MAX] = { };
 
+THREAD_LOCAL const Trace* http_trace = nullptr;
+
+static const TraceOption http_trace_options[] =
+{
+    { "js_proc",  TRACE_JS_PROC,  "enable JavaScript processing logging" },
+    { "js_dump",  TRACE_JS_DUMP,  "enable JavaScript data logging" },
+    { nullptr, 0, nullptr }
+};
+
+void HttpModule::set_trace(const Trace* trace) const
+{
+    http_trace = trace;
+}
+
+const TraceOption* HttpModule::get_trace_options() const
+{
+    return http_trace_options;
+}
+
 bool HttpModule::begin(const char*, int, SnortConfig*)
 {
     delete params;
diff --git a/src/service_inspectors/http_inspect/http_module.h b/src/service_inspectors/http_inspect/http_module.h
index 3ec9dd4b1..ac27843dc 100755
--- a/src/service_inspectors/http_inspect/http_module.h
+++ b/src/service_inspectors/http_inspect/http_module.h
@@ -33,6 +33,14 @@
 #define HTTP_NAME "http_inspect"
 #define HTTP_HELP "HTTP inspector"
 
+namespace snort
+{
+class Trace;
+struct SnortConfig;
+}
+
+extern THREAD_LOCAL const snort::Trace* http_trace;
+
 struct HttpParaList
 {
 public:
@@ -172,6 +180,9 @@ public:
     bool is_bindable() const override
     { return true; }
 
+    void set_trace(const snort::Trace*) const override;
+    const snort::TraceOption* get_trace_options() const override;
+
 #ifdef REG_TEST
     static const PegInfo* get_peg_names() { return peg_names; }
     static const PegCount* get_peg_counts() { return peg_counts; }
diff --git a/src/utils/js_normalizer.cc b/src/utils/js_normalizer.cc
index 9e6067782..38ccf0ef5 100644
--- a/src/utils/js_normalizer.cc
+++ b/src/utils/js_normalizer.cc
@@ -52,6 +52,9 @@ JSTokenizer::JSRet JSNormalizer::normalize(const char* src, size_t src_len, char
 {
     if (rem_bytes == 0 && !unlim)
     {
+        debug_log(5, http_trace, TRACE_JS_PROC, nullptr,
+            "depth limit reached\n");
+
         src_next = src + src_len;
         dst_next = dst;
         return JSTokenizer::EOS;
@@ -60,6 +63,9 @@ JSTokenizer::JSRet JSNormalizer::normalize(const char* src, size_t src_len, char
     size_t len = unlim ? src_len :
         src_len < rem_bytes ? src_len : rem_bytes;
 
+    debug_logf(4, http_trace, TRACE_JS_DUMP, nullptr,
+        "tmp buffer[%zu]: %.*s\n", tmp_buf_size, static_cast<int>(tmp_buf_size), tmp_buf);
+
     in_buf.pubsetbuf(tmp_buf, tmp_buf_size, const_cast<char*>(src), len);
     out_buf.pubsetbuf(dst, dst_len);
 
diff --git a/src/utils/js_normalizer.h b/src/utils/js_normalizer.h
index f0dd58969..9bbbeb8a5 100644
--- a/src/utils/js_normalizer.h
+++ b/src/utils/js_normalizer.h
@@ -73,6 +73,10 @@ protected:
 
         if (current_src_len + off < 0 and once)
         {
+            debug_logf(6, http_trace, TRACE_JS_PROC, nullptr,
+                "seek offset %ld, %p:%zu => %p:%zu\n",
+                off, src2, len2, src1, len1);
+
             off += current_src_len;
             once = false;
             setbuf(src1, len1);
@@ -85,7 +89,15 @@ protected:
     virtual int underflow() override
     {
         if (once)
+        {
+            debug_log(6, http_trace, TRACE_JS_PROC, nullptr,
+                "underflow, no buffer to switch to\n");
             return EOF;
+        }
+
+        debug_logf(6, http_trace, TRACE_JS_PROC, nullptr,
+            "underflow, %p:%zu => %p:%zu\n",
+            src1, len1, src2, len2);
 
         once = true;
         setbuf(src2, len2);
diff --git a/src/utils/js_tokenizer.h b/src/utils/js_tokenizer.h
index c6c3bc1f0..d7f73d054 100644
--- a/src/utils/js_tokenizer.h
+++ b/src/utils/js_tokenizer.h
@@ -25,6 +25,10 @@
 #include <vector>
 
 #include "log/messages.h"
+#include "main/snort_debug.h"
+#include "service_inspectors/http_inspect/http_enum.h"
+
+extern THREAD_LOCAL const snort::Trace* http_trace;
 
 // The longest pattern has 9 characters " < / s c r i p t > ",
 // 8 of them can reside in 1st chunk
@@ -61,7 +65,8 @@ public:
         CLOSING_TAG,
         BAD_TOKEN,
         IDENTIFIER_OVERFLOW,
-        TEMPLATE_NESTING_OVERFLOW
+        TEMPLATE_NESTING_OVERFLOW,
+        MAX
     };
 
     JSTokenizer(std::istream& in, std::ostream& out, JSIdentifierCtxBase& ident_ctx,
diff --git a/src/utils/js_tokenizer.l b/src/utils/js_tokenizer.l
index d2cb3e04c..ea8a350d5 100644
--- a/src/utils/js_tokenizer.l
+++ b/src/utils/js_tokenizer.l
@@ -37,7 +37,17 @@
 #include "utils/js_identifier_ctx.h"
 #include "utils/util_cstring.h"
 
-#define YY_USER_ACTION { states_push(); }
+#define YY_USER_ACTION                                      \
+    {                                                       \
+        debug_logf(5, http_trace, TRACE_JS_PROC, nullptr,   \
+            "pattern #%d, sc %d\n", yy_act, YY_START);      \
+                                                            \
+        debug_logf(5, http_trace, TRACE_JS_DUMP, nullptr,   \
+            "text '%s'\n", YYText());                       \
+                                                            \
+        states_push();                                      \
+    }
+
 #define EXEC(f) { auto r = (f); if (r) { BEGIN(regst); return r; } }
 #define EEOF(f) { auto r = (f); if (r) { if (r != SCRIPT_CONTINUE) BEGIN(regst); return r; } }
 %}
@@ -1208,10 +1218,16 @@ JSTokenizer::JSRet JSTokenizer::do_identifier_substitution(const char* lexeme)
 
     if (ident)
     {
+        debug_logf(6, http_trace, TRACE_JS_DUMP, nullptr,
+            "'%s' => '%s'\n", lexeme, ident);
+
         yyout << ident;
         return EOS;
     }
 
+    debug_logf(6, http_trace, TRACE_JS_DUMP, nullptr,
+        "'%s' => IDENTIFIER_OVERFLOW\n", lexeme);
+
     return IDENTIFIER_OVERFLOW;
 }
 
diff --git a/src/utils/test/js_normalizer_test.cc b/src/utils/test/js_normalizer_test.cc
index 00cfa6b16..65322a88f 100644
--- a/src/utils/test/js_normalizer_test.cc
+++ b/src/utils/test/js_normalizer_test.cc
@@ -28,13 +28,19 @@
 #include "utils/js_identifier_ctx.h"
 #include "utils/js_normalizer.h"
 
+// Mock functions
+
 namespace snort
 {
-// Mock for JSTokenizer
 [[noreturn]] void FatalError(const char*, ...)
 { exit(EXIT_FAILURE); }
+void trace_vprintf(const char*, TraceLevel, const char*, const Packet*, const char*, va_list) {}
+uint8_t TraceApi::get_constraints_generation() { return 0; }
+void TraceApi::filter(const Packet&) {}
 }
 
+THREAD_LOCAL const snort::Trace* http_trace = nullptr;
+
 class JSIdentifierCtxTest : public JSIdentifierCtxBase
 {
 public:
@@ -46,6 +52,8 @@ public:
     size_t size() const override { return 0; }
 };
 
+// Test cases
+
 using namespace snort;
 
 #define DEPTH 65535