Does this issue reproduce with the latest release?

Can you please test with Go 1.15.7 or 1.16beta1. Thank you

Have you tried running your program under the race detector? See https://blog.golang.org/race-detector .

@davecheney We'll go up to 1.16beta1 and then if that doesn't produce a crash we'll also run it with the race detector. Any other tricks we need to do to get a core dump in case that would help?

So it looks to me like we crashed on: MOVQ 0x20(SP), AX

That almost certainly means the thing being called corrupted the stack pointer somehow. This is the first use of SP after the call. Do you know what code it called?

You show the stack trace, but what was the error that was printed above the trace ("segmentation fault at ..." or something)?

That's a good question. I didn't get that from our tester and the system has been cleaned up since. If we can recreate the crash I will be sure they capture it this time.

Do you know what code it called?

Yes, the thing being called is Lumberjack's logger's write function:

// Write implements io.Writer.  If a write would cause the log file to be larger
// than MaxSize, the file is closed, renamed to include a timestamp of the
// current time, and a new log file is created using the original log file name.
// If the length of the write is greater than MaxSize, an error is returned.
func (l *Logger) Write(p []byte) (n int, err error) {
	l.mu.Lock()
	defer l.mu.Unlock()

	writeLen := int64(len(p))
	if writeLen > l.max() {
		return 0, fmt.Errorf(
			"write length %d exceeds maximum file size %d", writeLen, l.max(),
		)
	}

	if l.file == nil {
		if err = l.openExistingOrNew(len(p)); err != nil {
			return 0, err
		}
	}

	if l.size+writeLen > l.max() {
		if err := l.rotate(); err != nil {
			return 0, err
		}
	}

	n, err = l.file.Write(p)
	l.size += int64(n)

	return n, err
}

I don't see anything special here that should be corrupting the stack. I also thought the stack was generally inaccessible to Go programs and isn't generally susceptible to corruption.

Any other tricks we need to do to get a core dump in case that would help?

try env GOTRACEBACK=crash

Any other tricks we need to do to get a core dump in case that would help?

try env GOTRACEBACK=crash

Isn't that what happens when the code calls debug.SetTraceback("crash")?

I have finally been able to consistently reproduce our code crashing. This time though it crashes on:

> [unrecovered-panic] runtime.fatalpanic() /home/phuser/goroot1.16/src/runtime/panic.go:1190 (hits goroutine(768):1 total:1) (PC: 0x44aa60)
Warning: debugging optimized function
	runtime.curg._panic.arg: interface {}(string) "runtime error: invalid memory address or nil pointer dereference"

The block of code it crashes in does not seem like it should be possible to crash in this way:

		if p.h == nil {
			p.h = h
		}

		plog.LogDebug(class, "ready",
			zap.Int64("idx", p.idx),
			zap.Int("num", num),
crash here >>>			zap.Int("remaining", remaining),
			zap.Int("offset", offset),
		)

Because I can consistently crash now, I ran under dlv with the race detector on, and we have no races prior to the crash. However, this is interesting:

(dlv) p &remaining
(*int)(0xc01542b008)
(dlv) p remaining
131072
(dlv) p num
36
(dlv) p p
*(unreadable read out of bounds)
(dlv) p &p
("**github.ibm.com/Spectrum-Protect/Phusion/phusion.omittedType")(0xbeef0000)
(dlv)

It seems impossible to me that our code should be able to do this given that we pass the if statement which dereferences the pointer that is now pointing at 0xbeef0000. However, interestingly to me clobberfree sets memory to 0xdeadbeef which is suggestive of some sort of overlay somewhere that bleeds into our page pointer. Asking delve to emit goroutines also looks mangled, as there's several entries like this:

  Goroutine 852 - User: :0 ??? (0xe9fd9c) (thread 98019)
  Goroutine 853 - User: :0 ??? (0xe9fd9c) (thread 98024)

Given that the race detector didn't trip leading up to the crash, I really don't know where to take this next.

  	zap.Int64("pageIdx", page.pageIdx),

If this is the last reference to page in your function, then it is quite possible that the pointer is overwritten / stale by the point where the crash happens.
It's not clear from your output whether you're debugging an optimized binary or not. If dlv compiled your binary for you then I think it turns optimizations off, so maybe an overwrite couldn't happen? In which case, maybe the weird address does mean something.

However, interestingly to me clobberfree sets memory to 0xdeadbeef

Did you explicitly request clobberfree? It isn't normally run unless you set GODEBUG=clobberfree=1.

It's not the last reference, there's many more references beyond that line. The binary is compiled with go build -race and then run with dlv exec, I wasn't sure how to turn on the race detector when delve builds the code.

I did find some sequence of events in our code and how we receive data from FUSE, along with a subtle bug in our code which leads to a situation I didn't think possible with Go. The function we crash in goes roughly like this

Call helper function to find pointer to appropriate data structure or build a new one
Set reference to the receiver of the crashing function in the data structure from above if not set
Emit the logging message above
Perform operations on the data input into the function that crashed and store results into the data structure obtained above
Perform some tracking operations data structure
Loop back if there's more work to be done

The subtle bug in our code lies in the helper function which prepares a blank data structure if there isn't a matching one already. What we weren't doing was heading down the path that prepared the blank data structure in some situations, leading the crashing function to think it had a valid structure when it did not.

Here's the situation I didn't think possible: the helper function returns several pointers, including this necessary data structure. When this data structure creation path wasn't taken, the page output variable wasn't assigned by the helper function, which I had thought would result in return of a nil pointer. When I fix the helper function to always assign a valid data structure, the crash goes away.

So now my question is, when you have a function of the form:

func (t *T) helper(... input params) (page *ioPage, t2 *T2, ... err error)

Shouldn't page and t2 be nil until otherwise assigned? By naming them in the function declaration we should be able to rely on naked returns throughout the function always either returning the last assigned value or nil if never assigned. It seems like we're getting garbage that always equals 0xbeef000 for this data structure and the assigned result in the crashing function for t2 is always unreadable when the creation path isn't taken.

Did you explicitly request clobberfree? It isn't normally run unless you set GODEBUG=clobberfree=1.

No, I didn't dig too deep in that so I didn't realize it was behind an environment variable. Wonder where the beef is coming from then?

The binary is compiled with go build -race and then run with dlv exec, I wasn't sure how to turn on the race detector when delve builds the code.

Ok, that's an optimized binary. Try using go build -race -gcflags=-N and see if that changes anything.

So now my question is, when you have a function of the form:

func (t *T) helper(... input params) (page *ioPage, t2 *T2, ... err error)
Shouldn't page and t2 be nil until otherwise assigned?

Yes.

Can you share the code and the assembly for that helper function?

Ok, that's an optimized binary. Try using go build -race -gcflags=-N and see if that changes anything.

I will give that a try later on this afternoon.

Can you share the code and the assembly for that helper function?

I'll need to explore if that's a possibility and what approvals I might need. I will get back soon hopefully on that.

We need to work on paring this down for a minimal recreation so that we don't inadvertently expose confidential information before we can do that. I'm booked for the rest of this sprint, however we'll begin next week with our next sprint, so hopefully in the next few weeks we'll have what you're requesting ready.

Also, nothing changed when I used the gcflags argument.