Skip to content
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

Clean up logging #2628

Closed
wants to merge 2 commits into from

Conversation

Projects
None yet
8 participants
@ShadowNinja
Copy link
Member

commented Apr 15, 2015

  • Remove the ugly C-style debug stream system, replacing it with the
    StreamLogOutput and FileLogOutput classes. dstream becomes just another
    log level, except that it's always printed. This adds timestamps and
    thread names to dstream'd messages, removing the need for the DTIME macro.
    dstream's old functionality is replaced by rawstream.
  • Move global logging functions into a Logger class and use a global logger.
  • Add (and use) warning log level.
  • Map Irrlicht log event levels to Minetest log event levels and shorten the
    prefix to "Irrlicht: ". This adds timestamps, thread names, and filtering
    to the Irrlicht log messages. EDIT: Merged as a938387.
  • Don't set the Irrlicht log level to the file log level as this affects
    console output too. Filter Irrlicht log messages ourselves instead (which we can do because the levels are mapped now).
  • Rename macros with two leading underscores (these names are reserved for
    the compiler/library implementation).
  • Fix some instances where threads didn't de-register themselves from logging.

To do:

  • Fix setLevelSilenced() so that it works only on the level passed, instead of all levels (this causes minetest --run-unittests --info to not print the Running Test* lines in infostream, because LL_ERROR was disabled, but it affected all log levels). -- (this was NOT introduced by these changes)
  • Fix Irrlicht not passing the main menu's "Loaded texture" messages to the event handler as log events, instead printing them directly to stdout with printf.
@est31

This comment has been minimized.

Copy link
Contributor

commented Apr 15, 2015

great this fixes #2263

@nerzhul

This comment has been minimized.

Copy link
Member

commented Apr 16, 2015

Seems good to me

@rubenwardy

This comment has been minimized.

Copy link
Member

commented Apr 17, 2015

+1 for adding warning level, this is needed.

@C1ffisme

This comment has been minimized.

Copy link

commented Apr 17, 2015

By the way, could you possibly make logging remove any text that is older than say, 2 years (customizable in minetest.conf)?

Debug.txt takes several MEGABYTES just having logs that don't matter anymore.

@ShadowNinja ShadowNinja force-pushed the ShadowNinja:cleanup-logging branch from 6e470e1 to 9a606f5 Apr 17, 2015

@ShadowNinja

This comment has been minimized.

Copy link
Member Author

commented Apr 18, 2015

Updated: Don't set Irrlicht's log level to the file log level (because it applies to console logging too), filter messages ourselves instead. I noticed a new bug while adding this, which may be an Irrlicht bug (it's rather hard to debug so I don't really know). Also makes the engine make more use of warningstream.

@C1ffisme: Yes, but I won't in this PR.

@ShadowNinja ShadowNinja force-pushed the ShadowNinja:cleanup-logging branch 3 times, most recently from 0d61c28 to 01a1d00 Apr 18, 2015

src/log.h Outdated
#endif
}; // namespace log

This comment has been minimized.

Copy link
@sfan5

sfan5 Apr 18, 2015

Member

namespace is called logging.

if (env == NULL) return 0
#define GET_ENV_PTR ServerEnvironment* env = \
dynamic_cast<ServerEnvironment*>(getEnv(L)); \
if (env == NULL) return 0

This comment has been minimized.

Copy link
@sfan5

sfan5 Apr 18, 2015

Member

This should be intended by another tab.
Also this isn't related to logging in any way

* differently than lua_tostring.
*/
lua_pushvalue(L, -1); // Copy tostring
lua_pushvalue(L, i); // Copy 'i'th parameter

This comment has been minimized.

Copy link
@sfan5

sfan5 Apr 18, 2015

Member

Why change something with the comments here?

{
return (id != "" && path != "");
}
bool isValid() const { return !id.empty() && !path.empty(); }

This comment has been minimized.

Copy link
@sfan5

sfan5 Apr 18, 2015

Member

How very related to logging...

This comment has been minimized.

Copy link
@Zeno-

Zeno- Jul 28, 2015

Contributor

Why is this now on one line?

Also, !(id.empty() || path.empty()) might be clearer

@ShadowNinja ShadowNinja force-pushed the ShadowNinja:cleanup-logging branch 4 times, most recently from a44ab94 to e705527 Apr 18, 2015

@ShadowNinja ShadowNinja removed the WIP label Apr 26, 2015

@ShadowNinja ShadowNinja force-pushed the ShadowNinja:cleanup-logging branch 3 times, most recently from 418e981 to 2530ca8 Apr 26, 2015

@ShadowNinja ShadowNinja referenced this pull request Apr 27, 2015

Closed

Clean up mod profiler #2655

@kwolekr

This comment has been minimized.

Copy link
Contributor

commented Apr 27, 2015

I like the addition of the warning stream, fixing Lua print(), but that's just about it.

After taking a closer look at the log.cpp refactor, I'm not sure it actually adds any value. I mean we have functions transformed into methods of a C++ class, but how does this make the code better? Like, just as a single example: The addition of LogOutputEntry. This is fundamentally a wrapper class around ILogOutput that separates out the silenced boolean. How does this added abstraction make anything cleaner? You're adding unnecessary shit that shouldn't really be there. And then the usage of operator overloading! I thought we agreed to not use operator overloading unless it would provide huge benefit otherwise.

And then as much as the code style is cleaned up, certain eccentricities still do exist.
For example, the if/else if string comparison chain for converting log string levels to enum values. This is completely against the style. I get that it may look neater because things are lined up, but I'm not convinced it's cleaner overall than the official style and it's un-uniform with the rest of the code too.

How do the rest of you feel about this?

@kwolekr

This comment has been minimized.

Copy link
Contributor

commented Apr 27, 2015

From a functional standpoint, this patch makes dstream become a standard logging level that cannot be disabled.

This goes against the whole point of dstream though! dstream is a minimal, debugging log facility detached from the standard logging system so that it works even in the case that standard logging has some sort of problem.

@ShadowNinja ShadowNinja force-pushed the ShadowNinja:cleanup-logging branch from 2530ca8 to e0d57b7 Apr 30, 2015

@ShadowNinja ShadowNinja force-pushed the ShadowNinja:cleanup-logging branch Jul 6, 2015

@ShadowNinja

This comment has been minimized.

Copy link
Member Author

commented Jul 6, 2015

@est31: I split the face_position_cache change out, but left it on this branch for now. I changed the .hpp to .h (we can discuss a switch later).

@ShadowNinja ShadowNinja force-pushed the ShadowNinja:cleanup-logging branch 4 times, most recently Jul 19, 2015

inline v3s16 arealim(v3s16 p, s16 d)
{
if(p.X < 0)

This comment has been minimized.

Copy link
@est31

est31 Jul 25, 2015

Contributor

From the kernel code style

Don't put multiple statements on a single line unless you have
something to hide:

    if (condition) do_this;
      do_something_everytime;

This comment has been minimized.

Copy link
@ShadowNinja

ShadowNinja Jul 25, 2015

Author Member

It helps if you put comments below the changed code so I don't have to search for it in the "Files changed" tab. Also, there's a clear difference between that example and this: The following line isn't deceptively indented here. But if that's what you want it can be done...

This comment has been minimized.

Copy link
@est31

est31 Jul 25, 2015

Contributor

In this case its even OK I think, because it appears in a long chain. Our code styles shouldn't stand in the way if something is obviously better. You can leave it I think.

@est31 est31 added the Rebase needed label Jul 25, 2015

namespace logging {

/* Use this for logging everything.
* If you need to explicitly print something, use cout or cerr.

This comment has been minimized.

Copy link
@est31

est31 Jul 27, 2015

Contributor

Perhaps revise this, as we have rawstream now?

This comment has been minimized.

Copy link
@ShadowNinja

ShadowNinja Jul 30, 2015

Author Member

rawstream is part of the logging setup, and this implies that the list is of non-logging utilities (dstream used to be separate from the logging facilities in log.h).

This comment has been minimized.

Copy link
@est31

est31 Jul 30, 2015

Contributor

I see, ok then.

@est31

View changes

src/log.cpp Outdated

log_threadnames.erase(id);
const std::string Logger::getLevelName(LogLevel lev)

This comment has been minimized.

Copy link
@est31

est31 Jul 27, 2015

Contributor

Why is this inside the class, and stringToLevel isn't?

This comment has been minimized.

Copy link
@ShadowNinja

ShadowNinja Jul 30, 2015

Author Member

Good question, I'm not sure...

This comment has been minimized.

Copy link
@ShadowNinja

ShadowNinja Jul 30, 2015

Author Member

Found the answer:
getLevelName returns a label for display when printing. It should probably be named getLevelLabel since it doesn't actually convert to the level's name (eg, LL_NONE becomes ""). It's in the Logger class since it's tied to the actual logging and isn't useful outside of the logger.

stringToLevel, on the other hand, is a utility that's used to convert a level name to a level (eg, "none" -> LL_NONE and "" -> error/LL_MAX).

This comment has been minimized.

Copy link
@est31

est31 Jul 30, 2015

Contributor

For my server terminal, I'll need getLevelLabel. Currently it only prints the level number as integer.

This comment has been minimized.

Copy link
@ShadowNinja

ShadowNinja Jul 30, 2015

Author Member

Huh? You mean it prints y-m-d h:m:s: 3[Thread]: instead of y-m-d h:m:s: ACTION[Thread]:?

This comment has been minimized.

Copy link
@est31

est31 Jul 30, 2015

Contributor

Only shows one loglevel here, code is not yet ready for PR.
screenshot
https://github.com/est31/minetest/tree/ncurses-console

This comment has been minimized.

Copy link
@ShadowNinja

ShadowNinja Jul 30, 2015

Author Member

That's an issue with your code then, not this PR, right?

This comment has been minimized.

Copy link
@est31

est31 Jul 30, 2015

Contributor

Yes, my code, I'm waiting for the method to get exposed, so that I can use it.

@est31

View changes

src/main.cpp Outdated
case 3: conf_loglev = "info"; break;
case 4: conf_loglev = "verbose"; break;
default:
warningstream << "Supplied invalid debug_log_level!" << std::endl;

This comment has been minimized.

Copy link
@est31

est31 Jul 27, 2015

Contributor

Perhaps use a sane default, instead of returning?

This comment has been minimized.

Copy link
@Zeno-

Zeno- Jul 28, 2015

Contributor

Strange style. I don't think the body of the case should be on the same line. Even if that was acceptable then default should follow the same style. I also agree that case 0: return is pretty yuck (it's almost hidden).

This comment has been minimized.

Copy link
@ShadowNinja

ShadowNinja Jul 30, 2015

Author Member

@est31: It defaults to "action" now.
@Zeno-: I restructured it, better?

@Zeno-

View changes

src/util/numeric.h Outdated
p.Y = d-1;
if(p.Z > d-1)
p.Z = d-1;
if (p.X < 0) p.X = 0;

This comment has been minimized.

Copy link
@Zeno-

Zeno- Jul 28, 2015

Contributor

Why are these on one line? (@est31 I don't think this should be ignored at all; it's bad style).

Also, unless (d - 1) can equal -1 then these should be more optimally arranged.

This comment has been minimized.

Copy link
@ShadowNinja

ShadowNinja Jul 30, 2015

Author Member

Split the lines. Also, what do you mean by more optimally?

@ShadowNinja ShadowNinja force-pushed the ShadowNinja:cleanup-logging branch 2 times, most recently Jul 30, 2015

@est31 est31 force-pushed the minetest:master branch to a890c66 Aug 2, 2015

@ShadowNinja ShadowNinja force-pushed the ShadowNinja:cleanup-logging branch 3 times, most recently to e163424 Aug 24, 2015

@ShadowNinja

This comment has been minimized.

Copy link
Member Author

commented Aug 24, 2015

@nerzhul: It seems you have a bot posting build status in comments, please disable that, I can see the status in the place GitHub provides for it.

ShadowNinja added some commits Jul 6, 2015

Clean up logging
  * Remove the ugly C-style debug stream system, replacing it with the
    StreamLogOutput and FileLogOutput classes.  dstream becomes just another
    log level, except that it's always printed.  This adds timestamps and
    thread names to dstream'd messages, removing the need for the DTIME macro.
    dstream's old functionality is replaced by rawstream.
  * Move global logging functions into a Logger class and use a global logger.
  * Add (and use) warning log level.
  * Don't set the Irrlicht log level to the file log level as this affects
    console output too.  Filter Irrlicht log messages ourselves instead.
  * Rename macros with two leading underscores (these names are reserved for
    the compiler/library implementation).
Clean up numeric.h and split FaceFositionCache from it
I also optiized FacePositionCache a bit: I removed a map
lookup and vector copy from both branches of getFacePosition.

@ShadowNinja ShadowNinja force-pushed the ShadowNinja:cleanup-logging branch from e163424 to ca3a282 Oct 7, 2015

@kwolekr

This comment has been minimized.

Copy link
Contributor

commented Oct 12, 2015

This commit is absurd.
Please, NEVER do this again. This is taking way too long to review because it's so large and unwieldy, and it's low priority but needs to be committed very fast due to the sheer number of dependencies, so it blocks all the higher priority tasks.

A refactor of something is welcome but please don't confuse a large number of line changes with being productive.

@rubenwardy

This comment has been minimized.

Copy link
Member

commented Oct 12, 2015

I don't get why you did s/__FUNCTION_NAME/FUNCTION_NAME/ that doesn't belong in this commit.

@kwolekr

This comment has been minimized.

Copy link
Contributor

commented Oct 12, 2015

Lots of things don't belong in this commit.

I'm splitting it into 6 separate ones:

  • the actual log refactor
  • one for the warningstream changes
  • __FUNCTION_NAME change
  • serverlist 'dedicated' announcement
  • Lua deprecation warning modification
  • Android startup modification

Beginning to wonder if it would be more beneficial/easier to scrap this PR and re-implement each component of what it does in a correct, appropriate manner.

@kwolekr

This comment has been minimized.

Copy link
Contributor

commented Oct 13, 2015

Another few things:

  • Stop squishing code blocks onto a single line.
  • Stop changing empty string comparisons to use empty().
  • Stop changing header.h includes to cheader.
  • Stop changing unsigned int, u32, or size_t to "unsigned".
  • Stop randomly adding underscores in variable names.

These are annoying and DO NOT HELP MINETEST AT ALL.

@kwolekr

This comment has been minimized.

Copy link
Contributor

commented Oct 15, 2015

@kwolekr kwolekr closed this Oct 15, 2015

@t4im t4im referenced this pull request Jun 4, 2016

Closed

add warning log level #2263

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.