New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Log console output during replay to file #985 #76

Merged
merged 2 commits into from Oct 1, 2018

Conversation

4 participants
@cogutvalera
Member

cogutvalera commented Sep 17, 2018

PR for "Log console output during replay to file #985 bitshares/bitshares-core#985"

@abitmore

This comment has been minimized.

Member

abitmore commented Sep 17, 2018

Can you please briefly explain why change like this? There is no comment in your code.

@cogutvalera cogutvalera referenced this pull request Sep 17, 2018

Closed

Log console output during replay to file #985

5 of 9 tasks complete
@cogutvalera

This comment has been minimized.

Member

cogutvalera commented Sep 17, 2018

I can add comments right into code if required.
After debugging and researching code I've found the reason of this issue.

  1. During replay we can see logs in console but not in file because of next reason: fc::file_appender::impl::out (ofstream) is opened after rotate_files.
  2. So this means that ofstream will be opened after replay is completed and finished. Thus after replay we can see the same logs in console and file.
  3. Now after my changes ofstream is opened before replay happens. So this solution makes possible to see logs not only in console during replay but also we can see the same logs in file according to configuration in config.ini or logging.ini.
if(!my->cfg.rotate)
my->out.open( my->cfg.filename, std::ios_base::out | std::ios_base::app);
{
fc::scoped_lock<boost::mutex> lock( my->slock );

This comment has been minimized.

@jmjatlanta

jmjatlanta Sep 17, 2018

As this is a constructor, I do not see the need for a lock here.

This comment has been minimized.

@cogutvalera

cogutvalera Sep 17, 2018

Member

we have different threads, that's why I've added lock here, IMHO slock mutex is supposed to be used for log files within different threads, maybe I'm wrong.

Thanks !

@@ -141,9 +160,11 @@ namespace fc {
{
fc::create_directories(my->cfg.filename.parent_path());
if(!my->cfg.rotate)

This comment has been minimized.

@jmjatlanta

jmjatlanta Sep 17, 2018

I haven't walked all of the code, but if rotate == true, will removing this cause open() to be called twice (once here, and once in rotate_files()) ?

This comment has been minimized.

@cogutvalera

cogutvalera Sep 17, 2018

Member

if rotate check was removed, and twice won't be open because there is a check in open_log_filename method

@abitmore

Need better abstraction / modularization.

@@ -57,21 +69,30 @@ namespace fc {
}
}
void open_log_filename()

This comment has been minimized.

@abitmore

abitmore Sep 18, 2018

Member

This function name is confusing. I'd recommend rename it to open_log_file() or something else that can describe the logic better.

In addition, the check for file name inside the function made it even harder to understand, I think it would be better to move out the check, e.g. have an open() simply opens a file or perhaps close then reopen, and only call it when necessary (aka with a check).

In short, try to simplify the code.

fc::time_point _now;
fc::time_point_sec _start_time;
string _timestamp_string;
fc::path _old_log_filename, _log_filename, _link_filename;

This comment has been minimized.

@abitmore

abitmore Sep 18, 2018

Member

For member variables, please declare only one variable per line.

line << std::setw( 21 ) << (m.get_context().get_thread_name().substr(0,9) + string(":") + m.get_context().get_task_name()).c_str() << " ";
line << std::setw( 21 ) <<
(m.get_context().get_thread_name().substr(0,9) + string(":") + m.get_context().get_task_name()).c_str()
<< " ";

This comment has been minimized.

@abitmore

abitmore Sep 18, 2018

Member

The code style here looks a bit ugly. I'd prefer

line << "something"
     << "something else"
     << "the end";       
@@ -141,9 +160,7 @@ namespace fc {
{
fc::create_directories(my->cfg.filename.parent_path());

This comment has been minimized.

@abitmore

abitmore Sep 18, 2018

Member

Why not move the whole logic into constructor of impl class for simplicity? All operation is done on my anyway.

This comment has been minimized.

@cogutvalera

cogutvalera Sep 19, 2018

Member

I thought the same earlier, I agree it would be better ! Thanks !

@cogutvalera

This comment has been minimized.

Member

cogutvalera commented Sep 19, 2018

pushed new commit "more improvements"

Thanks !

@pmconrad

This comment has been minimized.

pmconrad commented Sep 19, 2018

So this means that ofstream will be opened after replay is completed and finished.

Why is this so?
file_appender::impl calls rotate_files asynchronously from the constructor. Either there's something wrong with the call, or the async excution happens only after replay. In the latter case, the obvious (and much simpler) fix would be to make the initial rotate_files call synchronous.

if( cfg.rotate )
{
FC_ASSERT( cfg.rotation_interval >= seconds( 1 ) );
FC_ASSERT( cfg.rotation_limit >= cfg.rotation_interval );

This comment has been minimized.

@abitmore

abitmore Sep 19, 2018

Member

I think these assertions should be put before creating log file, even before setup_log_filenames.

}
catch( ... )
{
std::cerr << "error opening log file: " << cfg.filename.preferred_string() << "\n";

This comment has been minimized.

@abitmore

abitmore Sep 19, 2018

Member

Is the appender usable after caught an exception here? What will happen when trying to write?

_old_log_filename = _log_filename;
open_log_file();
}

This comment has been minimized.

@abitmore

abitmore Sep 19, 2018

Member

The logic seems a bit strange.

  • Is there a chance that the file got closed but not reopened?
  • Is there a chance that the file be opened again when not closed?
@abitmore

This comment has been minimized.

Member

abitmore commented Sep 19, 2018

the obvious (and much simpler) fix would be to make the initial rotate_files call synchronous.

Probably because rotate_files() also removes old files that could take some time, thus not good to call on initialization. However, even it's the case, we can skip the removal on first call.

By the way, I guess the rotate_files(1) call is defensive? Looks like it will never be called.

@cogutvalera

This comment has been minimized.

Member

cogutvalera commented Sep 21, 2018

(just for the info) I've pushed 2 new commits:

  1. reverted all changes made before to current master branch
  2. Log console output during replay to file #985 (2nd simpler solution)
@pmconrad

If we decide to merge the second version, you should rebase -i to get rid of the first version. But not yet.

@@ -137,18 +134,7 @@ namespace fc {
file_appender::file_appender( const variant& args ) :
my( new impl( args.as<config>( FC_MAX_LOG_OBJECT_DEPTH ) ) )
{
try
{
fc::create_directories(my->cfg.filename.parent_path());

This comment has been minimized.

@pmconrad

pmconrad Sep 21, 2018

I think this must be moved to impl::impl(), not simply removed.

{
fc::create_directories(my->cfg.filename.parent_path());
if(!my->cfg.rotate)

This comment has been minimized.

@pmconrad

pmconrad Sep 21, 2018

...and this shouldn't be removed.

@cogutvalera

This comment has been minimized.

Member

cogutvalera commented Sep 21, 2018

I've cleaned up my previous changes with 1st solution and forced new push commit

@abitmore

This comment has been minimized.

Member

abitmore commented Sep 21, 2018

@cogutvalera: Peter said "not yet". He mean you should NOT rebase by now. Then you did it regardless :-/

@cogutvalera

This comment has been minimized.

Member

cogutvalera commented Sep 21, 2018

If we decide to merge the second version, you should rebase -i to get rid of the first version. But not yet.

IMHO the 2nd solution is simpler and it works as required, then why to rebase "not yet" ?

try
{
fc::create_directories(cfg.filename.parent_path());

This comment has been minimized.

@pmconrad

pmconrad Sep 24, 2018

create_directories should happen before rotate_files.

@pmconrad

This comment has been minimized.

pmconrad commented Sep 24, 2018

The idea was to preserve the original version in case my ideas didn't work. I'm ok with the rebase if it does work as intended.

@pmconrad

This comment has been minimized.

pmconrad commented Sep 24, 2018

Thanks! @abitmore @jmjatlanta please re-review.

@jmjatlanta

This comment has been minimized.

jmjatlanta commented Sep 25, 2018

There may be an edge case here that we may want to fix, but the chances of it happening are very remote. Scenario: Destructor called, then rotate_files gets the lock.

I am okay with that being there, as the file_appender is typically only destroyed at program exit, and the problem has probably been there from before this issue was opened.

@cogutvalera

This comment has been minimized.

Member

cogutvalera commented Sep 28, 2018

@pmconrad @jmjatlanta Thanks guys !

@pmconrad pmconrad merged commit 8e1b47a into bitshares:master Oct 1, 2018

1 check passed

continuous-integration/travis-ci/pr The Travis CI build passed
Details
@cogutvalera

This comment has been minimized.

Member

cogutvalera commented Oct 1, 2018

Thanks !

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment