Concurrency directory creation

[Legion112]

Monolog version 2.4.0

We run test in parallel in sometimes we experience following behaviour:

 There is no existing directory at "/php-tests/report/logs/e2e/PathToTestDir" and it could not be cr  
  eated: File exists   

This is from \Monolog\Handler\StreamHandler::createDir

[Seldaek]

Oh we did check for concurrency but I think there is a missing clearstatcache() in there to properly fix this issue. I'll fix this thanks for reporting 👍🏻

[Seldaek]

Hm no sorry.. PHP shouldn't cache the fact that a file is missing, so I don't quite see how this code can fail

monolog/src/Monolog/Handler/StreamHandler.php

Lines 193 to 198 in 60ad518

	set_error_handler([$this, 'customErrorHandler']);
	$status = mkdir($dir, 0777, true);
	restore_error_handler();
	if (false === $status && !is_dir($dir)) {
	throw new \UnexpectedValueException(sprintf('There is no existing directory at "%s" and it could not be created: '.$this->errorMessage, $dir));
	}

If mkdir failed, it checks for is_dir again and if the failure reason is File exists then it should definitely be there.

Is it possible that your concurrent test runs create the dir, log, and then delete the dir very quickly so you can run into a race condition where mkdir fails but is_dir still returns false as it was deleted already?

If so maybe we could fix this by retrying if it is still missing and the error is File exists I guess.

[Legion112]

Retry seem like a realy good option here @Seldaek.
Your idea is brilliant

[Seldaek]

@Legion112 I'm not sure this fixes anything in fact.. As per my comment on #1683 (comment) - I believe you may then run into another race condition whereas the directory gets wiped by another process and then the file write fails. The only real solution if you do clear the directory after the test is to run tests in different directories IMO.

[Legion112]

@Seldaek well let's check if $this->errorMessage === 'File exists' and do not throw exception in that case?
What do you think?

[Seldaek]

Maybe.. but if it exists why did is_dir() return false at line 196? Do you have a reliable way to reproduce the error so that we can try to inspect things further?

[Legion112]

#1685

[Legion112]

I don't know why is_dir returned false.
I understand that is strange case.
Maybe series of retry would prevent this issue.
Like try to run createDir body code 3 times only after 3 error throw exception.

[Seldaek]

These are all just band-aids though, not fixes. I would really like to understand what is going on before doing anything that hides the problem.

[Legion112]

We could try to look at is_dir
Several users have pointed that can return false in same cases.

[Seldaek]

What environment are you running this on? VM? virtual filesystem? etc?

[Legion112]

Docker container.
In AWS kubernetus.
Filesystem: OverlayFS

[Legion112]

Also in the documentation for is_dir

[Seldaek]

The stat cache is only for true result, so if is_dir returns true it will cache it, if false it doesn't cache, so that can't be it.

k8s / docker yeah sounds like that shouldn't cause weird issues like VMs but who knows.