通过syslog发送log4j2堆栈跟踪

Question

我正在尝试将堆栈跟踪记录到Logstash中。

日志堆栈是ELK (ElasticSearch，Logstash，Kibana)。

生成日志的应用程序是一个Java应用程序，使用slf4j作为日志接口，使用log4j2作为日志实现。

log4j2.xml以RFC5424格式声明了这个syslog附录：

<Appenders>
  <Syslog name="RFC5424" format="RFC5424" host="localhost" port="8514"
          protocol="TCP" appName="MyApp" includeMDC="true" mdcId="mdc"
          facility="LOCAL0" enterpriseNumber="18060" newLine="true"
          messageId="Audit" id="App">
    <LoggerFields>
      <KeyValuePair key="thread" value="%t"/>
      <KeyValuePair key="priority" value="%p"/>
      <KeyValuePair key="category" value="%c"/>
      <KeyValuePair key="exception" value="%ex{full}"/>
    </LoggerFields>
  </Syslog>
</Appenders>

我记录了Java应用程序中的Throwable，如下所示：

org.slf4j.LoggerFactory.getLogger("exception_test").error("Testing errors", new RuntimeException("Exception message"));

记录异常时，Logstash跟踪类似的内容，以向我展示它持续存在的内容：

{
   "@timestamp":"2016-11-08T11:08:10.387Z",
   "port":60397,
   "@version":"1",
   "host":"127.0.0.1",
   "message":"<131>1 2016-11-08T11:08:10.386Z MyComputer.local MyApp - Audit [mdc@18060 category=\"exception_test\" exception=\"java.lang.RuntimeException: Exception message",
   "type":"syslog",
   "tags":[
      "_grokparsefailure"
   ]
}

我确认Kibana在它的一个日志条目的_source字段中显示完全相同的JSON。

这里有一个问题:没有保存堆栈跟踪。而“测试错误”这一信息就丢失了。

"tags":["_grokparsefailure"]是不幸的，但与这个问题无关。

我尝试添加<ExceptionPattern/>，看看它是否会改变任何事情：

<Syslog name="RFC5424" format="RFC5424" host="localhost" port="8514"
        protocol="TCP" appName="MyApp" includeMDC="true" mdcId="mdc"
        facility="LOCAL0" enterpriseNumber="18060" newLine="true"
        messageId="Audit" id="App">
  <LoggerFields>
    <KeyValuePair key="thread" value="%t"/>
    <KeyValuePair key="priority" value="%p"/>
    <KeyValuePair key="category" value="%c"/>
    <KeyValuePair key="exception" value="%ex{full}"/>
  </LoggerFields>
  <ExceptionPattern>%ex{full}</ExceptionPattern>
</Syslog>

<ExceptionPattern/>替换了日志消息，而且(遗憾的是)省略了所有loggerFields。但它确实给了我一个类名和行号：

{
   "@timestamp":"2016-11-08T11:54:03.835Z",
   "port":60397,
   "@version":"1",
   "host":"127.0.0.1",
   "message":"at com.stackoverflow.LogTest.throw(LogTest.java:149)",
   "type":"syslog",
   "tags":[
      "_grokparsefailure"
   ]
}

再次:没有堆栈跟踪。再次声明：“测试错误”的消息丢失了。

如何使用log4j2将堆栈跟踪记录到Logstash中？我不一定要使用syslog附录。

主要的制约因素是：

• 不被锁定到任何特定的日志基础设施(这就是我使用syslog的原因)
• 需要将多行堆栈跟踪理解为单个日志条目。“堆栈跟踪的每一行”都是“单独的日志消息”是不可取的
• 堆栈跟踪必须能够接受过滤器。我的一个典型的异常可以有一个长达一页的堆栈跟踪。我想过滤掉像Spring这样的帧。

Answer 1

Log4j 2.5的SyslogAppender只能在UDP上发送堆栈跟踪。

<Syslog name="RFC5424" format="RFC5424" host="localhost" port="8514"
        protocol="UDP" appName="MyApp" includeMDC="true" mdcId="mdc"
        facility="LOCAL0" enterpriseNumber="18060" newLine="true"
        messageId="LogTest" id="App">
  <LoggerFields>
    <KeyValuePair key="thread" value="%t"/>
    <KeyValuePair key="priority" value="%p"/>
    <KeyValuePair key="category" value="%c"/>
    <KeyValuePair key="exception" value="%ex{full}"/>
  </LoggerFields>
  <ExceptionPattern>%ex{full}</ExceptionPattern>
</Syslog>

使用UDP：ExceptionPattern 和 LoggerFields.KeyValuePair["exception"]开始作为多行堆栈跟踪的解决方案。

这就是当我通过syslog通过UDP发送异常时logstash输出的内容：

{
    "@timestamp" => 2016-11-14T13:23:38.304Z,
      "@version" => "1",
          "host" => "127.0.0.1",
       "message" => "<131>1 2016-11-14T13:23:38.302Z BirchBox.local MyApp - LogTest [mdc@18060 category=\"com.stackoverflow.Deeply\" exception=\"java.lang.RuntimeException: Exception message\n\tat com.stackoverflow.Deeply.complain(Deeply.java:10)\n\tat com.stackoverflow.Nested.complain(Nested.java:8)\n\tat com.stackoverflow.Main.main(Main.java:20)\n\" priority=\"ERROR\" thread=\"main\"] Example error\njava.lang.RuntimeException: Exception message\n\tat com.stackoverflow.Deeply.complain(Deeply.java:10)\n\tat com.stackoverflow.Nested.complain(Nested.java:8)\n\tat com.stackoverflow.Main.main(Main.java:20)",
          "type" => "syslog",
          "tags" => [
        [0] "_grokparsefailure"
    ]
}

在[mdc@18060 exception=\"…\"]内部，我们得到LoggerFields.KeyValuePair["exception"]堆栈跟踪。

此外，由于ExceptionPattern，堆栈跟踪被插入到日志消息本身。

供参考:这是logstash通过syslog通过TCP发送异常时输出的内容(即上面描述的相同的SyslogAppender，但使用protocol="TCP" )：

{
    "@timestamp" => 2016-11-14T19:56:30.293Z,
          "port" => 63179,
      "@version" => "1",
          "host" => "127.0.0.1",
       "message" => "<131>1 2016-11-14T19:56:30.277Z BirchBox.local MyApp - Audit [mdc@18060 category=\"com.stackoverflow.Deeply\" exception=\"java.lang.RuntimeException: Exception message",
          "type" => "syslog",
          "tags" => [
        [0] "_grokparsefailure"
    ]
}
{
    "@timestamp" => 2016-11-14T19:56:30.296Z,
          "port" => 63179,
      "@version" => "1",
          "host" => "127.0.0.1",
       "message" => "at com.stackoverflow.Deeply.complain(Deeply.java:10)",
          "type" => "syslog",
          "tags" => [
        [0] "_grokparsefailure"
    ]
}
{
    "@timestamp" => 2016-11-14T19:56:30.296Z,
          "port" => 63179,
      "@version" => "1",
          "host" => "127.0.0.1",
       "message" => "at com.stackoverflow.Nested.complain(Nested.java:8)",
          "type" => "syslog",
          "tags" => [
        [0] "_grokparsefailure"
    ]
}
{
    "@timestamp" => 2016-11-14T19:56:30.296Z,
          "port" => 63179,
      "@version" => "1",
          "host" => "127.0.0.1",
       "message" => "at com.stackoverflow.Main.main(Main.java:20)",
          "type" => "syslog",
          "tags" => [
        [0] "_grokparsefailure"
    ]
}
{
    "@timestamp" => 2016-11-14T19:56:30.296Z,
          "port" => 63179,
      "@version" => "1",
          "host" => "127.0.0.1",
       "message" => "\" priority=\"ERROR\" thread=\"main\"] Example error",
          "type" => "syslog",
          "tags" => [
        [0] "_grokparsefailure"
    ]
}
{
    "@timestamp" => 2016-11-14T19:56:30.296Z,
          "port" => 63179,
      "@version" => "1",
          "host" => "127.0.0.1",
       "message" => "java.lang.RuntimeException: Exception message",
          "type" => "syslog",
          "tags" => [
        [0] "_grokparsefailure"
    ]
}
{
    "@timestamp" => 2016-11-14T19:56:30.297Z,
          "port" => 63179,
      "@version" => "1",
          "host" => "127.0.0.1",
       "message" => "at com.stackoverflow.Deeply.complain(Deeply.java:10)",
          "type" => "syslog",
          "tags" => [
        [0] "_grokparsefailure"
    ]
}
{
    "@timestamp" => 2016-11-14T19:56:30.298Z,
          "port" => 63179,
      "@version" => "1",
          "host" => "127.0.0.1",
       "message" => "at com.stackoverflow.Nested.complain(Nested.java:8)",
          "type" => "syslog",
          "tags" => [
        [0] "_grokparsefailure"
    ]
}
{
    "@timestamp" => 2016-11-14T19:56:30.298Z,
          "port" => 63179,
      "@version" => "1",
          "host" => "127.0.0.1",
       "message" => "at com.stackoverflow.Main.main(Main.java:20)",
          "type" => "syslog",
          "tags" => [
        [0] "_grokparsefailure"
    ]
}
{
    "@timestamp" => 2016-11-14T19:56:30.299Z,
          "port" => 63179,
      "@version" => "1",
          "host" => "127.0.0.1",
       "message" => "",
          "type" => "syslog",
          "tags" => [
        [0] "_grokparsefailure"
    ]
}

看起来TCP确实“工作”，但将单个日志消息拆分为许多syslog消息(例如，当遇到\n时)。