Unbounded per-connection state growth in dce-rpc scripts

[awelzel]

Constant worker memory growth with eventual OOM crash has been reported in the public Zeek Slack: https://zeekorg.slack.com/archives/CSZBXF6TH/p1685587437627989

After deploying per-conn-footprint which regularly logs the footprint of all connections and first-level fields, a connection was identified with a dce_rpc_backing table and a footprint of 4mio, growing at around 1800/s.

# [footprint, uid, services, duration, details]
[3863086,1687255886.350536,"ClMdKa4h5LSvI4BeTc",["SMB","DCE_RPC","KRB","GSSAPI"],2735.635337114334,"start_time=1,krb=32,conn=32,duration=1,ftp_data_reuse=1,id=8,dce_rpc_state=3,dce_rpc_backing=3814351,uid=1,vlan=1,orig=12,smb_state=48543,history=1,removal_hooks=6,extract_orig=1,dce_rpc=17,service=12,known_services_done=1,resp=12,extract_resp=1"]
[3982057,1687255946.351189,"ClMdKa4h5LSvI4BeTc",["SMB","DCE_RPC","KRB","GSSAPI"],2795.6359899044037,"start_time=1,krb=32,conn=32,duration=1,ftp_data_reuse=1,id=8,dce_rpc_state=13,dce_rpc_backing=3934193,uid=1,vlan=1,orig=12,smb_state=47659,history=1,removal_hooks=6,extract_orig=1,dce_rpc=20,service=12,known_services_done=1,resp=12,extract_resp=1"]
[4113009,1687256006.351253,"ClMdKa4h5LSvI4BeTc",["SMB","DCE_RPC","KRB","GSSAPI"],2855.6360540390015,"start_time=1,krb=32,conn=32,duration=1,ftp_data_reuse=1,id=8,dce_rpc_state=13,dce_rpc_backing=4053416,uid=1,vlan=1,orig=12,smb_state=59408,history=1,removal_hooks=6,extract_orig=1,service=12,known_services_done=1,resp=12,extract_resp=1"]

Can't easily tell using the footprint if it is c$dce_rpc_backing table growing or State$ctx_to_uuid within that table (that should be bounded by ~16k~ 64k though). Looking through the scripts, no provisions for cleaning up either is there.

[JustinAzoff]

So this definitely does look broken, but it seems because the fid was not expected to vary that much.

The comments in the analyzer say

fid: File ID of the PIPE that carried the :abbr:DCE-RPC (Distributed Computing Environment/Remote Procedure Calls) message. Zero will be used if the :abbr:DCE-RPC (Distributed Computing Environment/Remote Procedure Calls) was not transported over a pipe.

Running this on my laptop:

for p in ~/src/zeek/testing/btest/Traces/{smb,dce-rpc}/*; do
    echo $p
    zeek -Cr  $p misc/dump-events|fgrep 'fid:'
done

outputs almost entirely

                  [1] fid: count         = 0

and only one pcap, smb2.pcap outputs a non zero value

                  [1] fid: count         = 18446744069414584398
                  [1] fid: count         = 18446744069414584398
                  [1] fid: count         = 18446744069414584398
                  [1] fid: count         = 18446744069414584398
                  [1] fid: count         = 18446744069414584398

So it may have been expected that only a small number of such fids would be seen, and letting them accumulate was fine. None of the super large smb pcaps I created do this either, they make 1 or 2 fids as the share is initially accessed, regardless of the number of files accessed.

I think a first step might be to figure out what sort of client behavior creates a large number of fids and get a pcap of that.

[awelzel]

Thanks @JustinAzoff - yes. If it's was fid growing unbounded there should also be traces of the smb analyzer allocating a DCE_RPC analyzer per fid in the jemalloc profile.

I had mentioned in the description that it may also be ctx_to_uuid table within State. Should be okay to remove ctx_id from there in dce_rpc_response() and possibly capping the size, too.

[awelzel]

So this definitely does look broken, but it seems because the fid was not expected to vary that much.

yes. If it's was fid growing unbounded there should also be traces of the smb analyzer allocating a DCE_RPC analyzer per fid in the jemalloc profile.

The reporter provided a conn_footprint.log indicating it is the fid varying and dce_rpc_backing growing. The largest conn entry with a footprint of ~5mio indicates 139k entries in dce_rpc_backing: dce_rpc_backing=5221669 {entries 139069}

They are also running zeek-smb-clear-state which likely impacts reported fid_map sizes.

Looking at smb/smb-pipe.pac and forward_dce_rpc(): There might be some cleanup missing: A pipe's DCE-RPC analyzer isn't ever removed. Not in the normal case and also not in the cases where fids are discarded to prevent state growth (new from #2978).

# uid, history, footprint, details:
["C34eaME5CgbBrWxTf","ShADdagGGgTtGgTtGgTtgG",5010194,"known_services_done=1, extract_resp=1, ftp_data_reuse=1, uid=1, conn=32 {id=8, uid=1, local_resp=1, missed_bytes=1, ts=1, local_orig=1, proto=1}, extract_orig=1, krb=32 {id=8, uid=1, logged=1, ts=1}, orig=12 {size=1, state=1, num_pkts=1, flow_label=1, num_bytes_ip=1, l2_addr=1}, smb_state=86955 {uid_map=0, pending_cmds=79622 {entries 1078}, fid_map=6859 {entries 231}, tid_map=351 {entries 16}, pipe_map=0, recent_files=0, current_file=23, current_cmd=72, current_tree=19}, id=8 {resp_p=1, resp_h=1, orig_p=1, orig_h=1}, vlan=1, removal_hooks=6 {entries 2}, history=1, start_time=1, resp=12 {size=1, state=1, num_pkts=1, flow_label=1, num_bytes_ip=1, l2_addr=1}, dce_rpc_state=13 {named_pipe=1, ctx_to_uuid=8 {entries 2}, uuid=1}, duration=1, dce_rpc_backing=4923054 {entries 131053}, service=12 {entries 4}"]
["C34eaME5CgbBrWxTf","ShADdagGGgTtGgTtGgTtgG",5058169,"known_services_done=1, extract_resp=1, ftp_data_reuse=1, uid=1, conn=32 {id=8, uid=1, local_resp=1, missed_bytes=1, ts=1, local_orig=1, proto=1}, extract_orig=1, krb=32 {id=8, uid=1, logged=1, ts=1}, orig=12 {size=1, state=1, num_pkts=1, flow_label=1, num_bytes_ip=1, l2_addr=1}, smb_state=40463 {uid_map=0, pending_cmds=33640 {entries 455}, fid_map=6343 {entries 213}, tid_map=351 {entries 16}, pipe_map=0, recent_files=0, current_file=27, current_cmd=74, current_tree=19}, id=8 {resp_p=1, resp_h=1, orig_p=1, orig_h=1}, vlan=1, removal_hooks=6 {entries 2}, history=1, start_time=1, resp=12 {size=1, state=1, num_pkts=1, flow_label=1, num_bytes_ip=1, l2_addr=1}, dce_rpc_state=13 {named_pipe=1, ctx_to_uuid=8 {entries 2}, uuid=1}, duration=1, dce_rpc_backing=5017521 {entries 133607}, service=12 {entries 4}"]
["C34eaME5CgbBrWxTf","ShADdagGGgTtGgTtGgTtgG",5173687,"known_services_done=1, extract_resp=1, ftp_data_reuse=1, uid=1, conn=32 {id=8, uid=1, local_resp=1, missed_bytes=1, ts=1, local_orig=1, proto=1}, extract_orig=1, krb=32 {id=8, uid=1, logged=1, ts=1}, orig=12 {size=1, state=1, num_pkts=1, flow_label=1, num_bytes_ip=1, l2_addr=1}, smb_state=50191 {uid_map=0, pending_cmds=44268 {entries 600}, fid_map=5449 {entries 183}, tid_map=351 {entries 16}, pipe_map=0, recent_files=0, current_file=23, current_cmd=72, current_tree=19}, id=8 {resp_p=1, resp_h=1, orig_p=1, orig_h=1}, vlan=1, removal_hooks=6 {entries 2}, history=1, start_time=1, resp=12 {size=1, state=1, num_pkts=1, flow_label=1, num_bytes_ip=1, l2_addr=1}, dce_rpc_state=13 {named_pipe=1, ctx_to_uuid=8 {entries 2}, uuid=1}, duration=1, dce_rpc_backing=5123311 {entries 136434}, service=12 {entries 4}"]
["C34eaME5CgbBrWxTf","ShADdagGGgTtGgTtGgTtgG",5256823,"known_services_done=1, extract_resp=1, ftp_data_reuse=1, uid=1, conn=32 {id=8, uid=1, local_resp=1, missed_bytes=1, ts=1, local_orig=1, proto=1}, extract_orig=1, krb=32 {id=8, uid=1, logged=1, ts=1}, orig=12 {size=1, state=1, num_pkts=1, flow_label=1, num_bytes_ip=1, l2_addr=1}, smb_state=34969 {uid_map=0, pending_cmds=28591 {entries 387}, fid_map=5904 {entries 198}, tid_map=351 {entries 16}, pipe_map=0, recent_files=0, current_file=23, current_cmd=72, current_tree=19}, id=8 {resp_p=1, resp_h=1, orig_p=1, orig_h=1}, vlan=1, removal_hooks=6 {entries 2}, history=1, start_time=1, resp=12 {size=1, state=1, num_pkts=1, flow_label=1, num_bytes_ip=1, l2_addr=1}, dce_rpc_state=13 {named_pipe=1, ctx_to_uuid=8 {entries 2}, uuid=1}, duration=1, dce_rpc_backing=5221669 {entries 139069}, service=12 {entries 4}"]

[awelzel]

Can be provoked with rpcclient switching RPC pipe parameters from none to sealed on an established connection.

Pcap created as follows:

$ docker run -it --rm --hostname samba-container --name samba -p 139:139 -p 445:445           -v /tmp/samba_new:/mount dperson/samba -u "zeek;zeek" -u "alice;alice" -s "public;/mount/public" -s "zeek;/mount/zeek" -s "alice;/mount/alice"
$ (for i in {1..100}; do echo -e '\nsign\nenumdomusers\nqueryuser zeek\nnone'; done) | rpcclient -Uzeek 127.0.0.1 --password=zeek
$ tcpdump -i docker0 'tcp port 445' -w 200-fids.pcap

200-fids.pcap.gz

[JustinAzoff]

@awelzel would this work in the meantime?

module DCERPCClearState;

export {
    redef enum Notice::Type += {
        BrokenConnection,
    };

    ## The threshold for (|dce_rpc_backing|)
    ## If the size of the tables passes the threshold it is cleared and a
    ## connection is logged as broken.
    option threshold = 500;
}

event check_state(c: connection)
{
    if(!connection_exists(c$id))
        return;

    if(!c?$dce_rpc_backing)
        return;

    local next_sleep = 5min;

    if (|c$dce_rpc_backing| > threshold) {
        NOTICE([
            $note=BrokenConnection,
            $id=c$id,
            $msg=fmt("Broken dce_rpc connection detected. dce_rpc_backing=%d", |c$dce_rpc_backing|),
            $n=|c$dce_rpc_backing|,
            $identifier=c$uid
        ]);
        c$dce_rpc_backing = table();
        next_sleep = 1min;
    }
    schedule next_sleep { check_state(c) };
}

event dce_rpc_bind(c: connection, fid: count, ctx_id: count, uuid: string, ver_major: count, ver_minor: count) &priority=20
{
    if (!c?$dce_rpc_backing) {
        schedule 1min { check_state(c) };
    }
}

[awelzel]

Hey @JustinAzoff , yeah I think we need something like that also for dce-rpc. For the happy path, handling smb2_close_request() should already help enough. I was glancing at doing the "log outstanding request", but I got too confused how this currently is supposed to work..

diff --git a/scripts/base/protocols/dce-rpc/main.zeek b/scripts/base/protocols/dce-rpc/main.zeek
index 21ab584f7..02d8f1165 100644
--- a/scripts/base/protocols/dce-rpc/main.zeek
+++ b/scripts/base/protocols/dce-rpc/main.zeek
@@ -217,6 +217,22 @@ event dce_rpc_response(c: connection, fid: count, ctx_id: count, opnum: count, s
                }
        }

+
+# If a fid representing a pipe was closed, remove it from the BackingState
+# in dce_rpc_backing table.
+#
+# XXX: How would we know if the last request/response for the pipe still
+#      needs to be logged or has already?
+event smb2_close_request(c: connection, hdr: SMB2::Header, file_id: SMB2::GUID) &priority=-5
+       {
+       local fid = file_id$persistent + file_id$volatile;
+       if ( c?$dce_rpc_backing )
+               delete c$dce_rpc_backing[fid];
+       }
+
+
+# XXX: This is pretty broken: If we didn't log the last request and c$dce_rpc_bind
+#      is set, we'll go through the whole backing table and log everything again.
 hook finalize_dce_rpc(c: connection)
        {
        if ( ! c?$dce_rpc )

I'll take a peek at the smb analyzer, we should be able to do the same in pac to clean out the analyzers from the map.