Datetime import issues with in_tail and fluent_plugin_mongo.

[Carl Wilen]

I'm currently evaluating Fluent for importing logs into MongoDB. Because these logs are provided by applications outside our control I'm having to use tail plugin with regex format to make the log output Fluent. The log output is sent to MongoDB with the mongodb plugin. This scenario is working great except for date handling. Each log entry has a date in the following format: 2013-05-12 15:41:58,234. FluentD is storing the date values in MongoDB as "time" : ISODate("2013-05-12T15:41:59Z"). We need to store the millisecond value and specify the TimeZone information. I do not see any configuration setting for either the tail or mongodb plugins that control how the dates are imported into MongoDB. Am I missing something or is this functionality not yet available?

Thanks in advance for any information.

Carl

[Masahiro Nakagawa]

Hi Carl,

Currently, Fluentd's time assumes seconds unit. So default behavior can't handle milliseconds unit.
Simple solution is extending in_tail parser and set milliseconds value.
After back to home, I will show an example.

What do you think?

Masahiro

--
You received this message because you are subscribed to the Google Groups "Fluentd Google Group" group.
To unsubscribe from this group and stop receiving emails from it, send an email to fluentd+u...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.
 
 

[Masahiro Nakagawa]

Could you paste the sample log and configuration?

On May 21, 2013 11:12 PM, "Carl Wilen" <car...@gmail.com> wrote:

--

[Carl Wilen]

I was thinking of extending the in_tail plugin as I will need to handle some more complex cases in the logs. I was hesitant to do this starting off as I'm not familier with Ruby and I needed to get something up and running quickly. Any examples you could provide to point me in the right direction would be appreciated. Also, as requested here are some example log output:

2013-03-13 00:00:06,709 INFO  ? [API=PerformOnDemandPurchase] [Remote_URL=10.124.2.6] [Device_Type=] [Transaction_ID=649d96a2-d37a-4deb-b2ca-ea4dd35b2c9c] [Session_ID=] [Partner_Customer_ID=73185769884231] [?=?] Response from MongoServerProvider [Execution_time= 4 ms]  [Time_stamp = 2013-03-13 00:00:06.709]

2013-03-13 00:00:06,710 INFO  ? [API=PerformOnDemandPurchase] [Remote_URL=10.124.2.6] [Device_Type=] [Transaction_ID=649d96a2-d37a-4deb-b2ca-ea4dd35b2c9c] [Session_ID=] [Partner_Customer_ID=73185769884231] [?=?] Calling rightsLockerWebService to find Entitlements [Time_stamp = 2013-03-13 00:00:06.710]

2013-03-13 00:00:06,715 INFO  ? [API=PerformOnDemandPurchase] [Remote_URL=10.124.2.6] [Device_Type=] [Transaction_ID=649d96a2-d37a-4deb-b2ca-ea4dd35b2c9c] [Session_ID=] [Partner_Customer_ID=73185769884231] [?=?] [Action execution plus response serialization=8850 ms]

2013-03-13 00:00:06,715 INFO  ? [API=PerformOnDemandPurchase] [Remote_URL=10.124.2.6] [Device_Type=] [Transaction_ID=649d96a2-d37a-4deb-b2ca-ea4dd35b2c9c] [Session_ID=] [Partner_Customer_ID=73185769884231] [?=?] [Response={

  "ResultInfo":   {

    "ResultCode": "0",

    "ResultMessage": "Success"

  },

  "BillingTransactionID": "6022538280"

}]

2013-03-13 00:00:16,565 INFO  ? [API=GetKioskCartPricing] [Remote_URL=10.124.2.6] [Device_Type=] [Transaction_ID=WEBCSR20130312225916] [Session_ID=] [Partner_Customer_ID=18519648939352] [?=?] [Action execution plus response serialization=60018 ms]

2013-03-13 00:00:16,565 INFO  ? [API=GetKioskCartPricing] [Remote_URL=10.124.2.6] [Device_Type=] [Transaction_ID=WEBCSR20130312225916] [Session_ID=] [Partner_Customer_ID=18519648939352] [?=?] [Response=<ZoeResponse>

  <ResultInfo>

    <ResultCode>600010</ResultCode>

    <ResultMessage>I/O error: Read timed out; nested exception is java.net.SocketTimeoutException: Read timed out</ResultMessage>

  </ResultInfo>

</ZoeResponse>]

Milliseconds are required for performance of matching transactions.

Thanks again,

Carl.

[Masahiro Nakagawa]

Hi Carl,

Following in_tail example for millisecond time:

class TailTimeMsecInput < Fluent::TailInput

  Fluent::Plugin.register_input('tail_time_msec', self)

  def parse_line(line)

    time, record = super(line)

    time_msec = record.delete('time_msec')

    time_msec = Time.parse(time_msec)

    return time_msec.to_f, record

  end

end

Configuration example:

<source>

  type tail_time_msec

  # 'message' is a placeholder. Should specify correct format for " INFO  ? [API=PerformOnDemandPurchase] [Remote_URL=10.124.2.6] [Device_Type=] [Transaction_ID=649d96a2-d37a-4deb-b2ca-ea4dd35b2c9c] [Session_ID=] [Partner_Customer_ID=73185769884231] [?=?] Response from MongoServerProvider [Execution_time= 4 ms]  [Time_stamp = 2013-03-13 00:00:06.709]"

  format /^(?<time_msec>[^ ]* [^ ]*) (?<message>.*)$/

  # other configuration are same as normal in_tail

</source>

Fluentd's default time unit is now second.

But millisecond might work if plugin doesn't require second unit.

Masahiro

[Carl Wilen]

Thanks for the example. In essence, you are replacing the parsed time_msec value with a custom parse in the plugin leaving all other values as parsed?

Also, here is the current in_tail configuration I'm using;

<source>

  type tail

  format /^(?<time>[^ ]* [^ ]*) (?<level>[^ ]*)  (\? \[API=(?<api>[\w]+)\]) (\[Remote_URL=(?<remote_url>[^ ]*)\]) (\[Device_Type=(?<device_type>[^ ]*)\]) (\[Transaction_ID=(?<transaction_id>[^ ]*)\]) (\[Session_ID=(?<session_id>[^ ]*)\]) (\[Partner_Customer_ID=(?<partner_customer_id>[^ ]*)\]) (\[\?=\?\](?<response>.*))$/

  path /var/log/OL/orchestration.log

  tag ol

  pos_file /var/log/td-agent/tmp/orchestration.log.pos

  time_format %Y-%m-%d %T,%L

</source>

When extending the in_tail plugin you are still dependent on the record being created from the format regex right?

Thanks again,

Carl

[Masahiro Nakagawa]

> When extending the in_tail plugin you are still dependent on the record being created from the format regex right?

Yes. If you use this plugin with following configuration:

<source>

  type tail_time_msec

  format /^(?<time_msec>[^ ]* [^ ]*) (?<level>[^ ]*)  (\? \[API=(?<api>[\w]+)\]) (\[Remote_URL=(?<remote_url>[^ ]*)\]) (\[Device_Type=(?<device_type>[^ ]*)\]) (\[Transaction_ID=(?<transaction_id>[^ ]*)\]) (\[Session_ID=(?<session_id>[^ ]*)\]) (\[Partner_Customer_ID=(?<partner_customer_id>[^ ]*)\]) (\[\?=\?\](?<response>.*))$/

  path /var/log/OL/orchestration.log

  tag ol

  pos_file /var/log/td-agent/tmp/orchestration.log.pos

</source>

then following log is stored in mongodb.

{ "_id" : ObjectId("51a776af7e94c0176f000001"), "level" : "INFO", "api" : "CheckSimultaneousStreaming", "remote_url" : "1.1.1.1", "device_type" : "", "transaction_id" : "ENT-46a40d42-9921-4f58-8662-f996b925e847", "session_id" : "", "partner_customer_id" : "44852173370075", "response" : " isAllowedToStreamContent end:success pcn=44852173370075 deviceID=null productID=9cb068c4-55d9-4f52-bc0a-62de09ca945e", "time" : ISODate("2013-05-12T06:41:58.232Z") }

time is "2013-05-12T06:41:58.232Z", not "2013-05-12T06:41:58Z"

Masahiro

[pe...@diverta.co.jp]

Hello Mr. Masahiro

I found the Mongo Plugin can not work well with the log that forwarded from other server. (I have test it for one month, and get this conclusion)

I forward log from one server (with fluentd out_forward) to another server (with fluentd in_forward), but the mongo plugin sometime failed to transfer the log to mongoDB. Then I must restart the fluentd to get it work again.

The error message is like this:

2013-05-31 03:16:19 +0900 fluent.error: {"message":"forward error: can't convert String into Integer"}

2013-05-31 03:16:19 +0900 [error]: forward error: can't convert String into Integer

  2013-05-31 03:16:19 +0900 [error]: /usr/lib64/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.33/lib/fluent/mixin.rb:176:in `[]='

  2013-05-31 03:16:19 +0900 [error]: /usr/lib64/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.33/lib/fluent/mixin.rb:176:in `filter_record'

  2013-05-31 03:16:19 +0900 [error]: /usr/lib64/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.33/lib/fluent/mixin.rb:96:in `block in format_stream'

  2013-05-31 03:16:19 +0900 [error]: /usr/lib64/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.33/lib/fluent/event.rb:127:in `feed_each'

  2013-05-31 03:16:19 +0900 [error]: /usr/lib64/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.33/lib/fluent/event.rb:127:in `each'

  2013-05-31 03:16:19 +0900 [error]: /usr/lib64/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.33/lib/fluent/mixin.rb:95:in `format_stream'

  2013-05-31 03:16:19 +0900 [error]: /usr/lib64/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.33/lib/fluent/output.rb:224:in `emit'

  2013-05-31 03:16:19 +0900 [error]: /usr/lib64/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluent-plugin-mongo-0.7.0/lib/fluent/plugin/out_mongo.rb:100:in `emit'

  2013-05-31 03:16:19 +0900 [error]: /usr/lib64/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.33/lib/fluent/match.rb:38:in `emit'

  2013-05-31 03:16:19 +0900 [error]: /usr/lib64/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.33/lib/fluent/engine.rb:120:in `emit_stream'

  2013-05-31 03:16:19 +0900 [error]: /usr/lib64/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.33/lib/fluent/plugin/in_forward.rb:118:in `on_message'

  2013-05-31 03:16:19 +0900 [error]: /usr/lib64/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.33/lib/fluent/plugin/in_forward.rb:180:in `feed_each'

  2013-05-31 03:16:19 +0900 [error]: /usr/lib64/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.33/lib/fluent/plugin/in_forward.rb:180:in `on_read_msgpack'

  2013-05-31 03:16:19 +0900 [error]: /usr/lib64/fluent/ruby/lib/ruby/gems/1.9.1/gems/cool.io-1.1.0/lib/cool.io/io.rb:108:in `on_readable'

  2013-05-31 03:16:19 +0900 [error]: /usr/lib64/fluent/ruby/lib/ruby/gems/1.9.1/gems/cool.io-1.1.0/lib/cool.io/io.rb:170:in `on_readable'

  2013-05-31 03:16:19 +0900 [error]: /usr/lib64/fluent/ruby/lib/ruby/gems/1.9.1/gems/cool.io-1.1.0/lib/cool.io/loop.rb:96:in `run_once'

  2013-05-31 03:16:19 +0900 [error]: /usr/lib64/fluent/ruby/lib/ruby/gems/1.9.1/gems/cool.io-1.1.0/lib/cool.io/loop.rb:96:in `run'

  2013-05-31 03:16:19 +0900 [error]: /usr/lib64/fluent/ruby/lib/ruby/gems/1.9.1/gems/fluentd-0.10.33/lib/fluent/plugin/in_forward.rb:78:in `run'

2013年5月31日金曜日 1時04分30秒 UTC+9 repeatedly:

[pe...@diverta.co.jp]

It looks like a time format issue. 

2013年5月31日金曜日 3時23分54秒 UTC+9 pe...@diverta.co.jp: