topic Re: Sending logs over scp to heavy forwarder, why does splunk mangle, improperly break some of the events? in All Apps and Add-ons

Sending logs over scp to heavy forwarder, why does splunk mangle, improperly break some of the events?

JSkier — Tue, 06 Jun 2017 16:27:31 GMT

I'm using heavy forwarder to take logs in from a cloud ESA appliance. The logs sending over every 5 minutes via scp (deleting old files every 2 hours after modtime stops) work fine, line by line and time stamps all good. For some reason splunk is randomly ingesting some events by grabbing from a random place in the file, giving it a time stamp, and calling it an event.

For example, I most commonly get 1 - 3 characters, like ile, or id. Sometimes I get the middle to the end of an event. I don't understand why it's doing this, there is no line breaking (it's disabled) and I have enabled crcsalt by source.

I'm using splunk 6.4.6 on the indexers, and 6.6.1 on the heavy forwarder (started with 6.4.6). If I upload the file to my dev box, it's fine; for some reason the monitor feature of splunk is having issues. I also ingest WSA (but with universal forwarder) over scp, and I don't have these issues.

I have put the ESA app on the heavy forwader and search heads. Also tried just indexers and search heads, only input on heavy forwarder. None this changed anything.

This is all virtualized Linux, Ubuntu 64bit LTS servers.

props.conf:

CHARSET = utf-8
MAX_TIMESTAMP_LOOKAHEAD = 24
NO_BINARY_CHECK = true
SHOULD_LINEMERGE = false
TRUNCATE = 250000
TIME_PREFIX = \w{3}\s
TRANSFORMS-drop=esa_header_drop

transforms.conf

[esa_header_drop]
REGEX=^.*Info:\s(Begin\sLogfile|Logfile\srolled\sover|End\sLogfile|Version\:\s|Time\soffset\sfrom\sUTC\:).*
DEST_KEY=queue
FORMAT=nullQueue

I log amp, mail, gui, auth, http, via scp. They all have the props above, individually configured.

Sample event (good and bad) from one, full auth file:

le
Tue Jun  6 15:12:22 2017 Info: A publickey authentication attempt by the user ***** from 0.0.0.0 failed using an SSH connection.
Tue Jun  6 15:10:40 2017 Info: logout:10.0.0.1 user:- session:blahgfregre 
Tue Jun  6 15:09:28 2017 Info: logout:10.0.0.25 user:- blaggj4iogjio3 
Tue Jun  6 15:09:20 2017 Info: A publickey authentication attempt by the user ***** from 0.0.0.0 failed using an SSH connection.

Below is a screenshot of search finding one event, that gets mangled and duplicated (using the suggestion break before regex). Checking the file, there is only one event on one line, no idea why splunk is doing this.

Re: Sending logs over scp to heavy forwarder, why does splunk mangle, improperly break some of the events?

MuS — Tue, 06 Jun 2017 16:33:04 GMT

One thing I can think of is that the files come in slowly and Splunk breaks too early, therefore you get garbage lines. Have a look at the docs http://docs.splunk.com/Documentation/Splunk/latest/Admin/Inputsconf of inputs.conf for the options

time_before_close = <integer>
* Modification time delta required before the file monitor can close a file on
  EOF.
* Tells the system not to close files that have been updated in past <integer>
  seconds.
* Defaults to 3.

multiline_event_extra_waittime = [true|false]
* By default, the file monitor sends an event delimiter when:
  * It reaches EOF of a file it monitors and
  * Ihe last character it reads is a newline.
* In some cases, it takes time for all lines of a multiple-line event to
  arrive.
* Set to true to delay sending an event delimiter until the time that the
  file monitor closes the file, as defined by the 'time_before_close' setting,
  to allow all event lines to arrive.
* Defaults to false.

Re: Sending logs over scp to heavy forwarder, why does splunk mangle, improperly break some of the events?

JSkier — Tue, 29 Sep 2020 14:23:16 GMT

I've tried time_before_close = 120 which didn't do anything.

I'll try the multiline option, however all events are one line and I have line merge disabled (as it should be; all events are one line).

I turned on time before close and added the multi-line option, I'll see what happens.

Re: Sending logs over scp to heavy forwarder, why does splunk mangle, improperly break some of the events?

JSkier — Tue, 06 Jun 2017 17:02:53 GMT

Nope, still happening.

Re: Sending logs over scp to heavy forwarder, why does splunk mangle, improperly break some of the events?

MuS — Tue, 06 Jun 2017 18:09:19 GMT

can you post the props.conf settings for the used sourcetype and some sample events of good and bad events?

Re: Sending logs over scp to heavy forwarder, why does splunk mangle, improperly break some of the events?

JSkier — Tue, 06 Jun 2017 19:19:46 GMT

Changed in edit above.

Re: Sending logs over scp to heavy forwarder, why does splunk mangle, improperly break some of the events?

MuS — Tue, 06 Jun 2017 19:53:59 GMT

Why do you say there is no line breaking? The default line breaking is still happening.
Can you please add the raw event for one or two bad examples? There must be something triggering the line break or truncate ....

Re: Sending logs over scp to heavy forwarder, why does splunk mangle, improperly break some of the events?

JSkier — Tue, 06 Jun 2017 20:28:33 GMT

I threw in one file parsed by splunk as an example. Top entry is bad (also have unable to parse timestamp error in splunkd.log as well).

When I say no line breaking, all events are always one line, splunk is doing the line breaking (why, I don't know, that's why I'm here). Support is scratching their heads on this so far too.

Re: Sending logs over scp to heavy forwarder, why does splunk mangle, improperly break some of the events?

skalliger — Tue, 29 Sep 2020 14:19:32 GMT

I would try using BREAK_ONLY_BEFORE = RegEx

Use the RegEx for your timestamp here (write it yourself), so your events should only get split up when a new timestamp occurs.

Skalli

Re: Sending logs over scp to heavy forwarder, why does splunk mangle, improperly break some of the events?

JSkier — Wed, 07 Jun 2017 15:01:57 GMT

Thanks for the suggestion, this also doesn't work (still breaks and ends randomly).

Thinking this is a bug with monitoring feature on the heavy forwarder, but I'm open to more suggestions.

A side note, elasticsearch and filebeat sending the events from the same box don't have this problem at all; seems indicative that this is a splunk bug. Either way, once I find something that works through support, community, or just banging my head against the splunk wall until it works, I'll post it here.

Re: Sending logs over scp to heavy forwarder, why does splunk mangle, improperly break some of the events?

mattymo — Tue, 29 Sep 2020 14:23:55 GMT

I dont think its a bug, i think its the write buffers in your file. If you tail the file, you might even visually see the break. If the breaks happen often, fire up a tail -f and grab a coffee lol

You can confirm this by manually indexing the file manually AFTER it has been completely copied to the dir (oneshot) or just scp to ur desktop and upload the data into the add data wiz to confirm your props are all good

If the linebreaking is all good, then you have proven that all your config is fine, and you are dealing with a timing issue.

I would suggest, an easy way around this is to use a cronjob to move the files from the landing dir, to a different dir splunk is monitoring and I bet you dont see this issue.

I dont know enough ( or care to investigate) how Elastic and filebeat monitor the files, but Splunk is doing a live tail of the file so the time_before_close and multiline should get you close, but the main issue here is it can be an issue when monitoring a file AS it is being written.

Re: Sending logs over scp to heavy forwarder, why does splunk mangle, improperly break some of the events?

JSkier — Tue, 29 Sep 2020 14:20:10 GMT

When I uploaded to the dev box, it works fine. I think you're on to something with the ESA uploading via scp several files and splunk ingesting them in near real-time. I used time_before_close=120 and it didn't do anything.

I just had a short file come in while tailing, about 10 lines that splunk mangled twice. The tail -f command showed the file as it is on the filesystem (correctly), so me tailing the file isn't showing a problem.

What is odd is, the WSA (same Cisco appliance OS) sends the logs over in a similar fashion and doesn't have this problem at all (we've had this running for years now). Not sure why now it is all of a sudden a problem.

Re: Sending logs over scp to heavy forwarder, why does splunk mangle, improperly break some of the events?

mattymo — Wed, 07 Jun 2017 19:51:17 GMT

out of curiosity, if you find a broken event, then go back to the HF and find the real event, you can search those pieces in the index and examine the _indextime to see what the gap was....would be interesting to see if the pieces are on more than one indexer or both...

in the meantime quick cron should solve this for you while you continue to poke...

Re: Sending logs over scp to heavy forwarder, why does splunk mangle, improperly break some of the events?

JSkier — Wed, 07 Jun 2017 20:55:53 GMT

Sure thing. It's happening on both indexers, and the index time is always a few seconds after the original, full event. So, to splunk, it gets queued up as an event without a timestamp. This shows up in splunkd.log, so it gives it a later timestamp based off of the last event because it couldn't find a timestamp. Hopefully that answers your question.

I agree, I'll work on a script to send these over to another folder after modtime hits a certain point. Sounds like a reasonable temporary workaround until a solution is found.

Re: Sending logs over scp to heavy forwarder, why does splunk mangle, improperly break some of the events?

JSkier — Fri, 09 Jun 2017 18:04:36 GMT

I added a script to concatenate the files to a their own respective log files after not being modified for a minute and then deleting them (only if step 1 is successful). This leaves splunk to follow these new log files completely and logrotate handles clean up. This seems to have worked for several hours.

The fact that elasticsearch can monitor the files just fine, and splunk works fine with a buffer tells me there is some kind of a bug with the monitoring feature of the heavy forwarder receiving these types of logs over scp. I will keep this open and also push to have my ticket resolved appropriately.

Re: Sending logs over scp to heavy forwarder, why does splunk mangle, improperly break some of the events?

mattymo — Fri, 09 Jun 2017 21:30:45 GMT

i'm not sure this is a valid comparison at all. You have already stated that other sources have no issue. Please do follow up with support (i have a similar ticket open) but logging live files heavily depends on the process writing the logs. I know we love to call all unknowns "bugs" round here, but lets see if we can get some better proof.

also, are u saying that elastic is monitoring this exact same file??

Re: Sending logs over scp to heavy forwarder, why does splunk mangle, improperly break some of the events?

nnmiller — Fri, 09 Jun 2017 22:07:03 GMT

SSH has pretty bad performance, and therefore, so does scp. Once the network buffer is full, it's slow slow slow. There are a couple of ways around this: a) use the high performance network patches for SSH available here PSC HPN Patches (I use these myself on servers which do large file transfers), or switch to an ftp over SSL implementation, netcat, or similar.

For example, I had a customer using straight ftp to constantly transfer high volume firewall logs like this without issue.

I'm not even sure the HPN patches would do what is needed in this case, because of connection pauses. If logs are not coming continuously through that pipe, then you're going to have the connection restart overhead throwing off your time_before_close. So maybe add something like the following to /etc/ssh/sshd_config:

ClientAliveInterval 120
ClientAliveCountMax 720

I presume there's some sort of security policy to prevent you from just using syslog here?

Re: Sending logs over scp to heavy forwarder, why does splunk mangle, improperly break some of the events?

mattymo — Sat, 10 Jun 2017 01:37:58 GMT

hey side note, are you using forceTimeBasedAutoLB on this HF??

My client was, and I thought I had proved it was unrelated, but I am going to revisit and turn it off. Technically its useless on an HF as I understand anyways...

Re: Sending logs over scp to heavy forwarder, why does splunk mangle, improperly break some of the events?

JSkier — Sat, 10 Jun 2017 01:49:53 GMT

I do have "autolb" set on the output conf, but it seems 6.6.1 doesn't really even support that anymore... Is that what you're referring to?

We have two indexers, when PS set this up, it was before 6.4 came along with better support.

Re: Sending logs over scp to heavy forwarder, why does splunk mangle, improperly break some of the events?

JSkier — Sat, 10 Jun 2017 01:54:50 GMT

Thanks, I didn't think of hpn patches for splunk, but I've used them before for other large transfers. I'll look at giving that, and the configuration suggestions you mentioned a shot for sure.

Yeah, it's a cloud appliance, so no dice sending that stuff in the clear. I use TLS for syslog-ng receiver when I can, but, Cisco doesn't support it for sending from their appliances. It's pretty well wrapped up as an appliance, otherwise I'd say TLS netcat would be worth a go to.

I understand the ssh performance side, but again, elasticsearch beats handling it without issue really points me back to splunk as being the problem. However, with the WSA, that is on prem (also doing scp - because of syslog message length limitations) and it doesn't have these issues. So, it's possible splunk just doesn't like how long it takes to fully copy the file via scp.