Bug #5811
closedsmb: tx logs sometimes have duplicate `tree_id` output
Description
We have those events even for some suricata-verify tests, so should be easy to reproduce and debug, see for example:
smb-named-pipe-unicode/output/eve.json:{"timestamp":"2020-04-14T16:45:34.732215+0000","flow_id":1855357390218608,"pcap_cnt":14,"event_type":"alert","src_ip":"192.168.1.100","src_port":41688,"dest_ip":"192.168.1.3","dest_port":445,"proto":"TCP","pkt_src":"wire/pcap","tx_id":3,"alert":{"action":"allowed","gid":1,"signature_id":1,"rev":1,"signature":"Ascii named_pipe","category":"","severity":3},"smb":{"id":4,"dialect":"NT LM 0.12","command":"SMB1_COMMAND_TREE_CONNECT_ANDX","status":"STATUS_SUCCESS","status_code":"0x0","session_id":4096,"tree_id":2052,"tree_id":2052,"named_pipe":"\\192.168.1.3\\IPC$","service":{"request":"?????","response":"IPC"}},"app_proto":"smb","direction":"to_server","flow":{"pkts_toserver":8,"pkts_toclient":6,"bytes_toserver":1132,"bytes_toclient":1245,"start":"2020-04-14T16:45:34.694128+0000","src_ip":"192.168.1.100","dest_ip":"192.168.1.3","src_port":41688,"dest_port":445}}
Updated by Andreas Herz almost 2 years ago
Initial report at the forum, see https://forum.suricata.io/t/all-event-type-smb-events-have-double-tree-id-in-the-eve-logs-version-6-0-9/3146/5
Updated by Andreas Herz almost 2 years ago
The reason for that is, that in `rust/src/smb.log.rs` we have an additional entry that is print in addition:
Some(SMBTransactionTypeData::TREECONNECT(ref x)) => {
jsb.set_uint("tree_id", x.tree_id as u64)?;
While the generic one that is printed everytime is `tx.hdr.tree_id` this one is `x.tree_id` but based on the testruns it's always the same as the `hdr` one. So it might just be not needed at all or the stored value is wrong.
Updated by Jason Ish almost 2 years ago
Andreas Herz wrote in #note-2:
The reason for that is, that in `rust/src/smb.log.rs` we have an additional entry that is print in addition:
[...]While the generic one that is printed everytime is `tx.hdr.tree_id` this one is `x.tree_id` but based on the testruns it's always the same as the `hdr` one. So it might just be not needed at all or the stored value is wrong.
Thats my assumption as well. The `tree_id` is being "hoisted" up into the common header, cause if you look at the PCAP for a TREECONNECT
, the Tree ID
does exist only once, however our data structures suggest otherwise. My guess is that removing this line is the fix. Thoughts @Victor Julien ?
Updated by Andreas Herz almost 2 years ago
In addition to that I would also check if we read the correct tree_id.
In `smb-named-pipe-ascii-frames` we have the following event:
{"timestamp":"2020-03-10T18:22:46.113634+0000","flow_id":1704892135654207,"pcap_cnt":14,"event_type":"alert","src_ip":"192.168.1.100","src_port":55768,"dest_ip":"192.168.1.3","dest_port":445,"proto":"TCP","pkt_src":"wire/pcap","tx_id":3,"alert":{"action":"allowed","gid":1,"signature_id":1,"rev":1,"signature":"Ascii named_pipe","category":"","severity":3},"smb":{"id":4,"dialect":"NT LM 0.12","command":"SMB1_COMMAND_TREE_CONNECT_ANDX","status":"STATUS_SUCCESS","status_code":"0x0","session_id":4096,"tree_id":2049,"tree_id":2049,"named_pipe":"\\127.0.0.1\\IPC$","service":{"request":"?????","response":"IPC"}},"app_proto":"smb","direction":"to_server","flow":{"pkts_toserver":8,"pkts_toclient":6,"bytes_toserver":1517,"bytes_toclient":1261,"start":"2020-03-10T18:22:46.069271+0000","src_ip":"192.168.1.100","dest_ip":"192.168.1.3","src_port":55768,"dest_port":445}}
When I look into the pcap, the 2049 id is not from this packet, this packet has 65535 as value in wireshark. ANd based on the command and the src/dst I would say this is the packet 11 from the pcap which is the request (check the Tree ID in wireshark).
But the packet 12 is the response which has tree id 2049. Is this expected or another bug?
Updated by Jason Ish almost 2 years ago
Andreas Herz wrote in #note-4:
In addition to that I would also check if we read the correct tree_id.
In `smb-named-pipe-ascii-frames` we have the following event:
[...]When I look into the pcap, the 2049 id is not from this packet, this packet has 65535 as value in wireshark. ANd based on the command and the src/dst I would say this is the packet 11 from the pcap which is the request (check the Tree ID in wireshark).
But the packet 12 is the response which has tree id 2049. Is this expected or another bug?
SMB, I believe, correlates responses to requests before logging so you are seeing an amalgamation of the request and response being logged, and it appears to be choosing the tree_id from the response. Unfortunately, I'm not familiar enough with SMB to know what makes the most sense.
Updated by Jason Ish almost 2 years ago
Here are all the tests resulting in a duplicate tree_id
field. In all cases that value is the same:
FAIL: ./tests/dcerpc/zerologon/output/eve.json: key=tree_id, current value=1, new value=1 FAIL: ./tests/output-eve-smb-01/output/eve.json: key=tree_id, current value=2052, new value=2052 FAIL: ./tests/smb-dce_iface/output/eve.json: key=tree_id, current value=1, new value=1 FAIL: ./tests/smb-dce_opnum/output/eve.json: key=tree_id, current value=1, new value=1 FAIL: ./tests/smb-eicar-andx/output/eve.json: key=tree_id, current value=2051, new value=2051 FAIL: ./tests/smb-eicar-file-frames/output/eve.json: key=tree_id, current value=2048, new value=2048 FAIL: ./tests/smb-eicar-file-nbss-more-ffsmb/output/eve.json: key=tree_id, current value=2052, new value=2052 FAIL: ./tests/smb-eicar-file-segmentation-postheader/output/eve.json: key=tree_id, current value=2050, new value=2050 FAIL: ./tests/smb-eicar-file-segmentation-random/output/eve.json: key=tree_id, current value=2052, new value=2052 FAIL: ./tests/smb-eicar-file/output/eve.json: key=tree_id, current value=2048, new value=2048 FAIL: ./tests/smb-eicar-overlap/output/eve.json: key=tree_id, current value=2053, new value=2053 FAIL: ./tests/smb-eicar-padding/output/eve.json: key=tree_id, current value=4102, new value=4102 FAIL: ./tests/smb-named-pipe-ascii-frames/output/eve.json: key=tree_id, current value=2049, new value=2049 FAIL: ./tests/smb-named-pipe-ascii/output/eve.json: key=tree_id, current value=2049, new value=2049 FAIL: ./tests/smb-named-pipe-unicode/output/eve.json: key=tree_id, current value=2052, new value=2052 FAIL: ./tests/smb2-01/output/eve.json: key=tree_id, current value=201977730, new value=201977730 FAIL: ./tests/smb2-02/output/eve.json: key=tree_id, current value=1, new value=1 FAIL: ./tests/smb2-03-rule/output/eve.json: key=tree_id, current value=1, new value=1 FAIL: ./tests/smb2-05/output/eve.json: key=tree_id, current value=1, new value=1 FAIL: ./tests/smb2-06/output/eve.json: key=tree_id, current value=1, new value=1 FAIL: ./tests/smb2-07-frames/output/eve.json: key=tree_id, current value=1, new value=1 FAIL: ./tests/smb2-07/output/eve.json: key=tree_id, current value=1, new value=1 FAIL: ./tests/smb2-delete/output/eve.json: key=tree_id, current value=1, new value=1 FAIL: ./tests/smb3-01/output/eve.json: key=tree_id, current value=1, new value=1 FAIL: ./tests/smb3-02-midstream/output/eve.json: key=tree_id, current value=5, new value=5 FAIL: ./tests/smb3-03-midstream/output/eve.json: key=tree_id, current value=5, new value=5 FAIL: ./tests/smb2-named-pipe-unicode/output/eve.json: key=tree_id, current value=1, new value=1 FAIL: ./tests/bug-5162/output/eve.json: key=tree_id, current value=1, new value=1 FAIL: ./tests/dcerpc-smb-fail/output/eve.json: key=tree_id, current value=1, new value=1 FAIL: ./tests/dcerpc-smb-test-01/output/eve.json: key=tree_id, current value=1, new value=1 FAIL: ./tests/filesize-keyword/output/eve.json: key=tree_id, current value=2048, new value=2048 FAIL: ./tests/streamsize-keyword/output/eve.json: key=tree_id, current value=2048, new value=2048 FAIL: ./tests/smb2-08-rule/output/eve.json: key=tree_id, current value=1, new value=1 FAIL: ./tests/smb2-async-read/output/eve.json: key=tree_id, current value=4162756537, new value=4162756537
Updated by Victor Julien almost 2 years ago
- Subject changed from SMB events sometimes have duplicate `tree_id` output. to smb: tx logs sometimes have duplicate `tree_id` output
- Label Needs backport to 6.0 added
Updated by Victor Julien almost 2 years ago
- Status changed from New to In Review
- Assignee changed from OISF Dev to Jason Ish
- Target version changed from TBD to 7.0.0-rc1
Updated by Victor Julien almost 2 years ago
- Status changed from In Review to Closed
Updated by Victor Julien almost 2 years ago
- Status changed from Closed to Resolved
Updated by OISF Ticketbot almost 2 years ago
- Label deleted (
Needs backport to 6.0)
Updated by Victor Julien almost 2 years ago
- Related to Bug #5933: smb: tx logs sometimes have duplicate `tree_id` output (6.0.x backport) added
Updated by Victor Julien almost 2 years ago
- Status changed from Resolved to Closed