PHP file_put_contents does not work properly

spiritix commented 8 years ago

In some cases, specifically occurred when using Composer, the PHP function file_put_contents returns the number of written bytes like expected and the file is created, but it's empty. This causes a bug in Composer, see the following issue. Sometimes the problem can be solved by deleting the file, sometimes by reloading Vagrant, sometimes it can't be solved at all.

marcharding commented 8 years ago

Are you using laravel homestead? Homestead uses some mount options which cause problems with winnfsd in its current state.

spiritix commented 8 years ago

No, I am not using Homestead. My configuration looks like this:

config.vm.synced_folder "project", "/vagrant/project",
        id: "project",
        :nfs => true,
        :mount_options => ['nolock,vers=3,udp,noatime,actimeo=2']

marcharding commented 8 years ago

You are using the latest version, right? Which os? Ubuntu?

Please try :mount_options => ['rw,vers=3,tcp,nolock']

spiritix commented 8 years ago

Yes I am using the latest version. Guest OS is ubuntu/trusty64, host OS Windows 10. I will try to use the suggested option the next time the problem appears and provide feedback then.

marcharding commented 7 years ago

Any update here? This should not happen in the last few releases.

spiritix commented 7 years ago

Honestly, I did not get the chance to comprehensively test it with your suggested mount options. We simply avoided the issue by moving Composer's "vendor" folder out of the shared folder scope. If you fixed this issue in the meantime I will switch back to the original configuration now. I will report if it happens again.

YOzaz commented 6 years ago

👍 on this one... still hapenning. Mount options are:

nolock,vers=3,udp,noatime,actimeo=1

marcharding commented 6 years ago

Can you provide more input? It never happend for me in ages and the underlying issue that caused it was fixed long ago.

dave-newson commented 6 years ago

Experienced this same issue myself with ['rw,vers=3,udp,nolock'] options. Switched across to ['rw,vers=3,tcp,nolock'] and didn't have any issues, but switching back to ['rw,vers=3,udp,nolock'] again and trying to replicate the original issue failed, so my assumption is restarting winnfsd is what solved the problem.

This was done while checking out a large project, so prior experiencing the original problem Composer performed a huge number of writes, which may have contributed to whatever unhappy state winnfsd was in.

janpio commented 6 years ago

Having the same problem right now.

I use Homestead (v7.9.0) on Windows 10 with Vagrant (Vagrant 2.1.1), VirtualBox (5.2.12) and vagrant-winnfsd (WinNFSd 2.4.0) installed. My Homestead.yml has this folder definition:

folders:
    - map: ~/../../Projects
      to: /home/vagrant/projects
      type: "nfs"
      mount_options: ['nolock,vers=3,udp,noatime']

I get the error when I run the command composer dump-autoload via vagrant ssh in one of my projects in this projects folder:

$ composer dump-autoload
Generating optimized autoload files
PHP Fatal error:  Uncaught TypeError: Argument 1 passed to Composer\Autoload\ClassLoader::addClassMap() must be of the type array, integer given, called in phar:///usr/local/bin/composer/src/Composer/Autoload/AutoloadGenerator.php on line 760 and defined in phar:///usr/local/bin/composer/vendor/composer/ClassLoader.php:92
Stack trace:
#0 phar:///usr/local/bin/composer/src/Composer/Autoload/AutoloadGenerator.php(760): Composer\Autoload\ClassLoader->addClassMap(1)
#1 phar:///usr/local/bin/composer/src/Composer/Autoload/AutoloadGenerator.php(303): Composer\Autoload\AutoloadGenerator->getStaticFile('61478045442f960...', '/home/vagrant/p...', '/home/vagrant/p...', '/home/vagrant/p...', 50600)
#2 phar:///usr/local/bin/composer/src/Composer/Command/DumpAutoloadCommand.php(75): Composer\Autoload\AutoloadGenerator->dump(Object(Composer\Config), Object(Composer\Repository\InstalledFilesystemRepository), Object(Composer\Package\RootPackage), Object(Composer\Installer\InstallationManager), '/home/vagrant/p...', true)
#3 phar:///usr/local/ in phar:///usr/local/bin/composer/vendor/composer/ClassLoader.php on line 92

It seems to crash when writing vendor/composer/autoload_classmap.php, which is then left as a 0 byte file.

Only "fix" I could find was to vagrant halt, close and restart my command line, and vagrant up again. This seems to work most of the time.

Any other information I can provide?

marcharding commented 6 years ago

You can try switching udp with tcp in your mount options.

dave-newson commented 6 years ago

Experienced this issue again yesterday, details as follows:

Using no custom mount_options, VM had been up for a few hours
running Codeception CLI tests
file_put_contents failed (0 bytes) for 2 files, while another wrote successfully every time.
Deleted the files multiple times, always came back with the same 2/3 at 0 bytes.
Killed winnfsd process and restarted the VM - problem went away.

I'll run with the options previously suggested :mount_options => ['rw,vers=3,tcp,nolock'] and see if it comes up again.

@marcharding Do you have any suggestions for further debugging? I'm thinking of trying:

Run with logging on all the time
Add a custom batch command so I can "restart" winnfsd without restarting the VM, mostly to narrow the problem down to winnfsd specifically.

Update: Ran for 7 days using the above settings without incident. Logging seems to affect the performance of NFS, so I'll switch to no logging in case that's preventing the issue from re-appearing.

dave-newson commented 6 years ago

Finally reproduced this in a repeatable way.

Winnfsd

Winnfsd log output (duplicate lines truncated):

[15:44:52] NFS WRITE \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[ ... 320 lines ]
[15:44:53] NFS WRITE \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[15:44:53] NFS COMMIT \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[15:44:53] NFS GETATTR \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[15:44:53] NFS ACCESS \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[15:44:53] NFS READ \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[ ... 320 lines ]
[15:44:53] NFS READ \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[15:44:53] NFS GETATTR \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[15:44:53] NFS SETATTR \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[15:44:53] NFS WRITE \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[ ... 320 lines ]
[15:44:56] NFS WRITE \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[15:44:56] NFS COMMIT \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[15:44:56] NFS COMMIT \\?\W:\tms-vm-2\apps\tms\tms\test.txt  IO
[15:44:56] NFS GETATTR \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[15:44:56] NFS ACCESS \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[15:44:56] NFS READ \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[ ... 320 lines ]
[15:44:56] NFS READ \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[15:44:56] NFS GETATTR \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[15:44:56] NFS SETATTR \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[15:44:56] NFS WRITE \\?\W:\tms-vm-2\apps\tms\tms\test.txt No such file or directory IO
[ ... 344 lines ]
[15:44:56] NFS WRITE \\?\W:\tms-vm-2\apps\tms\tms\test.txt No such file or directory IO
[15:44:56] NFS GETATTR \\?\W:\tms-vm-2\apps\tms\tms\test.txt

Script

PHP Script:

<?php

const FILENAME = 'test.txt';

while (true) {

    // Create 1000 lines of 1K garbage
    $str = [];
    for ($i=0 ; $i<1024*100 ; $i++) {
        $str[] = str_pad("", 100, "a");
    }

    // Write
    file_put_contents(FILENAME, json_encode($str));

    // Read
    $size = filesize(FILENAME);
    $content = json_decode(file_get_contents(FILENAME));

    // Stats
    echo sprintf("\n %s | size %d | items %d", date("Y-m-d H:i:s"), $size, count($content));

    // Check: Size is zero?
    if ($size === 0) {
        throw new \Exception("Broke write (size)");
    }

    // Check: content is broken?
    if ($content === null) {
        throw new \Exception("Broke write (content)");
    }
};

Script output:

www-data@tms[/var/www/tms] (phpstan) $ php -f test.php

 2018-07-19 15:44:22 | size 10547201 | items 102400
 2018-07-19 15:44:25 | size 10547201 | items 102400
 2018-07-19 15:44:28 | size 10547201 | items 102400
 2018-07-19 15:44:30 | size 10547201 | items 102400
 2018-07-19 15:44:33 | size 10547201 | items 102400
 2018-07-19 15:44:36 | size 10547201 | items 102400
 2018-07-19 15:44:39 | size 10547201 | items 102400
 2018-07-19 15:44:42 | size 10547201 | items 102400
 2018-07-19 15:44:44 | size 10547201 | items 102400
 2018-07-19 15:44:47 | size 10547201 | items 102400
 2018-07-19 15:44:49 | size 10547201 | items 102400
 2018-07-19 15:44:52 | size 10547201 | items 102400
 2018-07-19 15:44:55 | size 10547201 | items 102400

 2018-07-19 15:44:55 | size 10547201 | items 0

PHP Fatal error:  Uncaught Exception: Broke write (content) in /var/www/tms/test.php:31
Stack trace:
#0 {main}
  thrown in /var/www/tms/test.php on line 31

Fatal error: Uncaught Exception: Broke write (content) in /var/www/tms/test.php:31
Stack trace:
#0 {main}
  thrown in /var/www/tms/test.php on line 31

Doing an ls

-rwxrwxrwx   1 www-data www-data       0 Jul 19 05:44 test.txt

What's happening

This script is running in an infinite loop and generating ~10Mb of JSON data
The data is written to disk (winnfsd mount) using file_put_contents.
The size of the file is read using filesize
The contents of the file is re-read using file_get_contents
The size is checked, and always echos out as the expected size (10547201)
The content is checked, and the count of items is echoed (102400)

When it goes wrong

PHP: size of the file is 10547201.
Linux: size of the file is 0.
Host: size of the file is 0.
PHP: The file is empty.
Linux: The file is empty.
Host: The file is empty.

What happens next

Trying to run the script again causes the exact same error immediately. Content does not get written to this file by PHP, and content does not get written to disk on the host.

Winnfsd logs:

[15:58:00] NFS GETATTR \\?\W:\tms-vm-2\apps\tms\tms\test.php
[15:58:00] NFS ACCESS \\?\W:\tms-vm-2\apps\tms\tms\test.php
[15:58:01] NFS GETATTR \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[15:58:01] NFS GETATTR \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[15:58:01] NFS ACCESS \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[15:58:01] NFS SETATTR \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[15:58:01] NFS WRITE \\?\W:\tms-vm-2\apps\tms\tms\test.txt No such file or directory IO
[ ... 320 lines ]
[15:58:01] NFS WRITE \\?\W:\tms-vm-2\apps\tms\tms\test.txt No such file or directory IO
[15:58:01] NFS GETATTR \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[15:58:01] NFS ACCESS \\?\W:\tms-vm-2\apps\tms\tms\test.txt

You can restore access to the file without restarting winnfsd.

Using vi to open, write and quit (vi -> :wq) is enough to restore access.

[16:02:26] NFS ACCESS \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[16:02:26] NFS GETATTR \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[16:02:26] NFS LOOKUP \\?\W:\tms-vm-2\apps\tms\tms\.test.txt.swp  NOENT
[16:02:26] NFS CREATE \\?\W:\tms-vm-2\apps\tms\tms\.test.txt.swp
[16:02:26] NFS SETATTR \\?\W:\tms-vm-2\apps\tms\tms\.test.txt.swp
[16:02:26] NFS ACCESS \\?\W:\tms-vm-2\apps\tms\tms
[16:02:26] NFS LOOKUP \\?\W:\tms-vm-2\apps\tms\tms\.test.txt.swx  NOENT
[16:02:26] NFS CREATE \\?\W:\tms-vm-2\apps\tms\tms\.test.txt.swx
[16:02:26] NFS SETATTR \\?\W:\tms-vm-2\apps\tms\tms\.test.txt.swx
[16:02:26] NFS REMOVE \\?\W:\tms-vm-2\apps\tms\tms\.test.txt.swx
[16:02:26] NFS REMOVE \\?\W:\tms-vm-2\apps\tms\tms\.test.txt.swp
[16:02:26] NFS LOOKUP \\?\W:\tms-vm-2\apps\tms\tms\.test.txt.swp  NOENT
[16:02:26] NFS CREATE \\?\W:\tms-vm-2\apps\tms\tms\.test.txt.swp
[16:02:26] NFS SETATTR \\?\W:\tms-vm-2\apps\tms\tms\.test.txt.swp
[16:02:26] NFS WRITE \\?\W:\tms-vm-2\apps\tms\tms\.test.txt.swp
[16:02:26] NFS SETATTR \\?\W:\tms-vm-2\apps\tms\tms\.test.txt.swp
[16:02:28] NFS LOOKUP \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[16:02:28] NFS LOOKUP \\?\W:\tms-vm-2\apps\tms\tms\4913  NOENT
[16:02:28] NFS CREATE \\?\W:\tms-vm-2\apps\tms\tms\4913
[16:02:28] NFS SETATTR \\?\W:\tms-vm-2\apps\tms\tms\4913
[16:02:28] NFS SETATTR \\?\W:\tms-vm-2\apps\tms\tms\4913
[16:02:28] NFS ACCESS \\?\W:\tms-vm-2\apps\tms\tms
[16:02:28] NFS REMOVE \\?\W:\tms-vm-2\apps\tms\tms\4913
[16:02:28] NFS LOOKUP \\?\W:\tms-vm-2\apps\tms\tms\test.txt~  NOENT
[16:02:28] NFS LOOKUP \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[16:02:28] NFS RENAME \\?\W:\tms-vm-2\apps\tms\tms\test.txt  \\?\W:\tms-vm-2\apps\tms\tms\test.txt~
[16:02:28] NFS WRITE \\?\W:\tms-vm-2\apps\tms\tms\.test.txt.swp
[16:02:28] NFS LOOKUP \\?\W:\tms-vm-2\apps\tms\tms\test.txt  NOENT
[16:02:28] NFS CREATE \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[16:02:28] NFS SETATTR \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[16:02:28] NFS REMOVE \\?\W:\tms-vm-2\apps\tms\tms\test.txt~
[16:02:29] NFS LOOKUP \\?\W:\tms-vm-2\apps\tms\tms\.test.txt.swp
[16:02:29] NFS REMOVE \\?\W:\tms-vm-2\apps\tms\tms\.test.txt.swp

It looks like vi is "fixing" the problem because it performs a RENAME of test.txt to test.txt~, and then does a CREATE to replace the original file.

Compare this with touch and output redirection which do not solve the problem:

touch test.txt
[16:02:12] NFS GETATTR \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[16:02:12] NFS ACCESS \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[16:02:12] NFS SETATTR \\?\W:\tms-vm-2\apps\tms\tms\test.txt

echo "" > test.txt
[16:08:47] NFS GETATTR \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[16:08:47] NFS SETATTR \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[16:08:47] NFS WRITE \\?\W:\tms-vm-2\apps\tms\tms\test.txt

Using echo "derp" > test.txt will actually write content for the file back onto the host, however PHP is still unable to use the file.

Interestingly you can mv the broken file around. Trying to use that broken file results in the same problem.

# Move the broken file
mv test.txt test2.txt
[16:10:06] NFS LOOKUP \\?\W:\tms-vm-2\apps\tms\tms\test2.txt  NOENT
[16:10:06] NFS GETATTR \\?\W:\tms-vm-2\apps\tms\tms\test.txt
[16:10:06] NFS RENAME \\?\W:\tms-vm-2\apps\tms\tms\test.txt  \\?\W:\tms-vm-2\apps\tms\tms\test2.txt

# Works: Kill with Ctrl-C before error occurs
php -f test.php

# Change the `FILENAME` constant to `test2.txt` in `test.php`
# Fails immediately
php -f test.php

Things I've tried that don't help

PHP clearstatcache();
echo 3 > /proc/sys/vm/drop_caches

Setup specifics

Host: Windows 10 10.0.17134
Virtualbox: 5.2.12r122591
Vagrant: 2.1.1
VM: Ubuntu 16.04.4 LTS (bento/ubuntu-16.04 @ 201806.08.0)
Docker: Docker version 18.03.1-ce, build 9ee9f40
Container: Amazon Linux 2 (2017.12) LTS Release Candidate
Mount type: volume
vagrant-winnfsd: 1.4.0
NFS options: ``` mount_type = 'nfs' mount_options = ['rw,vers=3,tcp,nolock'] config.winnfsd.uid = 33 config.winnfsd.gid = 33 config.winnfsd.host_ip = "192.168.56.1" config.winnfsd.logging = 'on'

marcharding commented 6 years ago

Thanks for the detailed report, i'll try to reproduce this with my setup.

dave-newson commented 6 years ago

A brief further update; I've been building and rebuilding my VM to work out the kinks, and so far I haven't had any issues outside of PHP, so I'm very much leaning towards a cache being used by PHP as the main problem. That's backed up by articles like this which indicate that PHP is bonkers.

Unfortunately I haven't any more to go on, but I might take another stab as diagnosis if this keeps coming up.

jantomicky commented 6 years ago

Had the same issue, seems to be solved by setting these _mountoptions:

mount_options: ['rw,vers=3,udp,nolock,actimeo=2']

And then excluding the synchronized folder from the Windows Defender workspace.

Windows 10, Version 1803, Build 17134.228 Vagrant 2.1.0 VirtualBox 5.2.12 WinNFSd 1.3.1 Laravel Homestead

Details in a related issue: https://github.com/composer/composer/issues/5707#issuecomment-414116940 where I describe a similar problem (getting a 0 byte file) when running gulp to minimize JavaScript sources.

dave-newson commented 6 years ago

Dang, nice find @jantomicky. Following your recommendation, I added the Windows Defender exclusions and gave my own options ( 'actimeo=1', 'nolock', 'udp', 'async' ) another spin with the test script.

I had one failure over the course of 5 minutes, and upon retrying it ran for well over 10 minutes without issue. I also feel like there's a speed increase for random reads, though I haven't bothered to run a real-world benchmark.

I wouldn't say the issue is 100% resolved, but I'd hazard a guess this will reduce the chance from 95% to 5%.

@marcharding citing the above, I'd strongly recommend adding something to the vagrant-winnfsd readme about adding a Windows Defender exclusion if you're experiencing read/write errors (something something security at your own risk something somthing).

Edit: The following command, run in Powershell (as admin) will exclude winnfsd from Defender's eye.

Add-MpPreference -ExclusionProcess winnfsd.exe

It's a tiny bit broad (no path), so I wonder if a more specific version could be added to vagrant-winnfsd.

Thanks again @jantomicky, this means we'll be able to move this solution into use across our team.

Edit: 10 days later, I've not had any problems with winnfsd since implementing the exclusion.

winnfsd / vagrant-winnfsd