NEC IXシリーズからfluentdでsyslogを受け取る時の注意点

概要

fluentdにはsyslog pluginが存在しており、各種機器からのsyslogを扱うことができます。
ところが、NECのルータIXシリーズのsyslogフォーマットはfluentdが想定しているものとは異なるためそのままでは受信できません。ログを受け取る度に後述するようなスタックトレースが出力されてしまいます。

解決方法

正しく受け取るために、formatを以下の様に指定しましょう。

タイムスタンプなしの場合

fluent.conf

<source>
  @type syslog
  port 11111
  bind 0.0.0.0
  tag ixix

  format /^ *(?<ident>[a-zA-Z0-9_\/\.\-]*)(?:\[(?<pid>[0-9]+)\])?(?:[^\:]*\:)? *(?<message>.*)$/
</source>

このコンフィグはIXにてsyslog timestamp datetime を設定して__いない__場合を想定しています。

syslog ip host 192.168.0.240 port 11111

タイムスタンプありの場合

fluent.conf

<source>
  @type syslog
  port 11111
  bind 0.0.0.0
  tag ixix

  format /^ (?<time>[^ ]* {1,2}[^ ]* [^ ]*) *(?<ident>[a-zA-Z0-9_\/\.\-]*)(?:\[(?<pid>[0-9]+)\])?(?:[^\:]*\:)? *(?<message>.*)$/
</source>

このformatは syslog timestamp datetime を設定して__いる__場合を想定しています。

syslog ip host 192.168.0.240 port 11111
syslog timestamp datetime

なぜこれが必要なの

以下の様ななんでもない設定ファイルでfluentdを動かすと、後述のようにスタックトレースを吐いて正しく扱うことができません。

fluentd.conf

<source>
  @type syslog
  port 11111
  bind 0.0.0.0
  tag ixix
</source>
<match ixix.**>
  @type stdout
</match>

fluentd-0.14.21の場合

2017-10-04 16:07:16 +0900 [error]: #0 fluent/log.rb:356:call: invalid input data="<135> Oct  4 16:07:16  ENV[007]: Environment monitor: 1.0 volt line is 0.9870V." error_class=Fluent::TimeParser::TimeParseError error="invalid time format: value =  Oct , error_class = ArgumentError, error = string doesn't match"
  2017-10-04 16:07:16 +0900 [error]: #0 plugin_helper/server.rb:515:call: /var/lib/gems/2.1.0/gems/fluentd-0.14.21/lib/fluent/time.rb:232:in `rescue in parse'
  2017-10-04 16:07:16 +0900 [error]: #0 plugin_helper/server.rb:515:call: /var/lib/gems/2.1.0/gems/fluentd-0.14.21/lib/fluent/time.rb:229:in `parse'
  2017-10-04 16:07:16 +0900 [error]: #0 plugin_helper/server.rb:515:call: /var/lib/gems/2.1.0/gems/fluentd-0.14.21/lib/fluent/plugin/parser_syslog.rb:106:in `block (2 levels) in parse_plain'
  2017-10-04 16:07:16 +0900 [error]: #0 plugin_helper/server.rb:515:call: /var/lib/gems/2.1.0/gems/fluentd-0.14.21/lib/fluent/plugin/parser_syslog.rb:106:in `synchronize'
  2017-10-04 16:07:16 +0900 [error]: #0 plugin_helper/server.rb:515:call: /var/lib/gems/2.1.0/gems/fluentd-0.14.21/lib/fluent/plugin/parser_syslog.rb:106:in `block in parse_plain'
  2017-10-04 16:07:16 +0900 [error]: #0 plugin_helper/server.rb:515:call: /var/lib/gems/2.1.0/gems/fluentd-0.14.21/lib/fluent/plugin/parser_syslog.rb:100:in `each'
  2017-10-04 16:07:16 +0900 [error]: #0 plugin_helper/server.rb:515:call: /var/lib/gems/2.1.0/gems/fluentd-0.14.21/lib/fluent/plugin/parser_syslog.rb:100:in `parse_plain'
  2017-10-04 16:07:16 +0900 [error]: #0 plugin_helper/server.rb:515:call: /var/lib/gems/2.1.0/gems/fluentd-0.14.21/lib/fluent/plugin/in_syslog.rb:188:in `message_handler'
  2017-10-04 16:07:16 +0900 [error]: #0 plugin_helper/server.rb:515:call: /var/lib/gems/2.1.0/gems/fluentd-0.14.21/lib/fluent/plugin/in_syslog.rb:150:in `block in start_udp_server'
  2017-10-04 16:07:16 +0900 [error]: #0 plugin_helper/server.rb:515:call: /var/lib/gems/2.1.0/gems/fluentd-0.14.21/lib/fluent/plugin_helper/server.rb:515:in `call'
  2017-10-04 16:07:16 +0900 [error]: #0 plugin_helper/server.rb:515:call: /var/lib/gems/2.1.0/gems/fluentd-0.14.21/lib/fluent/plugin_helper/server.rb:515:in `on_readable_with_sock'
  2017-10-04 16:07:16 +0900 [error]: #0 plugin_helper/server.rb:515:call: /var/lib/gems/2.1.0/gems/cool.io-1.5.1/lib/cool.io/io.rb:186:in `on_readable'
  2017-10-04 16:07:16 +0900 [error]: #0 plugin_helper/server.rb:515:call: /var/lib/gems/2.1.0/gems/cool.io-1.5.1/lib/cool.io/loop.rb:88:in `run_once'
  2017-10-04 16:07:16 +0900 [error]: #0 plugin_helper/server.rb:515:call: /var/lib/gems/2.1.0/gems/cool.io-1.5.1/lib/cool.io/loop.rb:88:in `run'
  2017-10-04 16:07:16 +0900 [error]: #0 plugin_helper/server.rb:515:call: /var/lib/gems/2.1.0/gems/fluentd-0.14.21/lib/fluent/plugin_helper/event_loop.rb:84:in `block in start'
  2017-10-04 16:07:16 +0900 [error]: #0 plugin_helper/server.rb:515:call: /var/lib/gems/2.1.0/gems/fluentd-0.14.21/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'

これはsyslog pluginのパーサとIXシリーズのsyslogフォーマットが一致していないことに起因します。このパーサでは以下の正規表現でマッチを掛けています。

fluentd-0.14.21/lib/fluent/plugin/parser_syslog.rb

      # From existence TextParser pattern
      REGEXP = /^(?<time>[^ ]*\s*[^ ]* [^ ]*) (?<host>[^ ]*) (?<ident>[^ :\[]*)(?:\[(?<pid>[0-9]+)\])?(?:[^\:]*\:)? *(?<message>.*)$/
      # From in_syslog default pattern
      REGEXP_WITH_PRI = /^\<(?<pri>[0-9]+)\>(?<time>[^ ]* {1,2}[^ ]* [^ ]*) (?<host>[^ ]*) (?<ident>[^ :\[]*)(?:\[(?<pid>[0-9]+)\])?(?:[^\:]*\:)? *(?<message>.*)$/
      REGEXP_RFC5424 = /\A^(?<time>[^ ]+) (?<host>[^ ]+) (?<ident>[^ ]+) (?<pid>[-0-9]+) (?<msgid>[^ ]+) (?<extradata>(\[(.*)\]|[^ ])) (?<message>.+)$\z/
      REGEXP_RFC5424_WITH_PRI = /\A^\<(?<pri>[0-9]{1,3})\>[1-9]\d{0,2} (?<time>[^ ]+) (?<host>[^ ]+) (?<ident>[^ ]+) (?<pid>[-0-9]+) (?<msgid>[^ ]+) (?<extradata>(\[(.*)\]|[^ ])) (?<message>.+)$\z/

一方、IXシリーズではtcpdumpで見ると異なるsyslog転送を行っているのが見て取れます。

syslog timestamp datetimeなしの場合
        0x0000:  4500 005b 0994 0000 4011 eeba c0a8 0003  E..[....@.......
        0x0010:  c0a8 00f0 0202 2b67 0047 e2fe 3c31 3335  ......+g.G..<135
        0x0020:  3e20 2045 4e56 5b30 3037 5d3a 2045 6e76  >..ENV[007]:.Env
        0x0030:  6972 6f6e 6d65 6e74 206d 6f6e 6974 6f72  ironment.monitor
        0x0040:  3a20 312e 3020 766f 6c74 206c 696e 6520  :.1.0.volt.line.
        0x0050:  6973 2030 2e39 3837 3056 2e              is.0.9870V.

        0x0000:  4500 006d 33e5 0000 4011 c458 c0a8 0002  E..m3...@..X....
        0x0010:  c0a8 00f0 0202 2b67 0059 fa8c 3c31 3838  ......+g.Y..<188
        0x0020:  3e20 4943 4d50 5b30 3034 5d3a 204d 6573  >.ICMP[004]:.Mes
        0x0030:  7361 6765 2074 7970 6520 3320 636f 6465  sage.type.3.code
        0x0040:  2033 2072 6563 6569 7665 6420 6672 6f6d  .3.received.from
        0x0050:  2031 3932 2e31 3638 2e30 2e32 3430 2074  .192.168.0.240.t
        0x0060:  6f20 3139 322e 3136 382e 302e 32         o.192.168.0.2

        0x0000:  4500 0071 09dd 0000 4011 ee5c c0a8 0002  E..q....@..\....
        0x0010:  c0a8 00f0 0202 2b67 005d b44e 3c31 3931  ......+g.].N<191
        0x0020:  3e20 2020 4950 5b30 3134 5d3a 2041 6464  >...IP[014]:.Add
        0x0030:  6564 2070 6163 6b65 7420 3139 322e 3136  ed.packet.192.16
        0x0040:  382e 302e 3234 3020 3e20 3139 322e 3136  8.0.240.>.192.16
        0x0050:  382e 302e 3220 746f 2071 7565 7565 2c20  8.0.2.to.queue,.
        0x0060:  4661 7374 4574 6865 726e 6574 312f 302e  FastEthernet1/0.
        0x0070:  30                                       0

syslog timestap datetimeありの場合
        0x0000:  4500 006b 092d 0000 4011 ef11 c0a8 0003  E..k.-..@.......
        0x0010:  c0a8 00f0 0202 2b67 0057 0539 3c31 3335  ......+g.W.9<135
        0x0020:  3e20 4f63 7420 2034 2031 353a 3430 3a32  >.Oct..4.15:40:2
        0x0030:  3620 2045 4e56 5b30 3037 5d3a 2045 6e76  6..ENV[007]:.Env
        0x0040:  6972 6f6e 6d65 6e74 206d 6f6e 6974 6f72  ironment.monitor
        0x0050:  3a20 312e 3020 766f 6c74 206c 696e 6520  :.1.0.volt.line.
        0x0060:  6973 2030 2e39 3837 3056 2e              is.0.9870V.j

IXが送るsyslogと、RFC3164やRFC5424を参考にしたと思われる受け側のsyslog pluginの想定を比較すると次の様な差異があります。

• rfc3164の観点から
  • TIMESTAMP、HOSTNAMEがともにない場合のフォーマットで送っている
  • 受け側ではTIMESTAMP, HOSTNAMEが存在することを想定している
    • RFC3164ではTIMESTAMPがない場合については記述しているがHOSTNAMEについては不明
    • どちらも"NILにしてはならない"という指定はない
      • ただし後続するスペースの扱いなどは不明(スペースだけ入れるのか入れないのか)
  • timestampなしの場合、TAGフィールドが右揃え固定4文字となっている様に見受けられる
    • " IP", " ENV", "SNMP"　のように左側にスペースを埋めている
    • これをHOSTNAME部と区別するのは無理そう
• RFC5424の観点から
  • バージョン番号がない
  • TIMESTAMP部はRFC3164形式で挿入される(syslog timestamp datetime設定時)

このように想定外のsyslogフォーマットなのでformatを指定してなんとかしましょう。

備考

上記は以下の機種で試験をしました。

• NEC IX2207 9.0.14
• NEC IX2015 8.3.8