Go test silently segfaults

[ocket8888]

What version of Go are you using (go version)?

$ go version
go version go1.15.5 linux/amd64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/ocket8888/.cache/go-build"
GOENV="/home/ocket8888/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/ocket8888/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/ocket8888"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/lib/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/lib/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build153052688=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I wrote a test that segfaults. Looks something like:

import "strings"
import "testing"
import "github.com/apache/trafficcontrol/lib/go-tc"

func TestSomething(t *testing.T) {
	var ptr *tc.Alerts
	t.Log("About to do something")
	result, err := DoSomething() // Makes an HTTP request
	t.Log("alerts: %s", strings.Join(ptr.ToStrings(), ", "))
	if err != nil {
		t.Fatal("err was non-nil")
	}
	//...
}

What did you expect to see?

SIGSEGV in the output. Obviously because ptr is never assigned, it's nil and so ptr.ToStrings should segfault. That was a typo - but it was hard for me to find, because:

What did you see instead?

The log line never appears in the test output, and neither did any indication that a segfault had occurred. The test run didn't even fail, only other runs (called with t.Run in an outer scope) failed to run because of data inter-dependencies between the tests.

[randall77]

The log line never appears in the test output

Which log line are you talking about? The "About to do something" should appear, but the "alerts:" one should not, as the fault happens before the call to t.Log happens.

Here's my simple test:

package p

import "testing"

func TestFoo(t *testing.T) {
	var p *int
	t.Log("A")
	t.Log("B:", *p)
}

This prints

% go test issue42816_test.go
--- FAIL: TestFoo (0.00s)
    issue42816_test.go:7: A
panic: runtime error: invalid memory address or nil pointer dereference [recovered]
	panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x10f8c3f]

goroutine 19 [running]:
testing.tRunner.func1(0xc0000ba100)
	/usr/local/go/src/testing/testing.go:874 +0x3a3
panic(0x111c8e0, 0x1232f50)
	/usr/local/go/src/runtime/panic.go:679 +0x1b2
command-line-arguments.TestFoo(0xc0000ba100)
	/Users/khr/gowork/issue42816_test.go:8 +0x6f
testing.tRunner(0xc0000ba100, 0x114f8b0)
	/usr/local/go/src/testing/testing.go:909 +0xc9
created by testing.(*T).Run
	/usr/local/go/src/testing/testing.go:960 +0x350
FAIL	command-line-arguments	0.139s
FAIL

[ocket8888]

The second log line. I don't expect it to appear; I do expect to see that panic trace, which did not occur.

[kennygrant]

The panic due to use of a nil pointer field would normally be printed. See this standalone example taking the bits out of the tc library you're using (and fixing the use of t.Log with a formatting param).

The call to ToStrings itself is not to blame though (it's fine to call a method on a nil pointer), it's trying to use a field on the nil pointer which would panic:

https://play.golang.org/p/HuxDtwJaYWv

var ptr *Alerts
t.Log("About to do something")
t.Logf("call nil pointer method (ok): %s", strings.Join(ptr.ToStringsDirect(), ", "))
t.Log("about to call nil fields and panic")
t.Logf("call nil fields (panic): %s", strings.Join(ptr.ToStrings(), ", "))

outputs:

=== RUN   TestSomething
    prog.go:10: About to do something
    prog.go:11: call nil pointer method (ok): 1, 2
    prog.go:12: about to call nil fields and panic
--- FAIL: TestSomething (0.00s)
panic: runtime error: invalid memory address or nil pointer dereference [recovered]
	panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x8 pc=0x4cb129]

Perhaps try moving the log line before DoSomething in your test or removing DoSomething for now, I suspect it is causing the test to time out and not appear.

[randall77]

@ocket8888 So can you show us a complete program, or the complete output it prints, or both? That would help a lot.

[ocket8888]

Kind of? It's quite large, and I'm not sure how much of it is required to reproduce the problem.

This is a test meant to go in the github.com/apache/trafficcontrol/traffic_ops/testing/api/v3 package. It's called using that package's WithObjs function which initializes a bunch of data for me - which is why the function name doesn't look like a test; it's not meant to be run on its own.

That DoSomething call is actually a TOSession.UpdateServerByIDWithHdr where TOSession is a github.com/apache/trafficcontrol/traffic_ops/v3-client.Session structure. It does not cause the tests to time out. When I replace the log line after the comment // This log line never appears... with one that uses alerts instead of alertsPtr, the tests pass successfully. With alertsPtr the tests fail with no output.

package v3

import (
	"errors"
	"fmt"
	"net/http"
	"net/url"
	"strconv"
	"strings"
	"testing"
	"time"

	"github.com/apache/trafficcontrol/lib/go-tc"
	"github.com/apache/trafficcontrol/lib/go-util"
)

func TryToRemoveLastServerInDeliveryService(t *testing.T) {
	cdns, _, err := TOSession.GetCDNsWithHdr(nil)
	if err != nil {
		t.Fatalf("Could not fetch CDNs: %v", err)
	}
	if len(cdns) < 1 {
		t.Fatal("Need at least one CDN to test removing the last server from a Delivery Service")
	}

	cdnID := cdns[0].ID

	user, _, err := TOSession.GetUserCurrentWithHdr(nil)
	if err != nil {
		t.Fatalf("Could not fetch current user: %v", err)
	}
	if user == nil {
		t.Fatalf("Current user is null")
	}
	if user.TenantID == nil {
		t.Fatalf("Current user has null Tenant ID")
	}

	types, _, err := TOSession.GetTypesWithHdr(nil, "deliveryservice")
	if err != nil {
		t.Fatalf("Could not fetch Types: %v", err)
	}
	if len(types) < 1 {
		t.Fatal("Need at least one Type with 'useInTable' of 'deliveryservice' to create a Delivery Service")
	}
	dsTypeID := types[0].ID

	xmlid := fmt.Sprintf("test-%d", time.Now().Unix())
	ds := tc.DeliveryServiceNullableV30{
		DeliveryServiceNullableV15: tc.DeliveryServiceNullableV15{
			DeliveryServiceNullableV14: tc.DeliveryServiceNullableV14{
				DeliveryServiceNullableV13: tc.DeliveryServiceNullableV13{
					DeliveryServiceNullableV12: tc.DeliveryServiceNullableV12{
						DeliveryServiceNullableV11: tc.DeliveryServiceNullableV11{
							Active:                   new(bool),
							AnonymousBlockingEnabled: new(bool),
							CDNID:                    &cdnID,
							DisplayName:              util.StrPtr("test"),
							DSCP:                     new(int),
							GeoLimit:                 new(int),
							GeoProvider:              new(int),
							InitialDispersion:        new(int),
							IPV6RoutingEnabled:       new(bool),
							LogsEnabled:              new(bool),
							MissLat:                  new(float64),
							MissLong:                 new(float64),
							OrgServerFQDN:            util.StrPtr("https://example.com"),
							Protocol:                 new(int),
							QStringIgnore:            new(int),
							RangeRequestHandling:     new(int),
							RegionalGeoBlocking:      new(bool),
							Signed:                   false,
							TenantID:                 user.TenantID,
							TypeID:                   &dsTypeID,
							XMLID:                    &xmlid,
						},
					},
				},
			},
		},
	}
	*ds.InitialDispersion = 1
	*ds.Active = true
	ds, _, err = TOSession.CreateDeliveryServiceV30(ds)
	if err != nil {
		t.Fatalf("Failed to create Delivery Service: %v", err)
	}
	if ds.ID == nil {
		t.Fatal("Delivery Service had null/undefined ID after creation")
	}

	cacheGroups, _, err := TOSession.GetCacheGroupsNullableWithHdr(nil)
	if err != nil {
		t.Fatalf("Could not fetch Cache Groups: %v", err)
	}
	if len(cacheGroups) < 1 {
		t.Fatal("Need at least one Cache Group for testing")
	}
	if cacheGroups[0].ID == nil {
		t.Fatal("Got a Cache Group for testing with null or undefined ID")
	}
	cacheGroupID := *cacheGroups[0].ID

	profile := tc.Profile{
		CDNID:       cdnID,
		Description: "test",
		Name:        xmlid,
		Type:        "ATS_PROFILE",
	}
	alerts, _, err := TOSession.CreateProfile(profile)
	t.Logf("Alerts from creating Profile: %s", strings.Join(alerts.ToStrings(), ", "))
	if err != nil {
		t.Fatalf("Failed to create new Profile in CDN #%d: %v", cdnID, err)
	}
	profiles, _, err := TOSession.GetProfileByNameWithHdr(profile.Name, nil)
	if err != nil {
		t.Fatalf("Could not fetch Profile '%s' after creation: %v", profile.Name, err)
	}
	if len(profiles) != 1 {
		t.Fatalf("Expected exactly one Profile named '%s'; got: %d", profile.Name, len(profiles))
	}
	profile = profiles[0]

	physLocs, _, err := TOSession.GetPhysLocationsWithHdr(nil, nil)
	if err != nil {
		t.Fatalf("Could not fetch Physical Locations: %v", err)
	}
	if len(physLocs) < 1 {
		t.Fatal("Need at least one Physical Location")
	}
	physLoc := physLocs[0]

	statuses, _, err := TOSession.GetStatusesWithHdr(nil)
	if err != nil {
		t.Fatalf("Could not fetch Statuses: %v", err)
	}
	if len(statuses) < 1 {
		t.Fatal("Need at least one Status")
	}

	var statusID int
	var badStatusID int
	found := false
	foundBad := false
	for _, status := range statuses {
		if status.Name == "ONLINE" || status.Name == "REPORTED" {
			statusID = status.ID
			found = true
			if foundBad {
				break
			}
		} else {
			badStatusID = status.ID
			foundBad = true
			if found {
				break
			}
		}
	}
	if !found || !foundBad {
		t.Fatal("Need at least one status with the name 'ONLINE' or 'REPORTED' and at least one status with neither of those names")
	}

	types, _, err = TOSession.GetTypesWithHdr(nil, "server")
	if err != nil {
		t.Fatalf("Could not fetch Types: %v", err)
	}
	if len(types) < 1 {
		t.Fatal("Need at least one Type with 'useInTable' of 'server' to create a server")
	}
	serverTypeID := types[0].ID

	server := tc.ServerV30{
		CommonServerProperties: tc.CommonServerProperties{
			CachegroupID:   &cacheGroupID,
			CDNID:          &cdnID,
			DomainName:     &xmlid,
			HostName:       &xmlid,
			HTTPSPort:      util.IntPtr(443),
			PhysLocationID: &physLoc.ID,
			ProfileID:      &profile.ID,
			RevalPending:   new(bool),
			StatusID:       &statusID,
			TCPPort:        util.IntPtr(80),
			TypeID:         &serverTypeID,
			UpdPending:     new(bool),
		},
		Interfaces: []tc.ServerInterfaceInfo{
			{
				Name: "eth0",
				IPAddresses: []tc.ServerIPAddress{
					{
						Address:        "198.51.100.1",
						ServiceAddress: true,
					},
				},
			},
		},
	}
	alerts, _, err = TOSession.CreateServerWithHdr(server, nil)
	if err != nil {
		t.Fatalf("Failed to create server: %v - alerts: %s", err, strings.Join(alerts.ToStrings(), ", "))
	}
	params := url.Values{}
	params.Set("hostName", *server.HostName)
	servers, _, err := TOSession.GetServersWithHdr(&params, nil)
	if err != nil {
		t.Fatalf("Could not fetch server after creation: %v", err)
	}
	if len(servers.Response) != 1 {
		t.Fatalf("Expected exactly 1 server with hostname '%s'; got: %d", *server.HostName, len(servers.Response))
	}
	server = servers.Response[0]
	if server.ID == nil {
		t.Fatal("Server had null/undefined ID after creation")
	}

	_, _, err = TOSession.CreateDeliveryServiceServers(*ds.ID, []int{*server.ID}, true)
	if err != nil {
		t.Fatalf("Failed to assign server to Delivery Service: %v", err)
	}

	_, _, err = TOSession.CreateDeliveryServiceServers(*ds.ID, []int{}, true)
	if err == nil {
		t.Error("Didn't get expected error trying to remove the only server assigned to a Delivery Service")
	} else {
		t.Logf("Got expected error trying to remove the only server assigned to a Delivery Service: %v", err)
	}

	_, _, err = TOSession.DeleteDeliveryServiceServer(*ds.ID, *server.ID)
	if err == nil {
		if err == nil {
			t.Error("Didn't get expected error trying to remove the only server assigned to a Delivery Service")
		} else {
			t.Logf("Got expected error trying to remove the only server assigned to a Delivery Service: %v", err)
		}
	}

	alerts, _, err = TOSession.DeleteServerByID(*server.ID)
	t.Logf("Alerts from deleting server: %s", strings.Join(alerts.ToStrings(), ", "))
	if err == nil {
		t.Error("Didn't get expected error trying to delete the only server assigned to a Delivery Service")
	} else {
		t.Logf("Got expected error trying to delete the only server assigned to a Delivery Service: %v", err)
	}

	alerts, _, err = TOSession.AssignDeliveryServiceIDsToServerID(*server.ID, []int{}, true)
	t.Logf("Alerts from removing Delivery Service from server: %s", strings.Join(alerts.ToStrings(), ", "))
	if err == nil {
		t.Error("Didn't get expected error trying to remove a Delivery Service from the only server to which it is assigned")
	} else {
		t.Logf("Got expected error trying to remove a Delivery Service from the only server to which it is assigned: %v", err)
	}

	server.StatusID = &badStatusID
	putRequest := tc.ServerPutStatus{
		Status:        util.JSONNameOrIDStr{ID: &badStatusID},
		OfflineReason: util.StrPtr("test"),
	}
	alertsPtr, _, err := TOSession.UpdateServerStatus(*server.ID, putRequest)
	if alertsPtr != nil {
		t.Logf("Alerts from updating server status: %s", strings.Join(alertsPtr.ToStrings(), ", "))
	}
	if err == nil {
		t.Error("Didn't get expected error trying to put server into a bad state when it's the only one assigned to a Delivery Service")
	} else {
		t.Logf("Got expected error trying to put server into a bad state when it's the only one assigned to a Delivery Service: %v", err)
	}

	alerts, _, err = TOSession.UpdateServerByIDWithHdr(*server.ID, server, nil)
	// This log line never appears in output, and nothing beyond it appears to be executed.
	t.Logf("Alerts from updating server status: %s", strings.Join(alertsPtr.ToStrings(), ", "))
	if err == nil {
		t.Error("Didn't get expected error trying to put server into a bad state when it's the only one assigned to a Delivery Service")
	} else {
		t.Logf("Got expected error trying to put server into a bad state when it's the only one assigned to a Delivery Service: %v", err)
	}

	oldID := *server.ID
	server.HostName = util.StrPtr(xmlid + "-quest")
	server.ID = nil
	alerts, _, err = TOSession.CreateServerWithHdr(server, nil)
	if err != nil {
		t.Fatalf("Failed to create server: %v - alerts: %s", err, strings.Join(alerts.ToStrings(), ", "))
	}
	params.Set("hostName", *server.HostName)
	servers, _, err = TOSession.GetServersWithHdr(&params, nil)
	if err != nil {
		t.Fatalf("Could not fetch server after creation: %v", err)
	}
	if len(servers.Response) != 1 {
		t.Fatalf("Expected exactly 1 server with hostname '%s'; got: %d", *server.HostName, len(servers.Response))
	}
	server = servers.Response[0]
	if server.ID == nil {
		t.Fatal("Server had null/undefined ID after creation")
	}

	_, _, err = TOSession.CreateDeliveryServiceServers(*ds.ID, []int{*server.ID}, true)
	if err == nil {
		t.Error("Didn't get expected error trying to replace the last server assigned to a Delivery Service with a server in a bad state")
	} else {
		t.Logf("Got expected error trying to replace the last server assigned to a Delivery Service with a server in a bad state: %v", err)
	}

	// Cleanup
	resp, err := TOSession.DeleteDeliveryService(strconv.Itoa(*ds.ID))
	if err != nil {
		t.Errorf("Failed to delete Delivery Service: %v", err)
	} else {
		t.Logf("Alerts from deleting Delivery Service: %v", resp.Alerts)
	}

	alerts, _, err = TOSession.DeleteServerByID(*server.ID)
	t.Logf("Alerts from deleting a server: %s", strings.Join(alerts.ToStrings(), ", "))
	if err != nil {
		t.Errorf("Failed to delete server: %v", err)
	}

	alerts, _, err = TOSession.DeleteServerByID(oldID)
	t.Logf("Alerts from deleting a server: %s", strings.Join(alerts.ToStrings(), ", "))
	if err != nil {
		t.Errorf("Failed to delete server: %v", err)
	}

	alerts, _, err = TOSession.DeleteProfileByID(profiles[0].ID)
	t.Logf("Alerts from deleting Profile: %s", strings.Join(alerts.ToStrings(), ", "))
	if err != nil {
		t.Errorf("Failed to clean up Profile: %v", err)
	}
}

[ocket8888]

You can see the test in my fork of apache/trafficcontrol at this commit fails silently. The test output is pretty noisy, but when run you can see that it only outputs log lines up until that problematic line and then nothing after that. Not even a segfault message.

Then I fix it in the next commit to that branch by changing alertsPtr to alerts and not much else.

[randall77]

I cloned your fork and couldn't get it to work:

$ git clone https://github.com/ocket8888/trafficcontrol
... some output ...
$ cd trafficcontrol
$ git checkout e03f07c3e4e25f1bb7b36987a5c6453d01d8af3c
$ cd traffic_ops/testing/api/v3
$ go test
# _/Users/khr/gowork/issue42816/trafficcontrol/traffic_ops/testing/api/v3
package _/Users/khr/gowork/issue42816/trafficcontrol/traffic_ops/testing/api/v3 (test)
	imports github.com/apache/trafficcontrol/lib/go-log: cannot find package "github.com/apache/trafficcontrol/lib/go-log" in any of:
	/usr/local/go/src/github.com/apache/trafficcontrol/lib/go-log (from $GOROOT)
	/Users/khr/gopath/src/github.com/apache/trafficcontrol/lib/go-log (from $GOPATH)
FAIL	_/Users/khr/gowork/issue42816/trafficcontrol/traffic_ops/testing/api/v3 [setup failed]

Making it use modules so it downloads its dependencies:

$ cd ../../../..
$ go mod init foo
$ cd traffic_ops/testing/api/v3
$ go test
go: finding module for package github.com/apache/trafficcontrol/lib/go-util
go: finding module for package github.com/apache/trafficcontrol/traffic_ops/testing/api/utils
go: finding module for package github.com/apache/trafficcontrol/lib/go-rfc
go: finding module for package github.com/apache/trafficcontrol/traffic_ops/traffic_ops_golang/auth
go: finding module for package github.com/apache/trafficcontrol/lib/go-log
go: finding module for package github.com/apache/trafficcontrol/lib/go-tc
go: finding module for package github.com/apache/trafficcontrol/traffic_ops/testing/api/config
go: finding module for package github.com/apache/trafficcontrol/traffic_ops/v3-client
go: finding module for package code.google.com/p/go.net/publicsuffix
# foo/traffic_ops/testing/api/v3
/Users/khr/gopath/pkg/mod/github.com/apache/trafficcontrol@v1.1.3/traffic_ops/client/traffic_ops.go:21:2: cannot find module providing package code.google.com/p/go.net/publicsuffix: unrecognized import path "code.google.com/p/go.net/publicsuffix": parse https://code.google.com/p/go.net/publicsuffix?go-get=1: no go-import meta tags (meta tag github.com/golang/go did not match import path code.google.com/p/go.net/publicsuffix)
FAIL	foo/traffic_ops/testing/api/v3 [setup failed]

Not sure what to do at this point to get it working. Could you make us some reproducible instructions? Step by step? Show us what output you get for each command you run?

[ocket8888]

Oh boy.

So, the first thing you need to do is - instead of using modules, because that's a whole chore in itself that we're working on - clone that into $GOPATH/src/github.com/apache/trafficcontrol - not $GOPATH/src/github.com/ocket8888/trafficcontrol. It's a fork of the apache project for the express purpose of contributing to that project. It's not meant to be used as though it were its own package.

Next, because those tests are integration tests between the Traffic Ops REST API server and our Go client for it, you need to get Traffic Ops running with a backing database. The simplest way to do that is using the development environment:

cd "$GOPATH/src/github.com/apache/trafficcontrol/infrastructure/cdn-in-a-box"
make
docker-compose -f docker-compose.yml -f docker-compose.readiness.yml build
docker-compose -f docker-compose.yml -f docker-compose.readiness.yml -f docker-compose.expose-ports.yml up -d
docker-compose logs -f readiness

... and at that point, wait for the readiness container to exit, signalling that the environment is ready. It's spinning up a fair bit more services than you actually need, but to bring up less services is actually harder. Plus, this has the advantage of requiring only gnu-make, (POSIX make probably works too), docker and docker-compose, whereas the actual process has thousands of Perl packages, postgresql, go, and Python3 as dependencies.

Okay, now you're ready to run the tests - but you still need to create a configuration file for the tests. Instructions on how to do that are in the dev documentation, but here's what I use to connect with the default CDN-in-a-Box environment that you just set up above:

{
	"default": {
		"logLocations": {
			"debug": "stderr",
			"error": "stderr",
			"event": "stderr",
			"info": "stderr",
			"warning": "stderr"
		},
		"includeSystemTests": true
	},
	"trafficOps": {
		"password": "twelve12",
		"URL": "https://localhost:6443",
		"users": {
			"admin": "admin",
			"disallowed": "disallowed",
			"extension": "extension",
			"federation": "federation",
			"operations": "operations",
			"portal": "portal",
			"readOnly": "readOnly"
		}
	},
	"trafficOpsDB": {
		"dbname": "traffic_ops",
		"description": "Why does this field even exist?",
		"hostname": "localhost",
		"password": "twelve",
		"port": "5432",
		"type": "Pg",
		"user": "traffic_ops"
	},
	"noPerl": false,
	"noISO": false
}

saved in e.g. traffic-ops-test.json then you pass it in by running go test --cfg ./traffic-ops-test.json . which must be run from within $GOPATH/src/github.com/apache/trafficcontrol/traffic_ops/testing/api/v3 - idk why, I've just had problems trying to point it at any configuration file that isn't in the current directory when testing.

[gopherbot]

Timed out in state WaitingForInfo. Closing.

(I am just a bot, though. Please speak up if this is a mistake or you have the requested information.)