Parsing apache access and error logs and inserting values in clickhouse

[SirUrban]

Hi,

since two weeks now I am struggling with the following task:
I have to receive apache access and error log as syslog messages and insert the separate values into clickhouse tables. With apache access logs I managed to do this using vector and a regex-parser transforms. With error logs I could not find out how to parse them correctly so that a clickhouse sink was able to insert the values into clickhouse.
Then I discovered the "parse_apache_log()" function and I thought it might be easier to use this instead of the regex-parser. But with this function I do have the problem that I do not understand how to get a result which can be handled by the clickhouse sink correctly.

In whole I'd like to do the following:

1. Define an input which receives the syslog messages. That's no problem. I did it like this:

[sources.in]
  address = "0.0.0.0:514" # required, required when mode = "tcp" or mode = "udp"
  mode = "tcp" # required
  type = "syslog" # required

2. I added a transforms section to modify some fields:

[transforms.field_modifier]
  type = "remap"
  inputs = ["in"]
  source = '''
  .uuid = uuid_v4()
  del(.facility)
  del(.severity)
  del(.source_type)
  del(.hostname)
  '''

3. I think I need to have a filter which separates access and error log message to be able to parse them differently (cause they do have different format):

[transforms.access_log_filter]
  type = "filter"
  inputs = ["field_modifier"]
  condition = '.appname == "apache_access"'

[transforms.error_log_filter]
  type = "filter"
  inputs = ["in"]
  condition = '.appname == "apache_error"'

4. I want to transform the syslog event and I want the following to be done:

• parse message field so that all parts (ip, status, path, length, user-agent ...) can be inserted by a sink into separate columns of a clickhouse table.

[transforms.access_log_parser]
  type = "remap"
  inputs = ["access_log_filter"]
  source = '''
  .message = parse_apache_log!(.message, "combined")
  '''

5. Last I have a sink to insert data into clickhouse:

[sinks.access_log]
  host = "http://localhost:8123" # required
  inputs = ["access_log_parser"] # required
  table = "access_log"
  type = "clickhouse" # required
  auth.password = "*****************"
  auth.strategy = "basic"
  auth.user = "default"
  encoding.timestamp_format = "unix"

I also will need a second sink for error logs - but as the sink for access logs does not work yet I left this out yet.

All this does not work. I do get a sink error:

Jun 07 11:05:17.847 ERROR sink{component_kind="sink" component_name=access_log component_type=clickhouse}:request{request_id=0}: vector::sinks::util::retries: Not retriable; dropping the request. reason="response status: 400 Bad Request"
Jun 07 11:05:17.847 ERROR sink{component_kind="sink" component_name=access_log component_type=clickhouse}:request{request_id=0}: vector::sinks::util::sink: Response wasn't successful. response=Response { status: 400, version: HTTP/1.1, headers: {"date": "Mon, 07 Jun 2021 09:05:17 GMT", "connection": "Keep-Alive", "content-type": "text/tab-separated-values; charset=UTF-8", "x-clickhouse-server-display-name": "logexplorer.az-logexplorer.scalecommerce", "transfer-encoding": "chunked", "x-clickhouse-query-id": "aa5965b2-3980-4ab3-82cb-2626492d4c10", "x-clickhouse-format": "TabSeparated", "x-clickhouse-timezone": "Europe/Berlin", "x-clickhouse-exception-code": "26", "keep-alive": "timeout=3", "x-clickhouse-summary": "{\"read_rows\":\"0\",\"read_bytes\":\"0\",\"written_rows\":\"0\",\"written_bytes\":\"0\",\"total_rows_to_read\":\"0\"}"}, body: b"Code: 26, e.displayText() = DB::ParsingException: Cannot parse JSON string: expected opening quote: (while reading the value of key message): (at row 1)\n (version 21.5.5.12 (official build))\n" }

I assume that step 4 is wrong but I have no idea how to do it the right way. For the parsing part I also tried this one:

[transforms.access_log_parser]
  type = "remap"
  inputs = ["access_log_filter"]
  source = '''
  . = parse_apache_log!(.message, "combined")
  '''

This does work so far that values are inserted in clickhouse - but only the parsed parts of the message field not the contents of other fields (uuid, appname, source_ip).
So if anybody could help me to get the message parsed without loosing the other fields - and also how to do it with error logs I'd very much appreciate some support!

[spencergilbert]

I expect you'll want to merge the parsed log event.

The first config you used set the .message field to the parsed results (an object), and the second overwrote the entire event (".") with the parsed results.

So, I think you should either use the merge function, or an object merge assignment (example here) like so:

parsed = parse_apache_log!(.message, "combined")
merge!(., parsed)

or

. |= parse_apache_log!(.message, "combined")

[jszwedko]

Thanks for confirming @SirUrban ! I opened #7827 to track the failed parsing when tid is missing. I believe we can get to both of those issues soon.

[SirUrban]

BTW: Regarding the timestamp issue - same thing seems to happen with nginx logs.

Original syslog message:

ruleset.c: processBATCH: next msg 0: [11/Jun/2021:09:12:10 +0200] az-logexplorer.scalecommerce.cloud 95.223.77.60 200 200 9675 0.000 0.072 0.073 GET / HTTP/1.1 ...

message in vector:

"message": Bytes(b"az-logexplorer.scalecommerce.cloud 95.223.77.60 200 200 9675 0.000 0.072 0.073 GET / HTTP/1.1"), "severity": Bytes(b"info")

Again the timestamp is missing.

[SirUrban]

May be there's a general problem with parsing timestamps? I tried to use the key-value-parser and got this:

$ parse_key_value!("time=\"2021.2021-06-11 09:54:11Z\", severity=[php7:emerg] , process=1700689 , message=\"PHP Parse error:  syntax error, unexpected '->' (T_OBJECT_OPERATOR) in /var/www/prod/releases/master-c7225365fd9faa26262cffeeb57b31bd7448c94a/source/index.php on line 14\"")
{ ", message": "PHP Parse error:  syntax error, unexpected '->' (T_OBJECT_OPERATOR) in /var/www/prod/releases/master-c7225365fd9faa26262cffeeb57b31bd7448c94a/source/index.php on line 14", ", process": "1700689", "09:54:11Z", severity": "[php7:emerg]", "time": "\"2021.2021-06-11" }

Looks a bit strange, doesn't it?

[jszwedko]

Yeah, I think that is the same issue as #7796 regarding it incorrectly consuming the timestamp.

[jszwedko]

Hmm, yeah, regarding the key value parser, it seems like it isn't picking up the quotes around the timestamp as delimiting the value. I'll open a separate issue for that. It is supposed to (and we can see it doing so with message).