Test-cases makes it hard to tell why a unit test fails

[markdryan]

Test-cases will report the test as failing and will colour it in red but it doesn't report the error message that actually caused the test to fail. This is because it only dumps the contents of standard error and not that of standard output which is where the logs from calls such as t.Fatalf go.

[tpepper]

We think this is a bug in go. https://golang.org/pkg/testing/#T documents that the test error report goes to stderr. Runtime observation is that it clearly goes instead to stdout, contrary to the documented behavior and natural expectations for differentiation between normal outputs and error outputs.

I'll open an issue against go and have a potential one-line patch to what appears to be the appropriate function, with 21 lines of documentation describing why. The patch may break other go users. Either the code needs to change or the documentation.

[tpepper]

golang/go#16138 opened with Go folks...

[markdryan]

Have something working now but need to clean it up a little. Anyway, here's some example output. Note that in this run almost all the tests are failing so there's lots of output. However, in general you'll only see logs from test cases that fail.

test-cases --text -colour=false github.com/01org/ciao/networking/libsnnet
Package  Test Case                    Time Taken Result  
libsnnet TestBridge_Basic             0.00s      FAIL    
libsnnet TestBridge_Dup               0.00s      FAIL    
libsnnet TestBridge_Invalid           0.00s      PASS    
libsnnet TestBridge_GetDevice         0.00s      FAIL    
libsnnet TestCNContainer_Base         0.00s      FAIL    
libsnnet TestCNContainer_Connectivity 0.00s      FAIL    
libsnnet TestCNContainer_Interop1     0.00s      FAIL    
libsnnet TestCNContainer_Interop2     0.00s      FAIL    
libsnnet TestCN_Scaling               0.00s      FAIL    
libsnnet TestCN_ResetNetwork          0.00s      FAIL    
libsnnet TestCN_MultiTenant           0.00s      FAIL    
libsnnet TestCN_Negative              0.00s      FAIL    
libsnnet TestCN_AndNN                 0.00s      FAIL    
libsnnet TestNN_Base                  0.00s      FAIL    
libsnnet TestCN_Base                  0.00s      FAIL    
libsnnet TestCN_Whitebox              0.00s      FAIL    
libsnnet TestCNCI_Init                0.00s      FAIL    
libsnnet TestCNCI_Internal            0.01s      FAIL    
libsnnet TestCnciVnic_Basic           0.00s      FAIL    
libsnnet TestCnciVnic_Dup             0.00s      FAIL    
libsnnet TestCnciVnic_Invalid         0.00s      PASS    
libsnnet TestCnciVnic_GetDevice       0.00s      FAIL    
libsnnet TestDnsmasq_Basic            0.01s      FAIL    
libsnnet TestDnsmasq_Negative         0.01s      FAIL    
libsnnet TestFw_Init                  0.00s      FAIL    
libsnnet TestFw_Ssh                   0.00s      FAIL    
libsnnet TestFw_Nat                   0.00s      FAIL    
libsnnet TestFw_All                   0.00s      FAIL    
libsnnet TestCN_Fuzz                  N/A        NOT RUN 
libsnnet TestCNCI_Fuzz                N/A        NOT RUN 
libsnnet TestNwPrimitives_Fuzz        N/A        NOT RUN 
libsnnet TestGre_Basic                N/A        NOT RUN 
libsnnet TestGre_Bridge               N/A        NOT RUN 
libsnnet TestGre_Negative             N/A        NOT RUN 
libsnnet TestCN_dbRebuild             N/A        NOT RUN 
libsnnet TestVnic_Basic               N/A        NOT RUN 
libsnnet TestVnicContainer_Basic      N/A        NOT RUN 
libsnnet TestVnic_Dup                 N/A        NOT RUN 
libsnnet TestVnicContainer_Dup        N/A        NOT RUN 
libsnnet TestVnic_Invalid             N/A        NOT RUN 
libsnnet TestVnicContainer_Invalid    N/A        NOT RUN 
libsnnet TestVnic_GetDevice           N/A        NOT RUN 
libsnnet TestVnicContainer_GetDevice  N/A        NOT RUN 
libsnnet TestVnic_Bridge              N/A        NOT RUN 
libsnnet TestVnicContainer_Bridge     N/A        NOT RUN 

Logs for failed tests
---------------------
Logs for libsnnet.TestBridge_Basic
        Error Trace:    bridge_test.go:48
    Error:      Expected nil, but got: &errors.errorString{s:"bridge error: create link add go_testbr operation not permitted"}

        Error Trace:    bridge_test.go:53
    Error:      Expected nil, but got: &errors.errorString{s:"bridge error: GetDevice: link by alias Link alias go_testbr not found"}

        Error Trace:    bridge_test.go:26
            bridge_test.go:30
            bridge_test.go:54
    Error:      Expected nil, but got: &errors.errorString{s:"bridge error: enable bridge unnitialized"}

        Error Trace:    bridge_test.go:26
            bridge_test.go:31
            bridge_test.go:54
    Error:      Expected nil, but got: &errors.errorString{s:"bridge error: disable bridge unnitialized"}

        Error Trace:    bridge_test.go:26
            bridge_test.go:32
            bridge_test.go:54
    Error:      Expected nil, but got: &errors.errorString{s:"bridge error: destroy bridge unnitialized"}

Logs for libsnnet.TestBridge_Dup
        Error Trace:    bridge_test.go:71
    Error:      Expected nil, but got: &errors.errorString{s:"bridge error: create link add go_testbr operation not permitted"}

Logs for libsnnet.TestBridge_GetDevice
        Error Trace:    bridge_test.go:107
    Error:      Expected nil, but got: &errors.errorString{s:"bridge error: create link add go_testbr operation not permitted"}

        Error Trace:    bridge_test.go:112
    Error:      Expected nil, but got: &errors.errorString{s:"bridge error: GetDevice: link by alias Link alias go_testbr not found"}

        Error Trace:    bridge_test.go:26
            bridge_test.go:30
            bridge_test.go:113
    Error:      Expected nil, but got: &errors.errorString{s:"bridge error: enable bridge unnitialized"}

        Error Trace:    bridge_test.go:26
            bridge_test.go:31
            bridge_test.go:113
    Error:      Expected nil, but got: &errors.errorString{s:"bridge error: disable bridge unnitialized"}

        Error Trace:    bridge_test.go:26
            bridge_test.go:32
            bridge_test.go:113
    Error:      Expected nil, but got: &errors.errorString{s:"bridge error: destroy bridge unnitialized"}

Logs for libsnnet.TestCNContainer_Base
        Error Trace:    cn_container_test.go:199
    Error:      Expected nil, but got: libsnnet.APIError{networkError:libsnnet.networkError{msg:"unable to associate with management network [{127.0.0.0 ffffff00}]", when:time.Time{sec:63602219507, nsec:543128818, loc:(*time.Location)(0xeaf4c0)}, category:"API"}}

Logs for libsnnet.TestCNContainer_Connectivity
        Error Trace:    cn_container_test.go:370
    Error:      Expected nil, but got: libsnnet.APIError{networkError:libsnnet.networkError{msg:"unable to associate with management network [{127.0.0.0 ffffff00}]", when:time.Time{sec:63602219507, nsec:543282647, loc:(*time.Location)(0xeaf4c0)}, category:"API"}}

Logs for libsnnet.TestCNContainer_Interop1
        Error Trace:    cn_container_test.go:452
    Error:      Expected nil, but got: libsnnet.APIError{networkError:libsnnet.networkError{msg:"unable to associate with management network [{127.0.0.0 ffffff00}]", when:time.Time{sec:63602219507, nsec:543398872, loc:(*time.Location)(0xeaf4c0)}, category:"API"}}

Logs for libsnnet.TestCNContainer_Interop2
        Error Trace:    cn_container_test.go:580
    Error:      Expected nil, but got: libsnnet.APIError{networkError:libsnnet.networkError{msg:"unable to associate with management network [{127.0.0.0 ffffff00}]", when:time.Time{sec:63602219507, nsec:543520262, loc:(*time.Location)(0xeaf4c0)}, category:"API"}}

Logs for libsnnet.TestCN_Scaling
        Error Trace:    cn_test.go:108
    Error:      Expected nil, but got: libsnnet.APIError{networkError:libsnnet.networkError{msg:"unable to associate with management network [{127.0.0.0 ffffff00}]", when:time.Time{sec:63602219507, nsec:543651964, loc:(*time.Location)(0xeaf4c0)}, category:"API"}}

Logs for libsnnet.TestCN_ResetNetwork
        Error Trace:    cn_test.go:198
    Error:      Expected nil, but got: libsnnet.APIError{networkError:libsnnet.networkError{msg:"unable to associate with management network [{127.0.0.0 ffffff00}]", when:time.Time{sec:63602219507, nsec:543767642, loc:(*time.Location)(0xeaf4c0)}, category:"API"}}

Logs for libsnnet.TestCN_MultiTenant
        Error Trace:    cn_test.go:265
    Error:      Expected nil, but got: libsnnet.APIError{networkError:libsnnet.networkError{msg:"unable to associate with management network [{127.0.0.0 ffffff00}]", when:time.Time{sec:63602219507, nsec:543885503, loc:(*time.Location)(0xeaf4c0)}, category:"API"}}

Logs for libsnnet.TestCN_Negative
        Error Trace:    cn_test.go:320
    Error:      Expected nil, but got: libsnnet.APIError{networkError:libsnnet.networkError{msg:"unable to associate with management network [{127.0.0.0 ffffff00}]", when:time.Time{sec:63602219507, nsec:544005344, loc:(*time.Location)(0xeaf4c0)}, category:"API"}}

Logs for libsnnet.TestCN_AndNN
        Error Trace:    cn_test.go:381
    Error:      Expected nil, but got: libsnnet.APIError{networkError:libsnnet.networkError{msg:"unable to associate with management network [{127.0.0.0 ffffff00}]", when:time.Time{sec:63602219507, nsec:544118972, loc:(*time.Location)(0xeaf4c0)}, category:"API"}}

Logs for libsnnet.TestNN_Base
        Error Trace:    cn_test.go:519
    Error:      Expected nil, but got: libsnnet.APIError{networkError:libsnnet.networkError{msg:"unable to associate with management network [{127.0.0.0 ffffff00}]", when:time.Time{sec:63602219507, nsec:544242273, loc:(*time.Location)(0xeaf4c0)}, category:"API"}}

Logs for libsnnet.TestCN_Base
        Error Trace:    cn_test.go:599
    Error:      Expected nil, but got: libsnnet.APIError{networkError:libsnnet.networkError{msg:"unable to associate with management network [{127.0.0.0 ffffff00}]", when:time.Time{sec:63602219507, nsec:544388316, loc:(*time.Location)(0xeaf4c0)}, category:"API"}}

Logs for libsnnet.TestCN_Whitebox
        Error Trace:    cn_test.go:721
    Error:      Expected nil, but got: &errors.errorString{s:"bridge error: create link add br_tenantUuid_subnetUuid_concUuid operation not permitted"}

        Error Trace:    cn_test.go:731
    Error:      Expected nil, but got: &errors.errorString{s:"gre error: create link add gre_tenantUuid_subnetUuid_concUuid operation not permitted"}

        Error Trace:    cn_test.go:734
    Error:      Expected nil, but got: &errors.errorString{s:"gre error: attach gre tunnel unnitialized"}

        Error Trace:    cn_test.go:735
    Error:      Expected nil, but got: &errors.errorString{s:"gre error: enable invalid gre link: &{{sgt_3044871f  gre_tenantUuid_subnetUuid_concUuid <nil>} 0xc8200b8f70 15 127.0.0.1 192.168.1.1  }"}

        Error Trace:    cn_test.go:736
    Error:      Expected nil, but got: &errors.errorString{s:"bridge error: enable bridge unnitialized"}

        Error Trace:    cn_test.go:744
    Error:      Expected nil, but got: &errors.errorString{s:"vnic error: createVMVnic vnic error: create link add vnic_tenantUuid_tenantUuid_ca:fe:00:01:02:03_concUuid Tuntap IOCTL TUNSETIFF failed, errno operation not permitted"}

        Error Trace:    cn_test.go:747
    Error:      Expected nil, but got: &errors.errorString{s:"vnic error: attach unnitialized"}

        Error Trace:    cn_test.go:748
    Error:      Expected nil, but got: &errors.errorString{s:"vnic error: enable unnitialized"}

        Error Trace:    cn_test.go:749
    Error:      Expected nil, but got: &errors.errorString{s:"bridge error: enable bridge unnitialized"}

Logs for libsnnet.TestCNCI_Init
        Error Trace:    cnci_test.go:69
    Error:      Expected nil, but got: &errors.errorString{s:"unable to associate with management network [{127.0.0.0 ffffff00}]"}

Logs for libsnnet.TestCNCI_Internal
        Error Trace:    cnci_test.go:144
    Error:      Expected nil, but got: &errors.errorString{s:"bridge error: create link add br_tenantUuid_subnetUuid_concUuid operation not permitted"}

        Error Trace:    cnci_test.go:147
    Error:      Expected nil, but got: &errors.errorString{s:"bridge error: enable bridge unnitialized"}

        Error Trace:    cnci_test.go:153
    Error:      Expected nil, but got: &errors.errorString{s:"d.Dev.AddIP failed bridge error: add ip bridge unnitialized 192.168.1.1/24"}

        Error Trace:    cnci_test.go:172
    Error:      Expected nil, but got: &errors.errorString{s:"gre error: create link add gre_tenantUuid_subnetUuid_cnUuid operation not permitted"}

        Error Trace:    cnci_test.go:175
    Error:      Expected nil, but got: &errors.errorString{s:"gre error: attach gre tunnel unnitialized"}

        Error Trace:    cnci_test.go:176
    Error:      Expected nil, but got: &errors.errorString{s:"gre error: enable invalid gre link: &{{sgt_e9448ff2  gre_tenantUuid_subnetUuid_cnUuid <nil>} 0xc820214750 15 127.0.0.1 127.0.0.1  }"}

Logs for libsnnet.TestCnciVnic_Basic
        Error Trace:    cncivnic_test.go:70
    Error:      Expected nil, but got: &errors.errorString{s:"cncivnic error: create netlink.LinkAdd testcnciVnic operation not permitted"}

        Error Trace:    cncivnic_test.go:72
    Error:      Expected nil, but got: &errors.errorString{s:"cncivnic error: enable link up operation not permitted"}

        Error Trace:    cncivnic_test.go:73
    Error:      Expected nil, but got: &errors.errorString{s:"cncivnic error: disable link down operation not permitted"}

        Error Trace:    cncivnic_test.go:74
    Error:      Expected nil, but got: &errors.errorString{s:"cncivnic error: destroy link del operation not permitted"}

Logs for libsnnet.TestCnciVnic_Dup
        Error Trace:    cncivnic_test.go:94
    Error:      Expected nil, but got: &errors.errorString{s:"cncivnic error: create netlink.LinkAdd testcnciVnic operation not permitted"}

Logs for libsnnet.TestCnciVnic_GetDevice
        Error Trace:    cncivnic_test.go:137
    Error:      Expected nil, but got: &errors.errorString{s:"cncivnic error: create netlink.LinkAdd testcnciVnic operation not permitted"}

        Error Trace:    cncivnic_test.go:141
    Error:      Expected nil, but got: &errors.errorString{s:"cncivnic error: getdevice interface does not exist: testcnciVnic"}

        Error Trace:    cncivnic_test.go:143
    Error:      Expected nil, but got: &errors.errorString{s:"cncivnic error: enable link up operation not permitted"}

        Error Trace:    cncivnic_test.go:144
    Error:      Expected nil, but got: &errors.errorString{s:"cncivnic error: disable link down operation not permitted"}

        Error Trace:    cncivnic_test.go:145
    Error:      Expected nil, but got: &errors.errorString{s:"cncivnic error: destroy link del operation not permitted"}

Logs for libsnnet.TestDnsmasq_Basic
        Error Trace:    dnsmasq_test.go:50
    Error:      Expected nil, but got: &errors.errorString{s:"bridge error: create link add dns_testbr operation not permitted"}

        Error Trace:    dnsmasq_test.go:62
    Error:      Expected nil, but got: &errors.errorString{s:"d.Dev.AddIP failed bridge error: add ip bridge unnitialized 192.168.1.1/24"}

        Error Trace:    dnsmasq_test.go:65
    Error:      Expected nil, but got: &errors.errorString{s:"No pid file open /tmp/dnsmasq_concuuid.pid: no such file or directory"}

        Error Trace:    dnsmasq_test.go:68
    Error:      Expected nil, but got: &errors.errorString{s:"d.Start failed d.Dev.AddIP failed bridge error: add ip bridge unnitialized 192.168.1.1/24"}

        Error Trace:    dnsmasq_test.go:71
    Error:      Expected nil, but got: &errors.errorString{s:"Process does not exist No pid file open /tmp/dnsmasq_concuuid.pid: no such file or directoryUnable to delete bridge IP bridge error: del ip bridge unnitialized"}

        Error Trace:    dnsmasq_test.go:74
    Error:      Expected nil, but got: &errors.errorString{s:"d.Start failed d.Dev.AddIP failed bridge error: add ip bridge unnitialized 192.168.1.1/24"}

        Error Trace:    dnsmasq_test.go:77
    Error:      Expected nil, but got: &errors.errorString{s:"No pid file open /tmp/dnsmasq_concuuid.pid: no such file or directory"}

        Error Trace:    dnsmasq_test.go:80
    Error:      Expected nil, but got: &errors.errorString{s:"Process does not exist No pid file open /tmp/dnsmasq_concuuid.pid: no such file or directoryUnable to delete bridge IP bridge error: del ip bridge unnitialized"}

Logs for libsnnet.TestDnsmasq_Negative
        Error Trace:    dnsmasq_test.go:105
    Error:      Expected nil, but got: &errors.errorString{s:"bridge error: create link add dns_testbr operation not permitted"}

        Error Trace:    dnsmasq_test.go:112
    Error:      Expected nil, but got: &errors.errorString{s:"d.Dev.AddIP failed bridge error: add ip bridge unnitialized 192.168.1.1/24"}

        Error Trace:    dnsmasq_test.go:119
    Error:      Expected nil, but got: &errors.errorString{s:"No pid file open /tmp/dnsmasq_concuuid.pid: no such file or directory"}

        Error Trace:    dnsmasq_test.go:130
    Error:      Expected nil, but got: &errors.errorString{s:"d.Start failed d.Dev.AddIP failed bridge error: add ip bridge unnitialized 192.168.1.1/24"}

        Error Trace:    dnsmasq_test.go:132
    Error:      Expected nil, but got: &errors.errorString{s:"No pid file open /tmp/dnsmasq_concuuid.pid: no such file or directory"}

        Error Trace:    dnsmasq_test.go:139
    Error:      Expected nil, but got: &errors.errorString{s:"Process does not exist No pid file open /tmp/dnsmasq_concuuid.pid: no such file or directoryUnable to delete bridge IP bridge error: del ip bridge unnitialized"}

        Error Trace:    dnsmasq_test.go:149
    Error:      Expected nil, but got: &errors.errorString{s:"d.Start failed d.Dev.AddIP failed bridge error: add ip bridge unnitialized 192.168.1.1/24"}

        Error Trace:    dnsmasq_test.go:150
    Error:      Expected nil, but got: &errors.errorString{s:"Process does not exist No pid file open /tmp/dnsmasq_concuuid.pid: no such file or directoryUnable to delete bridge IP bridge error: del ip bridge unnitialized"}

Logs for libsnnet.TestFw_Init
        Error Trace:    firewall_test.go:55
    Error:      Expected nil, but got: &errors.errorString{s:"Error: InitFirewall NAT enable [eth0] exit status 3: iptables v1.6.0: can't initialize iptables table `nat': Permission denied (you must be root)\nPerhaps iptables or your kernel needs to be upgraded.\n"}

Logs for libsnnet.TestFw_Ssh
        Error Trace:    firewall_test.go:69
    Error:      Expected nil, but got: &errors.errorString{s:"Error: InitFirewall NAT enable [eth0] exit status 3: iptables v1.6.0: can't initialize iptables table `nat': Permission denied (you must be root)\nPerhaps iptables or your kernel needs to be upgraded.\n"}

Logs for libsnnet.TestFw_Nat
        Error Trace:    firewall_test.go:95
    Error:      Expected nil, but got: &errors.errorString{s:"Error: InitFirewall NAT enable [eth0] exit status 3: iptables v1.6.0: can't initialize iptables table `nat': Permission denied (you must be root)\nPerhaps iptables or your kernel needs to be upgraded.\n"}

Logs for libsnnet.TestFw_All
exit status 2

Output from stderr
------------------
panic: runtime error: invalid memory address or nil pointer dereference [recovered]
    panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xb code=0x1 addr=0x18 pc=0x4b7ca7]

goroutine 46 [running]:
panic(0x946a80, 0xc82000e0d0)
    /usr/local/go/src/runtime/panic.go:481 +0x3e6
testing.tRunner.func1(0xc820254c60)
    /usr/local/go/src/testing/testing.go:467 +0x192
panic(0x946a80, 0xc82000e0d0)
    /usr/local/go/src/runtime/panic.go:443 +0x4e9
github.com/01org/ciao/networking/libsnnet.(*Firewall).ExtFwding(0x0, 0x1, 0x9f4a88, 0x4, 0x9f4a90, 0x4, 0x0, 0x0)
    github.com/01org/ciao/networking/libsnnet/_test/_obj_test/firewall.go:176 +0x717
github.com/01org/ciao/networking/libsnnet.TestFw_All(0xc820254c60)
    /home/markus/go/src/github.com/01org/ciao/networking/libsnnet/firewall_test.go:151 +0x19b
testing.tRunner(0xc820254c60, 0xe93ae8)
    /usr/local/go/src/testing/testing.go:473 +0x98
created by testing.RunTests
    /usr/local/go/src/testing/testing.go:582 +0x892

@mcastelino Note the panic at the end.

[markdryan]

@mcastelino I should note that I'm running these unit tests as a non root user ( I wanted them to fail to test test-cases). But I guess we shouldn't get the panic.

[tpepper]

The golang folks have close the issue I opened, with the resolution of updating the docs for Go 1.7 instead of changing the code to output to stderr. @markdryan's test-cases change wraps the annoying golang behavior with output of just error output to stderr.