problem with the size of the log[yii2/log/FileTarget]

[stu2162583]

What steps will reproduce the problem?

The log is full and concurrent

What is the expected result?

The log should be full

What do you get instead?

some logs are too small

Additional info

Q	A
Yii version	2.0.45
PHP version	7.2.6
Operating system	windows

same as #19079

hello, I'm back again, after our testing, The problem is due to rotateFiles and concurrency

config

'log' => [
	'targets' => [
		[
			'class' => 'yii\log\FileTarget',
			'categories' => ['open'],
			'logVars' => [],
			'maxFileSize' => 100, //for better display of errors
			'maxLogFiles' => 5,
			'logFile' => '@root/runtime/logs/open.log',
		]
	],
],

code

$request = Yii::$app->request;
$header = $request->getHeaders();
$get = $request->get();
$body = $request->bodyParams;
$method =  $request->method;
Yii::info([
	'header' => $header,
	'get' => $get,
	'body' => $body,
	'method' => $method,
], 'open');

test with ab

ab -n1000 -c10 http://example.com/path1/path2

You will see that some logs are very small

By the way, I don't think it's a good idea to attach an application log when logvar is not empty, preferably something that can be controlled.

'logVars' => ['_GET', '_POST'],

// will hava
... category: application ....

[bizley]

Hmm, does it work if you set rotateByCopy to false?

[stu2162583]

Hmm, does it work if you set rotateByCopy to false?

thanks！

Under Windows, same result, and when rename, there is an error. [yii\log\Dispatcher::dispatch] Unable to send log via yii\log\FileTarget: Exception (Invalid Configuration) 'yii\base\InvalidConfigException' with message 'Unable to append to log file: F:/codes/szy/ ycs/runtime/logs/open.log'

[virtual-designer]

What about file permissions? Are those log files writable by PHP?

[stu2162583]

What about file permissions? Are those log files writable by PHP?

Permissions are Windows default permissions. These logs are written by php

[virtual-designer]

What about file permissions? Are those log files writable by PHP?

Permissions are Windows default permissions. These logs are written by php

Then no idea. The owners of the repo need to check everything.

[stu2162583]

What about file permissions? Are those log files writable by PHP?

Permissions are Windows default permissions. These logs are written by php

Then no idea. The owners of the repo need to check everything.

ok，thanks！

[WinterSilence]

just try lock after clear cache and get file size

if ($this->enableRotation) {
    // clear stat cache to ensure getting the real current file size and not a cached one
    // this may result in rotating twice when cached file size is used on subsequent calls
    clearstatcache(false, $this->logFile);
    $fileSize = filesize($this->logFile) ?: 0;
}
$fp = fopen($this->logFile, 'a');
if ($fp === false) {
    throw new InvalidConfigException("Unable to append to log file: {$this->logFile}");
}
flock($fp, LOCK_EX);
if ($this->enableRotation && $fileSize > ($this->maxFileSize * 1024)) {

and clear file by 'w' mode

private function clearLogFile($rotateFile)
{
    $fp = fopen($rotateFile, 'w');
    if ($fp !== false) {
        fclose($fp);
    }
}

[stu2162583]

Thank you, after testing, there are still some problems.

I tested a rotateByCopy=true before, and the data in the source code was changed to:

if ($this->enableRotation && @filesize($this->logFile) > $this->maxFileSize * 1024) {
	@flock($fp, LOCK_UN);
	@fclose($fp);
	$this->rotateFiles();

It was changed to prevent windows from reporting errors.

if ($this->enableRotation && @filesize($this->logFile) > $this->maxFileSize * 1024) {
	$this->rotateFiles();
	@flock($fp, LOCK_UN);
	@fclose($fp);

It seems possible.

[WinterSilence]

@stu2162583 you must unlock file before do something with him

[stu2162583]

@stu2162583 you must unlock file before do something with him

What is this for? Are you afraid of affecting the file handle?
The operation after the lock was changed in version 2.16, and the previous versions were operated before the lock was released.
And if you don't operate in locks, will there be a problem of concurrent rotate?

[bizley]

@stu2162583 could you point the change in 2.0.16 that is the cause of that?

[stu2162583]

@stu2162583 could you point the change in 2.0.16 that is the cause of that?

#3563

2.0.16 https://github.com/yiisoft/yii2/blob/2.0.16/framework/log/FileTarget.php
2.0.15.1 https://github.com/yiisoft/yii2/blob/2.0.15.1/framework/log/FileTarget.php

[bizley]

So the only thing is that previously file was rotated and then lock was released, after the change it's the other way around. And the change is here made because of that comment by @nadirvishun

[WinterSilence]

@stu2162583 need unlock file before do something with him.

[stu2162583]

@bizley

Yes, he mentioned that the file must be renamed and then closed, but only if it is in a windows environment and rotateByCopy=false.

so, what to do next

[stu2162583]

@WinterSilence

Sorry, I don't know much about lock, what is the reason for doing this

[bizley]

Looks like we could adjust the process based on the selected options if this is only a matter of type of rotating and the OS.

[stu2162583]

Looks like we could adjust the process based on the selected options if this is only a matter of type of rotating and the OS.

It looks like this, after your testing, make sure.

Waiting for good news.

We are now self-adjusting to no longer limit the number of logs, and we have changed the lock position, and now the log appears to be full.

[mikehaertl]

Sorry, I don't know much about lock, what is the reason for doing this

@stu2162583 See this note in the PHP manual on flock():

flock() uses mandatory locking instead of advisory locking on Windows.

For the difference check e.g. this:

With the mandatory file-locking mechanism implemented, once a process acquires an exclusive lock, the operating system will prevent any other process from access the locked file. With such mechanism in place, the operating system will prevent access to the locked file until the exclusive lock is released.

On the other hand, an advisory mechanism provided by the operating system allows processes to find the status of locks and decide what to do. With such mechanism it is up to the process to ensure that the file lock is appropriately acquired and released.

That's why the behavior is different on Linux/Windows. IMO we should check the OS and use the apropriate logic accordingly.

[stu2162583]

Sorry, I don't know much about lock, what is the reason for doing this

@stu2162583 See this note in the PHP manual on flock():

flock() uses mandatory locking instead of advisory locking on Windows.

For the difference check e.g. this:

With the mandatory file-locking mechanism implemented, once a process acquires an exclusive lock, the operating system will prevent any other process from access the locked file. With such mechanism in place, the operating system will prevent access to the locked file until the exclusive lock is released.

On the other hand, an advisory mechanism provided by the operating system allows processes to find the status of locks and decide what to do. With such mechanism it is up to the process to ensure that the file lock is appropriately acquired and released.

That's why the behavior is different on Linux/Windows. IMO we should check the OS and use the apropriate logic accordingly.

thanks, i'll take a look

[mikehaertl]

@stu2162583 Is this a site with heavy load? If that's the case then it's probably another (parallel) process that locks the file immediately after your current process released the lock. That's why the file can neither be moved nor truncated.

[mikehaertl]

Ok I would say that we should never release any lock before rotation. This will always cause concurreny issues. A fix should probably:

• Keep flock() active until writing + rotation is done
• Disable Ignore rotateByCopy for Windows systems and make it true there by default

[mikehaertl]

After more analysis I would go so far and say that there's no easy fix. What we basically want is a mutex here. We try to re-implement it with file based locks. But that's a problem if the file that is used for locking is moved, which happens by default during rotation. In any case we have to keep the mutex-lock until all file processing is done.

I see only 2 reliable fixes:

• Keep the lock until end and always rotate by copying the file - even on Linux. Otherwhise there's always a concurrency issue. It never popped up on Linux because of advisory locking. But the current implementation is flawed and can cause log file inconsitencies on any OS. The higher cost of copying is probably neglectable. It could only be a problem when log files are huge and disk space is low.
• Alternatively refactor locking completely and use a dedicated lock file, like $this->logFile . '.lck'. This would work on any OS and basically re-implement what FileMutex does.

Using the mutex app component is not really an option as logging is crucial and must always work. But mutex could be broken if the developer configured a DB mutex and DB is gone. In that case we would not have any logs.

[WinterSilence]

@mikehaertl solution from PHP manual:

Because flock() requires a file pointer, you may have to use a special lock file to protect access to a file that you intend to truncate by opening it in write mode (with a "w" or "w+" argument to fopen()).

or by using flock() parameter $would_block

The optional third argument is set to 1 if the lock would block (EWOULDBLOCK errno condition).

[mikehaertl]

solution from PHP manual:

That was my second suggestion above.

or by using flock() parameter $would_block

This has nothing to do with it (also see here). We already block execution until the lock file is released by the other process. It's the logic when/what to lock/unlock that is flawed.

[WinterSilence]

@mikehaertl

This has nothing to do with it.

why? we try re-lock file if $would_block === 1 and use LOCK_NB: flock(LOCK_EX | LOCK_NB);

[mikehaertl]

See the linked SO answer that I linked in my last comment above. $would_block is basically just a flag that indicates that something is seriously going wrong when accessing the lock file. This is not related to our problem.

And we already use the default of blocking mode. That's fine because we want a 2nd process to wait a (hopefully) short amount of time until the 1st process will release the lock. LOCK_NB is not what we want.

[stu2162583]

@stu2162583 Is this a site with heavy load? If that's the case then it's probably another (parallel) process that locks the file immediately after your current process released the lock. That's why the file can neither be moved nor truncated.

Yes, there is still some load.
Thank you for your reply.

[stu2162583]

In addition, this problem can also be reproduced in the linux production environment, but I am using the windows development environment, and I do not have a linux test environment locally.

Maybe the problem on linux can be solved by modifying the lock position.

[mikehaertl]

Both suggested fixes come with a cost (BC break). But I would vote for option 2:

• Fix too early release of lock file
• Drop rotateByCopy and make it the default (otherwise locking is still broken as the lock remains on the now renamed file)

Option 1 of using a separate lock file (e.g. app.log.lck) would require us to copy the logic from FileMutex or to create an instance of it. It could also lead to problems if that file can not be written to the log directory due to some restrictions.

@samdark @bizley What do you think? It's a bit surprising that this bug exists for many years now. It's also a somewhat sensitive part of the framework so I'm a bit hesitant with any changes there.

[bizley]

I agree with option 2 as well. @samdark ?

[bizley]

@samdark since this would introduce BC-break we need your approval.

[samdark]

Dropping rotateByCopy seems to be OK. Needs to be mentioned in UPGRADE though.