Wildfly grok date not extracted

[jsec (Catalin)]

Hello,

I'm trying to parse the following wildfly log format:

2021-02-16 00:01:34,505 ERROR [org.springframework.boot.cttt.web.ErrorPageFilter] (default task-48) Forwarding to error page from request [/user/history] due to exception [org.hibernate.exception.DataException: could not execute statement]: javax.persistence.PersistenceException: org.hibernate.exception.DataException: could not execute statement
        at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1763) [hibernate-entitymanager-4.3.11.Final.jar:4.3.11.Final]
        at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1677) [hibernate-entitymanager-4.3.11.Final.jar:4.3.11.Final]
        at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1683) [hibernate-entitymanager-4.3.11.Final.jar:4.3.11.Final]
        at org.hibernate.jpa.spi.AbstractEntityManagerImpl.persist(AbstractEntityManagerImpl.java:1187) [hibernate-entitymanager-4.3.11.Final.jar:4.3.11.Final]
        at sun.reflect.GeneratedMethodAccessor99.invoke(Unknown Source) [:1.8.0_31]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_31]
        at java.lang.reflect.Method.invoke(Method.java:483) [rt.jar:1.8.0_31]
        at org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler.invoke(ExtendedEntityManagerCreator.java:344) [spring-orm-4.2.5.RELEASE.jar:4.2.5.RELEASE]
... 166 more

2021-02-16 00:02:35,372 ERROR [io.undertow.request] (default task-42) Undertow request failed HttpServerExchange{ POST /ccc-web-user/error}: java.lang.NullPointerException

2021-02-16 00:03:36,993 SEVERE [com.prompsit.bstweb.urlrules.SpacesRewriteRule] (default task-62) matches: Failed to match the url.: java.lang.IllegalArgumentException: URLDecoder: Incomplete trailing escape (%) pattern
        at java.net.URLDecoder.decode(URLDecoder.java:187) [rt.jar:1.8.0_31]
        at com.prompsit.bstweb.urlrules.SpacesRewriteRule.matches(SpacesRewriteRule.java:75) [ccc-web-5.40.1-SNAPSHOT.jar:]
        at sun.reflect.GeneratedMethodAccessor50.invoke(Unknown Source) [:1.8.0_31]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_31]
        at java.lang.reflect.Method.invoke(Method.java:483) [rt.jar:1.8.0_31]
        at org.tuckey.web.filters.urlrewrite.ClassRule.matches(ClassRule.java:119) [urlrewritefilter-4.0.5.jar:4.0.5]
        at org.tuckey.web.filters.urlrewrite.ClassRule.matches(ClassRule.java:101) [urlrewritefilter-4.0.5.jar:4.0.5]
        at org.tuckey.web.filters.urlrewrite.RuleChain.doRuleProcessing(RuleChain.java:83) [urlrewritefilter-4.0.5.jar:4.0.5]

I've configured the following grok:

if [type] == "wildfly-error-log" {
    grok {
    match => [ "message", "%{DATA} %{WORD:loglevel} \[%{DATA:class}\] \(%{DATA:thread}\) %{GREEDYDATA:message}" ]
    overwrite => [ "message" ]
  }

  mutate {
      add_field => { "read_timestamp" => "%{@timestamp}" }
    }

  date {
      match => [ "timestamp", "YYYY-MM-DD HH:mm:ss,SSS" ]
      remove_field => "timestamp"
    }

 }

However, in Kibana, the date is when the logstash ingest it, instead of getting the real date from the log ingested.
So instead of 2021-02-16 00:01:34 I get the actual date of ingesting time.

Can you help me please?

[Badger]

How do you set [timestamp]?

[jsec (Catalin)]

I've modified it logstash to:

if [type] == "wildfly-error-log" {

  grok {
      match => { "message" => "%{TIMESTAMP_ISO8601:timestamp} %{WORD:loglevel} \[%{DATA:class}\] \(%{DATA:thread}\) %{GREEDYDATA:message}" }
      overwrite => "message"
    }

    if "_grokparsefailure" in [tags] {
     mutate {
       add_tag => [ "ReferrerGrokNotmatch" ]
       remove_tag => ["_grokparsefailure"]
     }
   }


mutate {
  add_field => { "read_timestamp" => "%{@timestamp}" }
}
date {
  match => [ "timestamp", "YYYY-MM-DD HH:mm:ss,SSS" ]
  remove_field => "timestamp"
}

}

However, something is not right.

It seems it's seeing some data both from January and February for the same days, even though I've started the log ingestion this month, February 2021:

root@server:~# curl -s -XGET 'http://localhost:9200/_cat/indices?v&s=index' | grep wildf
green  open   wildfly-error-log-2021.01.17        ABriJowpR-iQH-3MFPkclQ   1   0     154179            0     81.4mb         81.4mb
green  open   wildfly-error-log-2021.01.18        eSfVKSznRmmwxdiqwH0sVA   1   0     192602            0    118.8mb        118.8mb
green  open   wildfly-error-log-2021.01.19        l__EmKv6Ty2NtS4_KxHiDg   1   0     163380            0     92.3mb         92.3mb
green  open   wildfly-error-log-2021.01.20        FoMiphelR9qBBwiWCIeWew   1   0     141251            0     75.8mb         75.8mb
green  open   wildfly-error-log-2021.01.21        P711UNGURM-WhOMcmmC8pg   1   0     146386            0     75.3mb         75.3mb
green  open   wildfly-error-log-2021.01.22        AGCOW1-ZSAqEZTrxNGwdlw   1   0      31833            0     29.5mb         29.5mb
green  open   wildfly-error-log-2021.02.17        keR34wgKQZC34SK6M9NJzw   1   0      63503            0     58.6mb         58.6mb
green  open   wildfly-error-log-2021.02.18        LRPpMxlPRsWteVWSYUWUyQ   1   0      62508            0     57.5mb         57.5mb
green  open   wildfly-error-log-2021.02.19        vSP8ZO7LQZCwR6hMdiDRDw   1   0      51387            0     47.9mb         47.9mb
green  open   wildfly-error-log-2021.02.20        rMFWCRPXQP-dJmKcR7eSCw   1   0      36900            0     34.9mb         34.9mb
green  open   wildfly-error-log-2021.02.21        FANYo3BoQwajalKlO3rpgg   1   0      42376            0     40.6mb         40.6mb
green  open   wildfly-error-log-2021.02.22        zDij5PlCSVu24sLAM9LE-A   1   0       8277            0        8mb            8mb

Somehow I tink it there are 2 issues here, it looks like it's setting the datetime at the moment it's ingesting it, and it should set the datetime from the error.log file.

And the second issue is with seeing some data to be from one month earlier.

[Badger]

@jsec

match => [ "timestamp", "YYYY-MM-DD HH:mm:ss,SSS" ]

DD is day of the year, so 2021-08-10 is Jan 10th, not Aug 10th. Day of the year overrides the month. Use dd.

[jsec (Catalin)]

Many thanks @Badger.
That solve my issue with the date being doubled, however I still don't receive the correct timestamp from logfile, but rather it's being set with the timestamp when being ingested.