io: Copy leaves file zero bytes in Azure AKS with CIFS — Go1.15 regression

[alhails]

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

$ go version
1.15.2

Does this issue reproduce with the latest release?

Yes (1.15.3)

What operating system and processor architecture are you using?

The issue is reproduced on Azure AKS node (Ubuntu 16.04 kernel 4.15.0-1098-azure)

What did you do?

We have a golang API running in Azure AKS. The initial problem was noticed with file upload via http multipart request. After upgrade to go 1.15, uploaded files were left as zero bytes. Before this, uploads were working fine.

My initial suspicion was that the problem was related to the addition of the copy_file_range syscall in os.File ReadFrom, but also our use of a CIFS file share for our running pod.

I have only been able to reproduce in AKS, not locally.

I've reproduced the issue with a very simple golang code example..

package main

import (
 "fmt"
 "io"
 "os"
)

func main() {
 src, err := os.Open("source.txt")
 if err != nil {
  fmt.Printf("Failed to open file: %s\n", err.Error())
  return
 }

 dst, err := os.Create("dest.txt")
 if err != nil {
  fmt.Printf("Failed to create file: %s\n", err.Error())
  return
 }
 _, err = io.Copy(dst, src)
 if err != nil {
  fmt.Printf("Failed to copy file: %s\n", err.Error())
  return
 }
}

When this is executed on the container file system, the file is copied correctly.
When this is executed on a CIFS volume in the container, the file is created but is left as zero bytes.

I now suspect that the issue is with the kernel or CIFS, so have raised an issue with the team responsible for the azure linux kernel - https://answers.launchpad.net/ubuntu/+source/linux-azure/+question/693837

However I thought I might also raise it here, in case anyone here has any thoughts on this issue.

Thanks

Alastair

[odeke-em]

Thank you for reporting this @alhails!

Kindly paging @tklauser @ianlancetaylor @alexbrainman.

[randall77]

Try Closeing the destination file after the io.Copy. You might also try Sync.
(I don't think either should be necessary, but worth the experiment.)

[alhails]

I've reproduced locally by mounting a CIFS share to my NAS drive(!). I get the same behaviour here ie file is left zero bytes, so maybe the azure kernel is out of the frame?

PS I'm using debian buster (kernel 4.19.0-12-amd64) if this is still relevant.

[alhails]

@randall77 Thanks for the suggestion

I still get the same behaviour (locally on the CIFS share) with...

package main

import (
	"fmt"
	"io"
	"os"
)

func main() {
	src, err := os.Open("source.txt")
	if err != nil {
		fmt.Printf("Failed to open file: %s\n", err.Error())
		return
	}
	defer src.Close()

	dst, err := os.Create("dest.txt")
	if err != nil {
		fmt.Printf("Failed to create file: %s\n", err.Error())
		return
	}
	defer dst.Close()

	_, err = io.Copy(dst, src)
	if err != nil {
		fmt.Printf("Failed to copy file: %s\n", err.Error())
		return
	}

	err = dst.Sync()
	if err != nil {
		fmt.Printf("Failed to sync file: %s\n", err.Error())
		return
	}
}

[tklauser]

Maybe related #42334?

@alhails does io.Copy return any error? Could you try logging what its first return value (written int64) is?

[alhails]

With amended copy...

	written, err := io.Copy(dst, src)
	if err != nil {
		fmt.Printf("Failed to copy file: %s\n", err.Error())
		return
	}
	fmt.Printf("written: %d\n", written)

I get the same output for both local disk (where file is written correctly) and on CIFS (where is left empty)

written: 4

PS my test source.txt just contains "123"

PPS There is no error returned

[ianlancetaylor]

I agree that it sounds like a problem with the copy_file_range system call. If possible, try changing the standard library to initialize copyFileRangeSupported to 0 in src/internal/poll/copy_file_range_linux.go. If that fixes the problem, then it's definitely copy_file_range.

This is problematic, though, since we do want to use copy_file_range but we don't want to break people unexpectedly like this. Please keep us updated on the question you filed. It may be necessary to check whether a file is on CIFS before using copy_file_range, assuming there is some way that we can check that at all.

CC @acln0

[ianlancetaylor]

Tentatively marking as a release blocker for 1.16, since we don't want this kind of surprising breakage in Go. We can remove the label if we discover that the problem only occurs on some limited kernel range or something.

[alhails]

I reproduced the failure from source (go1.15.4) and then made the tweak you suggested and the problem went away.

-var copyFileRangeSupported int32 = 1 // accessed atomically
+var copyFileRangeSupported int32 = 0 // accessed atomically

If this confirms it is an issue with copy_file_range, then is this a linux kernel issue? I would like to update my other ticket on https://answers.launchpad.net/ubuntu/+source/linux-azure/+question/693837

[gopherbot]

Change https://golang.org/cl/267958 mentions this issue: os, internal/poll: don't use copy_file_range on CIFS destinations

[acln0]

It's unfortunate that it doesn't seem to work for CIFS, where it could have helped significantly.

On my home system, I have a SMB share that I tested the program against. Everything worked correctly. My SMB server is FreeBSD 11.2, and my client is Debian 5.8.0-2-amd64. I don't know that we can draw any conclusion from this. It is also unclear to me how exactly CIFS and SMB differ, so perhaps this test I performed is not informative at all. They do differ at least in magic file system numbers, as far as man 2 statfs tells us (but more on this later).

This looks like a kernel bug, but even if we knew for a fact that this is a kernel bug, and we knew the precise range of affected kernels, trying to detect those specific kernel versions from within poll.CopyFileRange seems exceedingly difficult, since unlike other cases, where the error appeared in the form of a specific new errno value from copy_file_range (#40731, #40893, #42334), we do not seem to have the luxury of such a visible error here. It seems like no error is reported, but the results are silently wrong.

As for detecting file systems, I think we could call statfs and look for CIFS_MAGIC_NUMBER in the f_type field, but that seems rather heavy handed. (Sidenote: In the test I ran on my own system, I got SMB2_MAGIC_NUMBER when I interrogated the destination file path using the statfs system call, so perhaps my test is not relevant at all.)

In any case, I have sent CL 267958 for testing and for discussion. I'm not sure that is the right approach at all, but I think it's worth at least a try and a discussion.

@alhails Can you please try https://go-review.googlesource.com/c/go/+/267958? Can you also try it with the arguments in reverse?

@ianlancetaylor What do you think about calling statfs this way?