Bug 1426137 - Roll over log entries are visible when openshift_logging_fluentd_journal_read_from_head is set to false on json-file log driver envs
Summary: Roll over log entries are visible when openshift_logging_fluentd_journal_read...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: RFE
Version: 3.5.0
Hardware: Unspecified
OS: Unspecified
medium
low
Target Milestone: ---
: ---
Assignee: Peter Portante
QA Contact: Xiaoli Tian
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-02-23 09:40 UTC by Xia Zhao
Modified: 2019-06-12 12:41 UTC (History)
7 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-06-12 12:41:02 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)

Description Xia Zhao 2017-02-23 09:40:18 UTC
Description of problem:
Similar issue with https://bugzilla.redhat.com/show_bug.cgi?id=1410705:
Deploy logging with openshift_logging_fluentd_use_journal = true, parameter "openshift_logging_fluentd_journal_read_from_head "unspecified (according to https://github.com/openshift/openshift-ansible/blob/master/roles/openshift_logging/defaults/main.yml#L55, it should be default to false). Wait for a while until log entries for all necessary namespaces are ready, log in kibana UI, the roll over logs are displayed, and its index mapping was created in ES.

Version-Release number of selected component (if applicable):
https://github.com/openshift/openshift-ansible -b master

Steps to Reproduce:
1.Deploy logging 3.5.0 with ansible scripts ,including this parameter:
openshift_logging_fluentd_use_journal = true
and make sure parameter "openshift_logging_fluentd_journal_read_from_head "is unspecified in the inventory file
2. Double check and make sure JOURNAL_READ_FROM_HEAD is not set in fluentd (I also wonder why JOURNAL_SOURCE is also empty...):
$ oc rsh ${fluentd-pod}
sh-4.2# env | grep JOUR
USE_JOURNAL=true
JOURNAL_READ_FROM_HEAD=
JOURNAL_SOURCE=
3.Tail ES log for namespaces that was created prior to EFK deployments
4.Log in kibana

Actual results:
3.Index mappings was created in ES for namespaces that was created prior to EFK deployments
4.Roll over logs are displayed

Expected results:
3.Index mappings should not be created in ES for namespaces that was created prior to EFK deployments
4.Roll over logs (and indices) should not exist

Additional info:

Comment 1 Jeff Cantrill 2017-02-23 13:58:28 UTC
Lowering the priority as this is not a blocker.  @Rich is this the same issue as 'USE_JOURNAL' where this field can have 3 states?  It may just be that ansible is not interpreting the empty field as we desire.

Comment 2 Jeff Cantrill 2017-02-23 15:11:21 UTC
@Xia can you attach the fluentd daemonset and fluentd config file

Comment 3 Rich Megginson 2017-02-23 16:46:30 UTC
@Jeff - I don't think it is related.

@Xia - can you provide the output of oc exec ${fluentd-pod} -- cat /etc/fluent/configs.d/dynamic/input-syslog-default-syslog.conf ?

Comment 4 Xia Zhao 2017-03-01 07:57:00 UTC
Issue also repro when openshift_logging_fluentd_use_journal is not specified (in this case auto-detected the docker log driver), here is the output of input-syslog-default-syslog.conf, parameter "read_from_head " is true:

# oc rsh logging-fluentd-qpsgg

sh-4.2# cat /etc/fluent/configs.d/dynamic/input-syslog-default-syslog.conf
<source>
  @type tail
  @label @INGRESS
  path /var/log/messages
  pos_file /var/log/node.log.pos
  tag system.*
  format multiline
  # Begin possible multiline match: "Mmm DD HH:MM:SS "
  format_firstline /^[A-Z][a-z]{2}\s+[0-3]?[0-9]\s+[0-2][0-9]:[0-5][0-9]:[0-6][0-9]\s/
  # extract metadata from same line that matched format_firstline
  format1 /^(?<time>\S+\s+\S+\s+\S+)\s+(?<host>\S+)\s+(?<ident>[\w\/\.\-]*)(?:\[(?<pid>[0-9]+)\])?[^\:]*\:\s*(?<message>.*)$/
  time_format %b %d %H:%M:%S
  read_from_head true
  keep_time_key true
</source>

sh-4.2# env | grep JOUR
USE_JOURNAL=
JOURNAL_READ_FROM_HEAD=
JOURNAL_SOURCE=

Comment 5 Rich Megginson 2017-03-01 22:12:31 UTC
The fix for the original issue https://bugzilla.redhat.com/show_bug.cgi?id=1410705 was for the journal case:
Bug 1410705 - Roll over log entries are visible when journal-read-from-head 
is false

In this bz the docker log driver is json-file.  I guess we need a separate fix for the json-file log driver case.  But it has always been this way.  AFAICT, when using the json-file log driver, we have always used read_from_head true.  And, from http://docs.fluentd.org/v0.12/articles/in_tail#readfromhead
"
When this is true, in_tail tries to read a file during start up phase. If target file is large, it takes long time and starting other plugins isn't executed until reading file is finished.
"

So this is the current behavior, and has been so for over a year.

Is this the first time we've ever looked for roll over log entries when using the json-file log driver?

Comment 6 Xia Zhao 2017-03-02 02:37:18 UTC
(In reply to Rich Megginson from comment #5)

> when using the json-file log driver, we have always used read_from_head true
Yes, this is identical to what I've seen so far

> Is this the first time we've ever looked for roll over log entries when
> using the json-file log driver?

In my experiences, for the releases prior to 3.3, we used to collect for all roll over logs and this brought trouble to customers that they need to wait for days to collecting roll over log entries. 

With the introduce of parameter 'JOURNAL_READ_FROM_HEAD', we wanted to resolve this problem. I understand that this may have only been designed for journald log driver, just want to know if it's possible to also introduce this functionality to json-file log driver? If yes, please let me know if you want a separate bz to track this, thanks.

###########################################################

For the behaviors of journal log driver, as I mentioned in https://bugzilla.redhat.com/show_bug.cgi?id=1426137#c0, I'm using openshift_logging_fluentd_use_journal = true, but still encountered the bug repro when JOURNAL_READ_FROM_HEAD is empty. Let me double confirm this and update you later soon.

Comment 7 Rich Megginson 2017-03-02 02:52:53 UTC
(In reply to Xia Zhao from comment #6)
> With the introduce of parameter 'JOURNAL_READ_FROM_HEAD', we wanted to
> resolve this problem. I understand that this may have only been designed for
> journald log driver, just want to know if it's possible to also introduce
> this functionality to json-file log driver? If yes, please let me know if
> you want a separate bz to track this, thanks.

No other bug is needed.  I guess this bz is to "allow read_from_head false when using the json-file log driver and /var/log/messages".

Comment 9 Xia Zhao 2017-03-02 10:09:21 UTC
I'm having issue while retest with JOURNAL_READ_FROM_HEAD=empty on a use_journal=true env, get ERR_ADDRESS_UNREACHABLE when I visited the kibana route in browser, investigating...

Comment 10 Jeff Cantrill 2017-03-02 13:53:16 UTC
I'm going to move this to an RFE given it is a variance from the original design.  We should probably have PM weigh in on importance here.

Comment 11 Xia Zhao 2017-03-03 07:46:54 UTC
(In reply to Xia Zhao from comment #9)
> I'm having issue while retest with JOURNAL_READ_FROM_HEAD=empty on a
> use_journal=true env, get ERR_ADDRESS_UNREACHABLE when I visited the kibana
> route in browser, investigating...

I've addressed the error, it's caused by unproper network proxy used in my browser when visiting kibana. Kibana route can be accessed successfully now.

Comment 12 Xia Zhao 2017-03-03 08:21:35 UTC
@jcantril @rmeggins 

My original attempt here is to report the bug for rolled over log entries on journald log driver env when JOURNAL_READ_FROM_HEAD is default to empty, consider that this bz is currently assigned to RFE components talking about the behavior on json-file log drivers, do you think it proper to have a separate new bz for the original issue I encountered in #comment 0 ? 

I had reproduced it with openshift-ansible-3.5.18-1.git.0.01f8d4a.el7.noarch:

#####################################################
1) When I didn't specify openshift_logging_fluentd_journal_read_from_head in my inventory file, it should be default to false, but roll-over log entries was collected:

In side es log, I see index mapping was created for the roll-over log entries:
[2017-03-03 05:21:55,092][INFO ][cluster.metadata         ] [Mentor] [project.install-test.0321515b-ffc4-11e6-8e14-0e370a4933aa.2017.03.03] create_mapping [com.redhat.viaq.common]

# oc rsh logging-fluentd-qwz29

sh-4.2# cat /etc/fluent/configs.d/dynamic/input-syslog-default-syslog.conf
<source>
  @type systemd
  @label @INGRESS
  path "/run/log/journal"
  pos_file /var/log/journal.pos
  tag journal
</source>

sh-4.2# env | grep JOUR
USE_JOURNAL=true
JOURNAL_READ_FROM_HEAD=
JOURNAL_SOURCE=


######################################################
2) when I have these parameters in my inventory file:
openshift_logging_fluentd_use_journal=true
openshift_logging_fluentd_journal_read_from_head=false

The roll-over log entries was not collected:

# oc rsh logging-fluentd-3rbj5
sh-4.2# cat /etc/fluent/configs.d/dynamic/input-syslog-default-syslog.conf
<source>
  @type systemd
  @label @INGRESS
  path "/run/log/journal"
  pos_file /var/log/journal.pos
  tag journal
</source>

sh-4.2# env | grep JOUR
USE_JOURNAL=true
JOURNAL_READ_FROM_HEAD=false
JOURNAL_SOURCE=

Comment 13 Xia Zhao 2017-03-03 08:24:22 UTC
To be more clearer:

The issue I want to report to component=logging:
Roll over log entries are visible when openshift_logging_fluentd_journal_read_from_head is default to empty on journald log driver envs

The issue should be report to component=RFE:
Roll over log entries are visible when openshift_logging_fluentd_journal_read_from_head is set to false on json-file log driver envs

Comment 14 Rich Megginson 2017-03-03 15:57:16 UTC
(In reply to Xia Zhao from comment #13)
> To be more clearer:
> 
> The issue I want to report to component=logging:
> Roll over log entries are visible when
> openshift_logging_fluentd_journal_read_from_head is default to empty on
> journald log driver envs

So you're saying that https://bugzilla.redhat.com/show_bug.cgi?id=1410705 is _not_ fixed and should be reopened?

This is really strange - in both cases in https://bugzilla.redhat.com/show_bug.cgi?id=1426137#c12 the journal source configuration is identical.  Since the default value for JOURNAL_READ_FROM_HEAD is "false", it shouldn't matter if you omit it as in 1) or specify it as "false" as in 2).  This doesn't make any sense that you would get different behavior.  Can you please give me very detailed instructions about how to reproduce?


> 
> The issue should be report to component=RFE:
> Roll over log entries are visible when
> openshift_logging_fluentd_journal_read_from_head is set to false on
> json-file log driver envs

Correct.

Comment 15 Xia Zhao 2017-03-09 09:12:17 UTC
(In reply to Rich Megginson from comment #14)

> So you're saying that https://bugzilla.redhat.com/show_bug.cgi?id=1410705 is
> _not_ fixed and should be reopened?
> 
it should be fixed if openshift_logging_fluentd_journal_read_from_head=false is specified in inventory file, but not when not specified.

> This is really strange - in both cases in
> https://bugzilla.redhat.com/show_bug.cgi?id=1426137#c12 the journal source
> configuration is identical.  Since the default value for
> JOURNAL_READ_FROM_HEAD is "false", it shouldn't matter if you omit it as in
> 1) or specify it as "false" as in 2).  This doesn't make any sense that you
> would get different behavior.  Can you please give me very detailed
> instructions about how to reproduce?
> 

No problem, will create another bz tracking this, if you agree to only let this bz tracking the RFE request to json-file log drivers.

Comment 16 Xia Zhao 2017-03-09 09:23:50 UTC
The original issue to be reported was tracked here: https://bugzilla.redhat.com/show_bug.cgi?id=1430667

Comment 17 Peter Portante 2017-05-01 18:43:53 UTC
Is this a problem of seeing duplicate logs in Kibana?  Or are you not expecting to see old logs?

Comment 18 Xia Zhao 2017-05-02 05:29:25 UTC
As is mentioned in comment #0:

Expected results:
3.Index mappings should not be created in ES for namespaces that was created prior to EFK deployments
4.Roll over logs (and indices) should not exist

Comment 19 Peter Portante 2017-05-03 04:25:30 UTC
Xia, where are those expectations coming from?  Are they documented somewhere?

The "read_from_head" parameter mentioned is just about how fluentd works, as defined in their documentation [1]:

    read_from_head

    "If true, reads all available journal from head,
     otherwise starts reading from tail, ignored if
     pos file exists (and is valid).
     Defaults to false."

So do you have a valid pos file still on the system?

[1] https://github.com/reevoo/fluent-plugin-systemd

Comment 20 Xia Zhao 2017-05-11 07:21:26 UTC
The expectations comes from this fixed bz: bug #1410705.

Issue exist after removing the pos file on node, it recreates with the same content automatically after removing (want to know why?):

# cat /var/log/journal.pos 
s=2af158a52c45401386934930bf921487;i=8a0aa;b=fae70f5d672841ecb01fb751460984b0;m=3e8b6de6b;t=54f3a52a56a4c;x=b4a27ad7c8210b4e

# rm -rf journal.pos

# cat /var/log/journal.pos 
s=2af158a52c45401386934930bf921487;i=8a0aa;b=fae70f5d672841ecb01fb751460984b0;m=3e8b6de6b;t=54f3a52a56a4c;x=b4a27ad7c8210b4e

Comment 21 Rich Megginson 2017-05-11 18:45:50 UTC
If you delete the journal.pos file while fluentd is running, fluentd will just recreate it with the latest position.  If you keep monitoring the journal.pos file, you should see it being updated.

When fluentd starts up, if journal.pos is present, fluentd will always use this as the starting location to read the journal.  It doesn't matter what `read_from_head` is set to.

If journal.pos is not present, the default is `read_from_head false`.  This means, when fluentd starts up, if journal.pos is missing, fluentd will read only the latest entries from the journal.

If journal.pos is not present, and you have set JOURNAL_READ_FROM_HEAD=true during installation, or in the fluentd daemonset env. config, when fluentd starts up, fluentd will read all records in the journal.  This will include records from pods/namespaces/projects that may have been deleted, depending on when journal decides to rotate its logs.

Does this adequately explain the behavior you are seeing, and can we close this bug, or is further code/explanation required?

Comment 22 Xia Zhao 2017-07-13 08:24:50 UTC
@Rich,

Thanks for the explanation. Consider that journal.pos matter on the final test result, I'm considering on limit qe's scope on checking parameter inside fluentd to come across the impaction of journal.pos. 

Checked with 3.6 installers that the 3 values of openshift_logging_fluentd_journal_read_from_head can be successfully reflected in fluentd pod after deployment


# oc rsh logging-fluentd-pczkz
sh-4.2# cat /etc/fluent/configs.d/dynamic/input-syslog-default-syslog.conf
<source>
  @type systemd
  @label @INGRESS
  path "/run/log/journal"
  pos_file /var/log/journal.pos
  tag journal
  read_from_head true
</source>
sh-4.2# env | grep JOUR
JOURNAL_READ_FROM_HEAD=true
JOURNAL_SOURCE=

Based on the above test result, please feel free to transfer back this bz to ON_QA for closure.

Comment 23 Xia Zhao 2017-07-14 08:30:28 UTC
Set to verified according to comment #22.

Image tested with:
logging-fluentd            v3.6                b9eeeec142af        17 hours ago        231.7 MB

# openshift version
openshift v3.6.144
kubernetes v1.6.1+5115d708d7
etcd 3.2.1

ansible version:
openshift-ansible-playbooks-3.6.144-1.git.0.50e12bf.el7.noarch

Comment 25 Eric Rich 2019-06-12 12:41:02 UTC
This was provided with 3.6


Note You need to log in before you can comment on or make changes to this bug.