softwares:fluent_bit:fluent_bit_go_redit

Fluent Bit Redis output plugin

このプラグインは Fluent Bit から Redis にデータを書き込むための Output Plugin。これをインストールして使ってみた。このプラグインの GitHub の Readme.md では、Docker を使った例が載っている。Docker を使わなくても実行できるかよくわからなかったが、いろいろ調べて試してみたら、Docker を使わなくても実行できた。以下そのメモ。ちなみに、このプラグインをインストールする前に、fluent-bit コマンドをインストールしてあり、その時のメモはこちら。

インストール

git clone して、go でコンパイルする。

以下、インストールコマンド。

$ cd $HOME/nestdaq/src
$ git clone https://github.com/majst01/fluent-bit-go-redis-output
$ cd fluent-bit-go-redis-output
$ make
go test -cover -race -coverprofile=coverage.txt -covermode=atomic
[out-redis] build: version: redis connection to: hosts:[{hosta 6379} {hostb 6379}] db:0 usetls:false tlsskipverify:false key:testkey
configuration errors: db must be a integer: strconv.Atoi: parsing "a": invalid syntax
given time is not in a known format, defaulting to now.
pushed 3 logs
PASS
coverage: 75.0% of statements
ok  	github.com/majst01/fluent-bit-go-redis-output	0.029s
go build -ldflags "-X 'main.revision=556919d' -X 'main.builddate=2024-01-19 14:13:40+09:00'" -buildmode=c-shared -o out_redis.so .

途中、 configuration errors と言われるが、問題なさそう。これで、\$HOME/nestdaq/src/fluent-bit-go-redis-output ディレクトリ内に out_redis.h, out_redis.so, coverage.txt というファイルができる。fluent-bit のコマンドでつかうのは、おそらく out_redis.so だけでよさそう。

使ってみる

fluent-bit-go-redis-output ディレクトリ内に fluent-bit.conf というファイルがあり、これが configuration file の example のようだ。とりあえず、このファイルのバックアップを取ってから、中身を編集し、以下のようにシンプルにしてみる。

[SERVICE]
    Flush        1
    Daemon       Off
    Log_Level    debug
    Log_File     /dev/stdout
    Parsers_File parsers.conf
    Parsers_File parsers_java.conf

[INPUT]
    Name cpu

[OUTPUT]
    Name  stdout
    Match *

[Output]
    Name redis
    Match *
    UseTLS false
    TLSSkipVerify true
    # if port is ommited, 6379 is used
    Hosts localhost
#    Password
    DB 4
    Key logstash

Redis の部分は、Hosts を redis –> localhost, DB 0 –> DB 4 と編集した。これで、実行してみる。Redis のデータベースは NestDAQ では 3 まで使っているので、番号 4 をテストのために使うことにする。Redis が自分自身のコンピュータ (localhost) で立ち上がっている状態で、以下のコマンドを実行。

$ pwd # 今いるディレクトリを一応確認
/home/nestdaq/nestdaq/src/fluent-bit-go-redis-output
$ fluent-bit -e ./out_redis.so -c fluent-bit.conf
Fluent Bit v3.0.0
* Copyright (C) 2015-2024 The Fluent Bit Authors
* Fluent Bit is a CNCF sub-project under the umbrella of Fluentd
* https://fluentbit.io

 < Omitted >

[2024/01/19 14:37:46] [ info] Configuration:
[2024/01/19 14:37:46] [ info]  flush time     | 1.000000 seconds
[2024/01/19 14:37:46] [ info]  grace          | 5 seconds
[2024/01/19 14:37:46] [ info]  daemon         | 0
[2024/01/19 14:37:46] [ info] ___________
[2024/01/19 14:37:46] [ info]  inputs:
[2024/01/19 14:37:46] [ info]      cpu
[2024/01/19 14:37:46] [ info] ___________
[2024/01/19 14:37:46] [ info]  filters:
[2024/01/19 14:37:46] [ info] ___________
[2024/01/19 14:37:46] [ info]  outputs:
[2024/01/19 14:37:46] [ info]      stdout.0
[2024/01/19 14:37:46] [ info]      redis.1
[2024/01/19 14:37:46] [ info] ___________
[2024/01/19 14:37:46] [ info]  collectors:
[2024/01/19 14:37:46] [ info] [fluent bit] version=3.0.0, commit=71746b3571, pid=1340738
[2024/01/19 14:37:46] [debug] [engine] coroutine stack size: 24576 bytes (24.0K)
[2024/01/19 14:37:46] [ info] [storage] ver=1.5.1, type=memory, sync=normal, checksum=off, max_chunks_up=128
[2024/01/19 14:37:46] [ info] [cmetrics] version=0.6.6
[2024/01/19 14:37:46] [ info] [ctraces ] version=0.4.0
[2024/01/19 14:37:46] [ info] [input:cpu:cpu.0] initializing
[2024/01/19 14:37:46] [ info] [input:cpu:cpu.0] storage_strategy='memory' (memory only)
[2024/01/19 14:37:46] [debug] [cpu:cpu.0] created event channels: read=22 write=23
[2024/01/19 14:37:46] [debug] [stdout:stdout.0] created event channels: read=20 write=24
[2024/01/19 14:37:46] [debug] [redis:redis.1] created event channels: read=30 write=31
[2024/01/19 14:37:46] [ info] [output:stdout:stdout.0] worker #0 started
[out-redis] build:2024-01-19 14:13:40+09:00 version:556919d redis connection to: hosts:[{localhost 6379}] db:4 usetls:false tlsskipverify:true key:logstash
[2024/01/19 14:37:46] [debug] [router] match rule cpu.0:stdout.0
[2024/01/19 14:37:46] [debug] [router] match rule cpu.0:redis.1
[2024/01/19 14:37:46] [ info] [sp] stream processor started
[2024/01/19 14:37:46] [debug] [input chunk] update output instances with new chunk size diff=853, records=1, input=cpu.0
[2024/01/19 14:37:47] [debug] [task] created task=0x7f91f0024c40 id=0 OK
[2024/01/19 14:37:47] [debug] [output:stdout:stdout.0] task_id=0 assigned to thread #0
[0] cpu.0: [[1705642666.410254275, {}], {"cpu_p"=>0.416667, "user_p"=>0.416667, "system_p"=>0.000000, "cpu0.p_cpu"=>0.000000, "cpu0.p_user"=>0.000000, "cpu0.p_system"=>0.000000, "cpu1.p_cpu"=>5.000000, "cpu1.p_user"=>5.000000, "cpu1.p_system"=>0.000000, "cpu2.p_cpu"=>0.000000, "cpu2.p_user"=>0.000000, "cpu2.p_system"=>0.000000, "cpu3.p_cpu"=>0.000000, "cpu3.p_user"=>0.000000, "cpu3.p_system"=>0.000000, "cpu4.p_cpu"=>0.000000, "cpu4.p_user"=>0.000000, "cpu4.p_system"=>0.000000, "cpu5.p_cpu"=>0.000000, "cpu5.p_user"=>0.000000, "cpu5.p_system"=>0.000000, "cpu6.p_cpu"=>0.000000, "cpu6.p_user"=>0.000000, "cpu6.p_system"=>0.000000, "cpu7.p_cpu"=>0.000000, "cpu7.p_user"=>0.000000, "cpu7.p_system"=>0.000000, "cpu8.p_cpu"=>0.000000, "cpu8.p_user"=>0.000000, "cpu8.p_system"=>0.000000, "cpu9.p_cpu"=>0.000000, "cpu9.p_user"=>0.000000, "cpu9.p_system"=>0.000000, "cpu10.p_cpu"=>1.000000, "cpu10.p_user"=>0.000000, "cpu10.p_system"=>1.000000, "cpu11.p_cpu"=>0.000000, "cpu11.p_user"=>0.000000, "cpu11.p_system"=>0.000000}]
[2024/01/19 14:37:47] [debug] [out flush] cb_destroy coro_id=0
[2024/01/19 14:37:47] [debug] [input chunk] update output instances with new chunk size diff=853, records=1, input=cpu.0
given time is not in a known format, defaulting to now.
pushed 1 logs
[2024/01/19 14:37:47] [debug] [out flush] cb_destroy coro_id=0
[2024/01/19 14:37:47] [debug] [task] destroy task=0x7f91f0024c40 (task_id=0)
[2024/01/19 14:37:48] [debug] [task] created task=0x7f91f0024db0 id=0 OK
[2024/01/19 14:37:48] [debug] [output:stdout:stdout.0] task_id=0 assigned to thread #0
[0] cpu.0: [[1705642667.410595688, {}], {"cpu_p"=>3.250000, "user_p"=>2.916667, "system_p"=>0.333333, "cpu0.p_cpu"=>0.000000, "cpu0.p_user"=>0.000000, "cpu0.p_system"=>0.000000, "cpu1.p_cpu"=>29.000000, "cpu1.p_user"=>29.000000, "cpu1.p_system"=>0.000000, "cpu2.p_cpu"=>0.000000, "cpu2.p_user"=>0.000000, "cpu2.p_system"=>0.000000, "cpu3.p_cpu"=>0.000000, "cpu3.p_user"=>0.000000, "cpu3.p_system"=>0.000000, "cpu4.p_cpu"=>2.000000, "cpu4.p_user"=>1.000000, "cpu4.p_system"=>1.000000, "cpu5.p_cpu"=>0.000000, "cpu5.p_user"=>0.000000, "cpu5.p_system"=>0.000000, "cpu6.p_cpu"=>0.000000, "cpu6.p_user"=>0.000000, "cpu6.p_system"=>0.000000, "cpu7.p_cpu"=>0.000000, "cpu7.p_user"=>0.000000, "cpu7.p_system"=>0.000000, "cpu8.p_cpu"=>0.000000, "cpu8.p_user"=>0.000000, "cpu8.p_system"=>0.000000, "cpu9.p_cpu"=>1.000000, "cpu9.p_user"=>1.000000, "cpu9.p_system"=>0.000000, "cpu10.p_cpu"=>3.000000, "cpu10.p_user"=>2.000000, "cpu10.p_system"=>1.000000, "cpu11.p_cpu"=>0.000000, "cpu11.p_user"=>0.000000, "cpu11.p_system"=>0.000000}]
[2024/01/19 14:37:48] [debug] [out flush] cb_destroy coro_id=1
[2024/01/19 14:37:48] [debug] [input chunk] update output instances with new chunk size diff=853, records=1, input=cpu.0
given time is not in a known format, defaulting to now.
pushed 1 logs
...

こんな感じで、一秒間隔くらいで、メッセージが表示されていく。これを走らせた状態で、別の端末を開き、Redis の中身を見てみる。

$ redis-cli
127.0.0.1:6379> info keyspace
# Keyspace
db0:keys=54,expires=38,avg_ttl=2286
db1:keys=49,expires=0,avg_ttl=0
db2:keys=3,expires=0,avg_ttl=0
db3:keys=9,expires=0,avg_ttl=0
db4:keys=2,expires=0,avg_ttl=0
127.0.0.1:6379> select 4
OK
127.0.0.1:6379[4]> keys *
1) "logstash"
(integer) 112
127.0.0.1:6379[4]> llen logstash
(integer) 112
127.0.0.1:6379[4]> llen logstash
(integer) 113
127.0.0.1:6379[4]> type logstash
list

データベース 4 を選択し、Key 一覧を表示してみると、logstash という Key がいる。type は list。list の長さを llen コマンドで確認すると、1秒間隔くらいでどんどん数が増えていく。さらに、logstash の中身を全部表示してみる。

127.0.0.1:6379[4]> lrange logstash 0 -1

 < Omitted >

137) "{\"@tag\":\"cpu.0\",\"@timestamp\":\"2024-01-19T05:43:51.410648338Z\",\"cpu0.p_cpu\":0,\"cpu0.p_system\":0,\"cpu0.p_user\":0,\"cpu1.p_cpu\":0,\"cpu1.p_system\":0,\"cpu1.p_user\":0,\"cpu10.p_cpu\":3,\"cpu10.p_system\":1,\"cpu10.p_user\":2,\"cpu11.p_cpu\":36,\"cpu11.p_system\":0,\"cpu11.p_user\":36,\"cpu2.p_cpu\":1,\"cpu2.p_system\":0,\"cpu2.p_user\":1,\"cpu3.p_cpu\":0,\"cpu3.p_system\":0,\"cpu3.p_user\":0,\"cpu4.p_cpu\":0,\"cpu4.p_system\":0,\"cpu4.p_user\":0,\"cpu5.p_cpu\":0,\"cpu5.p_system\":0,\"cpu5.p_user\":0,\"cpu6.p_cpu\":2,\"cpu6.p_system\":2,\"cpu6.p_user\":0,\"cpu7.p_cpu\":2,\"cpu7.p_system\":0,\"cpu7.p_user\":2,\"cpu8.p_cpu\":2,\"cpu8.p_system\":1,\"cpu8.p_user\":1,\"cpu9.p_cpu\":1,\"cpu9.p_system\":0,\"cpu9.p_user\":1,\"cpu_p\":4.166666666666667,\"system_p\":0.4166666666666667,\"user_p\":3.75}"
138) "{\"@tag\":\"cpu.0\",\"@timestamp\":\"2024-01-19T05:43:52.41043964Z\",\"cpu0.p_cpu\":2,\"cpu0.p_system\":1,\"cpu0.p_user\":1,\"cpu1.p_cpu\":2,\"cpu1.p_system\":0,\"cpu1.p_user\":2,\"cpu10.p_cpu\":1,\"cpu10.p_system\":0,\"cpu10.p_user\":1,\"cpu11.p_cpu\":32,\"cpu11.p_system\":0,\"cpu11.p_user\":32,\"cpu2.p_cpu\":1,\"cpu2.p_system\":0,\"cpu2.p_user\":1,\"cpu3.p_cpu\":0,\"cpu3.p_system\":0,\"cpu3.p_user\":0,\"cpu4.p_cpu\":1,\"cpu4.p_system\":1,\"cpu4.p_user\":0,\"cpu5.p_cpu\":0,\"cpu5.p_system\":0,\"cpu5.p_user\":0,\"cpu6.p_cpu\":0,\"cpu6.p_system\":0,\"cpu6.p_user\":0,\"cpu7.p_cpu\":1,\"cpu7.p_system\":0,\"cpu7.p_user\":1,\"cpu8.p_cpu\":1,\"cpu8.p_system\":0,\"cpu8.p_user\":1,\"cpu9.p_cpu\":2,\"cpu9.p_system\":0,\"cpu9.p_user\":2,\"cpu_p\":3.5,\"system_p\":0.25,\"user_p\":3.25}"

こんな感じで表示される。正しく書き込まれている模様。

使ってみる: Redis の key を fluent-bit コマンド実行時に変える

FairMQ デバイスを複数走らせ、それぞれの出力を Redis の異なる Key の値として保存しようとすると、fluent-bit をたちあげたときに、Key の値を与えたくなる。この場合、fluent-bit の configuration file の variables を使うとできる。
- https://docs.fluentbit.io/manual/administration/configuring-fluent-bit/classic-mode/variables

Configuration file を以下のように変更。

[SERVICE]
    Flush        1
    Daemon       Off
    Log_Level    debug
    Log_File     /dev/stdout
    Parsers_File parsers.conf
    Parsers_File parsers_java.conf

[INPUT]
    Name cpu

[OUTPUT]
    Name  stdout
    Match *

[Output]
    Name redis
    Match *
    UseTLS false
    TLSSkipVerify true
    # if port is ommited, 6379 is used
    Hosts localhost
#    Password
    DB 4
    Key ${REDIS_KEY}

Key の部分を ${REDIS_KEY} として、環境変数から与えるようにしている。これで、fluent-bit を以下のように走らせる。

$ pwd # 今いるディレクトリを一応確認
/home/nestdaq/nestdaq/src/fluent-bit-go-redis-output
$ REDIS_KEY=key1 fluent-bit -e ./out_redis.so -c fluent-bit.conf

この状態で、Redis の中身をみると、key1 に値が保存されていく。

$ redis-cli
127.0.0.1:6379> select 4
OK
127.0.0.1:6379[4]> keys *
1) "key1"
2) "logstash"
127.0.0.1:6379[4]> lrange key1 0 -1

 < Omitted >

47) "{\"@tag\":\"cpu.0\",\"@timestamp\":\"2024-01-19T09:16:40.41090011Z\",\"cpu0.p_cpu\":3,\"cpu0.p_system\":0,\"cpu0.p_user\":3,\"cpu1.p_cpu\":0,\"cpu1.p_system\":0,\"cpu1.p_user\":0,\"cpu10.p_cpu\":2,\"cpu10.p_system\":1,\"cpu10.p_user\":1,\"cpu11.p_cpu\":29,\"cpu11.p_system\":0,\"cpu11.p_user\":29,\"cpu2.p_cpu\":0,\"cpu2.p_system\":0,\"cpu2.p_user\":0,\"cpu3.p_cpu\":1,\"cpu3.p_system\":1,\"cpu3.p_user\":0,\"cpu4.p_cpu\":0,\"cpu4.p_system\":0,\"cpu4.p_user\":0,\"cpu5.p_cpu\":0,\"cpu5.p_system\":0,\"cpu5.p_user\":0,\"cpu6.p_cpu\":1,\"cpu6.p_system\":1,\"cpu6.p_user\":0,\"cpu7.p_cpu\":0,\"cpu7.p_system\":0,\"cpu7.p_user\":0,\"cpu8.p_cpu\":0,\"cpu8.p_system\":0,\"cpu8.p_user\":0,\"cpu9.p_cpu\":1,\"cpu9.p_system\":0,\"cpu9.p_user\":1,\"cpu_p\":3,\"system_p\":0.16666666666666666,\"user_p\":2.8333333333333335}"

使ってみる: NestDAQ の出力を Redis に保存

とりあえず FairMQ デバイスの標準出力を全部パイプして Redis に書き込むようにしてみる。
NestDAQ と nestdaq-user-impl はこちらの手順にしたがってインストールしたものを使う。

script を実行している \$HOME/run/ ディレクトリに fluent-bit-go-redit-output の fluent-bit.conf, parsers.conf, out_redis.so をコピーしてくる。

$ cd $HOME/run
$ cp $HOME/nestdaq/src/fluent-bit-go-redis-output/fluent-bit.conf ./
$ cp $HOME/nestdaq/src/fluent-bit-go-redis-output/parsers.conf ./
$ cp $HOME/nestdaq/src/fluent-bit-go-redis-output/out_redis.so ./

そしたら、fluent-bit.conf を以下のように編集。

[SERVICE]
    Flush        1
    Daemon       Off
    Log_Level    debug
    Log_File     /dev/stdout
    Parsers_File parsers.conf

[INPUT]
    Name stdin
    Parser plain
    
[OUTPUT]
    Name  stdout
    Match *

[Output]
    Name redis
    Match *
    UseTLS false
    TLSSkipVerify true
    # if port is ommited, 6379 is used
    Hosts localhost
#    Password
    DB 4
    Key ${REDIS_KEY}

この中で、INPUT の Paser として plain を指定しており、すべての標準出力を各行ごとにそのまま OUTPUT に流している。

そのあと、ここの通りに Redis と NestDAQ の daq-webctl を立ち上げる。./topology_stbplayer_scr.sh も ./mq_param_stbplayer_scr.sh 走らせる。すでに Raw データ保存用のディレクトリ (scr, scrdata, data) はあるはず。
\$HOME/nestdaq/run ディレクトリで tmux を立ち上げ、４分割 (Ctrl-b % と Ctrl-b “ を使う。パネル移動は Ctrl-b o。)し、以下のように出力をパイプして FairMQ デバイスを立ち上げる。ちなみに、start_device.sh の中では、METRICS_PLUGINを外し、DAQSERVICE_PLUGIN, CONFIG_PLUGIN, TELEMETRY_PLUGIN をロードしている。TELEMETRY_PLUGIN と METRICS_PLUGIN を２つロードするとデッドロックするところがあったため。現在 (2024/01/19 8:00PM) は高橋さんが問題を修正済み。
```
<パネル 1>
$ ./start_device.sh STFBFilePlayer --wait 1000 --in-file run000408_00_stf.dat | REDIS_KEY=STFBFilePlayer fluent-bit -e ./out_redis.so -c ./fluent-bit.conf
<パネル 2>
$ ./start_device.sh Scaler | REDIS_KEY=Scaler fluent-bit -e ./out_redis.so -c ./fluent-bit.conf
<パネル 3>
$ ./start_device.sh FileSink --service-name ScrSink | REDIS_KEY=ScrSink fluent-bit -e ./out_redis.so -c ./fluent-bit.conf
<パネル 4>
$ ./start_device.sh FileSink | REDIS_KEY=FileSink fluent-bit -e ./out_redis.so -c ./fluent-bit.conf
```
各出力はデータベース番号 4 の STFBFilePlayer, Scaler, ScrSink, FileSink というキーに保存される。
tmux の出力は以下の感じ。

また、Redis の中身は以下の感じ。

$ redis-cli
127.0.0.1:6379> select 4
OK
127.0.0.1:6379[4]> keys *
1) "Scaler"
2) "STFBFilePlayer"
3) "ScrSink"
4) "FileSink"
127.0.0.1:6379[4]> lrange Scaler 0 -1 

 < Omitted >

50333) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-19T11:00:19.414887549Z\",\"message\":\"6.0e+01:0.0e+00|\"}"
50334) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-19T11:00:19.414929979Z\",\"message\":\"6.1e+01:0.0e+00|\"}"
50335) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-19T11:00:19.414974813Z\",\"message\":\"6.2e+01:0.0e+00|\"}"
50336) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-19T11:00:19.415017688Z\",\"message\":\"6.3e+01:0.0e+00|\"}"
50337) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-19T11:00:19.41506022Z\",\"message\":\"{\\\"id\\\":\\\"Scaler-0\\\",\\\"service-name\\\":\\\"Scaler\\\",\\\"process_name\\\":\\\"Scaler\\\",\\\"timestamp\\\":\\\"20:00:19.398088\\\",\\\"file\\\":\\\"Device.cxx\\\",\\\"line\\\":\\\"757\\\",\\\"func\\\":\\\"LogSocketRates\\\",\\\"severity\\\":\\\"INFO\\\",\\\"time_t\\\":\\\"1705662019\\\",\\\"log\\\":\\\" in[0]: in: 1 (0.000304 MB) out: 0 (0 MB)\\\"}\"}"
50338) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-19T11:00:19.41510353Z\"}"
50339) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-19T11:00:19.415143851Z\",\"message\":\"[\\u001b[01;36m20:00:19\\u001b[0m][\\u001b[01;32mINFO\\u001b[0m]  in[0]: in: 1 (0.000304 MB) out: 0 (0 MB)\"}"
50340) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-19T11:00:19.415189363Z\",\"message\":\"{\\\"id\\\":\\\"Scaler-0\\\",\\\"service-name\\\":\\\"Scaler\\\",\\\"process_name\\\":\\\"Scaler\\\",\\\"timestamp\\\":\\\"20:00:19.398265\\\",\\\"file\\\":\\\"Device.cxx\\\",\\\"line\\\":\\\"757\\\",\\\"func\\\":\\\"LogSocketRates\\\",\\\"severity\\\":\\\"INFO\\\",\\\"time_t\\\":\\\"1705662019\\\",\\\"log\\\":\\\"out[0]: in: 0 (0 MB) out: 1 (0.00056 MB)\\\"}\"}"
50341) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-19T11:00:19.415234633Z\"}"
50342) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-19T11:00:19.415278047Z\",\"message\":\"[\\u001b[01;36m20:00:19\\u001b[0m][\\u001b[01;32mINFO\\u001b[0m] out[0]: in: 0 (0 MB) out: 1 (0.00056 MB)\"}"
50343) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-19T11:00:20.410363252Z\",\"message\":\"{\\\"id\\\":\\\"Scaler-0\\\",\\\"service-name\\\":\\\"Scaler\\\",\\\"process_name\\\":\\\"Scaler\\\",\\\"timestamp\\\":\\\"20:00:20.398522\\\",\\\"file\\\":\\\"Device.cxx\\\",\\\"line\\\":\\\"757\\\",\\\"func\\\":\\\"LogSocketRates\\\",\\\"severity\\\":\\\"INFO\\\",\\\"time_t\\\":\\\"1705662020\\\",\\\"log\\\":\\\" in[0]: in: 1 (0.00044 MB) out: 0 (0 MB)\\\"}\"}"
50344) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-19T11:00:20.41044532Z\"}"
50345) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-19T11:00:20.410496187Z\",\"message\":\"[\\u001b[01;36m20:00:20\\u001b[0m][\\u001b[01;32mINFO\\u001b[0m]  in[0]: in: 1 (0.00044 MB) out: 0 (0 MB)\"}"
50346) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-19T11:00:20.410542475Z\",\"message\":\"{\\\"id\\\":\\\"Scaler-0\\\",\\\"service-name\\\":\\\"Scaler\\\",\\\"process_name\\\":\\\"Scaler\\\",\\\"timestamp\\\":\\\"20:00:20.398728\\\",\\\"file\\\":\\\"Device.cxx\\\",\\\"line\\\":\\\"757\\\",\\\"func\\\":\\\"LogSocketRates\\\",\\\"severity\\\":\\\"INFO\\\",\\\"time_t\\\":\\\"1705662020\\\",\\\"log\\\":\\\"out[0]: in: 0 (0 MB) out: 1 (0.00056 MB)\\\"}\"}"
50347) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-19T11:00:20.41058677Z\"}"
50348) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-19T11:00:20.410626053Z\",\"message\":\"[\\u001b[01;36m20:00:20\\u001b[0m][\\u001b[01;32mINFO\\u001b[0m] out[0]: in: 0 (0 MB) out: 1 (0.00056 MB)\"}"
(0.80s)

大量のメッセージが保持されている。メモリとか大丈夫なんだろうか？また、端末の出力のカラー部分のエスケープシーケンスも保持されてて見にくい。さらに、ダブルクオーテーションとかバックスラッシュもエスケープされているようでさらに読みづらい。あと、よくわかっていないが、given time is not in a known format, defaulting to now. というメッセージが大量に出ているのをなんとかしたい。fluent-bit configuration file の書き方も含めて今後調査する。

使ってみる: NestDAQ の出力を Redis に保存 (その２)

標準出力をそのまま Redis に書くと、色付き文字などのエスケープシーケンスが沢山あり、見るのが大変である。Telemetry plugin ありの 2024/1/29 時点の最新の NestDAQ を使うと、Telemetry plugin の出力が json フォーマットで出力されるが、以下のように Redis の保存される。

$ redis-cli
127.0.0.1:6379> select 4
OK
127.0.0.1:6379[4]> lrange Scaler 0 -1 

  < Omitted >

133394) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-29T06:25:41.867264379Z\",\"message\":\"{\\\"id\\\":\\\"Scaler-0\\\",\\\"service-name\\\":\\\"Scaler\\\",\\\"process_name\\\":\\\"Scaler\\\",\\\"timestamp\\\":\\\"15:25:41.483464\\\",\\\"file\\\":\\\"Device.cxx\\\",\\\"line\\\":\\\"757\\\",\\\"func\\\":\\\"LogSocketRates\\\",\\\"severity\\\":\\\"INFO\\\",\\\"time_t\\\":\\\"1706509541\\\",\\\"log\\\":\\\" in[0]: in: 0.999001 (0.000815185 MB) out: 0 (0 MB)\\\"}\"}"
133395) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-29T06:25:41.867273023Z\"}"
133396) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-29T06:25:41.86728056Z\",\"message\":\"[\\u001b[01;36m15:25:41\\u001b[0m][\\u001b[01;32mINFO\\u001b[0m]  in[0]: in: 0.999001 (0.000815185 MB) out: 0 (0 MB)\"}"
133397) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-29T06:25:41.867288791Z\",\"message\":\"{\\\"id\\\":\\\"Scaler-0\\\",\\\"service-name\\\":\\\"Scaler\\\",\\\"process_name\\\":\\\"Scaler\\\",\\\"timestamp\\\":\\\"15:25:41.485479\\\",\\\"file\\\":\\\"Device.cxx\\\",\\\"line\\\":\\\"757\\\",\\\"func\\\":\\\"LogSocketRates\\\",\\\"severity\\\":\\\"INFO\\\",\\\"time_t\\\":\\\"1706509541\\\",\\\"log\\\":\\\"out[0]: in: 0 (0 MB) out: 0.999001 (0.000559441 MB)\\\"}\"}"
133398) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-29T06:25:41.867296049Z\"}"
133399) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-29T06:25:41.867303618Z\",\"message\":\"[\\u001b[01;36m15:25:41\\u001b[0m][\\u001b[01;32mINFO\\u001b[0m] out[0]: in: 0 (0 MB) out: 0.999001 (0.000559441 MB)\"}"

この件について高橋さんから2024/1/19 9:09PM (JST) に Mattermost 上でコメントをいただいた。

    * https://www.rcnp.osaka-u.ac.jp/mattermost/spadi-alliance/pl/h11f8u91b3fm5rssc1un1guf5y
    * <code>FairMQのコマンドライン引数で

    --color false でFairMQ built-inのコンソール出力のモノクロ化
    --severity <level> でFairMQ built-inのコンソール出力のログレベル切り替え。--severity nolog とすると std::cout, std::cerrに直接出しているか、custom log sink (TelemetryPluginなど)を使っている場合にコンソールに出ます

https://github.com/FairRootGroup/FairMQ/blob/master/docs/Logging.md#5-logging

とりあえず、このオプションを使って見やすくしてみる。$HOME/run/start_device.sh の中身の var+=” –severity debug4“ を var+=” –severity nolog“ にし、fluent bit にパイプせずに実行してみる。

<パネル 1>
$ ./start_device.sh STFBFilePlayer --wait 1000 --in-file run000408_00_stf.dat --color false
<パネル 2>
$ ./start_device.sh Scaler --color false
<パネル 3>
$ ./start_device.sh FileSink --service-name ScrSink --color false
<パネル 4>
$ ./start_device.sh FileSink --color false

結果は以下の画像の感じになる。おそらく、Metrics plugin の出力がなくなり、Telemetry plugin の出力が残っている？

さらに、fluent bit にパイプして、redis に書き込んでみる。

<パネル 1>
$ ./start_device.sh STFBFilePlayer --wait 1000 --in-file run000408_00_stf.dat --color false | REDIS_KEY=STFBFilePlayer fluent-bit -e ./out_redis.so -c ./fluent-bit.conf
<パネル 2>
$ ./start_device.sh Scaler --color false | REDIS_KEY=Scaler fluent-bit -e ./out_redis.so -c ./fluent-bit.conf
<パネル 3>
$ ./start_device.sh FileSink --service-name ScrSink --color false | REDIS_KEY=ScrSink fluent-bit -e ./out_redis.so -c ./fluent-bit.conf
<パネル 4>
$ ./start_device.sh FileSink --color false | REDIS_KEY=FileSink fluent-bit -e ./out_redis.so -c ./fluent-bit.conf

Redisの結果は以下の感じ。

160698) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-29T06:51:24.864656566Z\",\"message\":\"{\\\"id\\\":\\\"Scaler-0\\\",\\\"service-name\\\":\\\"Scaler\\\",\\\"process_name\\\":\\\"Scaler\\\",\\\"timestamp\\\":\\\"15:51:24.628999\\\",\\\"file\\\":\\\"Scaler.cxx\\\",\\\"line\\\":\\\"158\\\",\\\"func\\\":\\\"HandleData\\\",\\\"severity\\\":\\\"INFO\\\",\\\"time_t\\\":\\\"1706511084\\\",\\\"log\\\":\\\"tsHeartbeatCounter: 100\\\"}\"}"
160699) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-29T06:51:24.864680934Z\"}"
160700) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-29T06:51:24.864716753Z\",\"message\":\"{\\\"id\\\":\\\"Scaler-0\\\",\\\"service-name\\\":\\\"Scaler\\\",\\\"process_name\\\":\\\"Scaler\\\",\\\"timestamp\\\":\\\"15:51:24.629088\\\",\\\"file\\\":\\\"Scaler.cxx\\\",\\\"line\\\":\\\"159\\\",\\\"func\\\":\\\"HandleData\\\",\\\"severity\\\":\\\"INFO\\\",\\\"time_t\\\":\\\"1706511084\\\",\\\"log\\\":\\\"tsHeartbeatFlag   : 0\\\"}\"}"
160701) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-29T06:51:24.864743743Z\"}"

さらに、$HOME/run/fluent-bit.conf で

[SERVICE]
    Flush        1
    Daemon       Off
    Log_Level    debug
    Log_File     /dev/stdout
    Parsers_File parsers.conf

[INPUT]
    Name stdin
#    Parser plain                                                                                                                                                                                                                           

[OUTPUT]
    Name  stdout
    Match *

[Output]
    Name redis
    Match *
    UseTLS false
    TLSSkipVerify true
    # if port is ommited, 6379 is used                                                                                                                                                                                                      
    Hosts localhost
#    Password                                                                                                                                                                                                                               
    DB 4
    Key ${REDIS_KEY}

というように、[INPUT] の Name stdin の Parser plain をコメントアウトし、デフォルトの json パーサーを有効にして、NestDAQ + fluent-bit を走らせると、json フォーマットで出力されたメッセージのみ Redis に書き込まれる。Redis の中身は以下のかんじになる。

571) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-29T07:00:46.864559421Z\",\"file\":\"Scaler.cxx\",\"func\":\"HandleData\",\"id\":\"Scaler-0\",\"line\":\"158\",\"log\":\"tsHeartbeatCounter: 995\",\"process_name\":\"Scaler\",\"service-name\":\"Scaler\",\"severity\":\"INFO\",\"time_t\":\"1706511646\",\"timestamp\":\"16:00:46.615054\"}"
572) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-29T07:00:47.86408278Z\",\"file\":\"Device.cxx\",\"func\":\"LogSocketRates\",\"id\":\"Scaler-0\",\"line\":\"757\",\"log\":\" in[0]: in: 0.997009 (0.000693918 MB) out: 0 (0 MB)\",\"process_name\":\"Scaler\",\"service-name\":\"Scaler\",\"severity\":\"INFO\",\"time_t\":\"1706511647\",\"timestamp\":\"16:00:47.568216\"}"
573) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-29T07:00:47.864251756Z\",\"file\":\"Device.cxx\",\"func\":\"LogSocketRates\",\"id\":\"Scaler-0\",\"line\":\"757\",\"log\":\"out[0]: in: 0 (0 MB) out: 0.997009 (0.000558325 MB)\",\"process_name\":\"Scaler\",\"service-name\":\"Scaler\",\"severity\":\"INFO\",\"time_t\":\"1706511647\",\"timestamp\":\"16:00:47.568961\"}"
574) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-29T07:00:47.86440722Z\",\"_attr\":{\"title\":\"Scaler2D\",\"xtitle\":\"\",\"ytitle\":\"\"},\"_stat\":{\"Entries\":0},\"counts\":[[0,2455,0,1496,0,1524,0,1367,0,1328,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,521,0,469,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0],[0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0]],\"xbins\":{\"max\":64,\"min\":0},\"ybins\":{\"max\":2,\"min\":0}}"
575) "{\"@tag\":\"stdin.0\",\"@timestamp\":\"2024-01-29T07:00:47.864544819Z\",\"file\":\"Scaler.cxx\",\"func\":\"HandleData\",\"id\":\"Scaler-0\",\"line\":\"158\",\"log\":\"tsHeartbeatCounter: 1000\",\"process_name\":\"Scaler\",\"service-name\":\"Scaler\",\"severity\":\"INFO\",\"time_t\":\"1706511647\",\"timestamp\":\"16:00:47.619254\"}"

ちなみに、fluent-bit の出力として標準出力に given time is not in a known format, defaulting to now. というメッセージが出るが、これは、fluent-bit-go-redis-output のプラグインの出力 (もっと言うと、 https://github.com/majst01/fluent-bit-go-redis-output/blob/556919d57c274432e54dcaac5a8c308127fde3b4/out_redis.go の出力) メッセージである。タイムスタンプの型（？）が output.FLBTime にも uint64 にもマッチしないときに出されるようだ。つまり、fluent-bit の入力にタイムスタンプがない場合、このメッセージが出ている？

Troubleshooting

Go 言語がない

$ make
go test -cover -race -coverprofile=coverage.txt -covermode=atomic
make: go: No such file or directory
make: *** [Makefile:17: test] Error 127

Go 言語をインストールする。

$ sudo apt install golang-go

目次

Fluent Bit Redis output plugin

Links

インストール

使ってみる

使ってみる: Redis の key を fluent-bit コマンド実行時に変える

使ってみる: NestDAQ の出力を Redis に保存

使ってみる: NestDAQ の出力を Redis に保存 (その２)

Troubleshooting

目次

Fluent Bit Redis output plugin

Links

インストール

使ってみる

使ってみる: Redis の key を fluent-bit コマンド実行時に 変える

使ってみる: NestDAQ の出力を Redis に保存

使ってみる: NestDAQ の出力を Redis に保存 (その２)

Troubleshooting

使ってみる: Redis の key を fluent-bit コマンド実行時に変える