Core: Suricata EVE output over syslog-ng truncated at about 2 KiB

[OliverO2]

Description
Suricata's EVE log messages forwarded via a syslog-ng target to another host appear truncated at a length of about 2 KiB.

Trying to parse the JSON contents then fails, of course, and there seems to be no stable set of elements in a truncated EVE log message, rendering such messages useless.

https://github.com/opnsense/core/issues/3401#issuecomment-502794782 seems to suggest that the length limitation should be gone with the move to syslog-ng.

I have already tried the following:

• Configured the receiving rsyslog daemon to support large messages (16 KiB) and verifying that this works.
• Configured the syslog-ng target with a TCP transport to avoid UDP restrictions.
• Patched these templates:
  
  
  
  • /usr/local/opnsense/service/templates/OPNsense/Syslog/syslog-ng-destinations.conf:
    
    
    
    
    
    • destination: changed network to syslog
    
    
    
  
  
  • /usr/local/opnsense/service/templates/OPNsense/Syslog/syslog-ng.conf:
    
    
    
    
    
    • options: added log_msg_size(131072);
    
    
    
  
  

To Reproduce

1. Configure Suricata for EVE syslog.
2. Create a syslog-ng log target forwarding Suricata log messages via TCP.
3. Force a Suricata alert with a larger payload.

I have also attached a small test script capable of sending large messages via different syslog interfaces. (However, I did not research which one Suricata is actually using.)

• log-test.py.txt

Expected behavior
Suricata should be able to transmit complete EVE syslog messages, including (at least the printable version of) the payload.

Environment
OPNsense 19.7.5_5-amd64
FreeBSD 11.2-RELEASE-p14-HBSD

[AdSchellevis]

It might be this https://github.com/syslog-ng/syslog-ng/issues/2484

I haven’t tried the sysctl yet, but it sounds a lot like what your describing @OliverO2

[OliverO2]

@AdSchellevis wow, that was ultra-quick! :) Thanks for the hint. I'll try to change that sysctl value and see what happens. As soon as I have a result, I'll post here. Should be no later than late Monday.

[AdSchellevis]

Unfortunately it doesn't seem to solve the issue at my end, although I'm not exactly sure what's happening either.

A simple python script sending both via a raw socket and using the syslog lib doesn't seem to be received in full by syslog-ng (/usr/local/sbin/syslog-ng -p /var/run/syslog-ng.pid -F -d -e)

import sys
import syslog
import socket

test_string = "pie9ooloipuo9Iuquohgi1aeghuo7eije9eic1iethaebishi5ujahquaeChee5oodash6iHoaf5Anei7li7iesei3aiPeiZ4IH1ohaeb1eeg5vieco2hootaamuo4eemooNg8ahPhah3heegh9rom5Uxuoghe7beex6aidoh2ia5Cheefe2ahs0shiebaewaihaet2jush7iux0h

syslog.openlog("suricata")
syslog.syslog(syslog.LOG_INFO, test_string + "XXXXX")

sock = socket.socket(socket.AF_UNIX, socket.SOCK_DGRAM)
sock.setsockopt(socket.SOL_SOCKET, socket.SO_SNDBUF, 8192)
sock.connect("/var/run/log")
sock.sendall((test_string + "XXXXX").encode())

[AdSchellevis]

my mistake, it just doesn't seem to log the full packet, when sending all to a file from syslog-ng, it seems to catch the manual sendall().

import socket

test_string = "pie9ooloipuo9Iuquohgi1aeghuo7eije9eic1iethaebishi5ujahquaeChee5oodash6iHoaf5Anei7li7iesei3aiPeiZ4IH1ohaeb1eeg5vieco2hootaamuo4eemooNg8ahPhah3heegh9rom5Uxuoghe7beex6aidoh2ia5Cheefe2ahs0shiebaewaihaet2jush7iux0haeye0ohphiej6laeS0ej2Yeiboozohgeireecae6hahb6rai4xohQuae2ahx8Xahk9aiCiem4OochiFi9icah4ou0ohkoo9moge4aayi0iemaiTu4feephahd7jahgh8thieL8deipig7xe9aehahfeeng0APohng2Eep0ao0gig6ohT7ceinooCoht2eh5Rekeeshietik5ooYoopi6eeS4lahcau7beiqu2ohc1nes6azu2faipohdoo0ohngoochai7ohj4ia8tosh3Oolepi1aet8Ootheexoonai3deing1cee8zei7Iey1biquaePhei5eethofiugahsah1xiibashae3wa3hexucooShab2ohkai4ahnai3hee8zail5Ur8taijeeThae4oot8leipiy3tairaen1teighuhoo2AiD7aiR9zoo3ooC7iexi6iW2athaesohvimoo4ahta6YeebaeT4zohch7woochi9feek5shoquie0cha4terai4phai0uu1piekeeb8uV3uo6Keen6neepouvo3Aetugai3voon5Phae4zogeezeeK7nae1ohS5xi2aiwoh5iezaikaejicez4ae2oolu4Dohpoogae6yeim8oiX3avie4Ta6miiv2riet5Caek0Fae9quie6oung6lohx8moo6sohmeedoh5eu4aigeequu3ieth1loh5eni6voiJ2iquaing9Queegoh9Roh7jooNgeen9eemeowah6Loh3yeesha3iechu7oquuo7ahyahth3ulah0Iesheevae5soh8ahl0see0AudiethaeSohlaim1gae8Ohk3oh4oojeehei5airahNool6ephieguree2rai0ughaiba9ya0Hoowook2pie6WezuothaisiuHae2ohCh6ahvooXaeboo7aeCeelaiyachi0ShunikooSah5aiqu5cheefaexoko6EiteejooYoh3Gah3gahgoog5Shahghee5DakaeLahshu8ceifoh2eenaidooK2yeir7aevaFoi7aeDuun3booR8maajacuf1ahluphoreiche1eif7dauvethui6sahkaig1aera7theupa1oovah4vooZ4aiR9uingee4Iiyoo2iemohshaifahf1ohphoochahfah5ru4aivai9eehie7Quai5phohquaote2taelolaiJooLahng8Geg4iag3shaey4Iug7iefudeV8ues5Raigh5kiu5quuowu9WeengaeghuuphohFiif9johveiKiem0se1oorohreehoh0UGhei0ooph2azia4za2uj3ahgh3phu3exohweesie5eemeo0sah8eef3deeseiD3uuph7EipeeQuazieviiwahr9eeMa6voopoo8wei2mee3eD8evaekooshoh8Paejuof8yoeR0poa5eothoch2Geigoh7iechieg4gaiF6eicoo7Aiweu5aiceacar6haey7FeiChiemaigom3iuyaveiSh8iezoo1aep7ephuu6yahahSaekeiPooh4ze4saeghuk7Ihee9Fae8Aiqui6boon3aGhelohfohph8ZaenauJ8ahquoofi7naKeeGhaphohghoo0feen7aemeexuL3ech8Eith1Ahshae0iera1OobeiKieco2cheaY2Iesh4kazieM8hie1fohyohzahHahf2Iem7ooseek0he5uotootheu9fe1baeThaidahs6tahcem3rieka1Eefeeng6iezie9quaehu2ael7Iecahre7shieCaarooTeikohcEND"

sock = socket.socket(socket.AF_UNIX, socket.SOCK_DGRAM)
sock.setsockopt(socket.SOL_SOCKET, socket.SO_SNDBUF, 8192)
sock.connect("/var/run/log")
sock.sendall((test_string + test_string + "XXXXX").encode())

Next tried to forward the same content to a tcp-syslog destination, which seems to be working too, I guess our (configuration?) issue is somewhere in suricata.

The python syslog.syslog() seems to be limited by default.

[AdSchellevis]

I think I have to agree with the last posting in the syslog-ng issue, suricata sends a message to syslog() which on FreeBSD seems to be limited at 2048 bytes now.

https://github.com/freebsd/freebsd/blob/11c242c7312a2c5301e5fe9a8bf4ddf0f372a226/lib/libc/gen/syslog.c#L141

I have to consult with @fichtner to confirm and see what's the next step here.

[fichtner]

Quick compare with OpenBSD:

https://github.com/freebsd/freebsd/blob/11c242c7312a2c5301e5fe9a8bf4ddf0f372a226/lib/libc/gen/syslog.c#L141
https://github.com/openbsd/src/blob/b66614995ab119f75167daaa7755b34001836821/sys/sys/syslog.h#L42

It seems that at some point or another arbitrary data via syslog isn't the best way to do it.

In any case, we can easily try to bump the limit in our src.git.

[AdSchellevis]

question is what a sane default is... If I'm understanding it correctly, linux seems to be using glibc's version, which accepts arbitrary lengths (probably the reason why this works on linux).

https://sourceware.org/git/?p=glibc.git;a=blob;f=misc/syslog.c;h=fd6537edf60e8ad637e97bdebbd5477a433d6db7;hb=refs/heads/master

eve alerts can grow pretty quickly, the syslog facility is a practical transport message from a software design point of view (consistency), but I'm not sure what the best fix is yet. Short term solution could be extending it, long term, it doesn't sound like the greatest plan in the world.

Let's think this over for a while and decide what todo later.

[fichtner]

we should bump to 8k and ship if it works, beyond that others will have to take over

[AdSchellevis]

8k still sounds small, but I agree it's an easy starting point, aligns with OpenBSD and likely solves some of the issues.

[OliverO2]

I have checked the distribution of EVE log message sizes on a sample of 8270 messages observed during the last month:

• Maximum message length (including binary and printable payload): 60k (1 occurrence)
• Maximum binary payload length: 34k (1 occurrence)
• Maximum printable payload length: 25k (1 occurrence)
• Maximum net message length (without payload data): 3k (NOTE: This figure is exaggerated as the subtracted payload lengths were calculated on parsed JSON data, which is shorter that its source.)
• 8182 (98,9%) printable payloads fit into 4k
• 8262 (99,9%) printable payloads fit into 6k
• 8 (0,1%) printable payloads required more than 6k

The longer printable payloads appeared to be useful even if truncated to about 4k.

However, this template sets Suricata's max payload size for EVE syslog output to 100kb:

• https://github.com/opnsense/core/blob/master/src/opnsense/service/templates/OPNsense/IDS/suricata.yaml#L138

All EVE data from my sample would fit into an 8k syslog limit without truncation, if EVE output to syslog were configured like this in src/opnsense/service/templates/OPNsense/IDS/suricata.yaml:

{% if not helpers.empty('OPNsense.IDS.general.LogPayload') %}
             payload: no
             payload-buffer-size: 4kb
             payload-printable: yes
{% endif %}

Note that this change would not affect the payload limits for file-based EVE logging.

I'd be in favor of changing the syslog limit to 8k as suggested and also modifying the Suricata template as shown above.

[fichtner]

@OliverO2 very helpful, thanks!

[fichtner]

There's a test base update available:

# opnsense-update -br 19.7.3_2

A reboot should make the new syslog buffer size effective. Should be easy to test with the proposed suricata.yaml changes. :)

Cheers,
Franco

[AdSchellevis]

@OliverO2 https://github.com/opnsense/core/commit/188c517a262d8ebd9752dc0a12acfab73bc4786a contains the suricata.yaml fix, which should solve the last piece of this issue.

[OliverO2]

Thanks to both of you, @fichtner, @AdSchellevis.

I'll put this to a test right away and will report results here. I've commented on 188c517a262d8ebd9752dc0a12acfab73bc4786a as I think that fix needs an additional tweak. Otherwise I'm pretty optimistic that we've nailed it.

[OliverO2]

Just a short feedback from the trenches: Testing continues (has been running for 19 hours by now), I have yet to see a message containing a sufficiently large printable payload.

[OliverO2]

Still not working unfortunately, but easily reproducible:

Reproduction

I have found a way to reproduce an IDS alarm with a payload that will produce a log message of 5383 bytes length. This should be the complete sequence of steps:

1. Install test base update 19.7.3_2
2. Modify templates/OPNsense/IDS/suricata.yaml as described above.
3. Configure Suricata
   
   
   
   • Alert on sid 2007671 from the emerging-policy.rules ruleset
   
   
   • Enable syslog alerts [x]
   
   
   • Enable eve syslog output [x]
   
   
   • Log package payload [x]
   
   
4. Configure _System: Settings: Logging / targets_
   
   
   
   • forward Suricata logging via TCP
   
   
5. Reboot
6. Download a Windows Update executable over a network connection monitored by Suricata (this is what I've used on Linux):
   curl http://au.download.windowsupdate.com/c/msdownload/update/software/defu/2019/11/am_delta_patch_1.305.1884.0_348c56fbcc95588923aa2beaf36351b25200b48b.exe >/dev/null

Tests Results

With the base update 19.7.3_2 installed, the 5k+ log message from the above event was not forwarded by syslog-ng at all. The corresponding fast log message from Suricata appeared normally. (Before that, shorter (below 2k) EVE log messages got forwarded correctly as well).

So it seems that an EVE log message which previously got truncated is now suppressed.

[AdSchellevis]

Ok, quite weird indeed, messages seem to vanish completely now (in stead of being truncated).
Code below only sends out TEST2 the long message is gone.

import syslog

test_string = "pie9ooloipuo9Iuquohgi1aeghuo7eije9eic1iethaebishi5ujahquaeChee5oodash6iHoaf5Anei7li7iesei3aiPeiZ4IH1ohaeb1eeg5vieco2hootaamuo4eemooNg8ahPhah3heegh9rom5Uxuoghe7beex6aidoh2ia5Cheefe2ahs0shiebaewaihaet2jush7iux0haeye0ohphiej6laeS0ej2Yeiboozohgeireecae6hahb6rai4xohQuae2ahx8Xahk9aiCiem4OochiFi9icah4ou0ohkoo9moge4aayi0iemaiTu4feephahd7jahgh8thieL8deipig7xe9aehahfeeng0APohng2Eep0ao0gig6ohT7ceinooCoht2eh5Rekeeshietik5ooYoopi6eeS4lahcau7beiqu2ohc1nes6azu2faipohdoo0ohngoochai7ohj4ia8tosh3Oolepi1aet8Ootheexoonai3deing1cee8zei7Iey1biquaePhei5eethofiugahsah1xiibashae3wa3hexucooShab2ohkai4ahnai3hee8zail5Ur8taijeeThae4oot8leipiy3tairaen1teighuhoo2AiD7aiR9zoo3ooC7iexi6iW2athaesohvimoo4ahta6YeebaeT4zohch7woochi9feek5shoquie0cha4terai4phai0uu1piekeeb8uV3uo6Keen6neepouvo3Aetugai3voon5Phae4zogeezeeK7nae1ohS5xi2aiwoh5iezaikaejicez4ae2oolu4Dohpoogae6yeim8oiX3avie4Ta6miiv2riet5Caek0Fae9quie6oung6lohx8moo6sohmeedoh5eu4aigeequu3ieth1loh5eni6voiJ2iquaing9Queegoh9Roh7jooNgeen9eemeowah6Loh3yeesha3iechu7oquuo7ahyahth3ulah0Iesheevae5soh8ahl0see0AudiethaeSohlaim1gae8Ohk3oh4oojeehei5airahNool6ephieguree2rai0ughaiba9ya0Hoowook2pie6WezuothaisiuHae2ohCh6ahvooXaeboo7aeCeelaiyachi0ShunikooSah5aiqu5cheefaexoko6EiteejooYoh3Gah3gahgoog5Shahghee5DakaeLahshu8ceifoh2eenaidooK2yeir7aevaFoi7aeDuun3booR8maajacuf1ahluphoreiche1eif7dauvethui6sahkaig1aera7theupa1oovah4vooZ4aiR9uingee4Iiyoo2iemohshaifahf1ohphoochahfah5ru4aivai9eehie7Quai5phohquaote2taelolaiJooLahng8Geg4iag3shaey4Iug7iefudeV8ues5Raigh5kiu5quuowu9WeengaeghuuphohFiif9johveiKiem0se1oorohreehoh0UGhei0ooph2azia4za2uj3ahgh3phu3exohweesie5eemeo0sah8eef3deeseiD3uuph7EipeeQuazieviiwahr9eeMa6voopoo8wei2mee3eD8evaekooshoh8Paejuof8yoeR0poa5eothoch2Geigoh7iechieg4gaiF6eicoo7Aiweu5aiceacar6haey7FeiChiemaigom3iuyaveiSh8iezoo1aep7ephuu6yahahSaekeiPooh4ze4saeghuk7Ihee9Fae8Aiqui6boon3aGhelohfohph8ZaenauJ8ahquoofi7naKeeGhaphohghoo0feen7aemeexuL3ech8Eith1Ahshae0iera1OobeiKieco2cheaY2Iesh4kazieM8hie1fohyohzahHahf2Iem7ooseek0he5uotootheu9fe1baeThaidahs6tahcem3rieka1Eefeeng6iezie9quaehu2ael7Iecahre7shieCaarooTeikohcEND"

syslog.openlog("suricata")
syslog.syslog(syslog.LOG_INFO, test_string + "XXXXX")
syslog.syslog(syslog.LOG_INFO, "TEST2")

maybe @fichtner has an idea, I don't see very obvious issues in the syslog changes at a first glance.

[OliverO2]

Monitoring the test code from @AdSchellevis via truss reveals that the sendto call on the /var/run/logpriv socket returns ERR#40 'Message too long':

# truss python3 /tmp/log-test2.py
[...]
socket(PF_LOCAL,SOCK_DGRAM|SOCK_CLOEXEC,0)   = 3 (0x3)
connect(3,{ AF_UNIX "/var/run/logpriv" },106)    = 0 (0x0)
sendto(3,"<14>Nov 14 08:15:36 suricata: pi"...,2083,0,NULL,0) ERR#40 'Message too long'
close(3)                     = 0 (0x0)
socket(PF_LOCAL,SOCK_DGRAM|SOCK_CLOEXEC,0)   = 3 (0x3)
connect(3,{ AF_UNIX "/var/run/logpriv" },106)    = 0 (0x0)
sendto(3,"<14>Nov 14 08:15:36 suricata: pi"...,2083,0,NULL,0) ERR#40 'Message too long'
sendto(3,"<14>Nov 14 08:15:36 suricata: TE"...,35,0,NULL,0) = 35 (0x23)
[...]

[OliverO2]

This will make it work:

# sysctl net.local.dgram.maxdgram=8196
net.local.dgram.maxdgram: 2048 -> 8196

After changing that value, Ad's test code runs as expected: both messaged are transferred to a configured syslog-ng target.

[AdSchellevis]

@OliverO2 thanks! we might need to change that default too in our default config. @fichtner what do you think?

[fichtner]

Yes please 😊

On 14. Nov 2019, at 08:36, Ad Schellevis [e-mail] wrote:


@OliverO2 thanks! we might need to change that default too in our default config. @fichtner what do you think?

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub, or unsubscribe.

[AdSchellevis]

@OliverO2 ok, this https://github.com/opnsense/core/commit/8917f1c06f18931bb52cc0fdb005c651bccc9f4b should be the final piece then. Closed the issue with it, can always reopen if it appears we still missed something. Thanks for your help!

[OliverO2]

@AdSchellevis, @fichtner yes, looks completely resolved now. I have just tested with Suricata and got a nicely forwarded syslog message of 3011 bytes.

Thanks for the excellent cooperation!