Warning for TimeFormat even though it is correct

[shahbour]

the log for fluent-bit is full of warning about invalid time format , but checking the date received and format it seems it is correct .

I could not tell why it is doing so

    [PARSER]
        Name        springboot
        Format      regex
        Regex       /^(?<date>[0-9]+-[0-9]+-[0-9]+\s+[0-9]+:[0-9]+:[0-9]+.[0-9]+)\s+\[(?<user_name>.*)\]\s+(?<log_level>[Aa]lert|ALERT|[Tt]race|TRACE|[Dd]ebug|DEBUG|[Nn]otice|NOTICE|[Ii]nfo|INFO|[Ww]arn?(?:ing)?|WARN?(?:ING)?|[Ee]rr?(?:or)?|ERR?(?:OR)?|[Cc]rit?(?:ical)?|CRIT?(?:ICAL)?|[Ff]atal|FATAL|[Ss]evere|SEVERE|EMERG(?:ENCY)?|[Ee]merg(?:ency)?)\s+(?<pid>[0-9]+)\s+---\s+\[(?<thread>.*)\]\s+(?<class_name>.*)\s+:\s+(?<message>.*)$/
        Time_Key    date
        Time_Format %Y-%m-%d %H:%M:%S.$L

[2018/08/11 15:02:30] [ warn] [parser:springboot] Invalid time format %Y-%m-%d %H:%M:%S.$L for '2018-08-11 15:02:30.975'.
[2018/08/11 15:02:33] [ warn] [parser:springboot] Invalid time format %Y-%m-%d %H:%M:%S.$L for '2018-08-11 15:02:33.367'.
[2018/08/11 15:02:34] [ warn] [parser:springboot] Invalid time format %Y-%m-%d %H:%M:%S.$L for '2018-08-11 15:02:34.535'.
[2018/08/11 15:02:36] [ warn] [parser:springboot] Invalid time format %Y-%m-%d %H:%M:%S.$L for '2018-08-11 15:02:36.598'.
[2018/08/11 15:02:37] [ warn] [parser:springboot] Invalid time format %Y-%m-%d %H:%M:%S.$L for '2018-08-11 15:02:37.900'.
[2018/08/11 15:02:39] [ warn] [parser:springboot] Invalid time format %Y-%m-%d %H:%M:%S.$L for '2018-08-11 15:02:39.347'.
[2018/08/11 15:02:41] [ warn] [parser:springboot] Invalid time format %Y-%m-%d %H:%M:%S.$L for '2018-08-11 15:02:41.120'.
[2018/08/11 15:02:42] [ warn] [parser:springboot] Invalid time format %Y-%m-%d %H:%M:%S.$L for '2018-08-11 15:02:42.420'.
[2018/08/11 15:02:42] [ warn] [parser:springboot] Invalid time format %Y-%m-%d %H:%M:%S.$L for '2018-08-11 15:02:42.617'.
[2018/08/11 15:02:45] [ warn] [parser:springboot] Invalid time format %Y-%m-%d %H:%M:%S.$L for '2018-08-11 15:02:45.014'.
[2018/08/11 15:02:46] [ warn] [parser:springboot] Invalid time format %Y-%m-%d %H:%M:%S.$L for '2018-08-11 15:02:46.981'.
[2018/08/11 15:02:47] [ warn] [parser:springboot] Invalid time format %Y-%m-%d %H:%M:%S.$L for '2018-08-11 15:02:47.722'.

[edsiper]

would you please supply a full example of a log line for the case in question ?

[shahbour]

Here is a sample of my logs

2018-08-17 06:44:58.865 [               ]  INFO 1 --- [ask-scheduler-1] c.t.config.CustomImapMailReceiver        : attempting to receive mail from folder [INBOX]
2018-08-17 06:45:21.298 [               ]  INFO 1 --- [ask-scheduler-8] c.t.config.CustomImapMailReceiver        : attempting to receive mail from folder [INBOX]
2018-08-17 06:46:59.576 [               ]  INFO 1 --- [ask-scheduler-1] c.t.config.CustomImapMailReceiver        : attempting to receive mail from folder [INBOX]
2018-08-17 06:47:21.699 [               ]  INFO 1 --- [ask-scheduler-8] c.t.config.CustomImapMailReceiver        : attempting to receive mail from folder [INBOX]
2018-08-17 06:49:00.256 [               ]  INFO 1 --- [ask-scheduler-1] c.t.config.CustomImapMailReceiver        : attempting to receive mail from folder [INBOX]
2018-08-17 06:49:22.049 [               ]  INFO 1 --- [ask-scheduler-8] c.t.config.CustomImapMailReceiver        : attempting to receive mail from folder [INBOX]
2018-08-17 06:51:00.932 [               ]  INFO 1 --- [ask-scheduler-1] c.t.config.CustomImapMailReceiver        : attempting to receive mail from folder [INBOX]
2018-08-17 06:51:23.370 [               ]  INFO 1 --- [ask-scheduler-8] c.t.config.CustomImapMailReceiver        : attempting to receive mail from folder [INBOX]
2018-08-17 06:53:01.693 [               ]  INFO 1 --- [ask-scheduler-1] c.t.config.CustomImapMailReceiver        : attempting to receive mail from folder [INBOX]
2018-08-17 06:53:24.678 [               ]  INFO 1 --- [ask-scheduler-8] c.t.config.CustomImapMailReceiver        : attempting to receive mail from folder [INBOX]

this is the output of fluentbit

[2018/08/17 06:49:01] [debug] [task] destroy task=0x7fd0c265b540 (task_id=0)
[2018/08/17 06:49:01] [debug] [dyntag tail.0] 0x7fd0c26ac360 destroy (tag=kube.var.log.containers.email-fetcher-sell-7d978c4c4c-57w5q_default_email-fetcher-sell-4e8181c2be47c04dc4fba19b481350154a3d5dd8a991c84fa03e8dcad8d53245.log, bytes=967)
[2018/08/17 06:49:22] [debug] [in_tail] file=/var/log/containers/email-fetcher-sell-7d978c4c4c-57w5q_default_email-fetcher-sell-4e8181c2be47c04dc4fba19b481350154a3d5dd8a991c84fa03e8dcad8d53245.log event
[2018/08/17 06:49:22] [ warn] [parser:springboot] Invalid time format %Y-%m-%d %H:%M:%S.$L for '2018-08-17 06:49:22.049'.
[2018/08/17 06:49:22] [debug] [input tail.0] [mem buf] size = 967
[2018/08/17 06:49:22] [debug] [in_tail] file=/var/log/containers/email-fetcher-sell-7d978c4c4c-57w5q_default_email-fetcher-sell-4e8181c2be47c04dc4fba19b481350154a3d5dd8a991c84fa03e8dcad8d53245.log read=232 lines=1
[2018/08/17 06:49:22] [debug] [task] created task=0x7fd0c265b540 id=0 OK
[2018/08/17 06:49:23] [debug] [out_es] HTTP Status=200
[2018/08/17 06:49:23] [debug] [out_es Elasticsearch response
{"took":9,"errors":false,"items":[{"index":{"_index":"logstash-2018.08.17","_type":"flb_type","_id":"UJilRmUB3KhquhqBTbU6","_version":1,"result":"created","_shards":{"total":2,"successful":1,"failed":0},"_seq_no":736,"_primary_term":1,"status":201}}]}
[2018/08/17 06:49:23] [debug] [task] destroy task=0x7fd0c265b540 (task_id=0)
[2018/08/17 06:49:23] [debug] [dyntag tail.0] 0x7fd0c26ac360 destroy (tag=kube.var.log.containers.email-fetcher-sell-7d978c4c4c-57w5q_default_email-fetcher-sell-4e8181c2be47c04dc4fba19b481350154a3d5dd8a991c84fa03e8dcad8d53245.log, bytes=967)
[2018/08/17 06:51:00] [debug] [in_tail] file=/var/log/containers/email-fetcher-sell-7d978c4c4c-57w5q_default_email-fetcher-sell-4e8181c2be47c04dc4fba19b481350154a3d5dd8a991c84fa03e8dcad8d53245.log event
[2018/08/17 06:51:00] [ warn] [parser:springboot] Invalid time format %Y-%m-%d %H:%M:%S.$L for '2018-08-17 06:51:00.932'.
[2018/08/17 06:51:00] [debug] [input tail.0] [mem buf] size = 967
[2018/08/17 06:51:00] [debug] [in_tail] file=/var/log/containers/email-fetcher-sell-7d978c4c4c-57w5q_default_email-fetcher-sell-4e8181c2be47c04dc4fba19b481350154a3d5dd8a991c84fa03e8dcad8d53245.log read=232 lines=1
[2018/08/17 06:51:00] [debug] [task] created task=0x7fd0c265b540 id=0 OK
[2018/08/17 06:51:01] [debug] [out_es] HTTP Status=200
[2018/08/17 06:51:01] [debug] [out_es Elasticsearch response
{"took":6,"errors":false,"items":[{"index":{"_index":"logstash-2018.08.17","_type":"flb_type","_id":"0ZimRmUB3KhquhqBzLcL","_version":1,"result":"created","_shards":{"total":2,"successful":1,"failed":0},"_seq_no":801,"_primary_term":1,"status":201}}]}
[2018/08/17 06:51:01] [debug] [task] destroy task=0x7fd0c265b540 (task_id=0)

As you can see it did complain about 2018-08-17 06:51:00.932 while the other did work, as if it is randomly or on something that I can't catch, it is possible to make fluent-bit log all the message when it is complaining about parsing time instead of just the datetime part

The only thing i notice is that it directly come after

[2018/08/17 06:51:00] [debug] [in_tail] file=/var/log/containers/email-fetcher-sell-7d978c4c4c-57w5q_default_email-fetcher-sell-4e8181c2be47c04dc4fba19b481350154a3d5dd8a991c84fa03e8dcad8d53245.log event

Checking Kibana and ES I see the message above already in database and I am able to view it

[nokute78]

Would you try this? $L -> %L

--- old.conf    2018-08-20 20:27:39.328020968 +0900
+++ new.conf    2018-08-20 20:27:34.599518399 +0900
@@ -3,4 +3,4 @@
         Format      regex
         Regex       /^(?<date>[0-9]+-[0-9]+-[0-9]+\s+[0-9]+:[0-9]+:[0-9]+.[0-9]+)\s+\[(?<user_name>.*)\]\s+(?<log_level>[Aa]lert|ALERT|[Tt]race|TRACE|[Dd]ebug|DEBUG|[Nn]otice|NOTICE|[Ii]nfo|INFO|[Ww]arn?(?:ing)?|WARN?(?:ING)?|[Ee]rr?(?:or)?|ERR?(?:OR)?|[Cc]rit?(?:ical)?|CRIT?(?:ICAL)?|[Ff]atal|FATAL|[Ss]evere|SEVERE|EMERG(?:ENCY)?|[Ee]merg(?:ency)?)\s+(?<pid>[0-9]+)\s+---\s+\[(?<thread>.*)\]\s+(?<class_name>.*)\s+:\s+(?<message>.*)$/
         Time_Key    date
-        Time_Format %Y-%m-%d %H:%M:%S.$L
+        Time_Format %Y-%m-%d %H:%M:%S.%L

[ProFfeSsoRr]

Same problem for crio parser: Time_Format %Y-%m-%dT%H:%M:%S.%N%:z in config. Trying "date +%Y-%m-%dT%H:%M:%S.%N%:z" in my shell and see time as is in my logs.

[shahbour]

Ok, I just changed the configuration to %, I don't recall from where I got the $.

Will give it some time before confirming if it worked

[shahbour]

Seems it is working perfectly now, Sorry for that mistake but I don't know from where I did this copy paste.