Splunk-Apps icon indicating copy to clipboard operation
Splunk-Apps copied to clipboard

Timestamps processing for CDL sources over HTTPS is not correct

Open MonkeyKa opened this issue 4 years ago • 7 comments

Describe the bug

All CDL sources map to an expected sourcetype of pan:firewall_cloud. This means that Splunk uses a consistent set of rules for all log events sent. Either ingestion time, the first timestamp found.

types sent by CDL include Traffic Threat GlobalProtect USERID HIPMATCH SYSTEM (probably more)

Expected behavior

More useful fields for timestamp by log type are likely For Traffic: SessionStartTime SYSTEM: EventTime All others: TimeGenerated

Possible solution

assume different sourcetypes for CDL Traffic and system logs to allow for different time stamp processing.

I currently have and Admin OnDemand request with Splunk to see if an appropriate TIME_PREFIX will allow selecting timestamp by finding a prioritized list of field names

TIME_PREFIX = (SessionStartTime: |EventTime: |TimeGenerated: )

based on a Splunk Answers post by Woodcock https://community.splunk.com/t5/Splunk-Search/How-to-write-regex-to-identify-and-use-time-field-B-for-event/m-p/129562

Steps to reproduce

  1. Install latest Splunk add-on for Palo Alto Networks to Splunk
  2. Set up Splunk HEC with endpoint defined to index=pan_logs sourcetype=pan:firewall_cloud
  3. Configure CDL to sent log streams over HTTPS the the Splunk HEC endpoint
  4. on log ingestion note that they all use the same rule to determine timestamp

Your Environment

Splunk Enterprise 8.0.7 Splunk_TA_paloalto 6.6.0

MonkeyKa avatar Aug 03 '21 20:08 MonkeyKa

More on this: Splunk AoD gave this config to pull event time between event types from CDL:

SHOULD_LINEMERGE = false
LINE_BREAKER = ([\r\n]+)
KV_MODE = JSON
TIME_PREFIX = (SessionStartTime":"|EventTime":"|TimeGenerated":")
TIME_FORMAT =
MAX_TIMESTAMP_LOOKAHEAD = 27
TRUNCATE = 50000

Basically if SessionStartTime is found, use what follows; otherwise if EventTime is found, use what follows; otherwise if TimeGenerated is found, use what follows


The only problem with this is that it does not automatically work on a Splunk HEC endpoint. I've since learned that Splunk has HEC endpoints for HTTPS sent JSON events or _raw logs. When sending JSON events to the event endpoint, Splunk does not honor any config. It just sets JSON ingestion time If events are sent to the _raw log endpoint, Splunk will honor config, but the _raw log endpoint cannot handle multiple logs being sent in one HTTPS request (which I have to imagine CDL would want to do) I don't have a good answer for this. Does PA have any ideas on how to best handle it?

reference on the HEC endpoints for event vs _raw https://medium.com/adarma-tech-blog/splunk-http-event-collectors-explained-2c22e87ab8d2 https://docs.splunk.com/Documentation/Splunk/8.2.3/Data/FormateventsforHTTPEventCollector

MonkeyKa avatar Nov 15 '21 23:11 MonkeyKa

Hi @MonkeyKa Thanks for creating this issue and bringing it to our attention. I will investigate this further and see if we can come up with a solution.

paulmnguyen avatar Nov 24 '21 23:11 paulmnguyen

I would like some clarification on what you are expecting. From what I've read it seems you are interested in having different fields be used as the timestamp in Splunk.

  • Traffic logs should use SessionStartTime.
  • System to use EventTime.
  • Others to use TimeGenerated.

Currently, we have configured HTTPS logs to use "TimeGenerated" as this is the timestamp the log was actually created. You are welcome to customize this. You would have to create a props.conf file in your local directory and add the changes you recommended. This should essentially give you timestamps you are looking for in Splunk.

paulmnguyen avatar Nov 24 '21 23:11 paulmnguyen

Hello @paulmnguyen

I am observing the same issue that @MonkeyKa described here.

Yes, the "TimeGenerated" is extracted as _time in the PA addon, But it looks like it doesn't work when we use the HTTP event endpoint.

when the events are formatted in JSON array from CDL, it's having another field called "time" appended before the event array. Pls refer to the Example event in the below URL, https://docs.paloaltonetworks.com/cortex/cortex-data-lake/cortex-data-lake-getting-started/get-started-with-log-forwarding-app/forward-logs-to-an-https-server.html

image

So as per the Splunk HEC documentation, HEC honors the timestamp in the JSON envelope and that's what is happening here.

https://docs.splunk.com/Documentation/Splunk/8.2.3/Data/HECRESTendpoints

image

let me add a screenshot of the logs from my end, You can see the difference between TimeGenerated and _time in the screenshot below.

image

For testing the parser, I extracted the logs and manually added the data into Splunk, then the "TimeGenerated" value is getting mapped properly. So this issue is happening only the events are sent view HEC event endpoint.

From my view, if the time is removed from the JSON array schema and auto_extract_timestamp is enabled in the HEC URL, then the HEC should be able to honor that TimeGenerated from the event array.

I also tested the same in my environment, I sent 2 events to the Splunk HEC, one with "time" in JSON array, another without "time" in the JSON array. The same can be tested In any environment.

Event sample:

{"time": 1437522387,"host": "stream-logf-111-111-11-1111-11","source": "Palo Alto Networks FLS AA","event":{"TimeReceived":"2021-11-15T07:50:26.000000Z","DeviceSN":"no-123","LogType":"USERID","Subtype":"login","ConfigVersion":"10.0","TimeGenerated":"2021-11-29T07:55:21.000000Z","VirtualLocation":"abc11111","SourceIP":"10.1.1.1","User":"rajkumar_with_time_in_json_array","MappingDataSourceName":"aaa","EventID":"0","CountofRepeats":1,"MappingTimeout":2700,"SourcePort":0,"DestinationPort":0,"MappingDataSource":"aaaaaa","MappingDataSourceType":"","SequenceNo":1234567,"DGHierarchyLevel1":453,"DGHierarchyLevel2":461,"DGHierarchyLevel3":0,"DGHierarchyLevel4":0,"VirtualSystemName":null,"DeviceName":"bbbb","VirtualSystemID":1,"MFAFactorType":null,"AuthCompletionTime":"2021-11-15T07:50:17.000000Z","AuthFactorNo":1,"UGFlags":"123","UserIdentifiedBySource":"xyz","Tag":null,"TimeGeneratedHighResolution":"2021-11-15T07:50:11.550000Z"}} {"host": "stream-logf-111-111-11-1111-11","source": "Palo Alto Networks FLS AA","event":{"TimeReceived":"2021-11-15T07:50:26.000000Z","DeviceSN":"no-123","LogType":"USERID","Subtype":"login","ConfigVersion":"10.0","TimeGenerated":"2021-11-29T07:55:21.000000Z","VirtualLocation":"abc11111","SourceIP":"10.1.1.1","User":"rajkumar_WITHOUT_time_in_json_array","MappingDataSourceName":"aaa","EventID":"0","CountofRepeats":1,"MappingTimeout":2700,"SourcePort":0,"DestinationPort":0,"MappingDataSource":"aaaaaa","MappingDataSourceType":"","SequenceNo":1234567,"DGHierarchyLevel1":453,"DGHierarchyLevel2":461,"DGHierarchyLevel3":0,"DGHierarchyLevel4":0,"VirtualSystemName":null,"DeviceName":"bbbb","VirtualSystemID":1,"MFAFactorType":null,"AuthCompletionTime":"2021-11-15T07:50:11.000000Z","AuthFactorNo":1,"UGFlags":"123","UserIdentifiedBySource":"xyz","Tag":null,"TimeGeneratedHighResolution":"2021-11-15T07:50:21.550000Z"}}

Both events reached Splunk, below are the _time field mapping in Splunk for both events ( Just run the query to the get the events, index=* time_in_json_array )

image

1st event has TimeGenerated mapped to the _time field properly because it doesn't have a "time" field when we sent to event to HEC

2nd event took the "time" field mapped to _time field because there was a "time" field in the JSON array which was sent to HEC.

From my point of view, it's very clear that PA has to remove the "time" from the JSON array as the "TimeGenerated" is the actual timestamp of the event.

Palo Alto team, pls correct me if I am wrong in this OR if there is a way to overcome this issue.

Thanks, Raj

Rajkumar-talion avatar Nov 30 '21 04:11 Rajkumar-talion

As called out by Raj, by default Splunk will use the time field for each event as sent to the HEC. This time field is not the same as any other time field for the record --I am guessing that it is either time received at CDL or time that the record was sent. Neither of these is useful for analysis. We'll leave aside what the best timestamp is for a moment to focus on what Splunk is doing

If HTTPS events are sent to the Splunk HEC event endpoint, per Splunks documentation https://docs.splunk.com/Documentation/Splunk/8.2.3/Data/FormateventsforHTTPEventCollector

  • if available event metadata time is used -- and as Raj has shown, the time metadata field is sent

However if event metadata for time is not available on the HEC event endpoint, the Splunk admin-on-demand consultant who I spoke to says Splunk does not parse the JSON to look for a next best time, He told me that Splunk would just set ingestion time for the event and ingests the data as JSON, ignoring any inputs.conf because it knows the data is JSON. This explanation is different than Raj's. And Raj's explanation includes an example, so I am inclined to believe that Splunk does parse the record somehow in that case. If it uses TimeGenerated as he shows, it must be using some kind of config because that is the second timestamp in the raw record.

Now, what is the best timestamp to use? I think that for most events Generated time is good enough.
But for traffic events the session start time is far more useful as it allows for

  • much better analysis of the connection frequency. That is if I were looking for a beacon (and I have looked for beacons), consistent duration between session start times is a very good tell.
  • much better correlation with the host events related to the network traffic

Event time for system events also allows for better correlation with host events, but in this case high precision is not as important.

MonkeyKa avatar Dec 01 '21 00:12 MonkeyKa

Hi @paulmnguyen,

I am also facing the exact same issue. Do you have patch planned for this?

rashishsharma avatar Apr 27 '22 21:04 rashishsharma

Being discussed with CDL product team. Most likely will require change in HEC header. Thanks @paulmnguyen for figuring this out.

btorresgil avatar May 19 '22 17:05 btorresgil

Closing issue as it has been fixed in the CDL header.

paulmnguyen avatar Oct 17 '22 16:10 paulmnguyen