Enhance scraper log archiving #1449

jamescowens · 2019-04-30T20:53:27Z

This commit implements putting the log archive files in the
logarchive subdirectory to prevent clutter.

It also implements deleting old log files per the following
configuration file (or command line) parameters:

deleteoldlogarchives=0|1 (default true)
logarchiveretainnumfiles=x (default 14)

deleteoldlogarchives defaults to true, which then means that
every time the log archiver is triggered (typically at midnight UTC)
it will archive the current scraper log file into the logarchive
directory, and then apply the rule to retain the x most recent files,
where x is specified by logarchiveretainnumfiles.

An immediate archive (and directory cleanup) can be triggered by issuing
the rpc command archivescraperlog.

If deletelogarchives is set to false, then the scraper.log files are
archived into the logarchive directory, but never deleted.

jamescowens · 2019-04-30T21:14:18Z

Note this is in scope for Denise. I have tested it on Linux and it works well. Testing on Windows (with the wide string stuff) now.

jamescowens · 2019-04-30T21:24:17Z

As usual, doesn't work on Windows. I must need an imbue... Nope that is not it. The archivescraperlog to force immediate archiving is not working on Windows. And I checked RC2 and it doesn't work there either...

cyrossignol

Tested, and it created the logarchive directory as expected. I dumped a bunch of old scraper log archives into it. The next housekeeping cycle didn't do anything because the PrevArchiveCheckDate ~~starts with today~~ seems to initialize with not_a_date_time on boot--fine. I ran archivescraperlog, and it deleted all but the 14 most recent archives. Great. I ran it again and it deleted the rest of the archives from the directory. Is that expected behavior?

jamescowens · 2019-04-30T22:48:26Z

Hmm... not supposed to do that.

src/scraper/scraper.cpp

This commit implements putting the log archive files in the logarchive subdirectory to prevent clutter. It also implements deleting old log files per the following configuration file (or command line) parameters: deleteoldlogarchives=0|1 (default true) logarchiveretainnumfiles=x (default 14) deleteoldlogarchives defaults to true, which then means that every time the log archiver is triggered (typically at midnight UTC) it will archive the current scraper log file into the logarchive directory, and then apply the rule to retain the x most recent files, where x is specified by logarchiveretainnumfiles. An immediate archive (and directory cleanup) can be triggered by issuing the rpc command archivescraperlog. If deletelogarchives is set to false, then the scraper.log files are archived into the logarchive directory, but never deleted.

jamescowens · 2019-04-30T23:22:49Z

For Windows, this part....

        {
            LOCK(cs_log);

            if (logfile.is_open())
            {
                logfile.flush();
                logfile.close();
            }

            plogfile = pathDataDir / "scraper.log";
            pfile_temp = pathDataDir / ("scraper-" + DateTimeStrFormat("%Y%m%d%H%M%S", nTime) + ".log");
            pfile_out = LogArchiveDir / ("scraper-" + DateTimeStrFormat("%Y%m%d%H%M%S", nTime) + ".log.gz");

            try
            {
                fs::rename(plogfile, pfile_temp);
            }
            catch(...)
            {
                LogPrintf("ERROR: Scraper: Logger: Failed to rename logging file\n");
                return false;
            }

I think doesn't work when another instance of the logger has a file handle open, for the same reason that we were having the problem with the dang client_state.xml file.

jamescowens · 2019-05-01T00:02:05Z

I will try to troubleshoot it tonight. The Linux build is working correctly now.

…

Sent from my iPhone

On Apr 30, 2019, at 7:34 PM, Cy Rossignol ***@***.***> wrote: @cyrossignol commented on this pull request. In src/scraper/scraper.cpp: > + + std::set<fs::directory_entry, std::greater <fs::directory_entry>> SortedDirEntries; + + // Iterate through the log archive directory and delete the oldest files beyond the retention rule + // The names are in format scraper-YYYYMMDDHHMMSS for the scraper logs, so filter by containing scraper + // The greater than sort in the set should then return descending order by datetime. + for (fs::directory_entry& DirEntry : fs::directory_iterator(LogArchiveDir)) + { + std::string sFilename = DirEntry.path().filename().string(); + size_t FoundPos = sFilename.find("scraper"); + + if (FoundPos != string::npos) SortedDirEntries.insert(DirEntry); + } + + // Now iterate through set of filtered filenames. Delete all files greater than retention count. + unsigned int i; I'll play with it a bit when I get home...don't have a Windows box to try it on at the moment. — You are receiving this because you were assigned. Reply to this email directly, view it on GitHub, or mute the thread.

jamescowens · 2019-05-01T02:00:20Z

I used Sysinternals Process Explorer to manually close the single file handle held open by the logger, and then ran archivescraperlog on my Windows testnet wallet. It worked. So this confirms the issue is trying to rename the file with another open handle on it. I think I have a solution. Will post new commit soon.

to work properly on Windows

jamescowens · 2019-05-01T03:12:19Z

Inelegant, but works. Tested on both Linux and Windows.

denravonska · 2019-05-01T03:58:58Z

src/scraper/scraper.cpp

@@ -304,6 +365,8 @@ void _log(logattribute eType, const std::string& sCall, const std::string& sMess

    log.output(sOut);

+    log.closelogfile();


I'm not sure I follow. Do we want to close the file each time we log?

We have to. There is no other way to do it. The performance loss is minimal. I already checked.

Don't we only need to close the file when we want to rotate?

Two threads are writing to that file. If one thread closes it before rotating, the other still has an open handle, so the rename won't work.

tomasbrod · 2019-05-01T08:24:09Z

src/scraper/scraper.cpp

@@ -304,6 +365,8 @@ void _log(logattribute eType, const std::string& sCall, const std::string& sMess

    log.output(sOut);

+    log.closelogfile();


I disagree with closing the log file after each message. The file should be closed WHEN archiving it. Two threads writing to the same file with two handles and two logger objects is bad design. A file should be opened by one instance of logger only and that instance must have mutex to lock when archiving.

If desired, the logging class can be split into backend and frontend. The backend holding only the mutex and file handle and frontend doing the formating and holding a reference to the backend. There can be then multiple frontends pointing to the same file and the archiving operation performed on the backend.

What I don't like about that we are not just renaming it. We are also compressing the file for archiving. The compression could take a while. The advantage of the approach as in the original scraper (before PR) and this PR is that the rename of the above file allows the archive process to work on the renamed file. The normal logging then immediately opens a new scraper.log file and continues writing and is not blocked by the compression process, which is acting on the renamed file.

Exerting a singleton pattern here will put the compression call in line with the rename, and the mutex will not be released for another use of the logger until the whole compression process is over.

So to recover that we would have to spawn a separate thread to do the compression. This is getting too complicated for the last minute to get Denise out the door.

I obviously am not suggesting to complicate matters TAHT much. Only the close-rename-reopen needs to be under the lock of mutex.

jamescowens · 2019-05-01T11:30:43Z

This is why I did not want to get into this at this stage in Denise. Now we are delaying the release for major surgery on the scraper logger. I am thinking about just removing the ability to instantly archive, which eliminates the second instance without major surgery. :|

…

Sent from my iPhone

On May 1, 2019, at 4:27 AM, Tomáš ***@***.***> wrote: @tomasbrod commented on this pull request. In src/scraper/scraper.cpp: > @@ -304,6 +365,8 @@ void _log(logattribute eType, const std::string& sCall, const std::string& sMess log.output(sOut); + log.closelogfile(); If desired, the logging class can be split into backend and frontend. The backend holding only the mutex and file handle and frontend doing the formating and holding a reference to the backend. There can be then multiple frontends pointing to the same file and the archiving operation performed on the backend. — You are receiving this because you were assigned. Reply to this email directly, view it on GitHub, or mute the thread.

cyrossignol

Retested the archivescraperlog command--works on Windows and Linux now 👍 Missed the window for the daily rotation last night I think, so I'm still waiting to observe that, but I don't see any obvious issues.

I'm not a big fan of reopening and closing the log file after each write either, but if we're talking about refactoring application-wide logging, maybe this problem will disappear in the next release.

jamescowens · 2019-05-01T14:04:27Z

Tomas, unless you really object, I would like to go with this as is. It works, and performs reasonably well. We need to overhaul the entire logging utility and combine the scraper and main logs together and implement Bitcoin's logging. This belongs in Elizabeth. It is too much to do at the last minute for Denise.

denravonska · 2019-05-01T14:26:54Z

@jamescowens I'd remove the RPC commands for manipulating the logs. It's a very niche use-case and I'd be surprised if we ever need it. If it simplifies the implementation then all the better.

jamescowens · 2019-05-01T16:18:31Z

I just tested on Linux and Windows, and that looks like it solved it. Nope first execution good on Windows, second failed.

jamescowens · 2019-05-01T16:33:37Z

I forgot to put the file reopen in the block containing the rename...

a la Bitcoin's newer approach.

jamescowens · 2019-05-01T17:15:56Z

Ok. Looks like it is fully working now. Please take a look. I would like to get this merged. I testing on both Linux and Windows...

denravonska · 2019-05-01T17:54:54Z

utACK as-is and we'll rewrite/fine tune for Elizabeth.

tomasbrod

Changing it later sounds good. I am unblocking this, but I cant test it.

jamescowens · 2019-05-01T18:01:45Z

@tomasbrod I tested on both Linux and Windows with the singleton pattern and it is working well... Merging.

cyrossignol · 2019-05-01T18:59:21Z

Late to the party... FWIW I was building...just tested and looks good!

jamescowens · 2019-05-01T19:19:53Z

Thanks @cyrossignol.

@jamescowens

Added: - Replace NeuralNetwork with portable C++ scraper #1387 (@jamescowens, @tomasbrod, @Cycy, @TheCharlatan, @denravonska). - Allow compile flags to be used for depends #1423 (@G-UK). - Add stake splitting and side staking info to getmininginfo #1424 (@jamescowens). - Add freedesktop.org desktop file and icon set #1438 (@a123b). Changed: - Disable Qt for windows Travis builds #1276 (@TheCharlatan). - Replace use of AppCache PROJECT section with strongly-typed structures #1415 (@cyrossignol). - Change dumpwallet to use appropriate data directory #1416 (@jamescowens). - Optimize ExtractXML() calls by avoiding unnecessary string copies #1419 (@cyrossignol). - Change signature of IsLockTimeWithinMinutes #1422 (@jamescowens). - Restore old poll output for getmininginfo RPC #1437 (@a123b). - Prevent segfault when using rpc savescraperfilemanifest #1439 (@jamescowens). - Improve miner status messages for ineligible staking balances #1447 (@cyrossignol). - Enhance scraper log archiving #1449 (@jamescowens). Fixed: - Re-enable full GUI 32-bit Windows builds - part of #1387 (@jamescowens). - Re-activate Windows Installer #1409 (@TheCharlatan). - Fix Depends and Travis build issues for ARM #1417 (@jamescowens). - Fix syncupdate icons #1421 (@jamescowens). - Fix potential BOINC crash when reading projects #1426 (@cyrossignol). - Fix freeze when unlocking wallet #1428 (@denravonska). - Fix RPC after high priority alert #1432 (@denravonska). - Fix missing poll in GUI when most recent poll expired #1455 (@cyrossignol). Removed: - Remove old, rudimentary side staking implementation #1381 (@denravonska). - Remove auto unlock #1402 (@denravonska). - Remove superblock forwarding #1430 (@denravonska).

jamescowens added this to the Denise milestone Apr 30, 2019

jamescowens self-assigned this Apr 30, 2019

jamescowens requested review from denravonska and cyrossignol and removed request for denravonska April 30, 2019 20:53

cyrossignol reviewed Apr 30, 2019

View reviewed changes

src/scraper/scraper.cpp Outdated Show resolved Hide resolved

jamescowens force-pushed the scraper_log_enhancement branch from 44f39dc to 94cb95a Compare April 30, 2019 23:17

Add closelogfile for scraper logger to allow archiving

de9732b

to work properly on Windows

jamescowens requested a review from cyrossignol May 1, 2019 03:28

denravonska reviewed May 1, 2019

View reviewed changes

tomasbrod suggested changes May 1, 2019

View reviewed changes

cyrossignol reviewed May 1, 2019

View reviewed changes

jamescowens force-pushed the scraper_log_enhancement branch from 63175c9 to 2fc6ca7 Compare May 1, 2019 16:31

jamescowens force-pushed the scraper_log_enhancement branch from 2fc6ca7 to 7dc3fa2 Compare May 1, 2019 16:41

Change the scraper logger to a singleton pattern

85274ea

a la Bitcoin's newer approach.

jamescowens force-pushed the scraper_log_enhancement branch from 7dc3fa2 to 85274ea Compare May 1, 2019 17:04

jamescowens requested review from denravonska, tomasbrod and cyrossignol May 1, 2019 17:16

denravonska approved these changes May 1, 2019

View reviewed changes

tomasbrod approved these changes May 1, 2019

View reviewed changes

jamescowens merged commit 920f664 into gridcoin-community:staging May 1, 2019

jamescowens deleted the scraper_log_enhancement branch October 23, 2019 00:05

		@@ -304,6 +365,8 @@ void _log(logattribute eType, const std::string& sCall, const std::string& sMess

		log.output(sOut);

		log.closelogfile();

Enhance scraper log archiving #1449

Enhance scraper log archiving #1449

Uh oh!

Conversation

jamescowens commented Apr 30, 2019

Uh oh!

jamescowens commented Apr 30, 2019

Uh oh!

jamescowens commented Apr 30, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

cyrossignol left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jamescowens commented Apr 30, 2019

Uh oh!

Uh oh!

jamescowens commented Apr 30, 2019

Uh oh!

jamescowens commented May 1, 2019 via email

Uh oh!

jamescowens commented May 1, 2019

Uh oh!

jamescowens commented May 1, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

denravonska May 1, 2019

Choose a reason for hiding this comment

Uh oh!

jamescowens May 1, 2019

Choose a reason for hiding this comment

Uh oh!

denravonska May 1, 2019

Choose a reason for hiding this comment

Uh oh!

cyrossignol May 1, 2019

Choose a reason for hiding this comment

Uh oh!

cyrossignol May 1, 2019

Choose a reason for hiding this comment

Uh oh!

tomasbrod May 1, 2019

Choose a reason for hiding this comment

Uh oh!

tomasbrod May 1, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jamescowens May 1, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

tomasbrod May 1, 2019

Choose a reason for hiding this comment

Uh oh!

jamescowens commented May 1, 2019 via email

Uh oh!

cyrossignol left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jamescowens commented May 1, 2019

Uh oh!

denravonska commented May 1, 2019

Uh oh!

jamescowens commented May 1, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jamescowens commented May 1, 2019

Uh oh!

jamescowens commented May 1, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

denravonska commented May 1, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

tomasbrod left a comment

Choose a reason for hiding this comment

Uh oh!

jamescowens commented Apr 30, 2019 •

edited

Loading

cyrossignol left a comment •

edited

Loading

jamescowens commented May 1, 2019 •

edited

Loading

tomasbrod May 1, 2019 •

edited

Loading

jamescowens May 1, 2019 •

edited

Loading

cyrossignol left a comment •

edited

Loading

jamescowens commented May 1, 2019 •

edited

Loading

jamescowens commented May 1, 2019 •

edited

Loading

denravonska commented May 1, 2019 •

edited

Loading