[Feature Request] Merge multi-log items which have same field into only one item.

[zw963]

This feature maybe similiar as #337, but, anyway, it old, let us start a new discuss here.

Following is original ruby on rails logger which output to log/production.log

As you can see, those log have a speical fields(let us call it uuid), it useful for group all log items come from one request.

For our current solution, we are use a tail parser to parse this log.

# /etc/td-agent-bit/parsers.conf

[PARSER]
    Name   rails_production
    Format regex
    Regex ^[A-Z], \[(?<time>\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{6}) #(?<pid>\d+)\]\s+(?<severity>[A-Z]+) -- (?<progname>.*): (?<labels>.*)\[(?<uuid>[a-z0-9]{8}-[a-z0-9]{4}-[a-z0-9]{4}-[a-z0-9]{4}-[a-z0-9]{12})\] (?<msg>.*)$
    Time_Key time
    Time_Format %Y-%m-%dT%H:%M:%S.%L
    Time_Offset +0900

We are get logs like this:

Apr 23 10:39:36 lggram fluent-bit[848599]: [36] airhost11.airhost_ror.tail.app: [1587605975.868258000, {"pid"=>"776118", "severity"=>"INFO", "uuid"=>"5b260e6d-6747-4798-a29a-0834155e316a", "msg"=>"Started GET "/users" for 127.0.0.1 at 2020-04-23 10:39:35 +0800"}]
Apr 23 10:39:36 lggram fluent-bit[848599]: [37] airhost11.airhost_ror.tail.app: [1587605975.868941000, {"pid"=>"776118", "severity"=>"INFO", "uuid"=>"5b260e6d-6747-4798-a29a-0834155e316a", "msg"=>"Processing by UsersController#index as HTML"}]
Apr 23 10:39:36 lggram fluent-bit[848599]: [38] airhost11.airhost_ror.tail.app: [1587605975.869645000, {"pid"=>"776118", "severity"=>"INFO", "uuid"=>"5b260e6d-6747-4798-a29a-0834155e316a", "msg"=>"  Rendering users/index.html.erb within layouts/application"}]
Apr 23 10:39:36 lggram fluent-bit[848599]: [39] airhost11.airhost_ror.tail.app: [1587605975.870725000, {"pid"=>"776118", "severity"=>"DEBUG", "uuid"=>"5b260e6d-6747-4798-a29a-0834155e316a", "msg"=>"  User Load (0.3ms)  SELECT "users".* FROM "users""}]
Apr 23 10:39:36 lggram fluent-bit[848599]: [40] airhost11.airhost_ror.tail.app: [1587605975.871073000, {"pid"=>"776118", "severity"=>"INFO", "uuid"=>"5b260e6d-6747-4798-a29a-0834155e316a", "msg"=>"  Rendered users/index.html.erb within layouts/application (1.4ms)"}]
Apr 23 10:39:41 lggram fluent-bit[848599]: [0] airhost11.airhost_ror.tail.app: [1587605975.871770000, {"pid"=>"776118", "severity"=>"INFO", "uuid"=>"5b260e6d-6747-4798-a29a-0834155e316a", "msg"=>"Completed 200 OK in 3ms (Views: 1.9ms | ActiveRecord: 0.3ms)"}]
Apr 23 10:39:41 lggram fluent-bit[848599]: [1] airhost11.airhost_ror.tail.app: [1587605976.067912000, {"pid"=>"776118", "severity"=>"INFO", "uuid"=>"45358e62-2652-4bd6-a213-b5f0fd9ec528", "msg"=>"Started GET "/users" for 127.0.0.1 at 2020-04-23 10:39:36 +0800"}]
Apr 23 10:39:41 lggram fluent-bit[848599]: [2] airhost11.airhost_ror.tail.app: [1587605976.068599000, {"pid"=>"776118", "severity"=>"INFO", "uuid"=>"45358e62-2652-4bd6-a213-b5f0fd9ec528", "msg"=>"Processing by UsersController#index as HTML"}]
Apr 23 10:39:41 lggram fluent-bit[848599]: [3] airhost11.airhost_ror.tail.app: [1587605976.069345000, {"pid"=>"776118", "severity"=>"INFO", "uuid"=>"45358e62-2652-4bd6-a213-b5f0fd9ec528", "msg"=>"  Rendering users/index.html.erb within layouts/application"}]
Apr 23 10:39:41 lggram fluent-bit[848599]: [4] airhost11.airhost_ror.tail.app: [1587605976.070199000, {"pid"=>"776118", "severity"=>"DEBUG", "uuid"=>"45358e62-2652-4bd6-a213-b5f0fd9ec528", "msg"=>"  User Load (0.3ms)  SELECT "users".* FROM "users""}]
Apr 23 10:39:41 lggram fluent-bit[848599]: [5] airhost11.airhost_ror.tail.app: [1587605976.079809000, {"pid"=>"776118", "severity"=>"INFO", "uuid"=>"45358e62-2652-4bd6-a213-b5f0fd9ec528", "msg"=>"  Rendered users/index.html.erb within layouts/application (1.1ms)"}]
Apr 23 10:39:41 lggram fluent-bit[848599]: [6] airhost11.airhost_ror.tail.app: [1587605976.080522000, {"pid"=>"776118", "severity"=>"INFO", "uuid"=>"45358e62-2652-4bd6-a213-b5f0fd9ec528", "msg"=>"Completed 200 OK in 12ms (Views: 11.0ms | ActiveRecord: 0.3ms)"}]

It working, but we have to use filter like uuid: "5b260e6d-6747-4798-a29a-0834155e316a" to view the whole picture of one request, at some times, this include hundred lines.

Our needs

Can we merge all log items which have same uuid to only one item? e.g.

Apr 23 10:39:36 lggram fluent-bit[848599]: [36] airhost11.airhost_ror.tail.app: [1587605975.868258000, {"pid"=>"776118", "severity"=>"INFO", "uuid"=>"5b260e6d-6747-4798-a29a-0834155e316a", "msg"=>"Started GET "/users" for 127.0.0.1 at 2020-04-23 10:39:35 +0800
Processing by UsersController#index as HTML
Rendering users/index.html.erb within layouts/application
User Load (0.3ms)  SELECT "users".* FROM "users"
Rendered users/index.html.erb within layouts/application (1.4ms)
Completed 200 OK in 3ms (Views: 1.9ms | ActiveRecord: 0.3ms)
"}]

Apr 23 10:39:41 lggram fluent-bit[848599]: [1] airhost11.airhost_ror.tail.app: [1587605976.067912000, {"pid"=>"776118", "severity"=>"INFO", "uuid"=>"45358e62-2652-4bd6-a213-b5f0fd9ec528", "msg"=>"Started GET "/users" for 127.0.0.1 at 2020-04-23 10:39:36 +0800
Processing by UsersController#index as HTML
Rendering users/index.html.erb within layouts/application
msg"=>"  User Load (0.3ms)  SELECT "users".* FROM "users"
Rendered users/index.html.erb within layouts/application (1.1ms)
Completed 200 OK in 12ms (Views: 11.0ms | ActiveRecord: 0.3ms)
"}]

can you please point out the correct direction for doing this?

In fact, i am not sure should we use Fluent Bit + SQL, or should we use Lua script to achieve this?

[zw963]

Hello, i am trying solved this issue use lua script, following is my solution.

-- merge_log.lua

local payload = {}

function merge_log(tag, timestamp, record)
  if payload.tags == record.tags then
    payload.msg = payload.msg .. "\n" .. record.msg
    payload.severity = record.severity
    return -1, 0, 0
  else
    local returned_payload = payload
    payload = nil               -- release memory
    payload = record
    payload.start_time = timestamp

    if returned_payload.msg then
      local start_time = returned_payload.start_time
      returned_payload.start_time = nil
      return 1, start_time, returned_payload
    else
      return -1, 0, 0
    end
  end
end

Following is fluent-bit filter config:

[FILTER]
    Name lua
    Match airhost1.airhost_ror.merged.tail.app
    script merge_log.lua
    call merge_log

It is working, but with following limit:

1. We use tail plugin to pull log from file, not all same uuid's logs is output sequentially because multi-process/threads output log into one file.
   e.g. like following:

i think this issue maybe can be improve, but, anyway, it far better then older one line logger.

2. Don't know why, generated kibana log timestamp not sequentically too, the log items processed by lua is was sent before the log which earlier than it, don't know if lua code issue cause this?

cb2fa096-bcf8-4a4e-9eeb-7e20e2d19f5

---

BTW, why return value 2 not working for fluent bit 1.3.9 ?

[filter_lua] unexpected Lua script return code 2, original record will be kept.

[github-actions]

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 5 days.