Unexplained test failure in LocaleFileImportStatus->testBulkImportUpdateExisting()

Thanks @Maxtorete! We can use this issue to track the test going forward and determine what's causing it.

Recategorizing because there is a good chance this might be related to this particular test rather than the testbot, and making the title more specific

I had this same test fail two out of three times on scratchtestbot last night ... suspect it is an intermittent core failure on HEAD.

I did roll out a new PIFR code release last night, but nothing that should affect run-tests.sh results.

Closed #1780810: Random failure in Drupal\locale\Tests\LocaleFileImportStatus::testBulkImportUpdateExisting() as a dupe

Since that assertion seems to be file-related, perhaps we're missing a clearstatcache() in that test.

@yched marked #1781156: Random testbot fails on LocaleFileImportStatus.php as a duplicate of this.

crosspost :-)

All right, it looks possible that a clear stat cache would be required. Are you saying it mostly works because tests get non-cached stats most of the time? And it fails because sometimes it does get cached stats?

As for what is happening in the test, it fails at the end of this code: http://api.drupal.org/api/drupal/core%21modules%21locale%21lib%21Drupal%...

What the test does, is that it fills in the locale_file table with file information that makes it appear that the file is 1 sec older then it actually is (using http://api.drupal.org/api/drupal/core%21modules%21locale%21lib%21Drupal%... which as its name suggests just mocks the file in the DB, it does not touch or create the file, the file is already there, curtesy of the setup method - it does retrieve the filemtime() from PHP though). Then it adds German and because the locale_file record said it was imported earlier (and compared to the file's date, it is new), it is imported again, which then the test assures has happened by checking specific strings (which passes) and by checking the file timestamp is equal to the original, which sometimes fail.

This seems to be the only place in this test class that indirectly retrieves the file stats, and I don't think other tests use the same files (they are created in the setup method for this test class). So not sure how could the stats be screwed up, but I hope I could help with this little overview.

First of all.

Secondly. :)

I sent #10 for re-testing, probably a dozen of times or so... no "luck."

So we need probably a patch that runs the entire Locale module test suite. We actually added a --module option to run-tests.sh, but I'm not sure whether that works correctly already. We could try by forcing it into that code path; i.e., like #10, just hi-jacking the $args.

How is either of those patches going to fix the problem, which has cropped up on another couple of issues I'm aware of (docs patches, this test fails randomly)?

The problem is that the test is assuming that about a second will pass while certain actions are happening in the test. It might be a second, it might be half a second, it might be two seconds... having a test relying on that is not a good idea. The test needs to be rewritten so it doesn't rely on this kind of thing.

@jhodgdon: please elaborate on where does this test assume 1 second is passed? What this test does is that it sets the last .po file import time known to Drupal (in the db) to 1 second prior to what PHP tells us about the last modification time of the file. Then it triggers a .po file import by adding a language and checks if the file was imported (because we set our record of the file earlier to be "old"). So its a timestamp in the db artificially set 1 sec smaller than the file's compared to the timestamp of the file, independent of how much time was spent as far as I see. What am I missing? There is clearly something wrong, but it does not seem to be time spent... Of course we can just increase the artificial diff to an hour, but we do not really understand why is it happening :/

Yeah, stepping through the test's code, it should technically work.

As mentioned before, let's try the entire Locale module group.

ahem... fixing the --module argument processing while being there ;)

err, what? LOL. Can anyone confirm those LocaleImportFunctionalTest failures locally? Pasting them here, since I'm going to send the patch for re-testing:

EDIT: Another re-test had these exceptions before the failures below in LocaleImportFunctionalTest:

filesize(): stat failed for /var/lib/drupaltestbot/sites/default/files/checkout/sites/default/files/translations/test.xx.po
Warning	locale.bulk.inc	462	locale_translate_batch_import()
fopen(/var/lib/drupaltestbot/sites/default/files/checkout/sites/default/files/translations/test.xx.po): failed to open stream: No such file or directory
Warning	PoStreamReader.php	168	Drupal\Component\Gettext\PoStreamReader->open()
ftell() expects parameter 1 to be resource, boolean given
Warning	PoStreamReader.php	169	Drupal\Component\Gettext\PoStreamReader->open()
fgets() expects parameter 1 to be resource, boolean given
Warning	PoStreamReader.php	263	Drupal\Component\Gettext\PoStreamReader->readLine()

Language file automatically imported.
218	Drupal\locale\Tests\LocaleImportFunctionalTest->testAutomaticModuleTranslationImportLanguageEnable()
Language file automatically imported.
219	Drupal\locale\Tests\LocaleImportFunctionalTest->testAutomaticModuleTranslationImportLanguageEnable()
String successfully imported.
228	Drupal\locale\Tests\LocaleImportFunctionalTest->testAutomaticModuleTranslationImportLanguageEnable()
String successfully imported.
237	Drupal\locale\Tests\LocaleImportFunctionalTest->testAutomaticModuleTranslationImportLanguageEnable()
String successfully imported.
248	Drupal\locale\Tests\LocaleImportFunctionalTest->testAutomaticModuleTranslationImportLanguageEnable()

Oh great... those test failures didn't appear right in the second run. Which inherently means that there's another random test failure in the Locale module tests ;)

I've tried to recreate this failure locally by running the test 200 times. It never occurred - which is very weird as it feels that it occurs 1/10 tests on qa.drupal.org.

I suggest that we commit the patch from #9 so that be have a bit more information when this test random breaks again.

Yeah, let's do that.

Patch in #9 is RTBC, not the later patches.

Committed/pushed #9.

Also random test failures are critical IMO, so bumping status.

Track on the D8MI sprint too. Looking forward to more information as it becomes available from test fails.

Getting this fail at #1738368: Not possible to use the entity getter to retrieve non-translatable field values:

Value '1347880235' is equal to value 1347880234.	
LocaleFileImportStatus.php
Drupal\locale\Tests\LocaleFileImportStatus->testBulkImportUpdateExisting()

That's the worst-case scenario then, because it gives no clues.

#26 is interesting.... Possibly there is a comparison of a ten digit string to a ten digit integer?

I have no idea of how exactly the PHP conversions are done to do such a precise check, but do we really need a check within last second (ie last digit of ten digit numbers)? Why not something like a unique prime integer of say 17 seconds?

Ok I think I've got this one... actually the way round the numbers in the error message is quite informative.. in #26:

1347880235 is the number from the database and 1347880234 is the timestamp from the file... so the number being updated to the db by locale_translate_import_form_submit() is a second later than the filemtime! Not the second earlier set by mockImportedPoFile().

So why is it a second later... because of this code... in Drupal\file\FileStorageController

  /**
   * Overrides Drupal\Core\Entity\DatabaseStorageController::presave().
   */
  protected function preSave(EntityInterface $entity) {
    $entity->timestamp = REQUEST_TIME;
    $entity->filesize = filesize($entity->uri);
    if (!isset($entity->langcode)) {
      // Default the file's language code to none, because files are language
      // neutral more often than language dependent. Until we have better
      // flexible settings.
      // @todo See http://drupal.org/node/258785 and followups.
      $entity->langcode = LANGUAGE_NOT_SPECIFIED;
    }
  }

The use of REQUEST_TIME is wrong.

Patch attached...

No, timestamp is when the managed file record itself was saved or last updated in Drupal. It is not intended or supposed to be the modified time of the actual file on disk.

Ok... #30 is obviously right ... and #29 was wrong since... the timestamp in the locale_file table only gets updated in two places:

In locale.bulk.inc when a language is imported...

        $file->timestamp = filemtime($file->uri);
        locale_translate_update_file_history($file);

and then in mockImportedPoFile(). In this function the timestamp is generated using filemtime(drupal_realpath($file->uri)); from locale_translate_file_create() which is only called from mockImportedPoFile().

So it is always set using filemtime() and the only difference is drupal_realpath().

Patch attached removes drupal_realpath() and changes test to ensure that the timestamp is greater that the timestamp set in mockImportedPoFile() which is as valid a test as the current test since what we are ensuring is that the timestamp is no longer the value set by mockImportedPoFile().

Oh yeah, having drupal_realpath() in filemtime() is very wrong as it is completely unnecessary and runs into issues like this. This is the correct fix, great work.

Ok great. Committed and pushed that to 8.x, too.

Hopefully we're now on the other side of this..? Thanks so much for your quick sleuthing!

I agree the fix looks good and I have not seen this error ever since, so great! Thanks everyone!

Removing sprint tag again :)