Logstash: NoMethodError: undefined method `to_iso8601' for nil:NilClass in event.rb

[clintongormley]

_From @emmanuelGuiton on October 13, 2015 12:24_

Hello,

I used a logstash 1.5.4 instance that processes a few tens of millions messages per day and that often crashes (almost once everyday). In logstash.err, ther is the following trace :

Oct 09, 2015 9:58:17 AM org.apache.http.impl.execchain.RetryExec execute
INFO: Retrying request to {}->http://10.176.61.21:9200
NoMethodError: undefined method `to_iso8601' for nil:NilClass
to_s at /opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-1.5.4-java/lib/logstash/event.rb:109
retry_flush at /opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-1.0.7-java/lib/logstash/outputs/elasticsearch.rb:729
times at org/jruby/RubyFixnum.java:275
each at org/jruby/RubyEnumerator.java:274
map at org/jruby/RubyEnumerable.java:764
retry_flush at /opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-1.0.7-java/lib/logstash/outputs/elasticsearch.rb:724
register at /opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-1.0.7-java/lib/logstash/outputs/elasticsearch.rb:480

Looking at elasticsearch.rb, the application crashes while trying to log an error :
@logger.error "too many attempts at sending event. dropping: #{next_event}"

Looking at event.rb, the to_s function (called when trying to log the event) assumes there is an existing timestamp field. But from the trace I suspect this field does not always exist. So Logstash crashes when trying to call to_is8601 on a non-existing timestamp.

The fix seems simple : testing if the timestamp field exists before trying to call its to_iso8601 method.
Sorry, I cannot submit a patch since I do not know anything about ruby.

_Copied from original issue: elastic/elasticsearch#14086_

[jsvd]

@emmanuelGuiton can you post your configuration?

[emmanuelGuiton]

Oops : sorry for the wrong post location.
About the configuration : Logstash 1.5.4
(And Linux Debian 8.2, JVM OpenJDK 8u66)

[jsvd]

can you post the config files logstash is using?

[emmanuelGuiton]

Oh, sorry. Here it is :

input
{
    rabbitmq
    {
        codec => json
        durable => true
        exchange => "exchange"
        host => "host"
        password => "password"
        port => 5672
        queue => "queue"
        threads => 2
        user => "user"
        vhost => "/"
    }

    syslog
    {
        port => 3514
        type => "syslog"
    }
}

filter
{
    # Add metadata fields
    mutate
    {
        add_field =>
        {
            "[@metadata][docType]" => "%{metadata:docType}"
            "[@metadata][id]" => "%{metadata:id}"
        }
    }

    if [type] == "syslog"
    {
        mutate
        {
            add_field => { "[@metadata][indexSuffix]" => "%{+YYYYMMdd}" }
            replace => [ "host", "%{logsource}" ]
            remove_field => [ "logsource" ]
        }
    }
    else
    {
        mutate
        {
            add_field => { "[@metadata][indexSuffix]" => "%{+YYYYMM}" }
        }
    }

    # Remove unnecessary fields
    mutate
    {
        remove_field => [ "@version","@timestamp", "metadata:docType", "metadata:id" ]
    }
}

output
{                                                                                                              
    if [type] == "syslog"
    {
        elasticsearch
        {
            flush_size => 10000
            host => "host1"
            index => "index-%{[@metadata][indexSuffix]}"
            protocol => "http"
            workers => 2
        }
    }
    else
    {
        if [@metadata][id] != ""
        {
            elasticsearch
            {
                flush_size => 10000
                host => "host2"
                index => "%{[@metadata][id]}-%{[@metadata][indexSuffix]}"
                document_type => "%{[@metadata][docType]}"
                protocol => "http"
                workers => 2
            }
        }
        else
        {
            elasticsearch
            {
                flush_size => 10000
                host => "host3"
                index => "mutu-%{[@metadata][indexSuffix]}"
                document_type => "%{[@metadata][docType]}"
                protocol => "http"
                workers => 2
            }
        }
    }
}

[purbon]

@emmanuelGuiton without testing it in details, and after checking the code, you see this error because you explicitly remove the @timestamp field.

see

  # Remove unnecessary fields
    mutate
    {
        remove_field => [ "@version","@timestamp", "metadata:docType", "metadata:id" ]
    }

and field that has @ as a prefix is a required LS reserved fields. Another questions is if the ES output should be able to store events without having a @timestamp.

[emmanuelGuiton]

@purbon
I do explicitely remove @timestamp. I do not want this field in my output and I do not want Elasticsarch to store it. Which I find legitimate : why would Logstash oblige users to store data they do not use ?
This works perfectly fine since removing @version and @timestamp has been made possible ( = since 1.5.0 if I remember correctly).

Since it is possible to remove these field, it should not be taken for granted in Logstash code that these fields are present. And that is the issue in the to_s function in event.rb.

[purbon]

@emmanuelGuiton for now I see this as a mandatory field in all LS, there is this expectation set in some parts of the code.

@jordansissel @suyograo would be nice to clear out the right expectations for this kind of fields. What do you think folks?

[purbon]

@emmanuelGuiton as this raises a more in deep discussion about expectations with @ variables, I opened #4044 to reach some consensus on the direction to take.

thanks a lot for your feedback.

for now, I would recommend, either not removing the @timestamp variable, this would be the easy road, or if you are more adventurous you can try to patch your LS.

[emmanuelGuiton]

For now, I've patched my Logstash instance using

self.sprintf("%{host} %{message}")

instead of

self.sprintf("#{timestamp.to_iso8601} %{host} %{message}")

in the to_s method of event.rb

I just hope it is correct.
I have no trace of "too many attempts at sending event" in my logs so I do not know for sure if this code has run.

[purbon]

This might work for now, would be nice to know the output of it for you, I mean if you see other error because of your removal/patch.

On the other side, would be nice if you can add your thoughts about the direction at #4044, I know you already did it here, but might like to have a discussion there, make sense to you?

[emmanuelGuiton]

Makes sense.
I commented on #4044 and I'll let you know if anything happens because of the patch.

[purbon]

cool, much appreciate it.

[tacoben]

this is exceptionally annoying if you are doing things like using logstash to dump data into kafka and just dont want the @timestamp variables....

i have multiple internal use cases where i have them dropped in a transform, but have to un-drop them to do any debugging.