Add new event logging options

[p0pr0ck5]

Need flexible logging destinations beyond error.log.

• resty socket logger
• plaintext file logger
• logger settings can use set_option

[p0pr0ck5]

need to emulate the buffering seen in resty socket logger in a file logger. will probably fork that and replace the socket connection code with file io. shudder

no file logging! dumb idea is dumb

[p0pr0ck5]

Actually, this is trickier than I thought, because the configuration interface we expose is per-host, while resty logger socket is config'd globally. Not sure if it's worth pursuing, or if users who need remote logging should implement a third party log shipper.

[nebpor]

Hey Robert, I'm having huge trouble getting FreeWAF to log - I've everything set up as described and using standard OpenResty NGINX build (albeit I've set log level to WARN now)... can't find any reason it's not logging WAF hits to either SQL injection rules or the 90000 rules ... any tips for the unwary?

I get the 302 in access.log when the WAF redirects to the 403 page, but nothing logged from the rule hit itself, which is what I'm interested in.

Lovely project BTW - looking at building some threat scoring and automatic rule updating for it.

Cheers!

[p0pr0ck5]

Hi!

Thanks for your interest in the project! A few things to note:

• Rule event logs are written to the server block's error log, not the access log (you mentioned seeing an entry in the access log, so I just want to confirm you're also checking the error log)
• Rule events are at present written with INFO severity, meaning if you set the error_log severity to WARN, you will not see rule events in the error log (I've opened a separate issue Allow custom log severity for event rule matches #12 to make a note to allow this log level to be configurable via set_option, it should go live later today)

So try setting your nginx's error_log directive to INFO instead of WARN, and let me know if you see entries for matched rules in your error log :) Thanks again for your interest and your note- it's really encouraging to get feedback from the community! I'd also be very open to any input or contribution! Let me know if you have any other questions or still having issue with event logs and we'll take a deeper look.

[nebpor]

Thank you for being so responsive (that's why I picked your WAF :) - that worked great. I was indeed looking in the error log before, as that was where I expected the WAF to log!

I've also incorporated your latest build as well, with the enhanced event_log_level - that's really good as different use cases will want to treat it differently, ie. "block things, I don't care" vs "block things and let me know"

It is now working, however by default it is logging the entirety of the rule it hits, which makes it very difficult to easily extract the event - for the complex rules, for example 41008 SQL injection, it generates a 30 line log entry ... would it be possible to make it configurable to only optionally record those details, so that for example it could just spit out "

Using a simpler rule, 90002 currently logs:
[warn] 23140#0: *24 [lua] fw.lua:276: log_event(): {"match":"rsa","rule":{"id":90002,"description":"SSH key scan (https://isc.sans.edu
/forums/diary/Gimme+your+keys+/18231)","action":"DENY","var":{"type":"URI","operator":"REGEX","pattern":"(?:(?:(?:id(?:(?:dsa(?:.old)?|rsa(?:.old)?)|entif
y)|key(?:.priv)?$|[dr]sa)))"},"opts":{}}}, client: 192.168.251.22, server: www.example.com, request: "GET /rsa_id HTTP/1.1", host: "www.example.com"

It would be great if that could be configurable shortened to something like:
[warn] {"match":"rsa","rule":{"id":90002,"action":"DENY"} {"type":"URI","operator", client: 192.168.251.22, server: www.example.com, request: "GET /rsa_id HTTP/1.1", host: "www.example.com"

You see where I'm going? This would make it easier for most security people to pick up into Splunk or their tool de jour, especially if they're moving from mod_security or similar.

If that is already configurable and I am just a dufus, apols in advance!

[p0pr0ck5]

Hey, really glad that worked out! It's super encouraging to see other people trying this out and using it :)

Because event logging currently makes use of the Nginx error log facility, a portion of the string written to the error log by the event logger cannot be changed (specifically, this portion):

[warn] 23140#0: *24 [lua] fw.lua:276: log_event():

So we wouldn't be able to just squeeze that down to '[warn]' or something similar in the Nginx error log. The portion that we write from fw.lua is a JSON blob; originally when I wrote this for my own uses, I piped error logs over a UDP socket to a separate data processor, but I figured that wouldn't be a good default option for most people, so I stuck it in the error logs. With regards to the size of the blob written, some events can indeed be large because we log the entire rule table (and some of the SQLi/XSS patterns are large optimized regexes). There is currently no way to configure what portions of the blob get logged by _log_event)_, that could get very messy using set_option.

I'm -very- hesitant to implement a separate file logger, largely because avoiding the overhead of separate syscalls and disk IO has been a key focus in developing this- it's why performance is so excellent. Having said that, it may be worth providing as an option for users who don't have ultra-high concurrency needs and want to keep data on-disk.

I think what I may end up pursuing is a global configuration module that would affect all instances in location{} blocks. This would let the user be able to point event logs to a specific UDP server or UNIX socket (for socket logging), or a file handle, and then configure what type of logging (e.g. socket, file, ngx error log, etc) each server/location block uses via set_option. We could also let users decide which portions of the JSON blob they want logged (e.g. not logging the pattern and description, as you suggested) via a global config. Let me chew on this for a few days and I'll let you know :)

[p0pr0ck5]

nebpor,

I pushed up a commit tonight that allows for configurable verbosity of event logs (9ddd3f0). It's on the 'improvements' branch if you'd like to take a look and play around with it.

I also pushed up another commit (aa0cd31) that provides wrappers for UDP socket and local file logging of event logs (not debug logs, those will stay in the error_log). Socket and file logging only log the JSON blob generated from the event data. An example (using the new default minimal verbosity):

root@dev:~# cat /tmp/waf.log
{"timestamp":1422765824,"match":"id_rsa","uri":"/id_rsa","client":"192.168.10.154","rule":{"id":90002}}
{"timestamp":1422765826,"match":"id_rsa","uri":"/id_rsa","client":"192.168.10.154","rule":{"id":90002}}

Socket logging is a -little- buggy in that, because lua-resty-logger-socket provides a single, global target server, we allow for multiple configurations to potentially conflict (in such a case, the global socket_logger object would be init'd with the values of whatever location configuration triggered _log_event() first). If multiple locations elect socket logging and are specified identical host/port values, no conflict will arise (the same logic follows for file logging and event_log_target_path).

I doubt agentzh (or anyone else) is going to put effort into resty logger sharding anytime soon, so I may work on it independently in the future, but for now I'd like to close this out and focus on adding features for a v0.4 release (namely persistent storage).

[nebpor]

Great stuff thanks, this is very helpful - I've moved to your improvements branch and it's now got frugal logs on.

Reason being, I am running this all on AWS and using the Cloudwatch Logs service to send error log to the Cloudwatch service, so I can run metrics across them to create alarms when bad stuff happens. The more minimal the log I can send, then the quicker it can send the logs and the smaller the runtime of the query looking for alarms.

I've got it all auto-building from source and auto-scaling on m3large instances - I'll benchmark it using Bees With Machine guns in the next few weeks so you can get an idea how it scales on AWS. I've scaled it to 10 WAFs at this point and there is no reason it just won't keep scaling!

[p0pr0ck5]

Glad that you're getting some use out of it, and thanks for recommending that change!

Just a reminder - disk-based logging is very inefficient in high-concurrency environments. FreeWAF's workload is designed to be CPU-bound as much as possible, avoiding context switches and external syscalls as part of the main process. I would be excited to see what kind of results you find! Please don't hesitate to open a new issue or send me an email with any results you come up with. Thanks again!