No data send to elasticsearch

[uken]

No data send to elasticsearch

[quasipedia]

I'm experiencing what I believe is the same problem. I'm prototyping on a Fedora 20 station. Some info on my configuration:

Ruby version: ruby 2.0.0p353 (2013-11-22 revision 43784) [x86_64-linux]
Plugin version: fluent-plugin-elasticsearch-0.4.0
Libcurl version: libcurl-devel-7.32.0-12.fc20.x86_64
Fluentd version: fluentd-0.10.53
Elasticsearch version: version[1.3.2]
Other system settings as per fluentd guidelines.

Fluentd configuration file:

<source>
  type forward
</source>

<match efk.**>
  type copy
  <store>
    type elasticsearch
    logstash_format true
    host localhost
    port 9200
    flush_interval 10
  </store>
  <store>
    type file
    path dicerolls
  </store>
</match>

<match **>
  type file
  path logfile
</match>

What I am seeing is events from my application being correctly logged on file, but not being sent to elastic search. Elastic search itself works (I can see the polling kibana does by monitoring the port with: tcpdump -x -X -i any 'port 9200') but no data reach it from fluentd.

Thank you in advance for your time! :)

[quasipedia]

I'm not a ruby coder, but by simply printf-debugging I seem to have found what the problem is this line.

Apparently the loop will always next and no processing of the log messages will be performed.

Removing the line completely won't solve the issue, but at least will try to process the log messages and fail with:

[warn]: fluent/output.rb:350:rescue in try_flush: temporarily failed to flush the buffer. next_retry=2014-09-08 16:15:43 +0200 error_class="NoMethodError" error="undefined method `has_key?' for #<String:0x0000000233bcb8>" instance=25773740

I don't know if this can help, but with my test application, the variable chunk that comes into the write function looks like this:

Variable chunk is #<Fluent::MemoryBufferChunk:0x00000001d22570 @data="\x93\xA3afk\xCET\r\xB8\x15\xDA\x00N{'score': 3, 'dice_type': 2, 'player': 'Charlie', 'dice_qty': 2, 'pid': 21939}", @unique_id="P(\xE5bY\x81\x15\xE0\xD8yq\xBD\xF4A\xEB\xE0", @mon_owner=#<Thread:0x00000003139108 run>, @mon_count=1, @mon_mutex=#<Mutex:0x00000001d272a0>, @key="">

It always feels good to know that you're not alone. But a solution would even been better :-)

I am running:
fluentd 0.10.53
elasticsearch 1.3.2
fluentd-plugin-elasticsearch 0.4.0

curl --version
curl 7.33.0 (x86_64-pc-linux-gnu) libcurl/7.33.0 OpenSSL/1.0.1g zlib/1.2.8 libidn/1.28 libssh2/1.4.3 librtmp/2.3
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtmp rtsp scp sftp smtp smtps telnet tftp
Features: AsynchDNS GSS-Negotiate IDN IPv6 Largefile NTLM NTLM_WB SSL libz TLS-SRP

ruby --version
ruby 2.0.0p353 (2013-11-22) [x86_64-linux-gnu]

I discovered that when I shutdown the fluentd processes (there are 2), the read entries from the apache logs are eventually send to elasticsearch and do become visible in kibana. I shutdown these processes using a 'kill -3 pidof ruby2.0' command and it takes maybe 1-2 minutes to shutdown.

I have tried adding "flush_interval 10s" (with and without the final 's'), but that does not make any difference.

thanks for pointing out that line. I did some further investigation and noticed that:

• in the previous release that line was not there yet
• the line was added in this commit: 8597b5d#diff-ae62a005780cc730c558e3e4f47cc544R94

[quasipedia]

Yes, I noticed that myself and tried to install version 0.3.1 of the plugin instead...

Unluckily the results are similar to those reported above when I manually removed the next test: it seems to me there is really a logic bug in terms of handling messages, as their format seems to take the plugin by surprise (it attempts to find a key in a string).

Since the code is not commented/documented and I am not a ruby guy I am a bit at loss in terms of how to fix it. Hopefully the maintainer will step in soon. :)

On another note: my log messages are generated automatically by the python fluent-logger module, it that may help. For the record, this is the relevant code:

from fluent import handler
logging.basicConfig(level=logging.INFO)
log = logging.getLogger('afk')
log.addHandler(handler.FluentHandler('afk', host='localhost', port=24224)
log.info({'key': 'my_key', 'key2': 'my_second_key'})

HTH fixing the bug! :)

[quasipedia]

Final comment for today... As a workaround I have been able to make the plugin work by JSON-encoding the record in the application and, after installing the JSON gem on my system adding the following:

require 'json'  # in the beginning of the file

record = JSON.parse(record)  # just above the offending "next" line

This is an ugly workaround, that may not be applicable to you if you haven't control on the code generating the log messages, but it's the best I could come up with. :(

More info:

http://stackoverflow.com/questions/24701230/fluentd-does-not-flush-any-data-to-elastic-search-but-does-flush-upon-shutdown

Final comment 1 hour ago says:

After much troubleshooting I found that there was a bug in the specific version of ruby installed that caused a thread to deadlock when starting up. The issue did not appear when shutting down as it was being called a differently. This is a specific bug re ruby 2.0.0-p353 ; the next release ruby 2.0.0-p451 fixes the issue.

https://groups.google.com/forum/#!msg/fluentd/t2uKfttiYCw/P8zy5kZpEIIJ

I'm running p353, let's see if I can install p451..

[quasipedia]

I don't think I have the same problem (I printf-debug the plugin and it does not "stuck" at message handling, it just "hop over" it... However - for the sake of the maintainer having all the data about my system, I added my ruby version to my previous message (it is the same you have: ruby 2.0.0p353 (2013-11-22 revision 43784) [x86_64-linux]).

Pfhew.. some hours later, I eventually installed ruby 2.1 from this ubuntu source:

https://launchpad.net/~brightbox/+archive/ubuntu/ruby-ng

After installing ruby2.1 and ruby2.1-dev, I was able to reinstall fluentd and the fluentd-elasticsearch plugin. (this was required to have fluentd switch from ruby 2.0 to 2.1)

Now it works :-)

[quasipedia]

Good for you! :)

The problem with the deadlock with that specific version of ruby is well known and documented on the fluentd site's FAQ.

My problem is different (although it causes the same symptom) and is linked to the format used for data serialisation.

So this issue is still a valid one for me. Hoping the maintainer will shed some light on it soon! :)

[adq]

Hey, I didn't make the change, but I did report the bug that led to it. Have a look at: #52

Basically, it really doesn't like it if you send invalid JSON at it. It looks like the fix (correctly?) simply ignores any message that was invalid; without this, the plugin would simply silently lock up trying to reprocess the same invalid json every hour or so. You don't want this on your site-wide log collection system :)

I suggest it should spit a warning rather than silently ditching it.

[quasipedia]

@adq - Hey, thank you for chipping in Andrew. I understand (and approve!) the logic behind the fix, but it seems to me something else is broken.

This is my first project with elastic, so I may miss something, but here's my situation:

I'm logging events from a python application using the fluent-logger module. As you can see from my example above, I'm feeding the log with a dictionary (python parlance for key-value array), which is exactly what the documentation of said plugin tells I should be doing.

From the out_elastic plugin I would expect either of the two:

• the dictionary being treated as what it is, and being fed to ES as a JSON object.
• the dictionary being treated as a string, and being fed to ES as such.

Unluckily it is only treated as "bad data" and skipped. I tried to pass a JSON dump directly, but this too is treated as "bad data", hence me coming up with the encoding/decoding hack.

If you have better suggestions on how to solve the problem (or on how to investigate it further), I'd be glad to try them! :)

[adq]

Have you setup the fluent log record formatter in your python log config?

There was a change recently that you have to explicitly set it to
fluent.handler.FluentRecordHandler or you end up with python's normal
printed dicts rather than json-compatible ones.

This used to happen automatically in older versions, but changed at some
point. It's actually exactly this issue that was causing the lockups I was
seeing.
On 12 Sep 2014 09:36, "Mac Ryan" [email protected] wrote:

@adq https://github.com/adq - Hey, thank you for chipping in Andrew. I
understand (and approve!) the logic behind the fix, but it seems to me
something else is broken.

This is my first project with elastic, so I may miss something, but here's
my situation:

I'm logging events from a python application using the fluent-logger
https://github.com/fluent/fluent-logger-python module. As you can see
from my example above, I'm feeding the log with a dictionary (python
parlance for key-value array), which is exactly what the documentation of
said plugin tells I should be doing.

From the out_elastic plugin I would expect either of the two:

• the dictionary being treated as what it is, and being fed to ES as a
  JSON object.
• the dictionary being treated as a string, and being fed to ES as
  such.

Unluckily it is only treated as "bad data" and skipped. I tried to pass a
JSON dump directly, but this too is treated as "bad data", hence me coming
up with the encoding/decoding hack.

If you have better suggestions on how to solve the problem (or on how to
investigate it further), I'd be glad to try them! :)

—
Reply to this email directly or view it on GitHub
#70 (comment)
.

[quasipedia]

@adq - Thank you so much Andrew! You were totally spot-on and your input shifts the responsibility onto the python plugin, rather than the fluentd one. I filed a bug and made a pull request with its solution here and here respectively.

Thank you again! :)
[And issue closed for me, but I'm not the owner, so I can't close it myself]