[kenhys]

Which issue(s) this PR fixes:
Fixes #

What this PR does / why we need it:

This PR fixes two problems with the logs for message_length_limit in in_tcp and in_syslog.

1. The info log for a buffer clear repeats.

   Before: when message_length_limit is set and a client sends data without a delimiter, an info log is written each time the buffer goes
   over the limit. The data until the next delimiter fills the buffer again, so the log repeats, and how often depends on the read size. For ex
   ample, sending 64MiB without a newline to in_tcp with message_length_limit 4096 wrote about 4,200 info lines.

   After: the buffer clear is logged only once for one message.

2. The head of the received data breaks fluentd's own log events.

   Before: the logs have the head of the received bytes as is. in_tcp writes it at info level, and in_syslog writes it at debug level. When
   the head has binary bytes, fluentd's own log event can not be made into JSON, and failed to emit fluentd's log event (JSON::GeneratorErro r) happens with <label @FLUENT_LOG>.

   After: the info logs of in_tcp show only the limit and the size, like in_syslog. The head is logged at debug level, and it is escaped wit
   h String#dump like the existing debug log of in_syslog for a message length that is not a number.

The tests wait for the log instead of sleeping where it matters, so they do not depend on how the server splits the reads. All the new tests
fail without the change to lib/.

Docs Changes:

Release Note:

in_tcp, in_syslog: log a buffer clear for message_length_limit only once per message, and log the head of the received data only at debug
level as an escaped string

[Watson1978]

Thanks for this. Logging the head only at debug with String#dump looks good to me.

I found two cases where the new "log only once" check hides a clear that master logs. Please see the inline comments.

[Watson1978]

MUST: discard_till_next_delimiter is a local variable of start, so all connections share it. This check now uses it to skip the log, so a clear on one connection can hide a clear on another connection.

For example, with message_length_limit 12 and delimiter ";", and each step received in a separate read:

1. Connection A sends "a" * 13 and closes without a delimiter.
2. Connection B sends "b" * 13.
3. Connection B sends ";ok;".

On master, both clears are logged. With this PR, only A's clear is logged. B's 13 bytes are dropped with no log (ok is still emitted). The same happens while A is still open, and in the single_emit path with <extract> and tag_key (line 164). Also, a delimiter on another connection resets the flag, so one long message on A can be logged more than once.

in_syslog keeps the flag per connection. in_tcp can do the same. For TCP and TLS, server_create and server_create_connection use the same connection setup, and server_create just registers the block with conn.data. So, in both paths, the flag can move into the connection block like this, and the declaration in start can be removed:

server_create_connection(:in_tcp_server_batch_emit, @port, bind: @bind, resolve_name: !!@source_hostname_key, send_keepalive_packet: @send_keepalive_packet) do |conn|
  discard_till_next_delimiter = false
  conn.data do |data|
    # the current body of the block
  end
end

I tried this locally. The existing tests passed, and the cases above were fixed. It also fixes an existing bug: on master, a valid line on B can be dropped because A set the flag.

Could you make this change, and add a test with two connections?

[Watson1978]

SHOULD (non-blocking, a follow-up PR is fine): With a delimiter of two or more bytes, such as "\r\n", the buffer.clear below can cut the delimiter in half. Then the next message boundary is missed, and the flag stays true until an intact delimiter is received. With this PR, the clears of other long messages before that are not logged.

For example, with message_length_limit 64 and delimiter "\r\n", send three 65-byte messages, each followed by "\r\n", so that each read ends right after the "\r". On master, three clears are logged. With this PR, only the first one is logged. in_tcp has the same problem in both paths.

The missed boundary itself is an existing bug. On master, the valid message after it is dropped too. In this example, keeping up to delimiter_size - 1 trailing bytes, instead of clearing all of them, fixed both. The existing tests passed:

buffer.slice!(0, buffer.bytesize - (delimiter_size - 1))

In in_tcp, it is buf.slice!(0, buf.bytesize - (del_size - 1)) in both paths. If you fix it here, please add a test that splits "\r\n" between reads, and checks that each long message is logged once and the next valid message is emitted.