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

Formatting matcher output #37

Closed
onsi opened this Issue May 24, 2014 · 3 comments

Comments

Projects
None yet
2 participants
@onsi
Owner

onsi commented May 24, 2014

Originally from onsi/ginkgo#73

This may already be implemented, I just haven't found it.

When I have an expectation like this:

Expect(something).ToNot(BeNil())

If it fails, it logs a deep inspection of something. I find that in many cases this leads to overwhelming output. For example, one of my structures includes a time.Time. This is (surprisingly) over 250 of output due to a massive DST lookup table that's included in its loc field. Some of my data structures include http or file handles that can generate thousands of lines of output (sometimes recursively, leading to hundreds of "too deep for me, man" messages).

I had assumed that I could implement Stringer or GoStringer to control the logging output, but Ginkgo doesn't seem to use these. Is there any way to get control over how complex structures are displayed?

@onsi onsi self-assigned this May 24, 2014

@onsi

This comment has been minimized.

Show comment
Hide comment
@onsi

onsi May 24, 2014

Owner

Gomega's formatter does not simply print out Stringer/GoStringer because the representations for either of these are often insufficient to correctly diagnose problems.

It's actually funny that you picked time.Time as an example. It happens to exemplify this problem perfectly. Here's a test that passes on OS X, but fails on Linux )(:

package bar_test

import (
    "encoding/json"
    . "github.com/onsi/ginkgo"
    . "github.com/onsi/gomega"

        "fmt"
    "testing"
    "time"
)

func TestBar(t *testing.T) {
    RegisterFailHandler(Fail)
    RunSpecs(t, "Bar Suite")
}

type Temporal struct {
    T time.Time
}

var _ = Describe("JSON", func() {
    It("should work", func() {
        original := Temporal{T: time.Now()}

        encoded, err := json.Marshal(original)
        Ω(err).ShouldNot(HaveOccurred())

        var hydrated Temporal

        err = json.Unmarshal(encoded, &hydrated)
        Ω(err).ShouldNot(HaveOccurred())

                fmt.Println(original, hydrated)
        Ω(hydrated).Should(Equal(original))
    })
})

All this is doing is JSON encoding a struct that contains a time.Time and then decoding it and asserting the original equals the decoded object. Apparently there's a wacky bug (feature?) in Go on Linux where the round trip results in an object that does not reflect.DeepEqual the original. Here's the output of the fmt.Println(original, hydrated) on linux:

{2014-05-24 19:40:30.57606596 +0000 UTC} {2014-05-24 19:40:30.57606596 +0000 UTC}

At first blush the values appear to be identical. If this is what Gomega showed you there'd be much confusion and no way to understand what was going wrong! Here's Gomega's formatted output:

  Expected
      <temporal_test.Temporal>: {
          T: {
              sec: 63536557230,
              nsec: 0x225611a8,
              loc: {name: "UTC", zone: nil, tx: nil, cacheStart: 0, cacheEnd: 0, cacheZone: nil},
          },
      }
  to equal
      <temporal_test.Temporal>: {
          T: {
              sec: 63536557230,
              nsec: 0x225611a8,
              loc: {
                  name: "Local",
                  zone: [
                      {name: "UTC", offset: 0, isDST: false},
                  ],
                  tx: [
                      {
                          when: -9223372036854775808,
                          index: 0,
                          isstd: false,
                          isutc: false,
                      },
                  ],
                  cacheStart: -9223372036854775808,
                  cacheEnd: 9223372036854775807,
                  cacheZone: {name: "UTC", offset: 0, isDST: false},
              },
          },
      }

As you can see the decoded object is missing the complex zone and tx fields... kinda crazy!


With all this said, I agree that Gomegas output can be overwhelmingly verbose at times. There isn't currently a way to change this but I would like to add one. I'm envisioning that you can instruct Gomega's format package to enter different verbosity modes. It will default to the current (high-verbosity) mode but you'll be able to do something like:

func TestBar(t *testing.T) {
       format.SetVerbosityLevel(format.Low)
    RegisterFailHandler(Fail)
    RunSpecs(t, "Bar Suite")
}

which would lead to much terser, but hopefully still useful for most cases, output.

Thoughts?

Owner

onsi commented May 24, 2014

Gomega's formatter does not simply print out Stringer/GoStringer because the representations for either of these are often insufficient to correctly diagnose problems.

It's actually funny that you picked time.Time as an example. It happens to exemplify this problem perfectly. Here's a test that passes on OS X, but fails on Linux )(:

package bar_test

import (
    "encoding/json"
    . "github.com/onsi/ginkgo"
    . "github.com/onsi/gomega"

        "fmt"
    "testing"
    "time"
)

func TestBar(t *testing.T) {
    RegisterFailHandler(Fail)
    RunSpecs(t, "Bar Suite")
}

type Temporal struct {
    T time.Time
}

var _ = Describe("JSON", func() {
    It("should work", func() {
        original := Temporal{T: time.Now()}

        encoded, err := json.Marshal(original)
        Ω(err).ShouldNot(HaveOccurred())

        var hydrated Temporal

        err = json.Unmarshal(encoded, &hydrated)
        Ω(err).ShouldNot(HaveOccurred())

                fmt.Println(original, hydrated)
        Ω(hydrated).Should(Equal(original))
    })
})

All this is doing is JSON encoding a struct that contains a time.Time and then decoding it and asserting the original equals the decoded object. Apparently there's a wacky bug (feature?) in Go on Linux where the round trip results in an object that does not reflect.DeepEqual the original. Here's the output of the fmt.Println(original, hydrated) on linux:

{2014-05-24 19:40:30.57606596 +0000 UTC} {2014-05-24 19:40:30.57606596 +0000 UTC}

At first blush the values appear to be identical. If this is what Gomega showed you there'd be much confusion and no way to understand what was going wrong! Here's Gomega's formatted output:

  Expected
      <temporal_test.Temporal>: {
          T: {
              sec: 63536557230,
              nsec: 0x225611a8,
              loc: {name: "UTC", zone: nil, tx: nil, cacheStart: 0, cacheEnd: 0, cacheZone: nil},
          },
      }
  to equal
      <temporal_test.Temporal>: {
          T: {
              sec: 63536557230,
              nsec: 0x225611a8,
              loc: {
                  name: "Local",
                  zone: [
                      {name: "UTC", offset: 0, isDST: false},
                  ],
                  tx: [
                      {
                          when: -9223372036854775808,
                          index: 0,
                          isstd: false,
                          isutc: false,
                      },
                  ],
                  cacheStart: -9223372036854775808,
                  cacheEnd: 9223372036854775807,
                  cacheZone: {name: "UTC", offset: 0, isDST: false},
              },
          },
      }

As you can see the decoded object is missing the complex zone and tx fields... kinda crazy!


With all this said, I agree that Gomegas output can be overwhelmingly verbose at times. There isn't currently a way to change this but I would like to add one. I'm envisioning that you can instruct Gomega's format package to enter different verbosity modes. It will default to the current (high-verbosity) mode but you'll be able to do something like:

func TestBar(t *testing.T) {
       format.SetVerbosityLevel(format.Low)
    RegisterFailHandler(Fail)
    RunSpecs(t, "Bar Suite")
}

which would lead to much terser, but hopefully still useful for most cases, output.

Thoughts?

@onsi

This comment has been minimized.

Show comment
Hide comment
@onsi

onsi May 28, 2014

Owner

I've struggle a bit with what to do here. I think what I ended up with on 05c2b32 is a reasonable compromise.

You can now modify the (global) maximum recursion depth for the format package by setting format.MaxDepth -- this can help make deeply nested structs less verbose.

You can also opt into displaying Stringer and GoStringer strings instead of the recursive formatting by setting format.UseStringerRepresentation to true.

These are global and affect all output. I think between the two knobs you can get better control over your output.

Thoughts?

Owner

onsi commented May 28, 2014

I've struggle a bit with what to do here. I think what I ended up with on 05c2b32 is a reasonable compromise.

You can now modify the (global) maximum recursion depth for the format package by setting format.MaxDepth -- this can help make deeply nested structs less verbose.

You can also opt into displaying Stringer and GoStringer strings instead of the recursive formatting by setting format.UseStringerRepresentation to true.

These are global and affect all output. I think between the two knobs you can get better control over your output.

Thoughts?

@bradfeehan

This comment has been minimized.

Show comment
Hide comment
@bradfeehan

bradfeehan Jul 28, 2014

Would it be possible to show the more verbose representation, but only if the less-verbose representations are identical? (vice-versa for inequality matches)

bradfeehan commented Jul 28, 2014

Would it be possible to show the more verbose representation, but only if the less-verbose representations are identical? (vice-versa for inequality matches)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment