in_udp: add test of message_length_limit #4117

daipom · 2023-03-29T12:56:23Z

Which issue(s) this PR fixes:
None.

What this PR does / why we need it:
Add test of message_length_limit for in_udp because there was no test for this option.

Docs Changes:
Not needed.

Release Note:
Not needed.

daipom · 2023-03-29T13:47:38Z

The new test is failing on Windows.
Looks like the specification is different only on Windows.

I'm looking into it in detail.

Error: test: message_length_limit(UdpInputTest::hoge): Errno::EMSGSIZE: A message sent on a datagram socket was larger than the internal message buffer or some other network limit, or the buffer used to receive a datagram into was smaller than the datagram itself. - recvfrom(2)
C:/Users/reang/Documents/work/fluentd/fluentd/lib/fluent/plugin_helper/server.rb:558:in `recvfrom'
C:/Users/reang/Documents/work/fluentd/fluentd/lib/fluent/plugin_helper/server.rb:558:in `on_readable_with_sock'
C:/Ruby32-x64/lib/ruby/gems/3.2.0/gems/cool.io-1.7.1/lib/cool.io/io.rb:186:in `on_readable'
C:/Ruby32-x64/lib/ruby/gems/3.2.0/gems/cool.io-1.7.1/lib/cool.io/loop.rb:88:in `run_once'
C:/Ruby32-x64/lib/ruby/gems/3.2.0/gems/cool.io-1.7.1/lib/cool.io/loop.rb:88:in `run'
C:/Users/reang/Documents/work/fluentd/fluentd/lib/fluent/plugin_helper/event_loop.rb:93:in `block in start'
C:/Users/reang/Documents/work/fluentd/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'

daipom · 2023-03-29T13:59:13Z

At least on non-Windows, the data over message_length_limit are discarded.

https://pubs.opengroup.org/onlinepubs/009695399/functions/recvfrom.html

If a message is too long to fit in the supplied buffer, and MSG_PEEK is not set in the flags argument, the excess bytes shall be discarded.

And there is no error EMSGSIZE.

daipom · 2023-03-29T14:03:03Z

On Windows, it seems that WSAEMSGSIZE error happens.

https://learn.microsoft.com/en-us/windows/win32/api/winsock/nf-winsock-recvfrom

daipom · 2023-03-29T14:18:47Z

On Windows, sending data over message_length_limit causes an unexpected error and the data is completely lost.

$ bundle exec fluentd -c .\fluent\fluent.conf -v
2023-03-29 23:14:07 +0900 [info]: fluent/log.rb:360:info: init supervisor logger path=nil rotate_age=nil rotate_size=nil
2023-03-29 23:14:07 +0900 [info]: fluent/log.rb:360:info: parsing config file is succeeded path=".\\fluent\\fluent.conf"
2023-03-29 23:14:07 +0900 [info]: fluent/log.rb:360:info: gem 'fluentd' version '1.16.0'
2023-03-29 23:14:07 +0900 [debug]: fluent/log.rb:339:debug: No fluent logger for internal event
2023-03-29 23:14:07 +0900 [info]: fluent/log.rb:360:info: using configuration file: <ROOT>
  <source>
    @type udp
    bind "192.168.10.8"
    tag "test"
    message_length_limit 32
    <parse>
      @type "none"
    </parse>
  </source>
  <match test.**>
    @type stdout
  </match>
</ROOT>
2023-03-29 23:14:07 +0900 [info]: fluent/log.rb:360:info: starting fluentd-1.16.0 pid=4576 ruby="3.2.0"
2023-03-29 23:14:07 +0900 [info]: fluent/log.rb:360:info: spawn command to main:  cmdline=["C:/Ruby32-x64/bin/ruby.exe", "-rC:/Ruby32-x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.8/lib/bundler/setup", "-Eutf-8", "C:/Ruby32-x64/lib/ruby/gems/3.2.0/bin/fluentd", "-c", ".\\fluent\\fluent.conf", "-v", "--under-supervisor"]
2023-03-29 23:14:10 +0900 [info]: #0 fluent/log.rb:360:info: init worker0 logger path=nil rotate_age=nil rotate_size=nil
2023-03-29 23:14:10 +0900 [info]: fluent/log.rb:360:info: adding match pattern="test.**" type="stdout"
2023-03-29 23:14:10 +0900 [info]: fluent/log.rb:360:info: adding source type="udp"
2023-03-29 23:14:10 +0900 [debug]: #0 fluent/log.rb:339:debug: No fluent logger for internal event
2023-03-29 23:14:10 +0900 [info]: #0 fluent/log.rb:360:info: starting fluentd worker pid=15020 ppid=4576 worker=0
2023-03-29 23:14:10 +0900 [info]: #0 fluent/log.rb:360:info: listening udp socket bind="192.168.10.8" port=5160
2023-03-29 23:14:10 +0900 [info]: #0 fluent/log.rb:360:info: fluentd worker is now running worker=0
2023-03-29 23:15:19.367809800 +0900 test: {"message":"hoge"}
2023-03-29 23:15:39 +0900 [error]: #0 fluent/log.rb:402:error: unexpected error in processing UDP data error_class=Errno::EMSGSIZE error="A message sent on a datagram socket was larger than the internal message buffer or some other network limit, or the buffer used to receive a datagram into was smaller than the datagram itself. - recvfrom(2)"
  2023-03-29 23:15:39 +0900 [error]: #0 cool.io/loop.rb:88:run_once: C:/Users/reang/Documents/work/fluentd/fluentd/lib/fluent/plugin_helper/server.rb:558:in `recvfrom'
  2023-03-29 23:15:39 +0900 [error]: #0 cool.io/loop.rb:88:run_once: C:/Users/reang/Documents/work/fluentd/fluentd/lib/fluent/plugin_helper/server.rb:558:in `on_readable_with_sock'
  2023-03-29 23:15:39 +0900 [error]: #0 cool.io/loop.rb:88:run_once: C:/Ruby32-x64/lib/ruby/gems/3.2.0/gems/cool.io-1.7.1/lib/cool.io/io.rb:186:in `on_readable'
  2023-03-29 23:15:39 +0900 [error]: #0 cool.io/loop.rb:88:run_once: C:/Ruby32-x64/lib/ruby/gems/3.2.0/gems/cool.io-1.7.1/lib/cool.io/loop.rb:88:in `run_once'
  2023-03-29 23:15:39 +0900 [error]: #0 cool.io/loop.rb:88:run_once: C:/Ruby32-x64/lib/ruby/gems/3.2.0/gems/cool.io-1.7.1/lib/cool.io/loop.rb:88:in `run'
  2023-03-29 23:15:39 +0900 [error]: #0 cool.io/loop.rb:88:run_once: C:/Users/reang/Documents/work/fluentd/fluentd/lib/fluent/plugin_helper/event_loop.rb:93:in `block in start'
  2023-03-29 23:15:39 +0900 [error]: #0 cool.io/loop.rb:88:run_once: C:/Users/reang/Documents/work/fluentd/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'

daipom · 2023-03-29T14:29:16Z

On Ubuntu focal, the data over message_length_limit` are discarded without any error.

$ bundle exec fluentd -c ../work/fluent.conf -v
2023-03-29 23:26:20 +0900 [info]: fluent/log.rb:360:info: init supervisor logger path=nil rotate_age=nil rotate_size=nil
2023-03-29 23:26:20 +0900 [info]: fluent/log.rb:360:info: parsing config file is succeeded path="../work/fluent.conf"
2023-03-29 23:26:20 +0900 [info]: fluent/log.rb:360:info: gem 'fluentd' version '1.16.0'
2023-03-29 23:26:20 +0900 [debug]: fluent/log.rb:339:debug: No fluent logger for internal event
2023-03-29 23:26:20 +0900 [info]: fluent/log.rb:360:info: using configuration file: <ROOT>
  <system>
  </system>
  <source>
    @type udp
    tag "test"
    bind "192.168.10.5"
    message_length_limit 32
    <parse>
      @type "none"
    </parse>
  </source>
  <match test.**>
    @type stdout
  </match>
  <source>
    @type monitor_agent
  </source>
</ROOT>
2023-03-29 23:26:20 +0900 [info]: fluent/log.rb:360:info: starting fluentd-1.16.0 pid=982411 ruby="3.2.0"
2023-03-29 23:26:20 +0900 [info]: fluent/log.rb:360:info: spawn command to main:  cmdline=["/home/daipom/.rbenv/versions/3.2.0/bin/ruby", "-r/home/daipom/.rbenv/versions/3.2.0/lib/ruby/site_ruby/3.2.0/bundler/setup", "-Eascii-8bit:ascii-8bit", "/home/daipom/.rbenv/versions/3.2.0/lib/ruby/gems/3.2.0/bin/fluentd", "-c", "../work/fluent.conf", "-v", "--under-supervisor"]
2023-03-29 23:26:20 +0900 [info]: #0 fluent/log.rb:360:info: init worker0 logger path=nil rotate_age=nil rotate_size=nil
2023-03-29 23:26:20 +0900 [info]: fluent/log.rb:360:info: adding match pattern="test.**" type="stdout"
2023-03-29 23:26:20 +0900 [info]: fluent/log.rb:360:info: adding source type="udp"
2023-03-29 23:26:20 +0900 [info]: fluent/log.rb:360:info: adding source type="monitor_agent"
2023-03-29 23:26:20 +0900 [debug]: #0 fluent/log.rb:339:debug: No fluent logger for internal event
2023-03-29 23:26:20 +0900 [info]: #0 fluent/log.rb:360:info: starting fluentd worker pid=982431 ppid=982411 worker=0
2023-03-29 23:26:20 +0900 [debug]: #0 fluent/log.rb:339:debug: listening monitoring http server on http://0.0.0.0:24220/api/plugins for worker0
2023-03-29 23:26:20 +0900 [debug]: #0 fluent/log.rb:339:debug: Start async HTTP server listening http://0.0.0.0:24220
2023-03-29 23:26:20 +0900 [debug]: #0 fluent/log.rb:339:debug:   0.0s: Async::IO::Socket
      | Binding to #<Addrinfo: 0.0.0.0:24220 TCP>
2023-03-29 23:26:20 +0900 [info]: #0 fluent/log.rb:360:info: listening udp socket bind="192.168.10.5" port=5160
2023-03-29 23:26:20 +0900 [info]: #0 fluent/log.rb:360:info: fluentd worker is now running worker=0
2023-03-29 23:26:47.859800904 +0900 test: {"message":"hoge"}
2023-03-29 23:26:52.054402922 +0900 test: {"message":"jfiaojeofpiajodkfjwoeeifojwiejok"}

$ netcat -u 192.168.10.5 5160
hoge
jfiaojeofpiajodkfjwoeeifojwiejokdjfoewioweifj

daipom · 2023-03-29T14:38:15Z

If we rescue Errno::EMSGSIZE, then we can ignore incoming data over message_length_limit on Windows.
However, we can't discard only the part of data that exceeds message_length_limit in the same way as non-Windows.

fluentd/lib/fluent/plugin_helper/server.rb

Lines 556 to 568 in 206b46b

    
             def on_readable_with_sock 
        
               begin 
        
                 data, addr = @sock.recvfrom(@max_bytes) 
        
               rescue Errno::EAGAIN, Errno::EWOULDBLOCK, Errno::EINTR, Errno::ECONNRESET, IOError, Errno::EBADF 
        
                 return 
        
               end 
        
               @callback.call(data, UDPCallbackSocket.new(@sock, addr, close_socket: @close_socket)) 
        
             rescue => e 
        
               @log.error "unexpected error in processing UDP data", error: e 
        
               @log.error_backtrace 
        
               raise if @under_plugin_development 
        
             end 
        
           end

daipom · 2023-03-29T14:39:43Z

We need to figure out what is the right specification.

ashie · 2023-03-30T00:59:02Z

Could you try with an undocumented parameter receive_buffer_size?

fluentd/lib/fluent/plugin/in_udp.rb

Line 46 in 206b46b

config_param :receive_buffer_size, :size, default: nil

https://learn.microsoft.com/en-us/windows-hardware/drivers/network/so-rcvbuf

I'm not sure whether it works as expected or not but it can tune the buffer size of a socket's receive buffer.

daipom · 2023-03-30T03:16:27Z

Could you try with an undocumented parameter receive_buffer_size?

fluentd/lib/fluent/plugin/in_udp.rb

Line 46 in 206b46b

config_param :receive_buffer_size, :size, default: nil

https://learn.microsoft.com/en-us/windows-hardware/drivers/network/so-rcvbuf

I'm not sure whether it works as expected or not but it can tune the buffer size of a socket's receive buffer.

Oh, thanks, I was not aware of that parameter.

Now I have confirmed that it doesn't work as expected. (On Windows)

Only receive_buffer_size 32
- Incoming data is emitted as is without any limitation and any error.
receive_buffer_size 4096 and message_length_limit 32
- The same error occurs.

daipom · 2023-03-31T04:54:00Z

I think what we need to do is the following 2 things:

Fix the unexpected error and the data over message_length_limit should be simply ignored on Windows.
Add documentation that the specifications differ depending on whether it is Windows or not.

https://docs.fluentd.org/plugin-helper-overview/api-plugin-helper-server#server_create-title-port-proto-nil-bind-0.0.0.0-shared-true-socket-nil-backlog-nil-tls_options-nil-m

This behavior on Windows looks like not being considered so far.

This can happen in in_syslog too.
As for in_syslog, as long as we can avoid unexpected errors, it looks good.
in_syslog should cut off or ignore the data over message_length_limit.

rfc5424: https://www.rfc-editor.org/rfc/rfc5424#section-6.1
- The server can cut off or ignore the data.
  
  All transport receiver
  implementations SHOULD be able to accept messages of up to and
  including 2048 octets in length. Transport receivers MAY receive
  messages larger than 2048 octets in length. If a transport receiver
  receives a message with a length larger than it supports, the
  transport receiver SHOULD truncate the payload. Alternatively, it
  MAY discard the message.
rfc3164: https://www.rfc-editor.org/rfc/rfc3164#section-4.1
- The data must be 1024 bytes or less.
  
  The total length of
  the packet MUST be 1024 bytes or less.

For in_udp, we can apply the same specification.
If we work hard to cut data off instead of just ignoring it for Windows, it would not be very happy.
Cutting data off would usually only cause a failure of parsing and the data would be eventually ignored.

ashie · 2023-03-31T07:59:58Z

Refs:

https://learn.microsoft.com/en-us/windows/win32/winsock/windows-sockets-error-codes-2

Return code/value	Description
WSAEMSGSIZE10040	Message too long. A message sent on a datagram socket was larger than the internal message buffer or some other network limit, or the buffer used to receive a datagram was smaller than the datagram itself.

Ruby's implementation:

WinSock might return truncated data but discarded by Ruby.

ashie · 2023-03-31T08:07:28Z

Fix the unexpected error and the data over message_length_limit should be simply ignored on Windows.

Add documentation that the specifications differ depending on whether it is Windows or not.

It looks good, please go a head 👍

ashie · 2023-03-31T08:13:26Z

If we work hard to cut data off instead of just ignoring it for Windows, it would not be very happy.
Cutting data off would usually only cause a failure of parsing and the data would be eventually ignored.

User might want to know which kind of data is lost, there is a similar feature request: #3739
You don't need to care such thing in this PR though.

daipom · 2023-03-31T08:23:39Z

If we work hard to cut data off instead of just ignoring it for Windows, it would not be very happy.
Cutting data off would usually only cause a failure of parsing and the data would be eventually ignored.

User might want to know which kind of data is lost, there is a similar feature request: #3739 You don't need to care such thing in this PR though.

Oh, I see!
I had thought that it might be better to provide an INFO log about ignored data.

I will change the target of this PR to fixing max_bytes parameter of server helper.
I'll think about logging in the case of EMSGSIZE .

daipom · 2023-03-31T10:18:30Z

I had thought that it might be better to provide an INFO log about ignored data.

Oh, now I understand. It is impossible because of

WinSock might return truncated data but discarded by Ruby.

daipom · 2023-04-07T00:56:49Z

I made another PR to fix the helper.

Server helper: Suppress error of UDPServer over max_bytes on Windows #4131

When that PR is merged, this PR's tests will succeed on Windows too.

Signed-off-by: Daijiro Fukuda <[email protected]>

ashie · 2023-04-11T05:21:13Z

Thanks!

daipom · 2023-04-11T05:25:04Z

Thanks for your review!

daipom requested review from ashie and removed request for ashie March 29, 2023 12:57

daipom marked this pull request as draft March 29, 2023 13:45

daipom mentioned this pull request Apr 7, 2023

Server helper: Suppress error of UDPServer over max_bytes on Windows #4131

Merged

daipom force-pushed the add-test-in_udp-message_length_limit branch 2 times, most recently from c874fc1 to 4aa4342 Compare April 10, 2023 13:08

in_udp: add test of message_length_limit

ea38c8f

Signed-off-by: Daijiro Fukuda <[email protected]>

daipom force-pushed the add-test-in_udp-message_length_limit branch from 4aa4342 to ea38c8f Compare April 10, 2023 15:29

daipom marked this pull request as ready for review April 11, 2023 00:43

daipom requested a review from ashie April 11, 2023 00:43

ashie approved these changes Apr 11, 2023

View reviewed changes

ashie merged commit 863ebca into fluent:master Apr 11, 2023

daipom deleted the add-test-in_udp-message_length_limit branch April 11, 2023 05:24

ashie added this to the v1.16.1 milestone Apr 13, 2023

ashie mentioned this pull request Oct 21, 2024

test_in_udp: add timeout for message_length_limit test #4676

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

in_udp: add test of message_length_limit #4117

in_udp: add test of message_length_limit #4117

daipom commented Mar 29, 2023

daipom commented Mar 29, 2023

daipom commented Mar 29, 2023

daipom commented Mar 29, 2023

daipom commented Mar 29, 2023

daipom commented Mar 29, 2023

daipom commented Mar 29, 2023

daipom commented Mar 29, 2023

ashie commented Mar 30, 2023

daipom commented Mar 30, 2023 •

edited

Loading

daipom commented Mar 31, 2023

ashie commented Mar 31, 2023 •

edited

Loading

ashie commented Mar 31, 2023

ashie commented Mar 31, 2023

daipom commented Mar 31, 2023

daipom commented Mar 31, 2023

daipom commented Apr 7, 2023

ashie commented Apr 11, 2023

daipom commented Apr 11, 2023

in_udp: add test of message_length_limit #4117

in_udp: add test of message_length_limit #4117

Conversation

daipom commented Mar 29, 2023

daipom commented Mar 29, 2023

daipom commented Mar 29, 2023

daipom commented Mar 29, 2023

daipom commented Mar 29, 2023

daipom commented Mar 29, 2023

daipom commented Mar 29, 2023

daipom commented Mar 29, 2023

ashie commented Mar 30, 2023

daipom commented Mar 30, 2023 • edited Loading

daipom commented Mar 31, 2023

ashie commented Mar 31, 2023 • edited Loading

ashie commented Mar 31, 2023

ashie commented Mar 31, 2023

daipom commented Mar 31, 2023

daipom commented Mar 31, 2023

daipom commented Apr 7, 2023

ashie commented Apr 11, 2023

daipom commented Apr 11, 2023

daipom commented Mar 30, 2023 •

edited

Loading

ashie commented Mar 31, 2023 •

edited

Loading