Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

io/ioutil: WriteFile does not write content to file #14491

Closed
TheHippo opened this issue Feb 24, 2016 · 16 comments
Closed

io/ioutil: WriteFile does not write content to file #14491

TheHippo opened this issue Feb 24, 2016 · 16 comments
Milestone

Comments

@TheHippo
Copy link

Using Go 1.5.3 on Linux/amd64:

Writing a file like:

err := ioutil.WriteFile("temp", []byte("foo"), 0644)
if err != nil {
    // error handling
}
// read "temp"

Reading the file content of temp immediately after writing it sometimes indicates the content hasn't been written to the file. Looking at the source code of WriteFile it seems like a call to Sync() is missing.

P.S.: Tested with larger content.

@ianlancetaylor
Copy link
Contributor

Please show us a complete test case that reproduces the problem.

It is never necessary to call Sync on a stable system. On GNU/Linux calling Sync just calls fsync.

@ianlancetaylor ianlancetaylor added this to the Go1.7 milestone Feb 24, 2016
@odeke-em
Copy link
Member

@TheHippo to complete your example where atleast the paths match I've written http://play.golang.org/p/v9Dd3dJYMH -- content shown below.
However, I cannot reproduce the bug you reported on Darwin nor on Linux.

package main

import (
    "bytes"
    "fmt"
    "io/ioutil"
    "log"
    "os"
)

func reproTrial(path string, content []byte) error {
    err := ioutil.WriteFile(path, content, 0644)
    if err != nil {
        return err
    }

    defer func() {
        _ = os.RemoveAll(path)
    }()

    retrieved, err := ioutil.ReadFile(path)
    if err != nil {
        return err
    }

    if !bytes.Equal(retrieved, content) {
        return fmt.Errorf("file %q content doesn't match, read %s expected %s\n", path, retrieved, content)
    }
    return nil
}

func main() {
    outfilePath := "temp"
    content := []byte("foo")

    if err := reproTrial(outfilePath, content); err != nil {
        log.Fatal(err)
    }
}

@hamaxx
Copy link
Contributor

hamaxx commented Feb 24, 2016

I can't reproduce either (Ubuntu 12.04 ssd, Amazon Linux EBS and ephemeral).

package main

import (
    "bytes"
    "io/ioutil"
    "log"
    "strconv"
)

func main() {

    for i := 0; i < 100000; i++ {
        w := []byte("foo " + strconv.Itoa(i))

        err := ioutil.WriteFile("temp", w, 0644)
        if err != nil {
            log.Fatal(err)
        }

        r, err := ioutil.ReadFile("temp")
        if err != nil {
            log.Fatal(err)
        }

        if !bytes.Equal(w, r) {
            log.Fatal("not equal", string(w), string(r))
        }
    }
}

@TheHippo
Copy link
Author

After some digging a few more facts about when/how this happens:

  • there is some real load on the file system
  • we do not read from go process:
    • as soon as the file is written a process (written in C) gets a signal to reload the file and there a about 1:5 chance the config file is empty

Writing the file "manually" and calling Sync() mitigates this issue completely

@mdempsky
Copy link
Member

@TheHippo What triggers the signal sent to the C process? Is the Go process sending it after the ioutil.WriteFile call returns successfully? If so, that still seems unexpected.

If you're able to provide a minimal but complete code sample that reproduces the issue (even if only on your loaded system), that would be helpful.

@cespare
Copy link
Contributor

cespare commented Feb 24, 2016

@TheHippo what FS?

@hamaxx
Copy link
Contributor

hamaxx commented Feb 24, 2016

There was nothing on the TV so I tried to reproduce it with an external process reading the file but couldn't. Even with the high IO load.

package main

import (
    "bufio"
    "fmt"
    "io/ioutil"
    "log"
    "os/exec"
)

func main() {
    cmd := exec.Command("./rdr/rdr")

    w, err := cmd.StdinPipe()
    if err != nil {
        log.Fatal(err)
    }

    r, err := cmd.StdoutPipe()
    if err != nil {
        log.Fatal(err)
    }

    err = cmd.Start()
    if err != nil {
        log.Fatal(err)
    }

    go func() {
        rs := bufio.NewScanner(r)
        for i := 0; i < 10000000; i++ {
            o := []byte(fmt.Sprintf("foo %d", i))

            err := ioutil.WriteFile("temp", o, 0644)
            if err != nil {
                log.Fatal(err)
            }

            fmt.Fprintln(w)

            rs.Scan()
            fmt.Println(rs.Text())

            if rs.Text() != string(o) {
                log.Fatal("not equal", rs.Text(), string(o))
            }
        }

        cmd.Process.Kill()
    }()

    if err := cmd.Wait(); err != nil {
        log.Fatal("EXIT ", err)
    }
}

Reader:

package main

import (
    "bufio"
    "fmt"
    "io/ioutil"
    "log"
    "os"
)

func main() {

    s := bufio.NewScanner(os.Stdin)
    for s.Scan() {
        r, err := ioutil.ReadFile("temp")
        if err != nil {
            log.Fatal(err)
        }

        fmt.Println(string(r))
    }
}

@dotwilbert
Copy link

I ran into the same issue on 3.19.0-32-generic x86_64 GNU/Linux. Linux Mint Rosa 17.3, based on Ubuntu 14.04.3 LTS.

Filesystem ext4 on LVM on LUKS encrypted drive.

go version go1.6 linux/amd64

My code parses logfiles and for testing writes each hit to a file in the file system: During a test run I got this:

panic: stat febtest1/DOC00004649.json: no such file or directory

goroutine 57570 [running]:
panic(0x546060, 0xc828c591b0)
    /usr/local/go/src/runtime/panic.go:464 +0x3e6
workers/hits2elasticlogweb.(*HitFileStorage).Store(0xc82001e420, 0x7f7d4b5e0080, 0xc828956480, 0x0, 0x0)
    /home/wvandepieterman/Projects/Development/idea-workspace/log-processing/src/workers/hits2elasticlogweb/hitfilestorage.go:243 +0x4dd
workers/hits2elasticlogweb.processHit(0xc82000ef50, 0xc828956480, 0xc82431b080, 0x7f7d4b624450, 0xc82001e420)
    /home/wvandepieterman/Projects/Development/idea-workspace/log-processing/src/workers/hits2elasticlogweb/hitworker.go:146 +0x15d
created by workers/hits2elasticlogweb.(*worker).start
    /home/wvandepieterman/Projects/Development/idea-workspace/log-processing/src/workers/hits2elasticlogweb/hits2elasticlogweb.go:100 +0x94c

Code responsible for the panic:

233 if update {
234     ioutil.WriteFile(hfs.Name+string(os.PathSeparator)+id+`.json`, h.ToJSON(true), 0644)
235 } else {
236     hc := new(Hit)
237     *hc = *h.(*Hit)
238     hc.Id = id
239     ioutil.WriteFile(hfs.Name+string(os.PathSeparator)+id+`.json`, hc.ToJSON(true), 0644)
240 }
241 istat, err := os.Stat(hfs.Name + string(os.PathSeparator) + id + `.json`)
242 if err != nil {
243     panic(err.Error())
244 }

Immediately after writing the file, I stat it to get the size. Cop out I know, but it demonstrates the point TheHippo is making.

Looking at it a few seconds later:

$ ls -ltr febtest1/DOC00004649.json 
-rw-r--r-- 1 wvandepieterman wvandepieterman 27887 Apr  2 00:36 febtest1/DOC00004649.json

If I'm allowed an opinion, I think a convenience and utility method WriteFile should guarantee that the file exists after it has completed and thus should call Sync. If you want performance you code it "manually" and take control of the Syncronization or not.

@minux
Copy link
Member

minux commented Apr 2, 2016 via email

@bradfitz
Copy link
Contributor

bradfitz commented Apr 2, 2016

I'm scrubbing bugs and am going to close this until there's something for us to fix. Like @minux said, please check your errors. They usually contain the answers.

@bradfitz bradfitz closed this as completed Apr 2, 2016
@dotwilbert
Copy link

As stated in the comment, the file does get created, I know it doesn't check the error code. All well and good but that is cheap deflection: You don't address the statement made that a convenience and utility method like WriteFile should guarantee that the file exists when it returns. It simply doesn't. I'm not asking for you or anybody to agree with me, but at least take a stance for or against.

@bradfitz
Copy link
Contributor

bradfitz commented Apr 2, 2016

You don't address the statement made that a convenience and utility method like WriteFile should guarantee that the file exists when it returns. It simply doesn't. I'm not asking for you or anybody to agree with me, but at least take a stance for or against.

I think that is the root of the confusion. Go is from a different style of languages compared to, say, Java, with which perhaps you're more familiar.

In Go, a function may not do what it says if it returns an error. Here are 821 functions and methods from the Go standard library which are no different from ioutil.WriteFile in that regard: https://gist.github.com/bradfitz/d921c0286a8479d6777d539f953db70d

Always check your errors.

@dotwilbert
Copy link

With that statement I agree and admittedly, the code is not production quality. If this were a code review the hammering on checking my errors would be warranted. But that is in this particular case not the point. There is only one spot in the code in which it creates the file which the panic claims is missing. Interrupting the test run and checking the whether the file really doesn't exist, I find the file is present and it is complete and contains what it should be containing. Still the panic just claimed it didn't exist. Although I cannot claim with absolute certainty that no error occurred I think I am reasonably sure that no error was returned, since the file is created and complete and correct. Unless there is a possibility that the function returns an error and does what it is supposed to do anyway, just a little time after returning (? Don't know how, but I would be interested in your explanation ?).

Leaves me with a timing issue during the interaction between the go run-time and the operating system. WriteFile thinks it has created the file (or not depending on your explanation) and returns. The os appears not to immediately write the file, might be busy with some other task (it is busy creating about 12000 files in about 1 minute). os.Stat panics b/c the file does not exists, I check after hitting CTRL-C and it turns out the file does exists and contains exactly what the expectation was. I think this confirms exactly what TheHippo claimed in his initial opening of this issue.

I will code around this and avoid using ioutil.WriteFile, since it is not reliable.

Wilbert

@bradfitz
Copy link
Contributor

bradfitz commented Apr 4, 2016

@dotwilbert, WriteFile is not special at all. You should not avoid it. If WriteFile succeeds without error, Stat should succeed too, immediately after it. If not, it's a problem with the filesystem or kernel or Go runtime. It's not something you can work around by changing which functions you use.

If anybody has a reliable repro of this, please file a new bug with details of the operating system, version, filesystem type, and Go code checking all its errors.

@dotwilbert
Copy link

Sounds fair. I will run multiple test runs. I'll check the errors and let you know when if it happens again.

@dotwilbert
Copy link

After carefully reviewing the testing procedure, I discovered an error on the command line. In the particular test above I processed more than the intended one day in a bash loop. This gives an alternate explanation for the existence of the file that the panic was about. I retract the remark about WriteFile's unreliability and commend you for standing by it. I'll continue testing with error checking enabled.

Thanks,

Wilbert

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

10 participants