Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add time stamps to log entries and use text payload #535

Merged
merged 16 commits into from
Aug 10, 2017

Conversation

chxchx
Copy link
Contributor

@chxchx chxchx commented Aug 3, 2017

Release note:

NONE

@ldemailly
Copy link
Contributor

/lgtm
/approve no-issue

/dogscience

@chxchx
Copy link
Contributor Author

chxchx commented Aug 3, 2017

@sebastienvas @kyessenov

This PR is to address the issue #528
After this PR, logs are recorded in the following format (excerpt from istio-ingress.log)

...
[2017-08-03 03:50:23.445][16][warning][main] external/envoy/source/server/server.cc:129] initializing epoch 0 (hot restart version=8.2490552)
[2017-08-03 03:50:23.457][16][warning][main] external/envoy/source/server/server.cc:285] starting main dispatch loop
[2017-08-03 03:50:23.460][16][warning][main] external/envoy/source/server/server.cc:280] all clusters initialized. initializing init manager
[2017-08-03 03:50:23.465][16][warning][upstream] external/envoy/source/server/lds_api.cc:79] lds: fetch failure: Failed to load certificate '/etc/istio/ingress-certs/tls.crt'
...

It is worth noting that the beginning of each log file contains config information and does not have timestamps. For actual log entries, timestamps are included.

Let me know if additional info should be recorded as well, or if different format is preferred.

@ldemailly
Copy link
Contributor

the date is probably unnecessary (time is enough) ?
what is [16][warning][main]
can it be [16 W main]

@istio-merge-robot
Copy link

/lgtm cancel //PR changed after LGTM, removing LGTM. @chxchx @ldemailly

@chxchx chxchx changed the title Access text payload and remove extra newline Add time stamps to log entries and use text payload Aug 3, 2017
@kyessenov
Copy link
Contributor

Since stackdriver aggregates logs from many pods, you should add pod IP into prefix as well.

@ldemailly
Copy link
Contributor

ps: please avoid force pushing, it's not great to have what I approved or commented on just disapear

Copy link
Contributor

@ldemailly ldemailly left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

let's remove the date etc per ^

@ldemailly ldemailly assigned chxchx and unassigned ldemailly Aug 4, 2017
@chxchx
Copy link
Contributor Author

chxchx commented Aug 4, 2017

PTAL

Turns out istio-ingress is not a good example to give, since the timestamps and severity etc are included in the payload directly, which is not the case for other logs on mixer, discovery, prometheus, etc. The following is an example from mixer.log.

[2017-08-04 13:40:29 -0700 PDT] attempting to acquire leader lease...
[2017-08-04 13:40:29 -0700 PDT] successfully acquired lease demo-test-b4e03742835b4e93987ee6e2e64/istio-ingress-controller-leader-istio
[2017-08-04 13:40:29 -0700 PDT] new leader elected (istio-pilot-1473650018-fk9d6)
[2017-08-04 13:40:29 -0700 PDT] I am the new status update leader
[2017-08-04 13:40:29 -0700 PDT] Event add: key "demo-test-b4e03742835b4e93987ee6e2e64/istio-pilot-1473650018-fk9d6"
[2017-08-04 13:40:30 -0700 PDT] Event add: key "demo-test-b4e03742835b4e93987ee6e2e64/istio-ingress-controller-leader-istio"

Also, when each log entry was recorded to stackdriver, the pod IP was not included with the log, so when I fetch from stackdriver there is no way for me to access such information. If the IP is super important we might want to put it in log payload when the log is generated, but that would be out of the scope of this PR.

Copy link
Contributor

@ldemailly ldemailly left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

can you change
"[2017-08-04 13:40:30 -0700 PDT]"
to
"[13:40:30]"

@chxchx
Copy link
Contributor Author

chxchx commented Aug 7, 2017

PTAL

@@ -186,7 +186,8 @@ func (t testInfo) FetchAndSaveClusterLogs(namespace string) error {
for _, logEntry := range entries {
timestamp := logEntry.GetTimestamp()
fmtTime := time.Unix(timestamp.Seconds, 0)
log := fmt.Sprintf("[%s] %s", fmtTime, logEntry.GetTextPayload())
log := fmt.Sprintf("[%d:%d:%d] %s",
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

don't you need %02d here ? what happens when the h/m/s are < 10 ?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good catch. Done.

log := fmt.Sprintf("[%02d:%02d:%02d] %s",
fmtTime.Hour(), fmtTime.Minute(), fmtTime.Second(), logEntry.GetTextPayload())
if log[len(log)-1:] != "\n" {
log += "\n"
Copy link
Contributor

@ldemailly ldemailly Aug 8, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

is it really the case that sometime there is already a \n and some times there isn't ? it may be quite expensive and maybe should be split
into (assuming f is buffered and not taking a lock each time)

f.WriteString(fmt.Sprintf("[%02d:%02d:%02d] ",fmtTime.Hour(), fmtTime.Minute(), fmtTime.Second())
txt := logEntry.GetTextPayload()
f.WriteString(txt))
if len(txt) == 0 || log[len(log)-1] != '\n' {
  f.WriteByte('\n')
}

but I would check logEntry.GetTextPayload() ? and try to avoid the if (maybe always add the newline

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah I was amazed by the heterogeneity in logs. The payload is formatted different and some has newline and the end while some don't. I do see the point of taking advantage of the file write buffer since concatenation on string essentially claims additional memory and copy everything over. I did take a look on the WriteString() source code and see no locks. I assume copy-on-write until we close the file to commit our writes.

@ldemailly
Copy link
Contributor

@chxchx should we merge this ? (/why not?)

@chxchx
Copy link
Contributor Author

chxchx commented Aug 9, 2017

@ldemailly Yes. It is ready.

@ldemailly
Copy link
Contributor

ldemailly commented Aug 9, 2017

I meant why didn't you click :-) now it needs rebase again

@sebastienvas
Copy link
Contributor

/lgtm

@istio-merge-robot
Copy link

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: chxchx, ldemailly, sebastienvas

The full list of commands accepted by this bot can be found here.

Needs approval from an approver in each of these OWNERS Files:

You can indicate your approval by writing /approve in a comment
You can cancel your approval by writing /approve cancel in a comment

@istio-merge-robot
Copy link

/test all [submit-queue is verifying that this PR is safe to merge]

@sebastienvas
Copy link
Contributor

/test all

@ldemailly
Copy link
Contributor

/retest

@yutongz
Copy link
Contributor

yutongz commented Aug 10, 2017

/test all

@istio-merge-robot
Copy link

/test all [submit-queue is verifying that this PR is safe to merge]

@chxchx
Copy link
Contributor Author

chxchx commented Aug 10, 2017

/test all

@istio-merge-robot
Copy link

/test all [submit-queue is verifying that this PR is safe to merge]

@sebastienvas sebastienvas merged commit 7f3fd71 into istio:master Aug 10, 2017
rshriram pushed a commit that referenced this pull request Oct 30, 2017
* Access text payload and remove extra newline

* Pretty Print Timestamps

* Timestamp excludes the date

* Zero pads single digit

* No concat but write to file buffer

* handle err from closing file


Former-commit-id: 7f3fd71
vbatts pushed a commit to vbatts/istio that referenced this pull request Oct 31, 2017
* Access text payload and remove extra newline

* Pretty Print Timestamps

* Timestamp excludes the date

* Zero pads single digit

* No concat but write to file buffer

* handle err from closing file


Former-commit-id: 7f3fd71
mandarjog pushed a commit that referenced this pull request Nov 2, 2017
* Access text payload and remove extra newline

* Pretty Print Timestamps

* Timestamp excludes the date

* Zero pads single digit

* No concat but write to file buffer

* handle err from closing file


Former-commit-id: 7f3fd71
rshriram pushed a commit to rshriram/istio that referenced this pull request Jul 31, 2018
howardjohn added a commit to howardjohn/istio that referenced this pull request Jan 12, 2020
This will help with issues where things are not reproducible
howardjohn pushed a commit to howardjohn/istio that referenced this pull request Jan 12, 2020
luksa pushed a commit to luksa/istio that referenced this pull request Sep 20, 2022
Co-authored-by: maistra-bot <null>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

8 participants