Tail plug-in fails to keep track of state of file when parser is used

[2x-bullet-time]

I have noticed tail plugin does not obey the state of the file when a parser is defined. Plugin will always start at the head of the file unless parser is blanked out. This issue can also be replicated using command line:

fluent-bit --parser=parsers.conf -i tail -p path=/var/log/syslog -p db=/var/log/xyz.sqlite -p parser=syslog-custom -o stdout

This command will work as expected if parser parameter is taken out.
This is my sosreport:

[Fluent Bit]
    Edition             Community Edition
    Version             0.12.12
    Built Flags          JSMN_PARENT_LINKS JSMN_STRICT FLB_HAVE_TLS FLB_HAVE_SQLDB FLB_HAVE_BUFFERING FLB_HAVE_FLUSH_LIBCO FLB_HAVE_FORK FLB_HAVE_PROXY_GO FLB_HAVE_REGEX FLB_HAVE_C_TLS FLB_HAVE_SETJMP FLB_HAVE_ACCEPT4 FLB_HAVE_INOTIFY

[Operating System]
    Name                Linux
    Release             4.1.15
    Version             #3 SMP PREEMPT Fri Jul 7 11:18:13 PDT 2017

[Hardware]
    Architecture        armv7l
    Processors          1

[Built Plugins]
    Inputs              cpu mem kmsg tail proc disk netif dummy head health serial stdin tcp mqtt lib forward random syslog
    Filters             grep stdout kubernetes parser record_modifier
    Outputs             counter es exit file forward http influxdb kafka-rest nats null plot stdout retry td lib flowcounter

[SERVER] Runtime configuration
    Flush               5
    Daemon              Off
    Log_Level           Debug

[INPUT] Instance
    Name                tail.0 (tail, id=0)
    Flags               DYN_TAG
    Threaded            No
    Tag                 tail.0
    Path                /var/log/syslog
    db                  /var/log/landing_files.sqlite
    Parser              syslog-custom


[OUTPUT] Instance
    Name                stdout.0 (stdout, mask_id=1)
    Match               *
    TLS Active          No
    Retry Limit         1

I am hoping I have done something wrong on my end. Thanks!

[edsiper]

@2x-bullet-time thanks for raising this issue.

I did some local tests and the problem that I found in in_tail plugin, is that if a parser fails against a log line (bad regex), that content is missed, the right behavior is to keep that information in "raw text" mode. I placed a fix for that behavior in GIT master and 0.12 branches.

[2x-bullet-time]

Thank you for your work. I will give it a try!

[2x-bullet-time]

@edsiper
I pulled down the latest version of master branch and recompiled it locally. When executing this command "fluent-bit -i tail -p path=/var/log/syslog -p db=/var/log/landing_files.db -o stdout", the tailing function works fine. However, when I run the following configuration file without a parser, in_tail will always read from beginning of file. This is my simple configuration file:

[SERVICE]
    Flush     5
    Parsers_File    parsers.conf
    Log_Level    debug
[INPUT]
    Name    tail
    Path    /var/log/syslog
    ##DB    /var/log/landing_files.db
    ##Parser    syslog-custom
##[FILTER]
    ##Name    grep
    ##Match    *
    ##Regex    process_name pppd
##[FILTER]
    ##Name    record_modifier
    ##Match    *
    ##Record    deviceURN 1234
    ##Record    deviceName Testing-Unit
[OUTPUT]
    Name stdout
    Match *

This is the sosreport associated with the above configuration file:

[Fluent Bit]
    Edition             Community Edition
    Version             0.13.0
    Built Flags          JSMN_PARENT_LINKS JSMN_STRICT FLB_HAVE_TLS FLB_HAVE_SQLDB FLB_HAVE_BUFFERING FLB_HAVE_FLUSH_LIBCO FLB_HAVE_FORK FLB_HAVE_PROXY_GO FLB_HAVE_REGEX FLB_HAVE_C_TLS FLB_HAVE_ACCEPT4 FLB_HAVE_INOTIFY

[Operating System]
    Name                Linux
    Release             4.1.15
    Version             #3 SMP PREEMPT Fri Jul 7 11:18:13 PDT 2017

[Hardware]
    Architecture        armv7l
    Processors          1

[Built Plugins]
    Inputs              cpu mem kmsg tail proc disk netif dummy head exec health serial stdin tcp mqtt lib forward random syslog
    Filters             grep stdout kubernetes parser record_modifier
    Outputs             counter es exit file forward http influxdb kafka-rest nats null plot stdout retry td lib flowcounter

[SERVER] Runtime configuration
    Flush               5
    Daemon              Off
    Log_Level           Debug

[INPUT] Instance
    Name                tail.0 (tail, id=0)
    Flags               DYN_TAG
    Threaded            No
    Tag                 tail.0
    Path                /var/log/syslog


[OUTPUT] Instance
    Name                stdout.0 (stdout, mask_id=1)
    Match               *
    TLS Active          No
    Retry Limit         1

This is the sosreport associated with the above command:

[Fluent Bit]
    Edition             Community Edition
    Version             0.13.0
    Built Flags          JSMN_PARENT_LINKS JSMN_STRICT FLB_HAVE_TLS FLB_HAVE_SQLDB FLB_HAVE_BUFFERING FLB_HAVE_FLUSH_LIBCO FLB_HAVE_FORK FLB_HAVE_PROXY_GO FLB_HAVE_REGEX FLB_HAVE_C_TLS FLB_HAVE_ACCEPT4 FLB_HAVE_INOTIFY

[Operating System]
    Name                Linux
    Release             4.1.15
    Version             #3 SMP PREEMPT Fri Jul 7 11:18:13 PDT 2017

[Hardware]
    Architecture        armv7l
    Processors          1

[Built Plugins]
    Inputs              cpu mem kmsg tail proc disk netif dummy head exec health serial stdin tcp mqtt lib forward random syslog
    Filters             grep stdout kubernetes parser record_modifier
    Outputs             counter es exit file forward http influxdb kafka-rest nats null plot stdout retry td lib flowcounter

[SERVER] Runtime configuration
    Flush               5
    Daemon              Off
    Log_Level           Info

[INPUT] Instance
    Name                tail.0 (tail, id=0)
    Flags               DYN_TAG
    Threaded            No
    Tag                 tail.0
    path                /var/log/syslog
    db                  /var/log/landing_files.db
    Routes              stdout.0


[OUTPUT] Instance
    Name                stdout.0 (stdout, mask_id=1)
    Match               *
    TLS Active          No
    Retry Limit         1

in_tail plugin does not keep track of the state of the file when parser is used, either in command or config-file mode.

This is the sosreport associated with a configuration file with parser enabled:

[Fluent Bit]
    Edition             Community Edition
    Version             0.13.0
    Built Flags          JSMN_PARENT_LINKS JSMN_STRICT FLB_HAVE_TLS FLB_HAVE_SQLDB FLB_HAVE_BUFFERING FLB_HAVE_FLUSH_LIBCO FLB_HAVE_FORK FLB_HAVE_PROXY_GO FLB_HAVE_REGEX FLB_HAVE_C_TLS FLB_HAVE_ACCEPT4 FLB_HAVE_INOTIFY

[Operating System]
    Name                Linux
    Release             4.1.15
    Version             #3 SMP PREEMPT Fri Jul 7 11:18:13 PDT 2017

[Hardware]
    Architecture        armv7l
    Processors          1

[Built Plugins]
    Inputs              cpu mem kmsg tail proc disk netif dummy head exec health serial stdin tcp mqtt lib forward random syslog
    Filters             grep stdout kubernetes parser record_modifier
    Outputs             counter es exit file forward http influxdb kafka-rest nats null plot stdout retry td lib flowcounter

[SERVER] Runtime configuration
    Flush               5
    Daemon              Off
    Log_Level           Info

[INPUT] Instance
    Name                tail.0 (tail, id=0)
    Flags               DYN_TAG
    Threaded            No
    Tag                 tail.0
    Path                /var/log/syslog
    db                  /var/log/landing_files.db
    Parser              syslog-custom


[OUTPUT] Instance
    Name                stdout.0 (stdout, mask_id=1)
    Match               *
    TLS Active          No
    Retry Limit         1

Thanks!

[2x-bullet-time]

@edsiper
When executing command "fluent-bit -i tail -p path=/var/log/syslog -p db=/var/log/landing_files.db -o stdout --verbose", in_tail plugin is able to pick up the offset value according to this log:

[2018/02/05 23:51:06] [ info] [engine] started
[2018/02/05 23:51:06] [debug] [in_tail] inotify watch fd=20
[2018/02/05 23:51:06] [debug] [in_tail] scanning path /var/log/syslog
[2018/02/05 23:51:06] [debug] [in_tail] add to scan queue /var/log/syslog, offset=3594
[2018/02/05 23:51:06] [debug] [router] default match rule tail.0:stdout.0
[2018/02/05 23:51:06] [debug] [in_tail] file=/var/log/syslog promote to TAIL_EVENT

However, it fails to detect it in these scenario(config file without parser, config file with parser, command with parser) according to this log:

[2018/02/05 23:54:51] [ info] [engine] started
[2018/02/05 23:54:51] [debug] [in_tail] inotify watch fd=19
[2018/02/05 23:54:51] [debug] [in_tail] scanning path /var/log/syslog
[2018/02/05 23:54:51] [debug] [in_tail] add to scan queue /var/log/syslog, offset=0
[2018/02/05 23:54:51] [debug] [router] input=tail.0 'DYNAMIC TAG'
[2018/02/05 23:54:51] [debug] [input tail.0] [mem buf] size = 4291
[2018/02/05 23:54:51] [debug] [in_tail] file=/var/log/syslog read=3594 lines=41
[2018/02/05 23:54:51] [debug] [in_tail] file=/var/log/syslog promote to TAIL_EVENT

Thanks!

[edsiper]

I cannot reproduce the problem you have stated.

This is my test log file (apache.log):

213.217.69.115 - - [06/feb/2018:11:23:01 -0600] "GET /churchy HTTP/1.0" 204 2216
193.56.73.36 - - [06/feb/2018:11:23:01 -0600] "GET /signable HTTP/1.0" 500 2216
18.240.253.3 - - [06/feb/2018:11:23:01 -0600] "GET /beclamour HTTP/1.0" 500 2216
205.219.243.165 - - [06/feb/2018:11:23:01 -0600] "GET /mowe HTTP/1.0" 200 2216
183.43.42.232 - - [06/feb/2018:11:23:01 -0600] "GET /Deimos HTTP/1.0" 200 2216
30.30.47.28 - - [06/feb/2018:11:23:01 -0600] "GET /basify HTTP/1.0" 204 2216
106.165.252.167 - - [06/feb/2018:11:23:01 -0600] "GET /triphase HTTP/1.0" 400 2216
204.168.117.164 - - [06/feb/2018:11:23:01 -0600] "GET /self-contentedly HTTP/1.0" 200 2216
251.244.238.241 - - [06/feb/2018:11:23:01 -0600] "GET /overblessedness HTTP/1.0" 400 2216
119.96.224.125 - - [06/feb/2018:11:23:01 -0600] "GET /senhora HTTP/1.0" 404 2216

1. Parser + DB:

$ fluent-bit -R parsers.conf -i tail -p path=apache.log -p parser=apache -p db=test.db -o stdout -f 1
Fluent-Bit v0.13.0
Copyright (C) Treasure Data

[2018/02/06 11:27:11] [ info] [engine] started
[0] tail.0: [1517937781.000000000, {"host"=>"213.217.69.115", "user"=>"-", "method"=>"GET", "path"=>"/churchy", "code"=>"204", "size"=>"2216", "referer"=>"", "agent"=>""}]
[1] tail.0: [1517937781.000000000, {"host"=>"193.56.73.36", "user"=>"-", "method"=>"GET", "path"=>"/signable", "code"=>"500", "size"=>"2216", "referer"=>"", "agent"=>""}]
[2] tail.0: [1517937781.000000000, {"host"=>"18.240.253.3", "user"=>"-", "method"=>"GET", "path"=>"/beclamour", "code"=>"500", "size"=>"2216", "referer"=>"", "agent"=>""}]
[3] tail.0: [1517937781.000000000, {"host"=>"205.219.243.165", "user"=>"-", "method"=>"GET", "path"=>"/mowe", "code"=>"200", "size"=>"2216", "referer"=>"", "agent"=>""}]
[4] tail.0: [1517937781.000000000, {"host"=>"183.43.42.232", "user"=>"-", "method"=>"GET", "path"=>"/Deimos", "code"=>"200", "size"=>"2216", "referer"=>"", "agent"=>""}]
[5] tail.0: [1517937781.000000000, {"host"=>"30.30.47.28", "user"=>"-", "method"=>"GET", "path"=>"/basify", "code"=>"204", "size"=>"2216", "referer"=>"", "agent"=>""}]
[6] tail.0: [1517937781.000000000, {"host"=>"106.165.252.167", "user"=>"-", "method"=>"GET", "path"=>"/triphase", "code"=>"400", "size"=>"2216", "referer"=>"", "agent"=>""}]
[7] tail.0: [1517937781.000000000, {"host"=>"204.168.117.164", "user"=>"-", "method"=>"GET", "path"=>"/self-contentedly", "code"=>"200", "size"=>"2216", "referer"=>"", "agent"=>""}]
[8] tail.0: [1517937781.000000000, {"host"=>"251.244.238.241", "user"=>"-", "method"=>"GET", "path"=>"/overblessedness", "code"=>"400", "size"=>"2216", "referer"=>"", "agent"=>""}]
[9] tail.0: [1517937781.000000000, {"host"=>"119.96.224.125", "user"=>"-", "method"=>"GET", "path"=>"/senhora", "code"=>"404", "size"=>"2216", "referer"=>"", "agent"=>""}]

2. Only DB (no parser):

$ fluent-bit -R parsers.conf -i tail -p path=apache.log -p db=test.db -o stdout -f 1
Fluent-Bit v0.13.0
Copyright (C) Treasure Data

[2018/02/06 11:27:57] [ info] [engine] started

no data output, because database offset is being used.

3. Only Parser (no database, expected to read from the beginning)

$ fluent-bit -R parsers.conf -i tail -p path=apache.log -p parser=apache -o stdout -f 1
Fluent-Bit v0.13.0
Copyright (C) Treasure Data

[2018/02/06 11:29:05] [ info] [engine] started
[0] tail.0: [1517937781.000000000, {"host"=>"213.217.69.115", "user"=>"-", "method"=>"GET", "path"=>"/churchy", "code"=>"204", "size"=>"2216", "referer"=>"", "agent"=>""}]
[1] tail.0: [1517937781.000000000, {"host"=>"193.56.73.36", "user"=>"-", "method"=>"GET", "path"=>"/signable", "code"=>"500", "size"=>"2216", "referer"=>"", "agent"=>""}]
[2] tail.0: [1517937781.000000000, {"host"=>"18.240.253.3", "user"=>"-", "method"=>"GET", "path"=>"/beclamour", "code"=>"500", "size"=>"2216", "referer"=>"", "agent"=>""}]
[3] tail.0: [1517937781.000000000, {"host"=>"205.219.243.165", "user"=>"-", "method"=>"GET", "path"=>"/mowe", "code"=>"200", "size"=>"2216", "referer"=>"", "agent"=>""}]
[4] tail.0: [1517937781.000000000, {"host"=>"183.43.42.232", "user"=>"-", "method"=>"GET", "path"=>"/Deimos", "code"=>"200", "size"=>"2216", "referer"=>"", "agent"=>""}]
[5] tail.0: [1517937781.000000000, {"host"=>"30.30.47.28", "user"=>"-", "method"=>"GET", "path"=>"/basify", "code"=>"204", "size"=>"2216", "referer"=>"", "agent"=>""}]
[6] tail.0: [1517937781.000000000, {"host"=>"106.165.252.167", "user"=>"-", "method"=>"GET", "path"=>"/triphase", "code"=>"400", "size"=>"2216", "referer"=>"", "agent"=>""}]
[7] tail.0: [1517937781.000000000, {"host"=>"204.168.117.164", "user"=>"-", "method"=>"GET", "path"=>"/self-contentedly", "code"=>"200", "size"=>"2216", "referer"=>"", "agent"=>""}]
[8] tail.0: [1517937781.000000000, {"host"=>"251.244.238.241", "user"=>"-", "method"=>"GET", "path"=>"/overblessedness", "code"=>"400", "size"=>"2216", "referer"=>"", "agent"=>""}]
[9] tail.0: [1517937781.000000000, {"host"=>"119.96.224.125", "user"=>"-", "method"=>"GET", "path"=>"/senhora", "code"=>"404", "size"=>"2216", "referer"=>"", "agent"=>""}]

I don't see any issue.

[2x-bullet-time]

I gave it another try using your apache log and here is the result:

I can now isolate parser from contributing to the problem. My regex was missing an end of line. Opps :/

in_tail plugin behaves properly when it is invoked via command line. However, it does not utilize offset when it is executed using a configuration file.

Here is the configuration file (db + parser):

[SERVICE]
    Flush     1
    Parsers_File    parsers.conf
    Log_Level    debug
    Daemon    Off
[INPUT]
    Name    tail
    path    /var/log/apache.log
    DB    /var/log/landing_files.db
    Parser    apache
[OUTPUT]
    Name    stdout
    Match    *

The same behavior is observed when parser is commented out.
An identical behavior also occurs when plug-in is tailing syslog + custom syslog parser + db.

[2x-bullet-time]

This might be a system/conf specific problem. I used the same set up on my ubuntu VM and it was working just fine in either mode. I will close this issue for now. Thank you.