LoginSignup
3
2

More than 5 years have passed since last update.

@n_kane(n_kane)

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

Posted at

概要

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

3
2
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
3
2