Invalid Frame Type, received: 1

Elastic Stack Logstash
1

Hello,

I installed the complete 5.0 stack (filebeat/logstash/elasticsearch/kibana). But I have following error in my logs continuously showing up:
[2016-11-09T14:17:34,982][ERROR][org.logstash.beats.BeatsHandler] Exception: org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 3
[2016-11-09T14:17:34,982][ERROR][org.logstash.beats.BeatsHandler] Exception: org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 1

Anybody any ideas?

2

Ok... Nevermind.... After 30 minutes it suddenly stoppped... No Idea what this was...

3

But... It keeps showing up and I get nog logs what so ever from logstash to elasticsearch... If I let filebeat send the logs to elasticsearch directly, there is no issue. But, if I let them pass through logstash for parsing my logs. No logs are showing up in kibana/
My output config:
output {
elasticsearch {
action => "%{[@metadata][action]}"
document_id => "%{[@metadata][_id]}"
hosts => ["elasticsearch01dev:9200","elasticsearch02dev:9200","elasticsearch03dev:9200"]
index => "filebeat-%{+YYYY.MM.dd}"
}
}

My input for the beats:
input {
beats {
port => 5044
}
}

Netstat:

tcp        0      0 0.0.0.0:5000            0.0.0.0:*               LISTEN      12252/java          
tcp        0      0 0.0.0.0:9545            0.0.0.0:*               LISTEN      1049/NetworkSensorS 
tcp        0      0 0.0.0.0:5044            0.0.0.0:*               LISTEN      12252/java          
tcp        0      0 0.0.0.0:22              0.0.0.0:*               LISTEN      1003/sshd           
tcp        0      0 127.0.0.1:25            0.0.0.0:*               LISTEN      1318/master         
tcp        0      0 10.206.13.219:9600      0.0.0.0:*               LISTEN      12252/java          
tcp        0      0 0.0.0.0:5665            0.0.0.0:*               LISTEN      1328/icinga2        
tcp        0      0 0.0.0.0:514             0.0.0.0:*               LISTEN      12252/java          
udp        0      0 0.0.0.0:40355           0.0.0.0:*                           21562/local         
udp        0      0 0.0.0.0:12201           0.0.0.0:*                           12252/java          
udp        0      0 10.206.13.219:123       0.0.0.0:*                           709/ntpd            
udp        0      0 127.0.0.1:123           0.0.0.0:*                           709/ntpd            
udp        0      0 0.0.0.0:123             0.0.0.0:*                           709/ntpd            
udp   214016      0 0.0.0.0:514             0.0.0.0:*                           12252/java          
udp        0      0 0.0.0.0:4739            0.0.0.0:*                           1049/NetworkSensorS 
udp        0      0 0.0.0.0:25826           0.0.0.0:*                           12252/java

Logs from filebeat:

2016-11-10T09:12:33+01:00 ERR Failed to publish events caused by: read tcp 10.206.13.187:34184->10.206.13.111:5044: i/o timeout
2016-11-10T09:13:04+01:00 ERR Connecting error publishing events (retrying): dial tcp 10.206.13.111:5044: i/o timeout
2016-11-10T09:13:36+01:00 ERR Failed to publish events caused by: read tcp 10.206.13.187:46881->10.206.13.219:5044: i/o timeout
2016-11-10T09:14:10+01:00 ERR Connecting error publishing events (retrying): dial tcp 10.206.13.111:5044: i/o timeout
2016-11-10T09:14:48+01:00 ERR Failed to publish events caused by: read tcp 10.206.13.187:46889->10.206.13.219:5044: i/o timeout
2016-11-10T09:15:04+01:00 ERR Connecting error publishing events (retrying): dial tcp 10.206.13.117:5044: getsockopt: connection refused
4

I can share some more details:

  • Everything is on 5.0
  • filebeat.yml has output.logstash configured with defaults (except for hosts)
  • Logstash hosts have a plain beats input with a port but no other parameters set, and a plain elasticsearch output
5

Can you telnet to the Logstash server on port 5044 from the host where Filebeat runs? What does your Filebeat config look like? What does the rest of your Logstash config look like? Are the parameters you use in the Elasticsearch output present on ALL events?

6
  • Are you getting any messages through?
  • What is the rate of messages?
  • Try to simplify the pipeline: use only 1 Logstash host, and switch to the stdout output instead of Elasticsearch output.
7

This is my complete logstash config from input to filters to output:

https://nextcloud.brusselsairport.be/index.php/s/0M2wRmYDshwOifm

I have a output for all of them. So I do have all my data. But the logs for logstash keep filling up with the same message over and over again at a rate you can't follow....

8

This one show up now also:

[2016-11-16T07:46:15,355][WARN ][logstash.filters.date    ] Failed parsing date from field {:field=>"timestamp", :value=>"2016-11-16 07:46:06,250", :exception=>"Invalid format: \"2016-11-16 07:46:06,250\" is malformed at \"-11-16 07:46:06,250\"", :config_parsers=>"YYYY/MM/dd HH:mm:ss", :config_locale=>"default=en_US"}
[2016-11-16T07:46:15,356][WARN ][logstash.filters.date    ] Failed parsing date from field {:field=>"timestamp", :value=>"2016-11-16 07:46:06,250", :exception=>"Invalid format: \"2016-11-16 07:46:06,250\" is malformed at \"-11-16 07:46:06,250\"", :config_parsers=>"YYYY/MM/dd HH:mm:ss", :config_locale=>"default=en_US"}
[2016-11-16T07:46:15,357][WARN ][logstash.filters.date    ] Failed parsing date from field {:field=>"timestamp", :value=>"2016-11-16 07:46:09,414", :exception=>"Invalid format: \"2016-11-16 07:46:09,414\" is malformed at \"-11-16 07:46:09,414\"", :config_parsers=>"YYYY/MM/dd HH:mm:ss", :config_locale=>"default=en_US"}
[2016-11-16T07:46:15,358][WARN ][logstash.filters.date    ] Failed parsing date from field {:field=>"timestamp", :value=>"2016-11-16 07:46:09,461", :exception=>"Invalid format: \"2016-11-16 07:46:09,461\" is malformed at \"-11-16 07:46:09,461\"", :config_parsers=>"YYYY/MM/dd HH:mm:ss", :config_locale=>"default=en_US"}
[2016-11-16T07:46:15,359][WARN ][logstash.filters.date    ] Failed parsing date from field {:field=>"timestamp", :value=>"2016-11-16 07:46:09,949", :exception=>"Invalid format: \"2016-11-16 07:46:09,949\" is malformed at \"-11-16 07:46:09,949\"", :config_parsers=>"YYYY/MM/dd HH:mm:ss", :config_locale=>"default=en_US"}
[2016-11-16T07:46:15,359][WARN ][logstash.filters.date    ] Failed parsing date from field {:field=>"timestamp", :value=>"2016-11-16 07:46:09,971", :exception=>"Invalid format: \"2016-11-16 07:46:09,971\" is malformed at \"-11-16 07:46:09,971\"", :config_parsers=>"YYYY/MM/dd HH:mm:ss", :config_locale=>"default=en_US"}
[2016-11-16T07:46:15,360][WARN ][logstash.filters.date    ] Failed parsing date from field {:field=>"timestamp", :value=>"2016-11-16 07:46:09,976", :exception=>"Invalid format: \"2016-11-16 07:46:09,976\" is malformed at \"-11-16 07:46:09,976\"", :config_parsers=>"YYYY/MM/dd HH:mm:ss", :config_locale=>"default=en_US"}
[2016-11-16T07:46:15,361][WARN ][logstash.filters.date    ] Failed parsing date from field {:field=>"timestamp", :value=>"2016-11-16 07:46:10,783", :exception=>"Invalid format: \"2016-11-16 07:46:10,783\" is malformed at \"-11-16 07:46:10,783\"", :config_parsers=>"YYYY/MM/dd HH:mm:ss", :config_locale=>"default=en_US"}
[2016-11-16T07:46:15,362][WARN ][logstash.filters.date    ] Failed parsing date from field {:field=>"timestamp", :value=>"2016-11-16 07:46:10,839", :exception=>"Invalid format: \"2016-11-16 07:46:10,839\" is malformed at \"-11-16 07:46:10,839\"", :config_parsers=>"YYYY/MM/dd HH:mm:ss", :config_locale=>"default=en_US"}

Any idea which filter this might be? :slight_smile:

9

You have a few date filters in your config with the pattern "YYYY/MM/dd HH:mm:ss", which apparently does not match the data received ("2016-11-16 07:46:09,949"). You will need to make sure that the patterns specified in the date filter exactly matches the data received, and you can specify more then one option if necessary.

10

OK, so you are getting messages through, which means that the config probably is OK. Is it messages about the Frame Type that is filling up the logs?

11

Both...
It goes like this:

org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 1
[2016-11-16T07:59:48,674][ERROR][org.logstash.beats.BeatsHandler] Exception: org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 1
[2016-11-16T07:59:48,674][ERROR][org.logstash.beats.BeatsHandler] Exception: org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 1
[2016-11-16T07:59:48,741][ERROR][logstash.codecs.json ] JSON parse error, original data now in message field {:error=>#<LogStash::Json::ParserError: Unexpected character ('<' (code 60)): expected a valid value (number, String, array, object, 'true', 'false' or 'null')
at [Source: <31>routed[7189]: rt_instance_monitor_job: fired
; line: 1, column: 2]>, :data=>"<31>routed[7189]: rt_instance_monitor_job: fired\n"}
[2016-11-16T07:59:48,742][ERROR][logstash.codecs.json ] JSON parse error, original data now in message field {:error=>#<LogStash::Json::ParserError: Unexpected character ('<' (code 60)): expected a valid value (number, String, array, object, 'true', 'false' or 'null')
at [Source: <31>routed[7189]: rt_instance_monitor_job: scheduled next instance monitor in 5 seconds
; line: 1, column: 2]>, :data=>"<31>routed[7189]: rt_instance_monitor_job: scheduled next instance monitor in 5 seconds\n"}
[2016-11-16T07:59:48,959][ERROR][org.logstash.beats.BeatsHandler] Exception: org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 3
[2016-11-16T07:59:48,959][ERROR][org.logstash.beats.BeatsHandler] Exception: org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 1
[2016-11-16T07:59:49,214][ERROR][org.logstash.beats.BeatsHandler] Exception: org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 3
[2016-11-16T07:59:49,214][ERROR][org.logstash.beats.BeatsHandler] Exception: org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 1
[2016-11-16T07:59:49,442][ERROR][org.logstash.beats.BeatsHandler] Exception: org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 3
0:05,765"", :config_parsers=>"YYYY/MM/dd HH:mm:ss", :config_locale=>"default=en_US"}
[2016-11-16T08:00:36,396][WARN ][logstash.filters.date ] Failed parsing date from field {:field=>"timestamp", :value=>"2016-11-16 08:00:05,772", :exception=>"Invalid format: "2016-11-16 08:00:05,772" is malformed at "-11-16 08:00:05,772"", :config_parsers=>"YYYY/MM/dd HH:mm:ss", :config_locale=>"default=en_US"}
[2016-11-16T08:00:36,397][WARN ][logstash.filters.date ] Failed parsing date from field {:field=>"timestamp", :value=>"2016-11-16 08:00:05,798", :exception=>"Invalid format: "2016-11-16 08:00:05,798" is malformed at "-11-16 08:00:05,798"", :config_parsers=>"YYYY/MM/dd HH:mm:ss", :config_locale=>"default=en_US"}
[2016-11-16T08:00:36,399][WARN ][logstash.filters.date ] Failed parsing date from field {:field=>"timestamp", :value=>"2016-11-16 08:00:07,214", :exception=>"Invalid format: "2016-11-16 08:00:07,214" is malformed at "-11-16 08:00:07,214"", :config_parsers=>"YYYY/MM/dd HH:mm:ss", :config_locale=>"default=en_US"}
[2016-11-16T08:00:36,566][ERROR][org.logstash.beats.BeatsHandler] Exception: org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 3
[2016-11-16T08:00:36,566][ERROR][org.logstash.beats.BeatsHandler] Exception: org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 1
[2016-11-16T08:00:36,578][ERROR][org.logstash.beats.BeatsHandler] Exception: org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 3
[2016-11-16T08:00:36,578][ERROR][org.logstash.beats.BeatsHandler] Exception: org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 3
[2016-11-16T08:00:36,579][ERROR][org.logstash.beats.BeatsHandler] Exception: org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 1
[2016-11-16T08:00:36,579][ERROR][org.logstash.beats.BeatsHandler] Exception: org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 1
[2016-11-16T08:00:36,706][ERROR][org.logstash.beats.BeatsHandler] Exception: org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 3
[2016-11-16T08:00:36,707][ERROR][org.logstash.beats.BeatsHandler] Exception: org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 1
[2016-11-16T08:00:36,849][WARN ][logstash.filters.date ] Failed parsing date from field {:field=>"timestamp", :value=>"2016-11-16 08:00:07,735", :exception=>"Invalid format: "2016-11-16 08:00:07,735" is malformed at "-11-16 08:00:07,735"", :config_parsers=>"YYYY/MM/dd HH:mm:ss", :config_locale=>"default=en_US"}

12

I have successfully removed the failed log lines for the filter:

0:05,765\"", :config_parsers=>"YYYY/MM/dd HH:mm:ss", :config_locale=>"default=en_US"}
[2016-11-16T08:00:36,396][WARN
 ][logstash.filters.date    ] Failed parsing date from field 
{:field=>"timestamp", :value=>"2016-11-16 08:00:05,772", 
:exception=>"Invalid format: \"2016-11-16 08:00:05,772\" is malformed
 at \"-11-16 08:00:05,772\"", :config_parsers=>"YYYY/MM/dd HH:mm:ss",
 :config_locale=>"default=en_US"}

Now the only thing that keeps filling up my logs and disk space is the invalid frame type

13

Based on this post it seems this might have been an issue fixed previously. If you are using all 5.0 components and this has resurfaced, it may be a question for the Logstash team.

14

I'm using all 5.0 components... :slight_smile:

15

I also have this issue on an all 5.0 stack.

16

I fixed that error. First, I did a yum update on client and server. This increased the versions of the ELK stack and beats.

Then, I installed updated the beats input plugin for logstash following the advice here:
https://www.elastic.co/guide/en/beats/libbeat/5.0/logstash-installation.html#logstash-setup

I also installed the filebeat index template following this:
https://www.elastic.co/guide/en/beats/filebeat/current/filebeat-template.html

I restarted all the services and something clicked because I no longer have that error.

17

After receiving events from my filebeat and then playing a bit with the multiline settings I get the exact same error message. Commenting out the multiline settings didn't help. Reinstalling didn't work either. Any news?

18

I tried this too and now i have the very latest versions (5.1.1) and the same issue. Run out of ideas after trying every trick i could find.
Seems the invalid frame I get is a http payload as I was able to replicate the filebeat issue from the browser.

[2016-12-09T19:35:50,889][INFO ][logstash.agent ] Successfully started Logstash API endpoint {:port=>9600}
[2016-12-09T19:36:04,204][ERROR][org.logstash.beats.BeatsHandler] Exception: org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 69
[2016-12-09T19:36:04,208][ERROR][org.logstash.beats.BeatsHandler] Exception: org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 84
[2016-12-09T19:36:36,208][ERROR][org.logstash.beats.BeatsHandler] Exception: org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 69
[2016-12-09T19:36:36,208][ERROR][org.logstash.beats.BeatsHandler] Exception: org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 84

19

Hi

I had the same issue. check the filebeat.yml
#================================ Outputs =====================================

Not only you need to remove the comment for hosts: ["localhost:5044"] but also for output.logstash: as well and then comment both elasticsearch host and ouput.

I Hope this would help you.

1 Like
20

I had ssl.verification_mode explicitly set to none and this caused exactly the same error on my machine. Maybe that's the culprit here?