Merge pull request #2399 in SNORT/snort3 from ~NEHASH4/snort3:dce_smb_logs to master

Squashed commit of the following:

commit 37b3a79e4b2c464593dd93399bfa2e1e11e6bed2
Author: Neha Sharma <nehash4@cisco.com>
Date:   Thu Aug 13 02:12:58 2020 -0400

    dec_rpc: introducing smb2 logs

diff --git a/src/service_inspectors/dce_rpc/dce_smb.cc b/src/service_inspectors/dce_rpc/dce_smb.cc
index 76e8b668d67192d99d76c2cd80d907f1ec678c0e..904f6a21511bd339ef29858969ab562cd0c9eaca 100644 (file)
--- a/src/service_inspectors/dce_rpc/dce_smb.cc
+++ b/src/service_inspectors/dce_rpc/dce_smb.cc
@@ -26,8 +26,9 @@
 
 #include "detection/detection_engine.h"
 #include "file_api/file_service.h"
-#include "protocols/packet.h"
+#include "main/snort_debug.h"
 #include "managers/inspector_manager.h"
+#include "protocols/packet.h"
 
 #include "dce_context_data.h"
 #include "dce_smb_commands.h"
@@ -380,11 +381,13 @@ void Dce2Smb::eval(Packet* p)
         {
             //1st packet of flow in smb1 session, create smb1 session and flowdata
             dce2_smb_sess = dce2_create_new_smb_session(p, &config);
+            debug_logf(dce_smb_trace, nullptr, "smb1 session created\n");
         }
         else if (DCE2_SMB_VERSION_2 == smb_version)
         {
             //1st packet of flow in smb2 session, create smb2 session and flowdata
             dce2_smb2_sess = dce2_create_new_smb2_session(p, &config);
+            debug_logf(dce_smb_trace, nullptr, "smb2 session created\n");
         }
         else
         {
@@ -392,6 +395,7 @@ void Dce2Smb::eval(Packet* p)
             //This means there is no flow data and this is not an SMB packet
             //if it is a TCP packet for smb data, the flow must have been 
             //already identified with version.
+            debug_logf(dce_smb_trace, nullptr, "non-smb packet detected\n");
             return;
         }
     }

diff --git a/src/service_inspectors/dce_rpc/dce_smb2.cc b/src/service_inspectors/dce_rpc/dce_smb2.cc
index 57642c723ec3000b81d72954aa4035bddeaf56d9..f324ad9b3234c4df773f3a0208fcfee64822b557 100644 (file)
--- a/src/service_inspectors/dce_rpc/dce_smb2.cc
+++ b/src/service_inspectors/dce_rpc/dce_smb2.cc
@@ -31,6 +31,27 @@
 
 using namespace snort;
 
+const char* smb2_command_string[SMB2_COM_MAX] = {
+    "SMB2_COM_NEGOTIATE",
+    "SMB2_COM_SESSION_SETUP",
+    "SMB2_COM_LOGOFF",
+    "SMB2_COM_TREE_CONNECT",
+    "SMB2_COM_TREE_DISCONNECT",
+    "SMB2_COM_CREATE",
+    "SMB2_COM_CLOSE",
+    "SMB2_COM_FLUSH",
+    "SMB2_COM_READ",
+    "SMB2_COM_WRITE",
+    "SMB2_COM_LOCK",
+    "SMB2_COM_IOCTL",
+    "SMB2_COM_CANCEL",
+    "SMB2_COM_ECHO",
+    "SMB2_COM_QUERY_DIRECTORY",
+    "SMB2_COM_CHANGE_NOTIFY",
+    "SMB2_COM_QUERY_INFO",
+    "SMB2_COM_SET_INFO",
+    "SMB2_COM_OPLOCK_BREAK"};
+
 static inline SmbFlowKey get_flow_key(void)
 {
     SmbFlowKey key;
@@ -57,11 +78,45 @@ static inline SmbFlowKey get_flow_key(void)
     return key;
 }
 
+DCE2_Smb2RequestTracker::DCE2_Smb2RequestTracker(uint64_t file_id_v,
+    uint64_t offset_v) : file_id(file_id_v), offset(offset_v)
+{
+    debug_logf(dce_smb_trace, nullptr, "request tracker created\n");
+    memory::MemoryCap::update_allocations(sizeof(*this));
+}
+
+DCE2_Smb2RequestTracker::DCE2_Smb2RequestTracker(char* fname_v,
+    uint16_t fname_len_v) : fname(fname_v), fname_len(fname_len_v)
+{
+    debug_logf(dce_smb_trace, nullptr, "request tracker created\n");
+    memory::MemoryCap::update_allocations(sizeof(*this));
+}
+
+DCE2_Smb2RequestTracker::~DCE2_Smb2RequestTracker()
+{
+    debug_logf(dce_smb_trace, nullptr, "request tracker terminating\n");
+    if (!file_id and fname)
+        snort_free(fname);
+    memory::MemoryCap::update_deallocations(sizeof(*this));
+}
+
+DCE2_Smb2FileTracker::DCE2_Smb2FileTracker(uint64_t file_id_v, DCE2_Smb2TreeTracker* ttr_v,
+    DCE2_Smb2SessionTracker* str_v) : file_id(file_id_v), ttr(ttr_v), str(str_v)
+{   
+    debug_logf(dce_smb_trace, nullptr, "file tracker %" PRIu64 " created\n", file_id);
+    memory::MemoryCap::update_allocations(sizeof(*this));
+}
+
 DCE2_Smb2FileTracker::~DCE2_Smb2FileTracker(void)
 {
+    debug_logf(dce_smb_trace, nullptr,
+        "file tracker %" PRIu64 " file name hash %" PRIu64 " terminating\n",
+         file_id, file_name_hash);
     FileFlows* file_flows = FileFlows::get_file_flows(DetectionEngine::get_current_packet()->flow);
     if (file_flows)
+    {
         file_flows->remove_processed_file_context(file_name_hash, file_id);
+    }
 
     if (file_name)
         snort_free((void*)file_name);
@@ -69,8 +124,39 @@ DCE2_Smb2FileTracker::~DCE2_Smb2FileTracker(void)
     memory::MemoryCap::update_deallocations(sizeof(*this));
 }
 
+DCE2_Smb2TreeTracker::DCE2_Smb2TreeTracker (uint32_t tid_v, uint8_t share_type_v) :
+    share_type(share_type_v), tid(tid_v)
+{
+    debug_logf(dce_smb_trace, nullptr, "tree tracker %" PRIu32 " created\n", tid);
+    memory::MemoryCap::update_allocations(sizeof(*this));
+}
+
+DCE2_Smb2TreeTracker::~DCE2_Smb2TreeTracker(void)
+{
+    debug_logf(dce_smb_trace, nullptr, "tree tracker %" PRIu32 " terminating\n", tid);
+
+    auto all_req_trackers = req_trackers.get_all_entry();
+    if (all_req_trackers.size())
+    {
+        debug_logf(dce_smb_trace, nullptr, "cleanup pending requests for below MIDs:\n");
+        for ( auto& h : all_req_trackers )
+        {
+            debug_logf(dce_smb_trace, nullptr, "mid %" PRIu64 "\n", h.first);
+            removeRtracker(h.first);
+        } 
+    } 
+    memory::MemoryCap::update_deallocations(sizeof(*this));
+}
+
+DCE2_Smb2SessionTracker::DCE2_Smb2SessionTracker()
+{
+    debug_logf(dce_smb_trace, nullptr, "session tracker %" PRIu64 " created\n", session_id);
+    memory::MemoryCap::update_allocations(sizeof(*this));
+}
+
 DCE2_Smb2SessionTracker::~DCE2_Smb2SessionTracker(void)
 {
+    debug_logf(dce_smb_trace, nullptr, "session tracker %" PRIu64 " terminating\n", session_id);
     removeSessionFromAllConnection();
     memory::MemoryCap::update_deallocations(sizeof(*this));
 }
@@ -127,6 +213,9 @@ static void DCE2_Smb2Inspect(DCE2_Smb2SsnData* ssd, const Smb2Hdr* smb_hdr,
     uint64_t sid = Smb2Sid(smb_hdr);
     uint32_t tid = Smb2Tid(smb_hdr);
 
+    debug_logf(dce_smb_trace, nullptr, "%s : mid %" PRIu64 " sid %" PRIu64 " tid %" PRIu32 "\n",
+        (command <= SMB2_COM_OPLOCK_BREAK ? smb2_command_string[command] : "unknown"),
+        mid, sid, tid);
     switch (command)
     {
     case SMB2_COM_CREATE:
@@ -220,6 +309,7 @@ void DCE2_Smb2Process(DCE2_Smb2SsnData* ssd)
     if (data_len < sizeof(NbssHdr) + SMB2_HEADER_LENGTH)
     {
         dce2_smb_stats.v2_hdr_err++;
+        debug_logf(dce_smb_trace, nullptr, "Header error with data length %d\n",data_len);
         return;
     }
 
@@ -246,6 +336,7 @@ void DCE2_Smb2Process(DCE2_Smb2SsnData* ssd)
             {
                 dce_alert(GID_DCE2, DCE2_SMB_BAD_NEXT_COMMAND_OFFSET,
                     (dce2CommonStats*)&dce2_smb_stats, ssd->sd);
+                debug_logf(dce_smb_trace, nullptr, "bad next command offset\n");
                 dce2_smb_stats.v2_bad_next_cmd_offset++;
                 return;
             }
@@ -258,6 +349,8 @@ void DCE2_Smb2Process(DCE2_Smb2SsnData* ssd)
             if (compound_request_index > DCE2_ScSmbMaxCompound((dce2SmbProtoConf*)ssd->sd.config))
             {
                 dce2_smb_stats.v2_cmpnd_req_lt_crossed++;
+                debug_logf(dce_smb_trace, nullptr, "compound req limit reached %" PRIu8 "\n",
+                    compound_request_index);
                 return;
             }
         }
@@ -267,8 +360,9 @@ void DCE2_Smb2Process(DCE2_Smb2SsnData* ssd)
         DCE2_SMB_PDU_STATE__RAW_DATA))
     {
         debug_logf(dce_smb_trace, nullptr,
-            "processing raw data file_name_hash %" PRIu64 " fid %" PRIu64 "\n",
-            ssd->ftracker_tcp->file_name_hash, ssd->ftracker_tcp->file_id);
+            "raw data file_name_hash %" PRIu64 " fid %" PRIu64 " dir %s\n",
+            ssd->ftracker_tcp->file_name_hash, ssd->ftracker_tcp->file_id,
+            ssd->ftracker_tcp->upload ? "upload" : "download");
 
         if (!DCE2_Smb2ProcessFileData(ssd, data_ptr, data_len))
             return;

diff --git a/src/service_inspectors/dce_rpc/dce_smb2.h b/src/service_inspectors/dce_rpc/dce_smb2.h
index 0e6c3b0f87a660db5e606c35946ad1b3f937fd5e..b8f5e3202b5197f2663c6c71e777bcb4c3a4fe9d 100644 (file)
--- a/src/service_inspectors/dce_rpc/dce_smb2.h
+++ b/src/service_inspectors/dce_rpc/dce_smb2.h
@@ -98,24 +98,9 @@ public:
     DCE2_Smb2RequestTracker(const DCE2_Smb2RequestTracker& arg) = delete;
     DCE2_Smb2RequestTracker& operator=(const DCE2_Smb2RequestTracker& arg) = delete;
 
-    DCE2_Smb2RequestTracker(uint64_t file_id_v, uint64_t offset_v = 0) :
-        file_id(file_id_v), offset(offset_v)
-    {
-        memory::MemoryCap::update_allocations(sizeof(*this));
-    }
-
-    DCE2_Smb2RequestTracker(char* fname_v, uint16_t fname_len_v) :
-        fname(fname_v), fname_len(fname_len_v)
-    {
-        memory::MemoryCap::update_allocations(sizeof(*this));
-    }
-
-    ~DCE2_Smb2RequestTracker()
-    {
-        if (!file_id and fname)
-            snort_free(fname);
-        memory::MemoryCap::update_deallocations(sizeof(*this));
-    }
+    DCE2_Smb2RequestTracker(uint64_t file_id_v, uint64_t offset_v = 0);
+    DCE2_Smb2RequestTracker(char* fname_v, uint16_t fname_len_v);
+    ~DCE2_Smb2RequestTracker();
 
     uint64_t get_offset()
     {
@@ -153,12 +138,7 @@ public:
     DCE2_Smb2FileTracker& operator=(const DCE2_Smb2FileTracker& arg) = delete;
 
     DCE2_Smb2FileTracker(uint64_t file_id_v, DCE2_Smb2TreeTracker* ttr_v,
-         DCE2_Smb2SessionTracker* str_v) : file_id(file_id_v), ttr(ttr_v),
-         str(str_v)
-    {
-        memory::MemoryCap::update_allocations(sizeof(*this));
-    }
-
+         DCE2_Smb2SessionTracker* str_v);
     ~DCE2_Smb2FileTracker();
 
     bool ignore = false;
@@ -185,16 +165,8 @@ public:
     DCE2_Smb2TreeTracker(const DCE2_Smb2TreeTracker& arg) = delete;
     DCE2_Smb2TreeTracker& operator=(const DCE2_Smb2TreeTracker& arg) = delete;
 
-    DCE2_Smb2TreeTracker (uint32_t tid_v, uint8_t share_type_v) : share_type(
-            share_type_v), tid(tid_v)
-    {
-        memory::MemoryCap::update_allocations(sizeof(*this));
-    }
-
-    ~DCE2_Smb2TreeTracker()
-    {
-        memory::MemoryCap::update_deallocations(sizeof(*this));
-    }
+    DCE2_Smb2TreeTracker (uint32_t tid_v, uint8_t share_type_v);
+    ~DCE2_Smb2TreeTracker();
 
     // File Tracker
     DCE2_Smb2FileTracker* findFtracker(uint64_t file_id)
@@ -369,8 +341,7 @@ class DCE2_Smb2SessionTracker
 {
 public:
 
-    DCE2_Smb2SessionTracker() { memory::MemoryCap::update_allocations(sizeof(*this)); }
-
+    DCE2_Smb2SessionTracker();
     ~DCE2_Smb2SessionTracker();
 
     void removeSessionFromAllConnection();
@@ -470,6 +441,7 @@ struct DCE2_Smb2SsnData
 #define SMB2_COM_QUERY_INFO       0x10
 #define SMB2_COM_SET_INFO         0x11
 #define SMB2_COM_OPLOCK_BREAK     0x12
+#define SMB2_COM_MAX              0x13
 
 struct Smb2WriteRequestHdr
 {
@@ -657,6 +629,7 @@ struct Smb2SetupResponseHdr
 
 #define SMB2_LOGOFF_REQUEST_STRUC_SIZE 4
 
+extern const char* smb2_command_string[SMB2_COM_MAX];
 /* Process smb2 message */
 void DCE2_Smb2Process(DCE2_Smb2SsnData* ssd);
 

diff --git a/src/service_inspectors/dce_rpc/dce_smb2_commands.cc b/src/service_inspectors/dce_rpc/dce_smb2_commands.cc
index 14db10c182f4e97a20f31b1a4e58c3465051a910..5a30cecabd8db85a7f276bfd14196410a13f39be 100644 (file)
--- a/src/service_inspectors/dce_rpc/dce_smb2_commands.cc
+++ b/src/service_inspectors/dce_rpc/dce_smb2_commands.cc
@@ -28,16 +28,19 @@
 #include "dce_smb2_commands.h"
 #include "hash/hash_key_operations.h"
 #include "log/messages.h"
+#include "main/snort_debug.h"
 #include "packet_io/active.h"
 #include "protocols/packet.h"
 
 using namespace snort;
 #define UNKNOWN_FILE_SIZE (~0)
 
-#define SMB2_CHECK_HDR_ERROR(smb_data, end, strcuture_size, counter) \
+#define SMB2_CHECK_HDR_ERROR(smb_data, end, strcuture_size, counter, cmd) \
     { \
         if ((smb_data + (strcuture_size)) > end) \
         { \
+            debug_logf(dce_smb_trace, nullptr, "%s : smb data beyond end detected\n",\
+                smb2_command_string[cmd]); \
             counter ++; \
             return; \
         } \
@@ -60,6 +63,7 @@ static inline FileContext* get_smb_file_context(uint64_t file_id, uint64_t
 
 static void DCE2_Smb2CleanFtrackerTcpRef(DCE2_Smb2SessionTracker* str, uint64_t file_id)
 {
+    debug_logf(dce_smb_trace, nullptr, "updating conn for fid %" PRIu64 "\n", file_id);
     auto all_conn_trackers = str->conn_trackers.get_all_entry();
     for ( auto& h : all_conn_trackers )
     {
@@ -101,12 +105,17 @@ bool DCE2_Smb2ProcessFileData(DCE2_Smb2SsnData* ssd, const uint8_t* file_data,
     ssd->ftracker_tcp->bytes_processed += detection_size;
     FileDirection dir = ssd->ftracker_tcp->upload ? FILE_UPLOAD : FILE_DOWNLOAD;
 
+    debug_logf(dce_smb_trace, nullptr, "file_process fid %" PRIu64 " data_size %" PRIu32 ""
+        " offset %" PRIu64 " bytes processed %" PRIu64 "\n", ssd->ftracker_tcp->file_id,
+        data_size, ssd->ftracker_tcp->file_offset, ssd->ftracker_tcp->bytes_processed);
+
     // Do not process data beyond file size if file size is known.
     FileFlows* file_flows = FileFlows::get_file_flows(p->flow);
     if ( !file_flows or (ssd->ftracker_tcp->file_size and
         ssd->ftracker_tcp->bytes_processed > ssd->ftracker_tcp->file_size) )
     {
         dce2_smb_stats.v2_extra_file_data_err++;
+        debug_logf(dce_smb_trace, nullptr, "extra file data\n");
 
         DCE2_Smb2TreeTracker* ttr = ssd->ftracker_tcp->ttr;
         uint64_t file_id = ssd->ftracker_tcp->file_id;
@@ -119,6 +128,8 @@ bool DCE2_Smb2ProcessFileData(DCE2_Smb2SsnData* ssd, const uint8_t* file_data,
     if (!file_flows->file_process(p, ssd->ftracker_tcp->file_name_hash, file_data, data_size,
         ssd->ftracker_tcp->file_offset, dir, ssd->ftracker_tcp->file_id))
     {
+        debug_logf(dce_smb_trace, nullptr, "file_process completed\n");
+
         DCE2_Smb2TreeTracker* ttr = ssd->ftracker_tcp->ttr;
         uint64_t file_id = ssd->ftracker_tcp->file_id;
         DCE2_Smb2CleanFtrackerTcpRef(ssd->ftracker_tcp->str, file_id);
@@ -139,17 +150,21 @@ void DCE2_Smb2Setup(DCE2_Smb2SsnData* ssd, const Smb2Hdr* smb_hdr, const uint64_
 
     if (structure_size == SMB2_ERROR_RESPONSE_STRUC_SIZE and Smb2Error(smb_hdr))
     {
+        debug_logf(dce_smb_trace, nullptr, "%s_RESP: error\n",
+            smb2_command_string[SMB2_COM_SESSION_SETUP]);
         dce2_smb_stats.v2_setup_err_resp++;
     }
     else if (structure_size == SMB2_SETUP_RESPONSE_STRUC_SIZE)
     {
         SMB2_CHECK_HDR_ERROR(
             smb_data, end, SMB2_SETUP_RESPONSE_STRUC_SIZE - 1,
-            dce2_smb_stats.v2_setup_resp_hdr_err)
+            dce2_smb_stats.v2_setup_resp_hdr_err, SMB2_COM_SESSION_SETUP)
         DCE2_Smb2FindElseCreateSid(ssd, sid);
     }
     else if (structure_size != SMB2_SETUP_REQUEST_STRUC_SIZE)
     {
+        debug_logf(dce_smb_trace, nullptr, "%s: invalid struct size\n",
+            smb2_command_string[SMB2_COM_SESSION_SETUP]);
         dce2_smb_stats.v2_setup_inv_str_sz++;
     }
 }
@@ -170,16 +185,20 @@ void DCE2_Smb2TreeConnect(DCE2_Smb2SsnData* ssd, const Smb2Hdr* smb_hdr,
     {
         SMB2_CHECK_HDR_ERROR(
             smb_data, end, SMB2_TREE_CONNECT_RESPONSE_STRUC_SIZE,
-            dce2_smb_stats.v2_tree_cnct_resp_hdr_err)
+            dce2_smb_stats.v2_tree_cnct_resp_hdr_err, SMB2_COM_TREE_CONNECT)
 
         if (!DCE2_Smb2InsertTid(ssd, tid,
             ((const Smb2TreeConnectResponseHdr*)smb_data)->share_type, str))
         {
+            debug_logf(dce_smb_trace, nullptr, "%s: ignored %d\n",
+                smb2_command_string[SMB2_COM_TREE_CONNECT], tid);
             dce2_smb_stats.v2_tree_cnct_ignored++;
         }
     }
     else if (structure_size != SMB2_TREE_CONNECT_REQUEST_STRUC_SIZE)
     {
+        debug_logf(dce_smb_trace, nullptr, "%s: invalid struct size\n",
+            smb2_command_string[SMB2_COM_TREE_CONNECT]);
         dce2_smb_stats.v2_tree_cnct_inv_str_sz++;
     }
 }
@@ -195,11 +214,13 @@ void DCE2_Smb2TreeDisconnect(DCE2_Smb2SsnData*, const uint8_t* smb_data,
     {
         SMB2_CHECK_HDR_ERROR(
             smb_data, end, SMB2_TREE_DISCONNECT_REQUEST_STRUC_SIZE,
-            dce2_smb_stats.v2_tree_discn_req_hdr_err)
+            dce2_smb_stats.v2_tree_discn_req_hdr_err, SMB2_COM_TREE_DISCONNECT)
         str->removeTtracker(tid);
     }
     else
     {
+        debug_logf(dce_smb_trace, nullptr, "%s: invalid struct size\n",
+            smb2_command_string[SMB2_COM_TREE_DISCONNECT]);
         dce2_smb_stats.v2_tree_discn_inv_str_sz++;
     }
 }
@@ -222,6 +243,8 @@ static void DCE2_Smb2CreateRequest(DCE2_Smb2SsnData* ssd,
         if (file_data >= end)
         {
             dce2_smb_stats.v2_crt_inv_file_data++;
+            debug_logf(dce_smb_trace, nullptr, "%s_REQ: invalid file data seen\n",
+                smb2_command_string[SMB2_COM_CREATE]);
             return;
         }
 
@@ -229,6 +252,9 @@ static void DCE2_Smb2CreateRequest(DCE2_Smb2SsnData* ssd,
         if (!size or (file_data + size > end))
         {
             dce2_smb_stats.v2_crt_inv_file_data++;
+            debug_logf(dce_smb_trace, nullptr, "%s_REQ: invalid file data seen with size %" PRIu16 "\n",
+                smb2_command_string[SMB2_COM_CREATE], size);
+
             return;
         }
 
@@ -245,12 +271,16 @@ static void DCE2_Smb2CreateRequest(DCE2_Smb2SsnData* ssd,
         }
         else
         {
+            debug_logf(dce_smb_trace, nullptr, "%s_REQ: max req exceeded\n",
+                smb2_command_string[SMB2_COM_CREATE]);
             dce_alert(GID_DCE2, DCE2_SMB_MAX_REQS_EXCEEDED, (dce2CommonStats*)&dce2_smb_stats,
                 ssd->sd);
         }
     }
     else
     {
+        debug_logf(dce_smb_trace, nullptr, "%s_REQ: name_offset %" PRIu16 "\n",
+            smb2_command_string[SMB2_COM_CREATE], name_offset);
         dce2_smb_stats.v2_crt_req_hdr_err++;
     }
 }
@@ -287,6 +317,11 @@ static void DCE2_Smb2CreateResponse(DCE2_Smb2SsnData*,
 
         FileContext* file = get_smb_file_context(ftracker->file_name_hash, fileId_persistent,
             true);
+
+        debug_logf(dce_smb_trace, nullptr, "%s_RESP: file size %" PRIu64 " fid %" PRIu64 ""
+            "file_name_hash %" PRIu64 " file %p\n", smb2_command_string[SMB2_COM_CREATE],
+            file_size, fileId_persistent, ftracker->file_name_hash, (void *)file);
+
         if (file)
         {
             if (file->verdict == FILE_VERDICT_UNKNOWN)
@@ -326,25 +361,33 @@ void DCE2_Smb2Create(DCE2_Smb2SsnData* ssd, const Smb2Hdr* smb_hdr,
             ttr->removeRtracker(mid);
 
         dce2_smb_stats.v2_crt_err_resp++;
+        debug_logf(dce_smb_trace, nullptr, "%s_RESP: error\n",
+            smb2_command_string[SMB2_COM_CREATE]);
     }
     // Using structure size to decide whether it is response or request
     else if (structure_size == SMB2_CREATE_REQUEST_STRUC_SIZE)
     {
         SMB2_CHECK_HDR_ERROR(
             smb_data, end, SMB2_CREATE_REQUEST_STRUC_SIZE - 1,
-            dce2_smb_stats.v2_crt_req_hdr_err)
+            dce2_smb_stats.v2_crt_req_hdr_err, SMB2_COM_CREATE)
 
         if (!ttr)
         {
+            debug_logf(dce_smb_trace, nullptr, "%s_REQ: mid stream session detected\n",
+                smb2_command_string[SMB2_COM_CREATE]);
             ttr = DCE2_Smb2InsertTid(ssd, tid, SMB2_SHARE_TYPE_DISK, str);
             if (!ttr)
             {
+                debug_logf(dce_smb_trace, nullptr, "%s_REQ: insert tree tracker failed\n",
+                    smb2_command_string[SMB2_COM_CREATE]);
                 return;
             }
         }
         else if (SMB2_SHARE_TYPE_DISK != ttr->get_share_type())
         {
             dce2_smb_stats.v2_crt_req_ipc++;
+            debug_logf(dce_smb_trace, nullptr, "%s_REQ: ignored for ipc share\n",
+                smb2_command_string[SMB2_COM_CREATE]);
             return;
         }
         DCE2_Smb2CreateRequest(ssd, (const Smb2CreateRequestHdr*)smb_data, end, str, ttr, mid);
@@ -353,10 +396,12 @@ void DCE2_Smb2Create(DCE2_Smb2SsnData* ssd, const Smb2Hdr* smb_hdr,
     {
         SMB2_CHECK_HDR_ERROR(
             smb_data, end, SMB2_CREATE_RESPONSE_STRUC_SIZE - 1,
-            dce2_smb_stats.v2_crt_resp_hdr_err)
+            dce2_smb_stats.v2_crt_resp_hdr_err, SMB2_COM_CREATE)
 
         if (!ttr)
         {
+            debug_logf(dce_smb_trace, nullptr, "%s_RESP: tree tracker missing\n",
+                 smb2_command_string[SMB2_COM_CREATE]);
             dce2_smb_stats.v2_crt_tree_trkr_misng++;
             return;
         }
@@ -364,6 +409,8 @@ void DCE2_Smb2Create(DCE2_Smb2SsnData* ssd, const Smb2Hdr* smb_hdr,
         DCE2_Smb2RequestTracker* rtr = ttr->findRtracker(mid);
         if (!rtr)
         {
+            debug_logf(dce_smb_trace, nullptr, "%s_RESP: req tracker missing\n",
+                 smb2_command_string[SMB2_COM_CREATE]);
             dce2_smb_stats.v2_crt_rtrkr_misng++;
             return;
         }
@@ -374,9 +421,9 @@ void DCE2_Smb2Create(DCE2_Smb2SsnData* ssd, const Smb2Hdr* smb_hdr,
         if (((const Smb2CreateResponseHdr*)smb_data)->file_attributes &
             SMB2_CREATE_RESPONSE_DIRECTORY)
         {
+            debug_logf(dce_smb_trace, nullptr, "%s_RESP: not processing for directory\n",
+                 smb2_command_string[SMB2_COM_CREATE]);
             ttr->removeRtracker(mid);
-            if (ssd->ftracker_tcp and ssd->ftracker_tcp->file_id == fileId_persistent)
-                ssd->ftracker_tcp = nullptr;
             DCE2_Smb2CleanFtrackerTcpRef(str, fileId_persistent);
             ttr->removeFtracker(fileId_persistent);
             return;
@@ -388,6 +435,8 @@ void DCE2_Smb2Create(DCE2_Smb2SsnData* ssd, const Smb2Hdr* smb_hdr,
     }
     else
     {
+        debug_logf(dce_smb_trace, nullptr, "%s: invalid struct size\n",
+            smb2_command_string[SMB2_COM_CREATE]);
         dce2_smb_stats.v2_crt_inv_str_sz++;
     }
 }
@@ -404,6 +453,8 @@ void DCE2_Smb2CloseCmd(DCE2_Smb2SsnData* ssd, const Smb2Hdr* smb_hdr,
 
     if (structure_size == SMB2_ERROR_RESPONSE_STRUC_SIZE and Smb2Error(smb_hdr))
     {
+        debug_logf(dce_smb_trace, nullptr, "%s_RESP: error\n",
+            smb2_command_string[SMB2_COM_CLOSE]);
         dce2_smb_stats.v2_cls_err_resp++;
     }
     // Using structure size to decide whether it is response or request
@@ -411,7 +462,7 @@ void DCE2_Smb2CloseCmd(DCE2_Smb2SsnData* ssd, const Smb2Hdr* smb_hdr,
     {
         SMB2_CHECK_HDR_ERROR(
             smb_data, end, SMB2_CLOSE_REQUEST_STRUC_SIZE,
-            dce2_smb_stats.v2_cls_req_hdr_err)
+            dce2_smb_stats.v2_cls_req_hdr_err, SMB2_COM_CLOSE)
 
         uint64_t fileId_persistent = alignedNtohq(&(((const
             Smb2CloseRequestHdr*)smb_data)->fileId_persistent));
@@ -419,6 +470,8 @@ void DCE2_Smb2CloseCmd(DCE2_Smb2SsnData* ssd, const Smb2Hdr* smb_hdr,
         if (!ftracker)
         {
             dce2_smb_stats.v2_cls_req_ftrkr_misng++;
+            debug_logf(dce_smb_trace, nullptr, "%s_REQ: ftracker missing %" PRIu64 "\n",
+                smb2_command_string[SMB2_COM_CLOSE], fileId_persistent);
             return;
         }
 
@@ -447,6 +500,8 @@ void DCE2_Smb2CloseCmd(DCE2_Smb2SsnData* ssd, const Smb2Hdr* smb_hdr,
     }
     else if (structure_size != SMB2_CLOSE_RESPONSE_STRUC_SIZE)
     {
+        debug_logf(dce_smb_trace, nullptr, "%s: invalid struct size\n",
+            smb2_command_string[SMB2_COM_CLOSE]);
         dce2_smb_stats.v2_cls_inv_str_sz++;
     }
 }
@@ -462,13 +517,15 @@ void DCE2_Smb2SetInfo(DCE2_Smb2SsnData*, const Smb2Hdr* smb_hdr,
     // Using structure size to decide whether it is response or request
     if (structure_size == SMB2_ERROR_RESPONSE_STRUC_SIZE and Smb2Error(smb_hdr))
     {
+        debug_logf(dce_smb_trace, nullptr, "%s: error resp\n",
+            smb2_command_string[SMB2_COM_SET_INFO]);
         dce2_smb_stats.v2_stinf_err_resp++;
     }
     else if (structure_size == SMB2_SET_INFO_REQUEST_STRUC_SIZE)
     {
         SMB2_CHECK_HDR_ERROR(
             smb_data, end, SMB2_SET_INFO_REQUEST_STRUC_SIZE,
-            dce2_smb_stats.v2_stinf_req_hdr_err)
+            dce2_smb_stats.v2_stinf_req_hdr_err, SMB2_COM_SET_INFO)
 
         const Smb2SetInfoRequestHdr* smb_set_info_hdr = (const Smb2SetInfoRequestHdr*)smb_data;
         const uint8_t* file_data =  (const uint8_t*)smb_set_info_hdr +
@@ -484,6 +541,9 @@ void DCE2_Smb2SetInfo(DCE2_Smb2SsnData*, const Smb2Hdr* smb_hdr,
                 ftracker->file_size = file_size;
                 FileContext* file = get_smb_file_context(ftracker->file_name_hash,
                     fileId_persistent);
+                debug_logf(dce_smb_trace, nullptr,
+                    "%s_REQ: set file size %" PRIu64 " fid %" PRIu64 " file %p\n",
+                    smb2_command_string[SMB2_COM_SET_INFO], file_size, fileId_persistent, (void*)file);
                 if (file)
                 {
                     file->set_file_size(ftracker->file_size);
@@ -492,15 +552,21 @@ void DCE2_Smb2SetInfo(DCE2_Smb2SsnData*, const Smb2Hdr* smb_hdr,
             else
             {
                 dce2_smb_stats.v2_stinf_req_ftrkr_misng++;
+                debug_logf(dce_smb_trace, nullptr,"%s_REQ: ftracker missing\n",
+                    smb2_command_string[SMB2_COM_SET_INFO]);
             }
         }
         else
         {
+            debug_logf(dce_smb_trace, nullptr,"%s_REQ: header error\n",
+                smb2_command_string[SMB2_COM_SET_INFO]);
             dce2_smb_stats.v2_stinf_req_hdr_err++;
         }
     }
     else if (structure_size != SMB2_SET_INFO_RESPONSE_STRUC_SIZE)
     {
+        debug_logf(dce_smb_trace, nullptr, "%s: invalid struct size\n",
+            smb2_command_string[SMB2_COM_SET_INFO]);
         dce2_smb_stats.v2_stinf_inv_str_sz++;
     }
 }
@@ -527,6 +593,8 @@ static void DCE2_Smb2ReadRequest(DCE2_Smb2SsnData* ssd,
     }
     else
     {
+        debug_logf(dce_smb_trace, nullptr, "%s_REQ: max req exceeded\n",
+            smb2_command_string[SMB2_COM_READ]);
         dce_alert(GID_DCE2, DCE2_SMB_MAX_REQS_EXCEEDED, (dce2CommonStats*)&dce2_smb_stats,
             ssd->sd);
         return;
@@ -541,6 +609,8 @@ static void DCE2_Smb2ReadRequest(DCE2_Smb2SsnData* ssd,
 
     if (ftracker->file_size and (offset > ftracker->file_size))
     {
+        debug_logf(dce_smb_trace, nullptr, "%s_REQ: invalid file offset\n",
+            smb2_command_string[SMB2_COM_READ]);
         dce_alert(GID_DCE2, DCE2_SMB_INVALID_FILE_OFFSET, (dce2CommonStats*)&dce2_smb_stats,
             ssd->sd);
     }
@@ -562,12 +632,16 @@ static void DCE2_Smb2ReadResponse(DCE2_Smb2SsnData* ssd, const Smb2Hdr* smb_hdr,
     request = ttr->findRtracker(message_id);
     if (!request)
     {
+        debug_logf(dce_smb_trace, nullptr, "%s_RESP: request tracker missing\n",
+            smb2_command_string[SMB2_COM_READ]);
         dce2_smb_stats.v2_read_rtrkr_misng++;
         return;
     }
     data_offset = alignedNtohs((const uint16_t*)(&(smb_read_hdr->data_offset)));
     if (data_offset + (const uint8_t*)smb_hdr > end)
     {
+        debug_logf(dce_smb_trace, nullptr, "%s_RESP: bad offset\n",
+            smb2_command_string[SMB2_COM_READ]);
         dce_alert(GID_DCE2, DCE2_SMB_BAD_OFF, (dce2CommonStats*)&dce2_smb_stats, ssd->sd);
     }
 
@@ -610,26 +684,30 @@ void DCE2_Smb2Read(DCE2_Smb2SsnData* ssd, const Smb2Hdr* smb_hdr,
         }
         ttr->removeRtracker(mid);
         dce2_smb_stats.v2_read_err_resp++;
+        debug_logf(dce_smb_trace, nullptr, "%s_RESP: error\n",
+            smb2_command_string[SMB2_COM_WRITE]);
     }
     // Using structure size to decide whether it is response or request
     else if (structure_size == SMB2_READ_REQUEST_STRUC_SIZE)
     {
         SMB2_CHECK_HDR_ERROR(
             smb_data, end, SMB2_READ_REQUEST_STRUC_SIZE - 1,
-            dce2_smb_stats.v2_read_req_hdr_err)
+            dce2_smb_stats.v2_read_req_hdr_err, SMB2_COM_READ)
         DCE2_Smb2ReadRequest(ssd, (const Smb2ReadRequestHdr*)smb_data, end, str, ttr, mid);
     }
     else if (structure_size == SMB2_READ_RESPONSE_STRUC_SIZE)
     {
         SMB2_CHECK_HDR_ERROR(
             smb_data, end, SMB2_READ_RESPONSE_STRUC_SIZE - 1,
-            dce2_smb_stats.v2_read_resp_hdr_err)
+            dce2_smb_stats.v2_read_resp_hdr_err, SMB2_COM_READ)
 
         DCE2_Smb2ReadResponse(ssd, smb_hdr, (const Smb2ReadResponseHdr*)smb_data, end, ttr, mid);
     }
     else
     {
         dce2_smb_stats.v2_read_inv_str_sz++;
+        debug_logf(dce_smb_trace, nullptr, "%s: invalid struct size\n",
+            smb2_command_string[SMB2_COM_WRITE]);
     }
 }
 
@@ -659,6 +737,8 @@ static void DCE2_Smb2WriteRequest(DCE2_Smb2SsnData* ssd, const Smb2Hdr* smb_hdr,
     }
     else
     {
+        debug_logf(dce_smb_trace, nullptr, "%s_REQ: max req exceeded\n",
+            smb2_command_string[SMB2_COM_WRITE]);
         dce_alert(GID_DCE2, DCE2_SMB_MAX_REQS_EXCEEDED, (dce2CommonStats*)&dce2_smb_stats,
             ssd->sd);
         return;
@@ -667,6 +747,8 @@ static void DCE2_Smb2WriteRequest(DCE2_Smb2SsnData* ssd, const Smb2Hdr* smb_hdr,
     data_offset = alignedNtohs((const uint16_t*)(&(smb_write_hdr->data_offset)));
     if (data_offset + (const uint8_t*)smb_hdr > end)
     {
+        debug_logf(dce_smb_trace, nullptr, "%s_REQ: bad offset\n",
+            smb2_command_string[SMB2_COM_WRITE]);
         dce_alert(GID_DCE2, DCE2_SMB_BAD_OFF, (dce2CommonStats*)&dce2_smb_stats, ssd->sd);
     }
 
@@ -714,13 +796,15 @@ void DCE2_Smb2Write(DCE2_Smb2SsnData* ssd, const Smb2Hdr* smb_hdr,
         }
         ttr->removeRtracker(mid);
         dce2_smb_stats.v2_wrt_err_resp++;
+        debug_logf(dce_smb_trace, nullptr, "%s_RESP: error\n",
+            smb2_command_string[SMB2_COM_WRITE]);
     }
     // Using structure size to decide whether it is response or request
     else if (structure_size == SMB2_WRITE_REQUEST_STRUC_SIZE)
     {
         SMB2_CHECK_HDR_ERROR(
             smb_data, end, SMB2_WRITE_REQUEST_STRUC_SIZE - 1,
-            dce2_smb_stats.v2_wrt_req_hdr_err)
+            dce2_smb_stats.v2_wrt_req_hdr_err, SMB2_COM_WRITE)
         DCE2_Smb2WriteRequest(ssd, smb_hdr, (const Smb2WriteRequestHdr*)smb_data, end, str, ttr,
             mid);
     }
@@ -730,6 +814,8 @@ void DCE2_Smb2Write(DCE2_Smb2SsnData* ssd, const Smb2Hdr* smb_hdr,
     }
     else
     {
+        debug_logf(dce_smb_trace, nullptr, "%s: invalid struct size\n",
+            smb2_command_string[SMB2_COM_WRITE]);
         dce2_smb_stats.v2_wrt_inv_str_sz++;
     }
 }
@@ -752,6 +838,8 @@ void DCE2_Smb2Logoff(DCE2_Smb2SsnData* ssd, const uint8_t* smb_data,
     }
     else
     {
+        debug_logf(dce_smb_trace, nullptr, "%s: invalid struct size\n",
+            smb2_command_string[SMB2_COM_LOGOFF]);
         dce2_smb_stats.v2_logoff_inv_str_sz++;
     }
 }

diff --git a/src/service_inspectors/dce_rpc/smb_message.cc b/src/service_inspectors/dce_rpc/smb_message.cc
index 0ff63b079b0665262ca9a46ed45ff9cfad3168b2..8777d867f88ef00947a75177fdf1b28db38624d9 100644 (file)
--- a/src/service_inspectors/dce_rpc/smb_message.cc
+++ b/src/service_inspectors/dce_rpc/smb_message.cc
@@ -1621,6 +1621,7 @@ void DCE2_Smb1Process(DCE2_SmbSsnData* ssd)
                 if (!DCE2_GcIsLegacyMode((dce2SmbProtoConf*)ssd->sd.config))
                 {
                     // Upgrade connection to SMBv2
+                    debug_log(dce_smb_trace, nullptr, "upgrading to smb2 session\n");
                     dce2SmbProtoConf* config = (dce2SmbProtoConf*)ssd->sd.config;
                     Dce2SmbFlowData* fd = (Dce2SmbFlowData*)p->flow->get_flow_data(
                         Dce2SmbFlowData::inspector_id);