messagepack bug in http (in) plugin

[Mizunanari]

Describe the bug

The http (in) plugin will not accept a messagepack request that should succeed if it accepts a messagepack request that fails.

To Reproduce

Create

mkdir -p /containers/fluentd
cd /containers/fluentd
mkdir ./output
ls -lnd ./output

compose.yaml

/containers/fluentd/compose.yaml

services:
 fluentd:
   restart: always
   image: fluent/fluentd:edge
   command: fluentd -c /fluentd/etc/fluent.conf
   user: 1000:1000
   ports:
     - 8888:8888
   volumes:
     - ./fluent.conf:/fluentd/etc/fluent.conf:ro
     - ./output:/var/fluentd/output

fluent.conf

/containers/fluentd/fluent.conf

# http input
<source>
  @type http
  port 8888
  bind 0.0.0.0
</source>

# file output
<match myapp.access>
  @type file
  path /var/fluentd/output/myapp.access
  <buffer>
    timekey 86400
    timekey_wait 600
    timekey_use_utc true
  </buffer>
</match>

compose up

docker compose up -d

Check

1. Successful Requests

msgpack=`echo -e "\x81\xa3bar\xa3bar"`

curl \
-X POST \
-H "Content-Type: application/x-www-form-urlencoded" \
-d "msgpack=$msgpack" \
http://localhost:8888/myapp.access

2. Failure Requests

msgpack=`echo -e "\x81\xa3bar\xa3bar"`

curl \
-X POST \
-H "Content-Type: application/msgpack" \
-d "msgpack=$msgpack" \
http://localhost:8888/myapp.access

400 Bad Request
undefined method `delete' for 109:Integer

      if t = @default_keep_time_key ? record[@parser_time_key] : record.delete(@parser_time_key)
                                                                       ^^^^^^

3. Same request as "1."

msgpack=`echo -e "\x81\xa3bar\xa3bar"`

curl \
-X POST \
-H "Content-Type: application/x-www-form-urlencoded" \
-d "msgpack=$msgpack" \
http://localhost:8888/myapp.access

400 Bad Request
undefined method `delete' for 115:Integer

      if t = @default_keep_time_key ? record[@parser_time_key] : record.delete(@parser_time_key)
                                                                       ^^^^^^^

Expected behavior

3. Same request as "1." succeeds

Your Environment

- Fluentd version: 1.16.2
- TD Agent version: 
- Operating system: Ubuntu 22.04.3 LTS
- Kernel version: 5.15.0-87-generic

Your Configuration

# http input
<source>
  @type http
  port 8888
  bind 0.0.0.0
</source>

# file output
<match myapp.access>
  @type file
  path /var/fluentd/output/myapp.access
  <buffer>
    timekey 86400
    timekey_wait 600
    timekey_use_utc true
  </buffer>
</match>

Your Error Log

fluentd -c /fluentd/etc/fluent.conf
2023-11-20 01:27:06 +0000 [info]: init supervisor logger path=nil rotate_age=nil rotate_size=nil
2023-11-20 01:27:06 +0000 [info]: parsing config file is succeeded path="/fluentd/etc/fluent.conf"
2023-11-20 01:27:06 +0000 [info]: gem 'fluentd' version '1.16.2'
2023-11-20 01:27:06 +0000 [info]: using configuration file: <ROOT>
  <source>
    @type http
    port 8888
    bind "0.0.0.0"
  </source>
  <match myapp.access>
    @type file
    path "/var/fluentd/output/myapp.access"
    <buffer>
      timekey 86400
      timekey_wait 600
      timekey_use_utc true
      path "/var/fluentd/output/myapp.access"
    </buffer>
  </match>
</ROOT>
2023-11-20 01:27:06 +0000 [info]: starting fluentd-1.16.2 pid=7 ruby="3.1.4"
2023-11-20 01:27:06 +0000 [info]: spawn command to main:  cmdline=["/usr/bin/ruby", "-Eascii-8bit:ascii-8bit", "/usr/bin/fluentd", "-c", "/fluentd/etc/fluent.conf", "--plugin", "/fluentd/plugins", "--under-supervisor"]
2023-11-20 01:27:07 +0000 [info]: #0 init worker0 logger path=nil rotate_age=nil rotate_size=nil
2023-11-20 01:27:07 +0000 [info]: adding match pattern="myapp.access" type="file"
2023-11-20 01:27:07 +0000 [info]: adding source type="http"
2023-11-20 01:27:07 +0000 [info]: #0 starting fluentd worker pid=16 ppid=7 worker=0
2023-11-20 01:27:07 +0000 [info]: #0 fluentd worker is now running worker=0
2023-11-20 01:27:24 +0000 [error]: #0 failed to process request error_class=NoMethodError error="undefined method `delete' for 109:Integer\n\n      if t = @default_keep_time_key ? record[@parser_time_key] : record.delete(@parser_time_key)\n                                                                       ^^^^^^^"
2023-11-20 01:27:53 +0000 [error]: #0 failed to process request error_class=NoMethodError error="undefined method `delete' for 115:Integer\n\n      if t = @default_keep_time_key ? record[@parser_time_key] : record.delete(@parser_time_key)\n

Additional context

No response

[ashie]

Thanks for you report, I can reproduce it. In this case, the request body including msgpack= in the second request is passed to msgpack parser: https://github.com/fluent/fluentd/blob/74db9477f445ef83384eca6da8d6c2049945d8cd/lib/fluent/plugin/in_http.rb#L577

Because it's invalid msgpack sequence, broken data is remained in https://github.com/fluent/fluentd/blob/74db9477f445ef83384eca6da8d6c2049945d8cd/lib/fluent/plugin/parser_msgpack.rb#L35

It will break also following data.

Someone should reset @unpakcer in msgpack parser on each request.

[Athishpranav2003]

@ashie can i work on this bug?

[daipom]

@Athishpranav2003 Thanks! but looks like this is already fixed in the current master.

[daipom]

I confirmed the following PR fixed this issue.

• #4474

[daipom]

I confirmed the following PR fixed this issue.

• #4474

Oh... this issue still remains in v1.16.x because it does not include #4474.

[Athishpranav2003]

Oh i see, only backport is pending Its fine, i will look at other issues and pick up something which interests me.

[daipom]

only backport is pending

#4474 is a large fix and has some specification changes, so it is not preferable to backport it to v1.16. It is a difficult problem how to handle this issue on v1.16...

[daipom]

I'm not sure yet, but it might be a good idea to backport just this commit about parser_msgpack to v1.16.

• https://github.com/fluent/fluentd/pull/4474/commits/8433ca7ff78525bf89e2fea0f58a048ff1e2b6a9

Or, as @ashie says in https://github.com/fluent/fluentd/issues/4346#issuecomment-1846623604, it might still be needed to consider the possibility that some data remains in the unpacker of parser_msgpack when an unexpected error occurs.