Sometimes logs cannot be trusted

The other day I spent way too much time debugging an issue where a temporary file I had created couldn’t be moved to its proper location after being uploaded. At first I thought the issue was related to the temporary file being created on a different mount point compared to where I wanted it moved to (I’ve heard that there might be problems if mount points use different file systems and stuff like that), but the error message invalid argument told me that this was something else.

These are the steps I performed in order to receive and store the file being sent:

1. Receive a message (via TCP socket) indicating a file transfer

All messages contain some basic information, which is sent as a struct:

type Message struct {
	Command    MessageType // uint8 "enum"
	Version    uint8
	DataLength uint64
	Text       [64]byte
}

2. Create a temporary file

// Create a temporary file named `upload_<random-number>.tmp` in the working directory
tmpFile, err := os.CreateTemp(workdir, "upload_*.tmp")
if err != nil {
    return fmt.Errorf("receiveFile: %w", err)
}

3. Read bytes from the socket and dump them into the temp file

bytesToRead := msg.DataLength
buf := make([]byte, 1024)

for bytesToRead > 0 {
    bytesRead, err := c.Read(buf)
    if err != nil {
        return fmt.Errorf("receiveFile: %w", err)
    }
    tmpBytesWritten, err := tmpFile.Write(buf[:bytesRead])
    if tmpBytesWritten != bytesRead {
        return fmt.Errorf("receiveFile: Bytes written to tmp file (%d) did not match...")
    }

    bytesToRead -= uint64(bytesRead)
}

At this stage I also made sure to call tmpFile.Sync() and tmpFile.Close() to be certain that all contents were properly written to disk before I tried to move the file.

4. Move the temporary file to its proper location

This is where things go bad. For those of you who are used to handle fixed size data, the bug will be quite obvious.

// copy filename from message and make sure there are no path separators in the filename
_, filename := filepath.Split(string(msg.Text[:]))
dstFile := filepath.Join(workdir, filename)

err = os.Rename(tmpFile.Name(), dstFile)
if err != nil {
    return fmt.Errorf("receiveFile: LinkError: %v", lerr)
}

When I ran this, I got the following error: Error: processMessage: receiveFile: LinkError: rename ...workdir/upload_2381928076.tmp .../workdir/testfile.txt: invalid argument. Since the tmpFile was created and the Name() method returned the correct name of that file in the working directory, I assumed that the issue was related to the dstFile value. However, the logged path to the destination file was correct, and I even logged the dstFile string by itself before I used it in filepath.Join() - again, everything looked correct.

The issue here is not specific to Go in any way. In fact, the exact same thing might have happened in C/C++ as well. The thing I did wrong, was to copy all the bytes in msg.Text into a string in order to get the filename. Even the trailing zeroes.

The result of this was that the filename variable contained the value {'t', 'e', 's', 't', 'f', 'i', 'l', 'e', '.', 't', 'x', 't', <nil>, <nil>, <nil>, ...}, which prints like testfile.txt, but really is something else. In this case, the string was passed on to the function os.Rename() which, as we know, was complaining about an invalid argument. It turns out that it was right (as is usually the case).

Printing the string as a slice of bytes, or calling len(filename) // 64 will help you spot issues like this. The standard output/logs however, cannot be trusted to tell the truth.

This was a great opportunity to feel a bit stupid and reflect on the fact that as a backend web developer, I’m quite spoiled with getting properly formatted strings handed to me.

My quick fix for this was to add a function to clean up the filename and return a properly formatted string.

// cleanByteString copies the leading non-zero bytes from a []byte into a string
func CleanByteString(byteStr []byte) string {
	for i, b := range byteStr {
		if b == 0 {
			return string(byteStr[0:i])
		}
	}

	return string(byteStr)
}