Ruby filter: Ruby exception occurred: undefined method `*' for nil:NilClass

[nicklaw (Nick)]

My circumstance is a little different to this post (I think).

I have the below filter that uses ruby to convert Nginx access request_time's and upsteam_response_time's to milliseconds:

filter {
  # NGINX ACCESS GROK
  if [type] == "nginx-access" {
    grok {
      patterns_dir => ["/usr/share/logstash/patterns"]
      match => { "message" => "%{NGINX_ACCESS}" }
      add_field => [ "received_from", "%{host}" ]
    }
    ruby {
      code => "
        requestTime = event.get('request_time')
        event.set('request_time_ms', requestTime == '-' ? nil : requestTime * 1000)

        upstreamResponseTime = event.get('upsteam_response_time')
        event.set('upsteam_response_time_ms', upstreamResponseTime == '-' ? nil : upstreamResponseTime * 1000)
      "
    }
    mutate {
      remove_field => [ "request_time", "upsteam_response_time" ]
    }
  }
}

Which appears to work fine, according to Kibana's interface. However, if I tail Logstash's logs, I see a heap of these exceptions:

[2017-10-30T02:37:59,264][ERROR][logstash.filters.ruby    ] Ruby exception occurred: undefined method `*' for nil:NilClass

Is anyone able to explain why this occurs?

Thanks in advanced.

[magnusbaeck (Magnus Bäck)]

If the event doesn't have a request_time field then event.get('request_time') will return nil. Same thing with upsteam_response_time.

[nicklaw (Nick)]

Sorry, I should have mentioned that we have modified the Nginx access log to include the request time and upstream response time. So our Nginx access log format looks like so:

# Append request_time and upstream_response_time to access logs
log_format e1_access_combined '$remote_addr - $remote_user [$time_local] '
            '"$request" $status $body_bytes_sent '
            '"$http_referer" "$http_user_agent" '
            '$request_time $upstream_response_time';

This Nginx log format then gets used in the Nginx config server block like this:

server {
    access_log /var/log/nginx/app.domain.com.access.log e1_access_combined;
}

This produces an access log such as:

101.187.80.204 - - [30/Oct/2017:18:18:19 +0000] "GET /global/index.js HTTP/1.1" 200 1416 "https://app.domain.com/invitations" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/61.0.3163.100 Safari/537.36" 0.036 0.036

and sometimes without a request time or upstream response time, such as:

59.100.28.70 - - [30/Oct/2017:18:18:03 +0000] "GET /js/plugin-1060b32613.js HTTP/1.1" 403 353826 "https://app.domain.com/s/fimma/invite/6949320-be3c272b" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 Safari/537.36 Edge/15.15063" - -

And we have the following GROK pattern for parsing the above log format in Logstash:

NG_USERNAME [a-zA-Z\.\@\-\+_%]+
NG_USER %{NG_USERNAME}
NGINX_ACCESS %{IPORHOST:client_ip} %{NG_USER:ident} %{NG_USER:auth} \[%{HTTPDATE:timestamp}\] "%{WORD:request_verb} %{URIPATHPARAM:request} HTTP/%{NUMBER:http_version}" %{NUMBER:response:int} (?:%{NUMBER:bytes:int}|-) (?:"(?:%{URI:referrer}|-)"|%{QS:referrer}) %{QS:useragent_raw} (?:%{NUMBER:request_time:float}|-) (?:%{NUMBER:upsteam_response_time:float}|-)

I hope that provides better in-site into our set up.