Adding connection data to the SSL log

Hello Zeek community,

I’m trying to add connection data including duration, orig_bytes, and resp_bytes to some of the logs that don’t usually have these fields. Keying off of the connection_state_remove event, I’m able to add the fields to some logs, such as RDP, but I’m having trouble adding the fields to the SSL log. When I run my script against different pcap files containing SSL traffic, the desired fields appear in the log but aren’t populated. Putting a “print c$ssl;” in the script shows that at least when the script is running, the fields appear to be populated correctly, but somehow aren’t then written to the SSL log. The logic of the script that works to populate these fields successfully in the RDP log doesn’t appear to work the same for the SSL log. Would appreciate any help you can provide. Thank you kindly.

export {

redef record SSL::Info += {

duration: interval &log &optional;

orig_ip_bytes: count &log &optional;

resp_ip_bytes: count &log &optional;

};

}

event connection_state_remove (c: connection)

{

if (! c?$ssl) return;

if ( c?$ssl && c?$duration){

c$ssl$duration = c$duration;

}

if ( c?$ssl && c$conn?$orig_ip_bytes){

c$ssl$orig_ip_bytes = c$conn$orig_ip_bytes;

}

if ( c?$ssl && c$conn?$orig_ip_bytes){

c$ssl$orig_ip_bytes = c$conn$orig_ip_bytes;

}

#print c$ssl;

}

SSL doesn't write its log on connection_state_remove, you'll want hook
ssl_finishing instead
-s

Unfortunately, hook ssl_finishing doesn't appear to work for this either. Creating an entirely new log and using the connection_state_remove event, the connection data and SSL::Info fields can both be written, but this is not ideal due to duplication of data (and possibly missing additional field values in SSL:Info, if the log is written later than connection_state_remove?)

‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐

Hi Virgil,

first - note that the accuracy of this response depends a bit on the Zeek version that you are running. I assume that you are running Zeek 3.0 for this.

What you are trying to do here is a bit more complex for SSL than for a lot of other protocols. The reason for this is that, unlike for a lot of other protocols, the ssl.log typically is not written at the end of the connection. Instead it is written when the connection switches to be encrypted - because after that time we cannot read any more information that typically would make it into ssl.log.

So - Smoot is correct that — typically — you would use the ssl_finishing hook to change the ssl log files. However, in this specific case you cannot use it because the information that you want is only available at the end of the connection.

Funnily what you want to achieve here is surprisingly difficult since we did not forsee this specific use-case. For up to 15 seconds of delay, you can use delay-tokens (which are another special case of the ssl logs). However, these are not really enough in this case.

You already came up with a workable solution - which is creating an entirely new log. It is also possible to just disable the logging mechanism that is used by the ssl scripts - and instead use your own logging. Note that this is kind of hack-ish and I am not really sure I would recommend it.

In any case, you could do something along these limes:

export {
  redef record SSL::Info += {
    duration: interval &log &optional;
    orig_ip_bytes: count &log &optional;
    resp_ip_bytes: count &log &optional;
  };
}

event ssl_established(c: connection) &priority=-4
  {
  # pretend that this record already was logged.
  c$ssl$logged = T;
  }

# Starting at 3.1.0-dev.282, we switch to successful_connection_remove
@if ( Version::at_least("3.1.0") && ( Version::info$beta = T || Version::info$commit == 0 || Version::info$commit >= 282 ) )
event successful_connection_remove(c: connection) &priority=-4
@else
event connection_state_remove(c: connection) &priority=-4
@endif
  {
  if ( ! c?$ssl )
    return;
    
  if ( c?$ssl && c?$duration)
    c$ssl$duration = c$duration;
  if ( c?$ssl && c$conn?$orig_ip_bytes)
    c$ssl$orig_ip_bytes = c$conn$orig_ip_bytes;
  if ( c?$ssl && c$conn?$resp_ip_bytes)
    c$ssl$resp_ip_bytes = c$conn$resp_ip_bytes;
    
  # let it be logged by the event with priority -5
  c$ssl$logged = F;
  }

Johanna

Thank you kindly, this is very helpful, and the context is helpful too.

Does there exist a reference document that would show the timing and/or order of what's happening internally in Zeek as traffic is processed? Using this example, something that might show the timing of when the SSL log is written and the preceding and following internal events? I haven't seen such a reference but it would be useful to have for unusual problems like this.
Thanks again!

‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐

Hi Virgil,

Thank you kindly, this is very helpful, and the context is helpful too.

Does there exist a reference document that would show the timing and/or order of what's happening internally in Zeek as traffic is processed? Using this example, something that might show the timing of when the SSL log is written and the preceding and following internal events?

Nothing that I know of. You can kind of figure such things out by loading the misc/dump-events script. That script dumps out the events that are processed in the order that they are processed. If you use that with a fairly minimal pcap file, it is not too hard to figure out what is going on.

In addition to that, for use-cases that are a bit outside of the norm, you might always still have to look at what exactly the base script for the protocol that you are interested in is doing.

Johanna