Logstash filter date match not replacing @timestamp

yhache · June 3, 2022, 8:17pm

Hi, I have a bunch of PHP log to add to my ELK cluster and i cannot get the @timestamp to work. I'm pretty sure it has something to do with the config file and the date format used in the PHP logs.

Here's my config file's Filter block ::

filter {
        # ignore log comments
        if [message] =~ "^#" {
                drop {}
        }
        grok {
                match => ["message", "\[(?<datetime>(%{MONTHDAY:day}-%{MONTH:month}-%{YEAR:year} %{TIME})) (?<timezone>([\a-zA-z\s\\]*))\] (?<message>(.|\r|\n)*)"]
        }
        date {
                match => ["datetime", "DD-MMM-yyyy HH:mm:ss"]
                target => "@timestamp"
        }
}

And here's a line of log ::

[03-Jun-2022 15:31:44 America/New_York] PHP Fatal error:  Uncaught ArgumentCountError: Too few arguments to function KhamaiController::getTelevisionPackages(), 4 passed in /home/papi/public_html/library/shared.php on line 48 and exactly 5 expected in /home/papi/public_html/application/controllers/khamai.php:527
Stack trace:
#0 /home/papi/public_html/library/shared.php(48): KhamaiController->getTelevisionPackages('96,84,103,83,86...', '1924,7054,7210,...', 'FR', '')
#1 /home/papi/public_html/library/shared.php(76): callHook()
#2 /home/papi/public_html/library/bootstrap.php(3): require_once('/home/papi/publ...')
#3 /home/papi/public_html/index.php(22): require_once('/home/papi/publ...')
#4 {main}
  thrown in /home/papi/public_html/application/controllers/khamai.php on line 527

When i use the grok debugger i can successfully tag the datetime as one variables but it doesnt replace @timestamp.

@timestamp : 03-Jun-2022 15:17:43
datetime : 06-Jul-2018 17:14:48

Thanks for your help on this!

Badger · June 3, 2022, 8:56pm

I did not know you could name fields within a custom pattern! Anyways ... it almost works for me

  "datetime" => "03-Jun-2022 15:31:44",
"@timestamp" => 2022-01-03T20:31:44Z,
     "month" => "Jun",

if you change DD (day of the year, so this forces the month to January) to dd then it does work (19 rather than 20 because January does not have DST but June does)

"@timestamp" => 2022-06-03T19:31:44Z,

Note also that since your grok has a field called 'message' the [message] field will end up as an array containing the original message and your new message string. You may want to look at the overwrite option of the filter.

yhache · June 6, 2022, 11:54am

Hi Badger, thanks for replaying so quick!

So yeah i can change the value to "dd" But even then, in your example, it was putting the @timestamp for today instead of the real one which should be 2018 (in my example)

About the [message], i understand your point, i should name my last variable something else.. or not put "message" , in front of the Grok match ?!

Badger · June 6, 2022, 12:42pm

No, your example was 03-Jun-2022 15:31:44 America/New_York.

yhache · June 6, 2022, 12:47pm

I'll add this Grok screenshot to help understand

As you can see, i was able to name my variable "datetime" and the Grok parser gets it too. But even if i do the match in my filter, it does not replace @timestamp.

As far as my example goes :

The @timestamp took is not reflecting the right datetime (it's not the same set of dates as my screenshot but it's all the same in the end)

I hope it helped.

leandrojmp · June 6, 2022, 2:24pm

Can you use a stdout output and share the logstash output?

I was not able to replicate your issue as well, for me the date filter is correctly replace the @timestamp field.

yhache · June 6, 2022, 3:08pm

You know what's worst..It seems to be working for "some" of he logs :

i will continue looking into it.

yhache · June 6, 2022, 3:59pm

Here's a log that was ingested correctly :

And here's what that wasn't :

leandrojmp · June 6, 2022, 5:07pm

In the second example the date filter failed for some reason that is still unclear.

I've replaced the date in the sample message that you shared to 05-Dec-2018 18:24:16 and the following date filter worked without any problem:

        date {
                match => ["datetime", "dd-MMM-yyyy HH:mm:ss"]
                target => "@timestamp"
        }

Can you share the full line from the event where you have _dateparsefailure? Also, can you share other examples where the date filter failed to see if there is any pattern on them?

yhache · June 6, 2022, 5:22pm

Here's the line directly from the log :

[05-Dec-2018 18:24:16 America/New_York] PHP Notice:  Undefined variable: langue in /home/papi/public_html/application/controllers/khamai.php on line 197

Another example :

[05-Dec-2018 19:12:29 America/Toronto] PHP Notice:  Trying to get property of non-object in /home/papi/public_html/application/models/ipblock.php on line 28

And another:

[14-Aug-2018 06:31:20 America/New_York] PHP Notice:  Undefined variable: langue in /home/papi/public_html/application/controllers/khamai.php on line 210

Badger · June 6, 2022, 6:13pm

It would be useful to see an event that fails to parse correctly in

output { stdout { codec => rubydebug } }

That would allow us to rule out timestamp being an array, or a LogStash::Timestamp.

What is the default locale on logstash server? Although I cannot think of a locale where May would parse but Dec would not.

yhache · June 6, 2022, 7:07pm

Here's the output of the stdout :

           "type" => "phpApi",
           "path" => "/home/papi/logs/php_error_log",
       "@version" => "1",
       "datetime" => "12-Dec-2018 09:30:58",
            "day" => "12",
        "message" => "[12-Dec-2018 09:30:58 America/Toronto] PHP Warning:  mssql_connect(): Unable to connect to server: 10.54.2.10 in /home/papi/include/source/db/db.class_mssql.php on line 237",
          "month" => "Dec",
           "host" => "webhost01.int.cablevision.ca",
    "log_message" => "PHP Warning:  mssql_connect(): Unable to connect to server: 10.54.2.10 in /home/papi/include/source/db/db.class_mssql.php on line 237",
           "time" => "09:30:58",
       "timezone" => "America/Toronto",
           "year" => "2018",
     "@timestamp" => 2022-06-06T19:06:25.897Z

yhache · June 6, 2022, 7:17pm

I tried making a new variable with the mutate function and match it after :

        grok {
                match => {"message" => "\[%{MONTHDAY:day}-%{MONTH:month}-%{YEAR:year} %{TIME:time} (?<timezone>([\a-zA-z\s\\]*))\] (?<log_message>(.|\r|\n)*)"}
        }
        mutate {
                add_field => {
                        "newDateTime" => "%{day}-%{month}-%{year} %{time}"
                }
        }
        date {
                match => ["newDateTime", "dd-MMM-yyyy HH:mm:ss"]
                target => "@timestamp"
        }

But the result is the same. @timestamp never gets changed but the value of newDateTime is the good one.

Badger · June 6, 2022, 7:25pm

You didn't answer my question about the locale.

Can you see if mutate { gsub => [ "datetime", "Dec", "Dec." ] } before the date filter helps? I am reminded of this thread.

yhache · June 6, 2022, 7:41pm

First, my locale is : LANG="en_CA.UTF-8" . So It should work just fine.

Secondly, here's the result of the gsub :

          "path" => "/home/papi/logs/php_error_log",
          "host" => "webhost01.int.cablevision.ca",
          "type" => "phpApi",
      "datetime" => "14-Jul.-2021 01:10:14",
           "day" => "14",
          "year" => "2021",
          "tags" => [
        [0] "multiline"
    ],
      "@version" => "1",
       "message" => "DB::getConn() error : PDOException Object\n(\n    [message:protected] => SQLSTATE[42000]: [Microsoft][ODBC Driver 13 for SQL Server",
         "month" => "Jul",
          "time" => "01:10:14",
      "timezone" => "America/New_York",
    "@timestamp" => 2022-06-06T19:35:34.592Z

I cropped the message itself beause it's multi-line. But as you can see, the @timestamp still ignores my setup in the conf file.

As a reference, i have not change a thing in the conf :

        date {
                match => ["thedatetime", "dd-MMM-yyyy HH:mm:ss"]
                target => "@timestamp"
        }

I'm sure i am just missing something "stupid" but i don't understand what it could be.

Badger · June 6, 2022, 8:02pm

There is no _dateparsefailure tag on that message. I do not understand what could be going wrong.

yhache · June 6, 2022, 8:34pm

I tried different things, with a smaller data set.. Trying to see where it could fail. So i created a new field "newdatetime" then i tried to associate the datetime to it :

        grok {
                match => {"message" => "\[(?<datetime>(%{MONTHDAY:day}-%{MONTH:month}-%{YEAR:year} %{TIME:time})) %{DATA:timezone}\] (?<message>(.|\r|\n)*)"}
                overwrite => ["message"]
        }
        mutate{
                add_field => {"newdatetime"=>""}
        }
        date {
                match => ["datetime","dd-MMM-yyyy HH:mm:ss"]
                target => "newdatetime"
        }

Here's the result... :

{
           "type" => "phpApi",
       "datetime" => "08-Jul-2018 00:38:24",
     "@timestamp" => 2022-06-06T20:30:35.431Z,
            "day" => "08",
       "timezone" => "America/Toronto",
        "message" => "PHP Notice:  Trying to get property of non-object in /home/papi/public_html/application/models/ipblock.php on line 28",
           "host" => "webhost01.int.cablevision.ca",
           "tags" => [
        [0] "_dateparsefailure"
    ],
           "year" => "2018",
       "@version" => "1",
          "month" => "Jul",
           "path" => "/home/papi/logs/php_error_test_log",
           "time" => "00:38:24",
    "newdatetime" => ""
}

It's like the match does not work at all..

Badger · June 6, 2022, 9:03pm

Can you enable log.level DEBUG and see what this line prints?

yhache · June 6, 2022, 9:46pm

Ill try tomorrow... But i thought about something... What if i gsub all month into numbers then convert it to date time !?

yhache · June 7, 2022, 12:26pm

[DEBUG] 2022-06-07 08:24:44.552 [Converge PipelineAction::Create] DateFilter - Date filter with format=dd-MMM-yyyy HH:mm:ss, locale=null, timezone=null built as org.logstash.filters.parser.JodaParser