Fix trace log duration for all logging implementations

[k-simons]

• The spec specifies that it should be in milliseconds, however right now we are emitting in nanoseconds
• This is because the Math.Round() just zeroes out the last 3 digits, we still need to divide to truncate them

This change is 

[bmoylan]

Reviewed 3 of 3 files at r1.
Reviewable status: all files reviewed, 2 unresolved discussions (waiting on @k-simons)

a discussion (no related file):
Is it possible to test this?

---

---

wlog-glog/internal/marshalers/wtracing_spanmodel.go, line 58 at r1 (raw file):

		_, _ = builder.WriteString(separator)
	}
	_, _ = builder.WriteString(fmt.Sprintf("%s: %d", trc1log.SpanDurationKey, int64(span.Duration.Round(time.Microsecond))/1e3))

I think int64(span.Duration/time.Microsecond) would do the same thing?

[nmiyake]

Reviewable status: all files reviewed, 2 unresolved discussions (waiting on @k-simons and @ksimons)

a discussion (no related file):

Previously, bmoylan (Brad Moylan) wrote…

Is it possible to test this?

@ksimons and I have been discussing (he reached out before submitting this PR) and I do believe it's possible. I'm working on a commit to amend this PR to add the tests.

---

[k-simons]

@bmoylan I had a test at 380e785 but it was only for a single implentation

@nmiyake There are no span options that allow me to edit the duration and interface has private methods so I cannot create my own

[nmiyake]

@k-simons took a look, and I thought that the service loggers used the function to marshal objects, but it turns out that it doesn't, which means the approach I outlined won't work.

The alternate approach I would suggest is to add another test at wlog/trclog/trc1log/trc1logtests/tests.go:98 and test the output within the trace logging -- you'd need to perform some sleep and then assert with a bit of a range.

If that's not feasible, then I don't think you need to specifically add a test here (a test showing that we divide by 1,000 isn't really helpful without the context of the behavior)

[k-simons]

@nmiyake Ok I pushed up a test. I think this is the best that we can do given the interfaces and options available. I confirmed that the test fails when I revert the fix

[bmoylan]

Just some nits!

Reviewed 1 of 2 files at r3.
Reviewable status: all files reviewed, 2 unresolved discussions (waiting on @k-simons)

---

wlog/trclog/trc1log/trc1logtests/tests.go, line 141 at r3 (raw file):

func getDurationValue(t *testing.T, entry logreader.Entry) int64 {
	for k, v := range entry {

Can we not just do v, ok := entry["span"]?

---

wlog-glog/internal/marshalers/wtracing_spanmodel.go, line 58 at r1 (raw file):

Previously, bmoylan (Brad Moylan) wrote…

I think int64(span.Duration/time.Microsecond) would do the same thing?

ping, I think this reads more simply

[bmoylan]

---

wlog/trclog/trc1log/trc1logtests/tests.go, line 133 at r3 (raw file):

			// Ensure the duration matches the sleep amount
			intValue := getDurationValue(t, entries[0])
			assert.True(t, intValue < 200000, "duration must be less than 200 milliseconds")

would intValue*time.Microsecond, 200*time.Millisecond be clearer?

[nmiyake]

Can you please create this as a test separate from jsonOutputTests? As currently written, this adds a sleep to every JSON test case, which doesn't feel as correct. Since we're explicitly testing the timing aspect here, would prefer adding the separate function.

If this is still unclear let me know and I can push up a commit that shows the skeleton of the structure.

Reviewable status: all files reviewed, 4 unresolved discussions (waiting on @k-simons)

---

wlog/trclog/trc1log/trc1logtests/tests.go, line 101 at r3 (raw file):

func JSONTestSuite(t *testing.T, loggerProvider func(w io.Writer) trc1log.Logger) {
	jsonOutputTests(t, loggerProvider)
}

Please add a new function like "durationFormatOutputTest" at the same level as jsonOutputTests. Then, that test function should have a single test (which is pretty similar to the Run function) that has the sleep and asserts the duration.

[k-simons]

@bmoylan @nmiyake addressed both CRs

[k-simons]

Reviewable status: 0 of 4 files reviewed, 4 unresolved discussions (waiting on @bmoylan and @nmiyake)

---

wlog/trclog/trc1log/trc1logtests/tests.go, line 101 at r3 (raw file):

Previously, nmiyake (Nick Miyake) wrote…

Please add a new function like "durationFormatOutputTest" at the same level as jsonOutputTests. Then, that test function should have a single test (which is pretty similar to the Run function) that has the sleep and asserts the duration.

Done.

---

wlog/trclog/trc1log/trc1logtests/tests.go, line 133 at r3 (raw file):

Previously, bmoylan (Brad Moylan) wrote…

would intValue*time.Microsecond, 200*time.Millisecond be clearer?

Done

---

wlog/trclog/trc1log/trc1logtests/tests.go, line 141 at r3 (raw file):

Previously, bmoylan (Brad Moylan) wrote…

Can we not just do v, ok := entry["span"]?

Done

---

wlog-glog/internal/marshalers/wtracing_spanmodel.go, line 58 at r1 (raw file):

Previously, bmoylan (Brad Moylan) wrote…

ping, I think this reads more simply

Done

[nmiyake]

on my end

Reviewed 4 of 4 files at r4.
Reviewable status: all files reviewed, 3 unresolved discussions (waiting on @bmoylan)

[bmoylan]

Reviewed 4 of 4 files at r4.
Reviewable status: all files reviewed, 2 unresolved discussions (waiting on @k-simons)

---

wlog/trclog/trc1log/trc1logtests/tests.go, line 119 at r4 (raw file):

	// Ensure the duration matches the sleep amount
	intValue := getDurationValue(t, entries[0])
	assert.True(t, intValue*time.Microsecond < 200*time.Millisecond, "duration must be less than 200 milliseconds")

since assert.True can't tell you much, you probably want the intValue included in the failure message

---

wlog/trclog/trc1log/trc1logtests/tests.go, line 157 at r4 (raw file):

func getDurationValue(t *testing.T, entry logreader.Entry) time.Duration {
	v, ok := entry["span"]
	assert.True(t, ok)

require.True so you don't continue if you don't find the span?

[k-simons]

Reviewable status: all files reviewed, 2 unresolved discussions (waiting on @bmoylan)

---

wlog/trclog/trc1log/trc1logtests/tests.go, line 119 at r4 (raw file):

Previously, bmoylan (Brad Moylan) wrote…

since assert.True can't tell you much, you probably want the intValue included in the failure message

Sorry where?

---

wlog/trclog/trc1log/trc1logtests/tests.go, line 157 at r4 (raw file):

Previously, bmoylan (Brad Moylan) wrote…

require.True so you don't continue if you don't find the span?

Done.

[bmoylan]

Reviewable status: all files reviewed, 2 unresolved discussions (waiting on @k-simons)

---

wlog/trclog/trc1log/trc1logtests/tests.go, line 119 at r4 (raw file):

assert.True(t, intValue*time.Microsecond < 200*time.Millisecond, "duration must be less than 200 milliseconds")

this will just print "duration must be less than 200 milliseconds" without telling you what it got

---

wlog/trclog/trc1log/trc1logtests/tests.go, line 157 at r4 (raw file):

Previously, k-simons wrote…

Done.

forgot to push?

[k-simons]

Reviewable status: 3 of 4 files reviewed, 2 unresolved discussions (waiting on @bmoylan and @nmiyake)

---

wlog/trclog/trc1log/trc1logtests/tests.go, line 119 at r4 (raw file):

Previously, bmoylan (Brad Moylan) wrote…

assert.True(t, intValue*time.Microsecond < 200*time.Millisecond, "duration must be less than 200 milliseconds")

this will just print "duration must be less than 200 milliseconds" without telling you what it got

Done.

---

wlog/trclog/trc1log/trc1logtests/tests.go, line 157 at r4 (raw file):

Previously, bmoylan (Brad Moylan) wrote…

forgot to push?

Done

[bmoylan]

Reviewed 1 of 1 files at r6.
Reviewable status: complete! all files reviewed, all discussions resolved