Uploaded image for project: 'Moodle'
  1. Moodle
  2. MDL-72026

Race conditions writing tmp files in file system filedir

XMLWordPrintable

    • MOODLE_310_STABLE, MOODLE_311_STABLE, MOODLE_39_STABLE
    • MDL-72026-fileapi-race
    • Hide

      This is easiest done comparing before and after the patch:

      1) Download attached test file kitten.jpg to your local wwwroot

      2) Confirm it's sha1 hash:

      $ sha1sum kitten.jpg 
      a3eb1d7cb63ddd6df5b2edf7720ca4631badd4f6 kitten.jpg

      3) Turn on fileio debugging to watch for reads, writes, stats and misses on datadir:

      $CFG->debugfileio = 1 + 2 + 4 + 8; 

      4) Now configure artificial delays in the file system:

      $CFG->debugfileiodelay = [
      		 
          4  => 0.1, // Read
      		 
          8  => 0.1, // Stat
      		 
          16 => 0.1, // File read chunk of bytes
      		 
          32 => 10,  // File write chunk of bytes
      		 
      ];

      5) Download the test script MDL-72026-file-rename-race.php to wwwroot

      6) Run the test script redirecting stderr to stdout so we can grep to just filedir logs and do this simultaneously in two terminals so they race each other

      php MDL-72026-file-rename-race.php 2>&1 | grep filedir

      7) You will need to delete the internal filedir file if you do repeat tests

      rm /var/your/path/to/sitedata/filedir/a3/eb/a3eb1d7cb63ddd6df5b2edf7720ca4631badd4f6 

      8) Confirm that there was no exceptions and that the file in filedir was created. Prior to the patch there should be exceptions in one or both terminals.

      Show
      This is easiest done comparing before and after the patch: 1) Download attached test file kitten.jpg to your local wwwroot 2) Confirm it's sha1 hash: $ sha1sum kitten.jpg a3eb1d7cb63ddd6df5b2edf7720ca4631badd4f6 kitten.jpg 3) Turn on fileio debugging to watch for reads, writes, stats and misses on datadir: $CFG->debugfileio = 1 + 2 + 4 + 8 ;  4) Now configure artificial delays in the file system: $CFG->debugfileiodelay = [ 4 => 0.1 , // Read 8 => 0.1 , // Stat 16 => 0.1 , // File read chunk of bytes 32 => 10 , // File write chunk of bytes ]; 5) Download the test script MDL-72026 -file-rename-race.php to wwwroot 6) Run the test script redirecting stderr to stdout so we can grep to just filedir logs and do this simultaneously in two terminals so they race each other php MDL- 72026 -file-rename-race.php 2 >& 1 | grep filedir 7) You will need to delete the internal filedir file if you do repeat tests rm /var/your/path/to/sitedata/filedir/a3/eb/a3eb1d7cb63ddd6df5b2edf7720ca4631badd4f6  8) Confirm that there was no exceptions and that the file in filedir was created. Prior to the patch there should be exceptions in one or both terminals.
    • 2
    • Team Hedgehog 2023 Sprint 4.2, Team Hedgehog 2023 Sprint 4.3

      This is found while testing MDL-71991

      So I've been tinkering and have MDL-70243 at a functional enough state where I can artificially slow down the file system and reproduce at least one race condition:

      Here is what a file write looks like when it doesn't exist in file dir:

      FILEIO 403676 22:07:05.224076 [4]   stat /var/lib/sitedata/moodle.local/filedir bootstrap * line 80 of /lib/filestorage/file_system_filedir.php: call to is_dir()
      		 
      FILEIO 403676 22:07:05.224184 [4]   stat /var/lib/sitedata/moodle.local/trashdir bootstrap * line 96 of /lib/filestorage/file_system_filedir.php: call to is_dir()
      		 
      FILEIO 403676 22:07:05.242538 [2]   miss /var/lib/sitedata/moodle.local/filedir/a3/eb/a3eb1d7cb63ddd6df5b2edf7720ca4631badd4f6 bootstrap * line 355 of /lib/filestorage/file_system_filedir.php: call to file_exists()
      		 
      FILEIO 403676 22:07:05.242635 [4]   stat /var/lib/sitedata/moodle.local/filedir/a3/eb bootstrap * line 371 of /lib/filestorage/file_system_filedir.php: call to is_dir()
      		 
      FILEIO 403676 22:07:05.242739 [2]   miss /var/lib/sitedata/moodle.local/filedir/a3/eb/a3eb1d7cb63ddd6df5b2edf7720ca4631badd4f6.tmp bootstrap * line 386 of /lib/filestorage/file_system_filedir.php: call to copy()
      		 
      FILEIO 403676 22:07:05.242891 [1]  write /var/lib/sitedata/moodle.local/filedir/a3/eb/a3eb1d7cb63ddd6df5b2edf7720ca4631badd4f6.tmp bootstrap * line 386 of /lib/filestorage/file_system_filedir.php: call to copy()
      		 
      FILEIO 403676 22:07:08.984638 [3]   read /var/lib/sitedata/moodle.local/filedir/a3/eb/a3eb1d7cb63ddd6df5b2edf7720ca4631badd4f6.tmp bootstrap * line 2445 of /lib/filestorage/file_storage.php: call to sha1_file()
      		 
      FILEIO 403676 22:07:08.997028 [1]  write /var/lib/sitedata/moodle.local/filedir/a3/eb/a3eb1d7cb63ddd6df5b2edf7720ca4631badd4f6.tmp -> /var/lib/sitedata/moodle.local/filedir/a3/eb/a3eb1d7cb63ddd6df5b2edf7720ca4631badd4f6 bootstrap * line 399 of /lib/filestorage/file_system_filedir.php: call to rename()
      		 
      FILEIO 403676 22:07:08.997176 [2]   miss /var/lib/sitedata/moodle.local/filedir/a3/eb/a3eb1d7cb63ddd6df5b2edf7720ca4631badd4f6.tmp bootstrap * line 400 of /lib/filestorage/file_system_filedir.php: call to file_exists()
      		 
      FILEIO 403676 22:07:09.009602 [4]   stat /var/lib/sitedata/moodle.local/filedir/da/39/da39a3ee5e6b4b0d3255bfef95601890afd80709 bootstrap * line 431 of /lib/filestorage/file_system_filedir.php: call to file_exists()

      And this is what it does when it already exists:

      FILEIO 403412 22:02:11.789714 [4] stat /var/lib/sitedata/moodle.local/filedir bootstrap * line 80 of /lib/filestorage/file_system_filedir.php: call to is_dir() 
      FILEIO 403412 22:02:11.789762 [4] stat /var/lib/sitedata/moodle.local/trashdir bootstrap * line 96 of /lib/filestorage/file_system_filedir.php: call to is_dir() 
      FILEIO 403412 22:02:11.803814 [4] stat /var/lib/sitedata/moodle.local/filedir/a3/eb/a3eb1d7cb63ddd6df5b2edf7720ca4631badd4f6 bootstrap * line 355 of /lib/filestorage/file_system_filedir.php: call to file_exists() 
      FILEIO 403412 22:02:11.817631 [4] stat /var/lib/sitedata/moodle.local/filedir/da/39/da39a3ee5e6b4b0d3255bfef95601890afd80709 bootstrap * line 431 of /lib/filestorage/file_system_filedir.php: call to file_exists()

      When two processes over lap one or sometimes both explode:

      FILEIO 403756 22:08:59.256469 [4]   stat /var/lib/sitedata/moodle.local/filedir bootstrap * line 80 of /lib/filestorage/file_system_filedir.php: call to is_dir()
      		 
      FILEIO 403756 22:08:59.256521 [4]   stat /var/lib/sitedata/moodle.local/trashdir bootstrap * line 96 of /lib/filestorage/file_system_filedir.php: call to is_dir()
      		 
      FILEIO 403756 22:08:59.271550 [2]   miss /var/lib/sitedata/moodle.local/filedir/a3/eb/a3eb1d7cb63ddd6df5b2edf7720ca4631badd4f6 bootstrap * line 355 of /lib/filestorage/file_system_filedir.php: call to file_exists()
      		 
      FILEIO 403756 22:08:59.271617 [4]   stat /var/lib/sitedata/moodle.local/filedir/a3/eb bootstrap * line 371 of /lib/filestorage/file_system_filedir.php: call to is_dir()
      		 
      FILEIO 403756 22:08:59.271691 [4]   stat /var/lib/sitedata/moodle.local/filedir/a3/eb/a3eb1d7cb63ddd6df5b2edf7720ca4631badd4f6.tmp bootstrap * line 386 of /lib/filestorage/file_system_filedir.php: call to copy()
      		 
      FILEIO 403756 22:08:59.271760 [1]  write /var/lib/sitedata/moodle.local/filedir/a3/eb/a3eb1d7cb63ddd6df5b2edf7720ca4631badd4f6.tmp bootstrap * line 386 of /lib/filestorage/file_system_filedir.php: call to copy()
      		 
      FILEIO 403756 22:09:03.082026 [3]   read /var/lib/sitedata/moodle.local/filedir/a3/eb/a3eb1d7cb63ddd6df5b2edf7720ca4631badd4f6.tmp bootstrap * line 2445 of /lib/filestorage/file_storage.php: call to sha1_file()
      		 
      PHP Warning:  fopen(/var/lib/sitedata/moodle.local/filedir/a3/eb/a3eb1d7cb63ddd6df5b2edf7720ca4631badd4f6.tmp): failed to open stream: No such file or directory in /var/www/moodle.local/lib/classes/local/stream/stream_wrapper_base.php on line 302
      		 
      PHP   4. file_system_filedir->add_file_from_path() /var/www/moodle.local/lib/filestorage/file_storage.php:1829
      		 
      PHP   5. file_storage::hash_from_path() /var/www/moodle.local/lib/filestorage/file_system_filedir.php:392
      		 
      Warning: fopen(/var/lib/sitedata/moodle.local/filedir/a3/eb/a3eb1d7cb63ddd6df5b2edf7720ca4631badd4f6.tmp): failed to open stream: No such file or directory in /var/www/moodle.local/lib/classes/local/stream/stream_wrapper_base.php on line 302
      		 
          0.3449   21806056   4. file_system_filedir->add_file_from_path() /var/www/moodle.local/lib/filestorage/file_storage.php:1829
      		 
          4.1692   21807824   5. file_storage::hash_from_path() /var/www/moodle.local/lib/filestorage/file_system_filedir.php:392
      		 
      PHP Warning:  sha1_file(/var/lib/sitedata/moodle.local/filedir/a3/eb/a3eb1d7cb63ddd6df5b2edf7720ca4631badd4f6.tmp): failed to open stream: "core\local\stream\fileio_wrapper::stream_open" call failed in /var/www/moodle.local/lib/filestorage/file_storage.php on line 2445
      		 
      PHP   4. file_system_filedir->add_file_from_path() /var/www/moodle.local/lib/filestorage/file_storage.php:1829
      		 
      PHP   5. file_storage::hash_from_path() /var/www/moodle.local/lib/filestorage/file_system_filedir.php:392
      		 
      Warning: sha1_file(/var/lib/sitedata/moodle.local/filedir/a3/eb/a3eb1d7cb63ddd6df5b2edf7720ca4631badd4f6.tmp): failed to open stream: "core\local\stream\fileio_wrapper::stream_open" call failed in /var/www/moodle.local/lib/filestorage/file_storage.php on line 2445
      		 
          0.3449   21806056   4. file_system_filedir->add_file_from_path() /var/www/moodle.local/lib/filestorage/file_storage.php:1829
      		 
          4.1692   21807824   5. file_storage::hash_from_path() /var/www/moodle.local/lib/filestorage/file_system_filedir.php:392
      		 
      FILEIO 403756 22:09:03.083024 [1]  write /var/lib/sitedata/moodle.local/filedir/a3/eb/a3eb1d7cb63ddd6df5b2edf7720ca4631badd4f6.tmp bootstrap * line 394 of /lib/filestorage/file_system_filedir.php: call to unlink()
      		 
      * line 396 of /lib/filestorage/file_system_filedir.php: file_exception thrown
      		 
      * line 1829 of /lib/filestorage/file_storage.php: call to file_system_filedir->add_file_from_path()
      		 
      !! Stack trace: * line 396 of /lib/filestorage/file_system_filedir.php: file_exception thrown
      		 
      * line 1829 of /lib/filestorage/file_storage.php: call to file_system_filedir->add_file_from_path()

      The rename isn't the root cause in this  scenario, it is the tmp file. I tested this with $CFG->preventfilelocking on and off and it doesn't make a difference, in fact the $fs->add_file_from_path() doesn't even honor preventfilelocking and never attempts to use a file lock for either the tmp file or the real one.

      I've got a simple patch which use uniqid()

       

       

       

       

        1. kitten.jpg
          kitten.jpg
          2.86 MB
        2. MDL-72026-file-rename-race.php
          0.5 kB

            Unassigned Unassigned
            brendanheywood Brendan Heywood
            Votes:
            0 Vote for this issue
            Watchers:
            12 Start watching this issue

              Created:
              Updated:

                Estimated:
                Original Estimate - Not Specified
                Not Specified
                Remaining:
                Remaining Estimate - 0 minutes
                0m
                Logged:
                Time Spent - 4 hours, 29 minutes
                4h 29m

                  Error rendering 'clockify-timesheets-time-tracking-reports:timer-sidebar'. Please contact your Jira administrators.