diff --git a/groups/bal/ball/ball_asyncfileobserver.t.cpp b/groups/bal/ball/ball_asyncfileobserver.t.cpp index bac6c6f778..f60d40b5ec 100644 --- a/groups/bal/ball/ball_asyncfileobserver.t.cpp +++ b/groups/bal/ball/ball_asyncfileobserver.t.cpp @@ -18,6 +18,7 @@ #include #include #include +#include #include @@ -30,6 +31,7 @@ #include #include +#include #include #include @@ -394,18 +396,18 @@ int countLoggedRecords(const bsl::string& fileName) return numLines / 2; } -/// Wait (for up to 5 seconds) until the specified `observer` drains its -/// record queue (by processing all pending log records). -void waitEmptyRecordQueue( - bsl::shared_ptr observer) +/// Wait up until the specified `numSeconds` until the specified `observer` +/// drains its record queue (by processing all pending log records). +void waitEmptyRecordQueue(const ball::AsyncFileObserver *observer, + int numSeconds = 5) { bsls::Stopwatch timer; timer.start(); do { bslmt::ThreadUtil::microSleep(1000, 0); - } while (observer->recordQueueLength() > 0 - && timer.elapsedTime() < 5); + } while (observer->recordQueueLength() > 0 && + timer.elapsedTime() < numSeconds); ASSERTV(timer.elapsedTime(), observer->recordQueueLength(), @@ -418,32 +420,47 @@ void waitEmptyRecordQueue( /// `ball::FileObserver2::OnFileRotationCallback`. This class records every /// invocation of the function-call operator, and is intended to test /// whether `ball::FileObserver2` calls the log-rotation callback -/// appropriately. +/// appropriately. Note that this class is implemented with the "pimpl" +/// idiom os that copies of the functor will share the same reporting +/// information. class LogRotationCallbackTester { // PRIVATE TYPES struct Rep { - private: + private: // NOT IMPLEMENTED Rep(const Rep&); Rep& operator=(const Rep&); public: // DATA - int d_invocations; - int d_status; - bsl::string d_rotatedFileName; + int d_invocations; + int d_status; + bslmt::Latch *d_latch_p; + bsl::string d_rotatedFileName; // TRAITS BSLMF_NESTED_TRAIT_DECLARATION(Rep, bslma::UsesBslmaAllocator); // CREATORS - /// Create an object with default attribute values. Use the + /// Create an object with default attribute values, and use the /// specified `basicAllocator` to supply memory. explicit Rep(bslma::Allocator *basicAllocator) : d_invocations(0) , d_status(0) + , d_latch_p(0) + , d_rotatedFileName(basicAllocator) + { + } + + /// Create an object with default attribute values, arriving + /// on the specified `latch` on calls to `publish`, and using + /// specified `basicAllocator` to supply memory. + explicit Rep(bslmt::Latch *latch, bslma::Allocator *basicAllocator) + : d_invocations(0) + , d_status(0) + , d_latch_p(latch) , d_rotatedFileName(basicAllocator) { } @@ -457,6 +474,7 @@ class LogRotationCallbackTester { bsl::shared_ptr d_rep; public: + // CREATORS /// Create a callback tester object with default attribute values. Use @@ -467,6 +485,16 @@ class LogRotationCallbackTester { reset(); } + /// Create a callback tester object with default attribute values. Use + /// the specified `basicAllocator` to supply memory. + explicit LogRotationCallbackTester(bslmt::Latch *latch, + bslma::Allocator *basicAllocator) + { + d_rep.createInplace(basicAllocator, latch, basicAllocator); + reset(); + } + + // MANIPULATORS /// Set the value at the status address supplied at construction to the @@ -477,6 +505,9 @@ class LogRotationCallbackTester { ++d_rep->d_invocations; d_rep->d_status = status; d_rep->d_rotatedFileName = rotatedFileName; + if (d_rep->d_latch_p) { + d_rep->d_latch_p->arrive(); + } } /// Reset the attributes of this object to their default values. @@ -495,7 +526,7 @@ class LogRotationCallbackTester { int numInvocations() const { return d_rep->d_invocations; } /// Return the status passed to the most recent invocation of the - /// function-call operation, or `UNINITIALIZED` if `numInvocations` is + /// function-call operation, or `k_UNINITIALIZED` if `numInvocations` is /// 0. int status() const { return d_rep->d_status; } @@ -506,7 +537,6 @@ class LogRotationCallbackTester { { return d_rep->d_rotatedFileName; } - }; typedef LogRotationCallbackTester RotCb; @@ -982,7 +1012,7 @@ int main(int argc, char *argv[]) using namespace BALL_ASYNCFILEOBSERVER_RELEASERECORDS_TEST; - bslmt::Barrier barrier(3); + bslmt::Barrier barrier(3, bsls::SystemClockType::e_MONOTONIC); bsls::AtomicInt releaseCounter(500); bsl::function publisherFunctor = @@ -1004,7 +1034,7 @@ int main(int argc, char *argv[]) } while (0 != rc && bsls::SystemTime::nowMonotonicClock() < timeout); if (0 != rc) { - ASSERTV(0 && + ASSERTV(rc, 0 && "FAILURE: case 12 `releaseRecords` timed out (deadlock?)"); bsl::exit(testStatus); } @@ -1505,7 +1535,7 @@ int main(int argc, char *argv[]) } // Wait some time for async writing to complete. - waitEmptyRecordQueue(X); + waitEmptyRecordQueue(X.ptr()); fflush(stderr); bsl::fstream stderrFs; @@ -1560,312 +1590,204 @@ int main(int argc, char *argv[]) // all messages regardless of their severity and the observer will see // each message only once. - ball::LoggerManagerConfiguration configuration; - ASSERT(0 == configuration.setDefaultThresholdLevelsIfValid( - ball::Severity::e_TRACE)); - - ball::LoggerManagerScopedGuard guard(configuration); - - ball::LoggerManager& manager = ball::LoggerManager::singleton(); - -#ifdef BSLS_PLATFORM_OS_UNIX bslma::TestAllocator ta(veryVeryVeryVerbose); - int loopCount = 0; - int fileCount = 0; - bsl::string line(&ta); - - if (verbose) cout << "Test-case infrastructure setup." << endl; - { - // Create a temporary directory for log files. - bdls::TempDirectoryGuard tempDirGuard("ball_"); - bsl::string fileName(tempDirGuard.getTempDirName()); - bdls::PathUtil::appendRaw(&fileName, "testLog"); - - bsl::shared_ptr mX(new(ta) Obj(ball::Severity::e_OFF, - &ta), - &ta); - bsl::shared_ptr X = mX; - - mX->startPublicationThread(); - - ASSERT(0 == manager.registerObserver(mX, "testObserver")); - - BALL_LOG_SET_CATEGORY("ball::AsyncFileObserverTest"); - - if (verbose) cout << "Testing setup." << endl; - { - bsl::string fn_time = fileName + bsl::string(".%T"); - ASSERT(0 == mX->enableFileLogging(fn_time.c_str())); - ASSERT(true == X->isFileLoggingEnabled()); - ASSERT(1 == mX->enableFileLogging(fn_time.c_str())); - - BALL_LOG_TRACE << "log 1"; - - glob_t globbuf; - ASSERT(0 == glob((fileName + ".2*").c_str(), 0, 0, &globbuf)); - ASSERT(1 == globbuf.gl_pathc); - - // Wait for the async logging to complete. - waitEmptyRecordQueue(X); - - int logRecordCount = countLoggedRecords(globbuf.gl_pathv[0]); - ASSERTV(globbuf.gl_pathv[0], - logRecordCount, - 1 == logRecordCount); - - ASSERT(true == X->isFileLoggingEnabled()); - - globfree(&globbuf); - } - - if (verbose) cout << "Testing lifetime-constrained rotation." - << endl; - { - ASSERT(bdlt::DatetimeInterval(0) == X->rotationLifetime()); + BALL_LOG_SET_CATEGORY("TestCategory"); + ball::Context context; + bdls::TempDirectoryGuard tempDirGuard("ball_"); - mX->rotateOnTimeInterval(bdlt::DatetimeInterval(0,0,0,3)); + if (veryVerbose) { + P(tempDirGuard.getTempDirName()) + } - ASSERT(bdlt::DatetimeInterval(0,0,0,3) == - X->rotationLifetime()); + bsl::string fileName(tempDirGuard.getTempDirName()); + bdls::PathUtil::appendRaw(&fileName, "caseTestingFileRotation"); - // Wait for [longer than] rotation interval and log new - // messages. - bslmt::ThreadUtil::microSleep(0, 4); + const ball::Severity::Level e_INFO = ball::Severity::e_INFO; - // Those logs will go into a file after rotation. - BALL_LOG_TRACE << "log 1"; - BALL_LOG_DEBUG << "log 2"; + if (verbose) { + cerr << "Testing `forceRotation`" << endl; + } + { + bslmt::Latch latch(1); + LogRotationCallbackTester rotationCb(&latch, Z); - // Wait up to 3 seconds for the rotation to complete. - bsls::Stopwatch timer; - timer.start(); - do { - bslmt::ThreadUtil::microSleep(1000, 0); - glob_t globbuf; - ASSERT( - 0 == glob((fileName + ".2*").c_str(), 0, 0, &globbuf)); - fileCount = static_cast(globbuf.gl_pathc); - globfree(&globbuf); - } while (fileCount < 2 && timer.elapsedTime() < 3); + bsl::string fileName(tempDirGuard.getTempDirName()); + bdls::PathUtil::appendRaw(&fileName, "caseTestingFileRotation_forceRotation"); - // Check that a rotation occurred. - glob_t globbuf; - ASSERT(0 == glob((fileName + ".2*").c_str(), 0, 0, &globbuf)); - ASSERTV(globbuf.gl_pathc, 2 == globbuf.gl_pathc); + Obj mX(ball::Severity::e_ERROR, &ta); - // Wait for the async logging to complete. - waitEmptyRecordQueue(X); + mX.setOnFileRotationCallback(rotationCb); + mX.startPublicationThread(); + mX.enableFileLogging(fileName.c_str()); - // Check the number of lines in the file. - ASSERT(2 == countLoggedRecords(globbuf.gl_pathv[1])); - globfree(&globbuf); - mX->disableTimeIntervalRotation(); + mX.publish(createRecord("Message 1", e_INFO, Z), context); + mX.stopPublicationThread(); + mX.startPublicationThread(); - // Wait for [longer than] rotation interval and log new - // message. - bslmt::ThreadUtil::microSleep(0, 4); + mX.forceRotation(); - BALL_LOG_FATAL << "log 3"; + latch.wait(); - // Check that no rotation occurred. - ASSERT(0 == glob((fileName + ".2*").c_str(), 0, 0, &globbuf)); - ASSERT(2 == globbuf.gl_pathc); + mX.publish(createRecord("Message 2", e_INFO, Z), context); + mX.stopPublicationThread(); - // Wait for the async logging to complete. - waitEmptyRecordQueue(X); + mX.disableFileLogging(); - ASSERT(3 == countLoggedRecords(globbuf.gl_pathv[1])); - globfree(&globbuf); + if (veryVerbose) { + P_(fileName); + P(rotationCb.rotatedFileName()); } - if (verbose) cout << "Testing forced rotation." << endl; - { - mX->disableTimeIntervalRotation(); - mX->forceRotation(); - - BALL_LOG_TRACE << "log 1"; - BALL_LOG_DEBUG << "log 2"; - BALL_LOG_INFO << "log 3"; - BALL_LOG_WARN << "log 4"; + int numRecordsFile1 = + countLoggedRecords(rotationCb.rotatedFileName()); + int numRecordsFile2 = countLoggedRecords(fileName); - // Check that the rotation occurred. - glob_t globbuf; - ASSERT(0 == glob((fileName + ".2*").c_str(), 0, 0, &globbuf)); - ASSERT(3 == globbuf.gl_pathc); + ASSERTV(numRecordsFile1, 1 == numRecordsFile1); + ASSERTV(numRecordsFile2, 1 == numRecordsFile2); + } + if (verbose) { + cerr << "Testing `rotateOnSize`" << endl; + } + { + bsl::string oneKbMessage(1024, 'x', Z); + bslmt::Latch latch(1); + LogRotationCallbackTester rotationCb(&latch, Z); - // Wait for the async logging to complete. - waitEmptyRecordQueue(X); + bsl::string fileName(tempDirGuard.getTempDirName()); + bdls::PathUtil::appendRaw(&fileName, "caseTestingFileRotation_rotateOnSize"); - ASSERT(4 == countLoggedRecords(globbuf.gl_pathv[2])); - globfree(&globbuf); - } - if (verbose) cout << "Testing size-constrained rotation." << endl; - { - bslmt::ThreadUtil::microSleep(0, 2); - ASSERT(0 == X->rotationSize()); - mX->rotateOnSize(1); - ASSERT(1 == X->rotationSize()); - for (int i = 0 ; i < 30; ++i) { - BALL_LOG_TRACE << "log"; + Obj mX(ball::Severity::e_ERROR, &ta); - // We sleep because otherwise, the loop is too fast to make - // the timestamp change so we cannot observe the rotation. + mX.setOnFileRotationCallback(rotationCb); - bslmt::ThreadUtil::microSleep(200 * 1000); - } + // Set the file size rotation to a very small value, so all records + // should rotate. - glob_t globbuf; - ASSERT(0 == glob((fileName + ".2*").c_str(), 0, 0, &globbuf)); - ASSERT(4 <= globbuf.gl_pathc); + mX.rotateOnSize(1); + mX.startPublicationThread(); + mX.enableFileLogging(fileName.c_str()); - // We are not checking the last one since we do not have any - // information on its size. - for (size_t i = 0; i < globbuf.gl_pathc - 3; ++i) { - bsl::ifstream fs; - fs.open(globbuf.gl_pathv[i + 2], bsl::ifstream::in); - fs.clear(); + mX.publish(createRecord(oneKbMessage, e_INFO, Z), context); + mX.stopPublicationThread(); + mX.startPublicationThread(); - ASSERT(fs.is_open()); + // Rotate on this next record. - bsl::string::size_type fileSize = 0; - bsl::string line(&ta); + mX.publish(createRecord(oneKbMessage, e_INFO, Z), context); + mX.stopPublicationThread(); + mX.startPublicationThread(); - while (getline(fs, line)) { - fileSize += line.length() + 1; - } - fs.close(); + latch.wait(); - ASSERT(fileSize > 1024); - } + // Disable roation. - int oldNumFiles = static_cast(globbuf.gl_pathc); - globfree(&globbuf); + mX.disableSizeRotation(); - ASSERT(1 == X->rotationSize()); - mX->disableSizeRotation(); - ASSERT(0 == X->rotationSize()); + mX.publish(createRecord(oneKbMessage, e_INFO, Z), context); + mX.stopPublicationThread(); + mX.startPublicationThread(); + mX.publish(createRecord(oneKbMessage, e_INFO, Z), context); + mX.stopPublicationThread(); + mX.startPublicationThread(); + mX.publish(createRecord(oneKbMessage, e_INFO, Z), context); - for (int i = 0 ; i < 30; ++i) { - BALL_LOG_TRACE << "log"; - bslmt::ThreadUtil::microSleep(50 * 1000); - } + mX.stopPublicationThread(); + mX.disableFileLogging(); - // Verify that no rotation occurred. - ASSERT(0 == glob((fileName + ".2*").c_str(), 0, 0, &globbuf)); - ASSERT(oldNumFiles == (int)globbuf.gl_pathc); - globfree(&globbuf); + if (veryVerbose) { + P_(fileName); + P(rotationCb.numInvocations()); } - mX->disableFileLogging(); - mX->stopPublicationThread(); - - // Deregister here as we used local allocator for the observer. - ASSERT(0 == manager.deregisterObserver("testObserver")); + ASSERTV(rotationCb.numInvocations(), 1 == rotationCb.numInvocations()); + } + if (verbose) { + cerr << "Testing `rotateOnTimeInterval`" << endl; } - - // Test with no timestamp. - if (verbose) cout << "Test-case infrastructure setup." << endl; { - // Create a temporary directory for log files. - bdls::TempDirectoryGuard tempDirGuard("ball_"); - bsl::string fileName(tempDirGuard.getTempDirName()); - bdls::PathUtil::appendRaw(&fileName, "testLog"); - bsl::shared_ptr mX(new(ta) Obj(ball::Severity::e_OFF, &ta), - &ta); + bslmt::Latch latch(1); + LogRotationCallbackTester rotationCb(&latch, Z); - bsl::shared_ptr X = mX; + bsl::string fileName(tempDirGuard.getTempDirName()); + bdls::PathUtil::appendRaw(&fileName, "caseTestingFileRotation_rotateOnTimeInterval"); - mX->startPublicationThread(); - bslmt::ThreadUtil::microSleep(0, 1); - ASSERT(0 == manager.registerObserver(mX, "testObserver")); - BALL_LOG_SET_CATEGORY("ball::AsyncFileObserverTest"); + Obj mX(ball::Severity::e_ERROR, &ta); - if (verbose) cout << "Testing setup." << endl; - { - ASSERT(0 == mX->enableFileLogging(fileName.c_str())); - ASSERT(X->isFileLoggingEnabled()); - ASSERT(1 == mX->enableFileLogging(fileName.c_str())); + bdlt::DatetimeInterval interval(0, 0, 0, 1); + mX.setOnFileRotationCallback(rotationCb); - BALL_LOG_TRACE << "log 1"; - - glob_t globbuf; - ASSERT(0 == glob((fileName + "*").c_str(), 0, 0, &globbuf)); - ASSERT(1 == globbuf.gl_pathc); - - // Wait for the async logging to complete. - waitEmptyRecordQueue(X); + // Enable roation on a 1s interval. Note that intervals < 1s are + // ignored. + mX.rotateOnTimeInterval(interval); + mX.enableFileLogging(fileName.c_str()); - ASSERT(1 == countLoggedRecords(globbuf.gl_pathv[0])); - globfree(&globbuf); - } + bdlt::Datetime startTime = bdlt::CurrentTime::utc(); + bdlt::Datetime rotationTime = startTime + interval; - if (verbose) cout << "Testing lifetime-constrained rotation." - << endl; - { - ASSERT(bdlt::DatetimeInterval(0) == X->rotationLifetime()); + ASSERTV(mX.rotationLifetime(), interval == mX.rotationLifetime()); - mX->rotateOnTimeInterval(bdlt::DatetimeInterval(0,0,0,3)); - ASSERT(bdlt::DatetimeInterval(0,0,0,3) == - X->rotationLifetime()); + mX.startPublicationThread(); + mX.enableFileLogging(fileName.c_str()); - bslmt::ThreadUtil::microSleep(0, 4); - BALL_LOG_TRACE << "log 1"; - BALL_LOG_DEBUG << "log 2"; + mX.publish(createRecord("Message 1", e_INFO, Z), context); + mX.publish(createRecord("Message 2", e_INFO, Z), context); + mX.publish(createRecord("Message 3", e_INFO, Z), context); - // Wait up to 3 seconds for the rotation to complete. + mX.stopPublicationThread(); + mX.startPublicationThread(); - loopCount = 0; - do { - bslmt::ThreadUtil::microSleep(0, 1); - glob_t globbuf; - ASSERT( - 0 == glob((fileName + "*").c_str(), 0, 0, &globbuf)); - fileCount = static_cast(globbuf.gl_pathc); - globfree(&globbuf); - } while (fileCount < 2 && loopCount++ < 3); + ASSERTV(rotationCb.numInvocations(), 0 == rotationCb.numInvocations()); - // Check that a rotation occurred. + // Delay so one rotation will occur on the next record. + while (bdlt::CurrentTime::utc() <= rotationTime) { + bslmt::ThreadUtil::microSleep(1000); + } - glob_t globbuf; - ASSERT(0 == glob((fileName + "*").c_str(), 0, 0, &globbuf)); - ASSERT(2 == globbuf.gl_pathc); + mX.publish(createRecord("Message 4", e_INFO, Z), context); + mX.publish(createRecord("Message 5", e_INFO, Z), context); + mX.publish(createRecord("Message 6", e_INFO, Z), context); - // Wait for the async logging to complete. - waitEmptyRecordQueue(X); + latch.wait(); + mX.stopPublicationThread(); + mX.startPublicationThread(); - ASSERT(2 == countLoggedRecords(globbuf.gl_pathv[0])); - globfree(&globbuf); + // Disable time rotation. + mX.disableTimeIntervalRotation(); - mX->disableTimeIntervalRotation(); - bslmt::ThreadUtil::microSleep(0, 4); - BALL_LOG_FATAL << "log 3"; - // Check that no rotation occurred. + // Delay enough that a rotation would have occured. + while (bdlt::CurrentTime::utc() <= rotationTime) { + bslmt::ThreadUtil::microSleep(1000); + } - ASSERT(0 == glob((fileName + "*").c_str(), 0, 0, &globbuf)); - ASSERT(2 == globbuf.gl_pathc); + mX.publish(createRecord("Message 7", e_INFO, Z), context); + mX.publish(createRecord("Message 8", e_INFO, Z), context); + mX.publish(createRecord("Message 9", e_INFO, Z), context); - // Wait for the async logging to complete. - waitEmptyRecordQueue(X); + mX.stopPublicationThread(); + mX.disableFileLogging(); - ASSERT(3 == countLoggedRecords(globbuf.gl_pathv[0])); - globfree(&globbuf); + if (veryVerbose) { + P_(fileName); + P(rotationCb.numInvocations()); } - mX->disableFileLogging(); - mX->stopPublicationThread(); + ASSERTV(rotationCb.numInvocations(), 1 == rotationCb.numInvocations()); - // Deregister here as we used local allocator for the observer. - ASSERT(0 == manager.deregisterObserver("testObserver")); + + int numRecordsFile1 = + countLoggedRecords(rotationCb.rotatedFileName()); + int numRecordsFile2 = countLoggedRecords(fileName); + ASSERTV(numRecordsFile1, 3 == numRecordsFile1); + ASSERTV(numRecordsFile2, 6 == numRecordsFile2); } -#endif } break; case 5: { // --------------------------------------------------------------------