Check message format to prevent plugin from crashing

[stanhu]

We were running into this issue quite a bit in a production system, and I added debug messages:

2015-12-18 00:38:43 +0000 [warn]: unexpected error in in_secure_forward error_class=NoMethodError error=#<NoMethodError: undefined method `[]' for true:TrueClass>
2015-12-18 00:38:43 +0000 [warn]: error caused from x.x.x.x:34968
2015-12-18 00:38:43 +0000 [warn]: Backtrace: ["/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-secure-forward-0.3.3/lib/fluent/plugin/in_secure_forward.rb:260:in `on_message'", "/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-secure-forward-0.3.3/lib/fluent/plugin/input_session.rb:124:in `on_read'", "/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-secure-forward-0.3.3/lib/fluent/plugin/input_session.rb:185:in `feed_each'", "/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-secure-forward-0.3.3/lib/fluent/plugin/input_session.rb:185:in `block in start'", "/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-secure-forward-0.3.3/lib/fluent/plugin/input_session.rb:178:in `loop'", "/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-secure-forward-0.3.3/lib/fluent/plugin/input_session.rb:178:in `start'"]

This seems to happen when connections break in the middle of a transfer, causing a bad payload.

[stanhu]

There may be a deeper issue here that I don't quite understand yet. Before this fix, I would notice that the on_read would eventually stop being called. For example:

2015-12-17 22:11:29 +0000 [warn]: fluent/engine.rb:330:emit: no patterns matched tag="5"
2015-12-17 22:11:29 +0000 [debug]: plugin/input_session.rb:69:check_ping: checking ping
2015-12-17 22:11:29 +0000 [debug]: plugin/input_session.rb:122:on_read: on_read
2015-12-17 22:11:30 +0000 [debug]: plugin/input_session.rb:105:generate_pong: generating pong
2015-12-17 22:11:30 +0000 [trace]: fluent/engine.rb:339:block in emit: no patterns matched tag="t"
2015-12-17 22:11:30 +0000 [debug]: plugin/input_session.rb:137:on_read: connection established
2015-12-17 22:11:30 +0000 [debug]: plugin/input_session.rb:122:on_read: on_read
2015-12-17 22:11:30 +0000 [debug]: plugin/input_session.rb:122:on_read: on_read
2015-12-17 22:11:30 +0000 [trace]: fluent/engine.rb:339:block in emit: no patterns matched tag="2"
2015-12-17 22:11:30 +0000 [debug]: plugin/input_session.rb:122:on_read: on_read
2015-12-17 22:11:30 +0000 [debug]: plugin/input_session.rb:69:check_ping: checking ping
2015-12-17 22:11:30 +0000 [debug]: plugin/input_session.rb:105:generate_pong: generating pong
2015-12-17 22:11:30 +0000 [debug]: plugin/input_session.rb:137:on_read: connection established
2015-12-17 22:11:30 +0000 [debug]: plugin/input_session.rb:122:on_read: on_read
2015-12-17 22:11:30 +0000 [debug]: plugin/input_session.rb:122:on_read: on_read
2015-12-17 22:11:30 +0000 [debug]: plugin/input_session.rb:122:on_read: on_read
2015-12-17 22:11:30 +0000 [debug]: plugin/input_session.rb:122:on_read: on_read
2015-12-17 22:11:30 +0000 [debug]: plugin/input_session.rb:122:on_read: on_read
2015-12-17 22:11:30 +0000 [debug]: plugin/input_session.rb:122:on_read: on_read
2015-12-17 22:11:30 +0000 [debug]: plugin/input_session.rb:122:on_read: on_read
2015-12-17 22:11:30 +0000 [debug]: plugin/input_session.rb:122:on_read: on_read
2015-12-17 22:11:30 +0000 [debug]: plugin/input_session.rb:122:on_read: on_read
2015-12-17 22:11:31 +0000 [debug]: plugin/input_session.rb:191:rescue in block in start: Connection closed from 'x.x.x.x'(x.x.x.x)
2015-12-17 22:11:34 +0000 [trace]: plugin/in_secure_forward.rb:194:block in run: accept tcp connection (ssl session not established yet)
2015-12-17 22:11:34 +0000 [trace]: plugin/in_secure_forward.rb:199:block in run: session instances: all=531 closed=0
2015-12-17 22:11:36 +0000 [debug]: plugin/input_session.rb:148:start: starting server
2015-12-17 22:11:37 +0000 [trace]: plugin/input_session.rb:150:start: accepting ssl session
2015-12-17 22:11:38 +0000 [trace]: plugin/in_secure_forward.rb:194:block in run: accept tcp connection (ssl session not established yet)
2015-12-17 22:11:38 +0000 [debug]: plugin/input_session.rb:122:on_read: on_read
2015-12-17 22:11:39 +0000 [trace]: plugin/in_secure_forward.rb:199:block in run: session instances: all=532 closed=0
2015-12-17 22:11:40 +0000 [debug]: plugin/input_session.rb:63:generate_helo: generating helo
2015-12-17 22:11:41 +0000 [debug]: plugin/input_session.rb:148:start: starting server
2015-12-17 22:11:43 +0000 [trace]: plugin/in_secure_forward.rb:194:block in run: accept tcp connection (ssl session not established yet)
2015-12-17 22:11:45 +0000 [debug]: plugin/input_session.rb:191:rescue in block in start: Connection closed from 'x.x.x.x.' (x.x.x.x)
2015-12-17 22:11:48 +0000 [trace]: plugin/input_session.rb:150:start: accepting ssl session
2015-12-17 22:11:49 +0000 [trace]: plugin/in_secure_forward.rb:199:block in run: session instances: all=533 closed=0
2015-12-17 22:11:50 +0000 [debug]: plugin/input_session.rb:148:start: starting server
2015-12-17 22:11:54 +0000 [debug]: plugin/input_session.rb:63:generate_helo: generating helo
2015-12-17 22:11:57 +0000 [trace]: plugin/in_secure_forward.rb:194:block in run: accept tcp connection (ssl session not established yet)
2015-12-17 22:11:57 +0000 [trace]: plugin/input_session.rb:150:start: accepting ssl session
2015-12-17 22:12:00 +0000 [debug]: plugin/input_session.rb:191:rescue in block in start: Connection closed from 'x.x.x.x' '(x.x.x.x)
2015-12-17 22:12:03 +0000 [trace]: plugin/in_secure_forward.rb:199:block in run: session instances: all=533 closed=0

Notice the total number of sessions is quite high, and it seems to max out at ~540.

[stanhu]

Closing in favor of #29, since I that is actually the root cause.