Syslog parsing not getting fields in message

[ilcylic]

Hi, this is probably something really obvious, but I'm not seeing it. Hopefully it's not just a stupid typo like my last question. ;)

I've got a configuration going where I have syslogd running on a machine, outputting to both a file and to localhost port 8514. Relevant config snippets follow:

[sources.local_syslog]
  type = "syslog"
  max_length = 102_400
  address = "127.0.0.1:8514"
  mode = "udp"

[transforms.parsed_syslog]
  inputs = ["local_syslog"]
  type = "remap"
  source = '''
    ., err = parse_syslog(.message)
    .source = "syslog-logging"
  '''

[sinks.print]
  type = "console"
  inputs = [
    "parsed_syslog"
  ]
  encoding.codec = "json"

Now here's where things get a little weird.

When I get a message directly from syslog, vector produces only the following output (tcpdump for completeness):

Feb  9 19:30:00 logging cron.info crond[12372]: USER root pid 4650 cmd run-parts /etc/periodic/15min


{"source":"syslog-logging"}


19:30:00.477085 IP (tos 0x0, ttl 64, id 63620, offset 0, flags [DF], proto UDP (17), length 115)
    xxx.aurora.dev.53203 > xxx.aurora.dev.8514: [bad udp cksum 0xfe72 -> 0x53c8!] UDP, length 87
	0x0000:  4500 0073 f884 4000 4011 43f3 7f00 0001  E..s..@.@.C.....
	0x0010:  7f00 0001 cfd3 2142 005f fe72 3c37 383e  ......!B._.r<78>
	0x0020:  4665 6220 2039 2031 393a 3330 3a30 3020  Feb..9.19:30:00.
	0x0030:  6372 6f6e 645b 3132 3337 325d 3a20 5553  crond[12372]:.US
	0x0040:  4552 2072 6f6f 7420 7069 6420 3436 3530  ER.root.pid.4650
	0x0050:  2063 6d64 2072 756e 2d70 6172 7473 202f  .cmd.run-parts./
	0x0060:  6574 632f 7065 7269 6f64 6963 2f31 356d  etc/periodic/15m
	0x0070:  696e 0a                                  in.

When I then paste the very same line back into the syslog with the 'logger' util:

Feb  9 19:30:31 logging user.notice root: Feb  9 19:30:00 logging cron.info crond[12372]: USER root pid 4650 cmd run-parts /etc/periodic/15min


{"appname":"cron.info","hostname":"logging","message":"crond[12372]: USER root pid 4650 cmd run-parts /etc/periodic/15min","source":"syslog-logging","timestamp":"2022-02-09T19:30:00Z"}


19:30:31.779986 IP (tos 0x0, ttl 64, id 1886, offset 0, flags [DF], proto UDP (17), length 155)
    xxx.aurora.dev.53203 > xxx.aurora.dev.8514: [bad udp cksum 0xfe9a -> 0xf895!] UDP, length 127
	0x0000:  4500 009b 075e 4000 4011 34f2 7f00 0001  E....^@.@.4.....
	0x0010:  7f00 0001 cfd3 2142 0087 fe9a 3c31 333e  ......!B....<13>
	0x0020:  4665 6220 2039 2031 393a 3330 3a33 3120  Feb..9.19:30:31.
	0x0030:  726f 6f74 3a20 4665 6220 2039 2031 393a  root:.Feb..9.19:
	0x0040:  3330 3a30 3020 6c6f 6767 696e 6720 6372  30:00.logging.cr
	0x0050:  6f6e 2e69 6e66 6f20 6372 6f6e 645b 3132  on.info.crond[12
	0x0060:  3337 325d 3a20 5553 4552 2072 6f6f 7420  372]:.USER.root.
	0x0070:  7069 6420 3436 3530 2063 6d64 2072 756e  pid.4650.cmd.run
	0x0080:  2d70 6172 7473 202f 6574 632f 7065 7269  -parts./etc/peri
	0x0090:  6f64 6963 2f31 356d 696e 0a              odic/15min.

Is there something about the way the parse_syslog() function works that the format of my log file isn't playing nicely with?

What's the best way to solve this? Write my own regex in VRL?

[jszwedko]

Hi @ilcylic !

I'm guessing what is happening is:

    ., err = parse_syslog(.message)

Is actually returning an error, causing it to write null to .. I'd add:

if err != null {
  log(err)
}

to confirm.

My second guess is that you don't need to be parsing the incoming event with parse_syslog in VRL because the syslog source already parses the incoming data as syslog data. I would try removing the ., err = parse_syslog(.message) altogether.

[ilcylic]

So, I didn't try adding the line about "err != null", opting to try one thing at a time and to start with commenting out:

    ., err = parse_syslog(.message)

which worked, so I stopped touching it. ;)

More seriously, now that you've explained the bit about the "syslog" source already dealing with the received message as syslog, it makes a lot of sense that it was only the messages that I'd effectively "double encapsulated" as syslog that were showing up. The messages that came in that were regular syslog messages got parsed once, and then parsed again, and there's nothing there. The ones I sent with logger got parsed, and conveniently, had another syslog message inside of them for the second round of parsing to catch.

Thanks for the help. Hey, at least this one wasn't just a typo. :D

[jszwedko]

Aha! Yeah, that makes sense. You could do something like:

parsed, err = parse_syslog(.message)
if err == null {
  . = parsed
}

To handle both single and double encapsulated messages.

[ilcylic]

Conveniently, the double encapsulation was only a side effect of a misfortunately complimentary flaw in the testing procedure that happened to generate them (because I hadn't thought all the way through the results of pasting full syslog message lines into logger, thus leading to the double encapsulation) and also happened to work perfectly with the programming error I had made in the transform section...

So it was sort of a perfect storm of bug and flawed input that had originally made me think it was working, and then get confused when it "stopped" working. I don't expect to encounter double encapsulated messages in the production environment. In fact, if I've run into one, that's probably a real error I should deal with. :D