Issue with log purging when FileChannel compression is enabled

[sdaly2107]

Expected behavior

Expect that rotated log count is consistent when compression enabled.

Actual behavior

When FileChannel compression is enabled, we sometimes see too many files being retained, or too little. Issues occurs around 1 in 20 runs.

Steps to reproduce the problem

-Open new FileChannel (flush false, 1 M rotation, 3 purge count, archive timestamp, times local, compress true)
-Log x1024 1Kb messages 5 times
-Close fine channel
-Expected current log and 3 compressed archives - actually sometimes seeing 2 archives, and sometimes 5

Example code to reproduce -

static const uint32_t MAX_ROLLOVER_TIMES = 5;
static const uint32_t LONG_MESSAGE_LENGTH = 1024;
static const uint32_t LONG_MAX_FILESIZE = 1024;

std::vector<uint8_t> longMessage(LONG_MESSAGE_LENGTH, 0x40);
longMessage.push_back(0);

Poco::Path logsPath(Poco::Path::current(), "logs");
Poco::File logsDir(logsPath.toString());
logsDir.createDirectory();
logsPath.append("test.log");


Poco::AutoPtr<Poco::FileChannel> fileChannel = new Poco::FileChannel("ABC");
fileChannel->setProperty(Poco::FileChannel::PROP_PATH, logsPath.toString());
fileChannel->setProperty(Poco::FileChannel::PROP_FLUSH, "false");
fileChannel->setProperty(Poco::FileChannel::PROP_ROTATION, "1 M");
fileChannel->setProperty(Poco::FileChannel::PROP_PURGECOUNT, "3");
fileChannel->setProperty(Poco::FileChannel::PROP_ARCHIVE, "timestamp");
fileChannel->setProperty(Poco::FileChannel::PROP_TIMES, "local");
fileChannel->setProperty(Poco::FileChannel::PROP_COMPRESS, "true");

fileChannel->open();


std::string text(longMessage.begin(), longMessage.end());

for (uint32_t i = 1; i <= MAX_ROLLOVER_TIMES; ++i)
{
    for (uint32_t j = 0; j < LONG_MAX_FILESIZE; ++j)
    {
        Poco::Message message("ABC", text, Poco::Message::PRIO_INFORMATION);
        fileChannel->log(message);
    }

}

Poco::Thread::sleep(2000);
fileChannel->close();

POCO version

1.7.9

Compiler and version

VS2017 / v141

Operating system and version

Windows 10

Other relevant information

[preranamkhare]

Hi,
Is this issue fixed for linux platform and if yes which version ?

[github-actions]

This issue is stale because it has been open for 365 days with no activity.

[matejk]

Hi, Is this issue fixed for linux platform and if yes which version ?

@preranamkhare, do you get this issue in Linux. It was reported for Windows.

[matejk]

Reproducible with Poco 1.13 on macOS 14.2.

[matejk]

Root of the problem is that renaming, deletion and creating compressed files is handled independently in two threads inside ArchiveStrategy.cpp (compressImpl and moveFile).

The situation is even worse with numbered files because it is more likely that compression will try to process one of the files that is being renamed due to log rotation.

[matejk]

@aleks-f, @obiltschnig:

I see two possibilities to solve this issue:

• Introduce locking between renaming files and compression that also handles file names
• Perform log rotation after compression finishes with a new ActiveDispatcher in some way and serialise execution of those two
  • When compression is not enabled, only rotation dispatcher would be used

[matejk]

Additional investigation shows that PurgeStrategy would have to be synchronised with log file rotation and compression.