Skip to content

[RFC] refactor logging #309

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

Closed
wants to merge 10 commits into from

Conversation

christiankerl
Copy link
Contributor

I started to refactor the logging. this allows to configure the log level and change log output to something else than console. default behavior produces almost identical output as the current implementation (messages are now prefixed with the log level). I tried to keep the api as simple as possible and to avoid global state.

TODO:

  • refactor remaining classes to use new logging api (I will do this as soon as we agree on the api)
  • decide whether Freenect2 owns the Log instance passed to Freenect2::setLog(...)

…nto refactor_logging

Conflicts:
	examples/protonect/CMakeLists.txt
…d Freenect2 to manage lifetime of Log instance
@floe
Copy link
Contributor

floe commented Jun 27, 2015

Since this is a rather large changeset, can I suggest to delay this until 0.2? Otherwise, most PRs which are still pending for 0.1 might have to be rebased/re-merged...

@christiankerl
Copy link
Contributor Author

if we merge this as last 0.1 PR? just thought it would be good not to print to console in a released library

@floe
Copy link
Contributor

floe commented Jun 29, 2015

OK, good point; let's do that. I was mostly thinking that for 0.1 to be completed sometime soon, we shouldn't add a lot more PRs, because that will drive up the number of merge conflicts and delay a release.

@xlz
Copy link
Member

xlz commented Jun 29, 2015

Can you add a feature to configure log level with an environment variable? This is usual practice in libraries. And getenv is in C standard.

@christiankerl
Copy link
Contributor Author

@xlz can you give some example of a library doing this? what if multiple programs use libfreenect2 and want different log levels? what should be the name?LIBFREENECT2_LOG_LEVEL? And should the values be strings (uppercase/lowercase/doesn't matter?) or numbers?

@xlz
Copy link
Member

xlz commented Jun 29, 2015

https://github.com/libusb/libusb/blob/c141457debff6156b83786eb69b46d873634e5bd/libusb/core.c#L1985-L2017 for example. It is to make debugging easier without having to recompile. Of course it will be turned off by default (the environment variable does not exist without user creation), and will not interfere with multiple programs using libfreenect2.

The rest does not matter.

@christiankerl
Copy link
Contributor Author

@xlz I implemented the changes you requested

one more question: should the log level be copied from the old logger to the new one if setLogger is called?

@xlz
Copy link
Member

xlz commented Jun 30, 2015

@christiankerl If log level is part of a logger then yes. Copying an object should include its property.

@xlz
Copy link
Member

xlz commented Jul 1, 2015

I'm not sure if I understood the question correctly. There is some ambiguity to simple answer yes or no. Anyway I expect log level to be a property of Logger, not a property of the user of Logger.

@christiankerl
Copy link
Contributor Author

basically if the logger is changed with freenect2::setlogger should this new logger get the log level of the previous one?

@xlz
Copy link
Member

xlz commented Jul 1, 2015

I expect user will set the desired log level when creating the new Logger. And the new logger should use the new log level. I guess the dilemma is when the user does not do that, should it use the default log level from the default constructor, or use the previous explicitly set log level in the old logger.

If the objective is to allow the user to do less work, I think you can add something like user_log_level to Logger which stores input from API calls and override implicit defaults and will be copied to new logger by setLogger() if the new logger has no explicitly set log level. If both have explicitly set log level then use the one of the new logger. Then again there is the log level from environment variables. Prioritizing with several implicit behaviors gets confusing really fast.

The simplest thing to do is design the API such that the user has to set the log level during/after creating a new Logger. And make it very clear to the user.

@christiankerl
Copy link
Contributor Author

ok I changed the api such that the logger level can only be changed by creating a new logger, this ensures that the user is aware which logger and level he wants to use

@christiankerl
Copy link
Contributor Author

@floe @xlz is the api fine for you? then i would refactor the remaining code...

@floe
Copy link
Contributor

floe commented Jul 8, 2015

Yes, this looks very sensible to me.

@laborer2008
Copy link
Contributor

I believe that a good loging system should strictly point to the line of code in the sources.
C and C++ have __LINE__, __FILE__ and __PRETTY_FUNCTION__/__FUNCSIG__/__func__ macros for this.

@xlz
Copy link
Member

xlz commented Jul 8, 2015

@christiankerl API is fine.

@laborer2008 The code is changing a lot. Line numbers in log will be confusing. Also, none of the function macros are in C++98 standard. It seems __FUNCTION__ works in gcc, various versions of msvc, and probably clang.

@laborer2008
Copy link
Contributor

xlz, you are right. Line numbers are distracting. But they can help novices to get to know sources and debug the library. In my projects I prefer to implement such a feature to be switchable at compile time. __LINE__ and __FILE__ are portable. For gcc/icc/clang/whatever compatible I would use __PRETTY_FUNCTION__ for msvc - __FUNCSIG__ and for other compilers (if any) - nothing.

@xlz
Copy link
Member

xlz commented Jul 8, 2015

@laborer2008 If you take a look at log messages in the current code, most are unique enough for locating the functions, and specific lines. A __CLASS__ macro would help to remove the duplicating class names in every log messages. It can be extracted from __PRETTY_FUNCTION__/__FUNCSIG__, yes.

@christiankerl
Copy link
Contributor Author

ok, I included __PRETTY_FUNCTION__/__FUNCSIG__, but didn't test on Windows/MacOSX, I could also add some parsing code to extract just class and method name, but I think it's fine this way?!

@xlz
Copy link
Member

xlz commented Jul 10, 2015

It might be too verbose. Log message would look like this:

[Warning] [void libfreenect2::Freenect2Impl::removeDevice(Freenect2DeviceImpl *)] tried to remove device, which is not in the internal device list!

@christiankerl
Copy link
Contributor Author

just updated all core classes except the packet processors to use the new logging api. one thing that seems somewhat hacky is how the logger is propagated from Freenect2DeviceImpl::onLoggerChanged() to the objects created by the packet pipeline -> ideas/comments are welcome

@xlz
Copy link
Member

xlz commented Jul 11, 2015

It is indeed quite hacky. AFAICT the usual reentrant library API design is first to create a single "context" instance which basically wraps global variables in a structure, and derive other structures which all hold a reference to the context. Then the logger is usually a member of the context.

@xlz
Copy link
Member

xlz commented Aug 12, 2015

@christiankerl What's your plan on this PR? I tried to add some libusb check messages but it would conflict with this PR.

Following the previous comment, my suggestion is that instead of inheriting WithLoggerImpl in several classes, add a Freenect2* context pointer to each of those classes, and pass the pointer to the main Freenect2 context through constructors of the classes. Then use #define LOG_DEBUG (::libfreenect2::LogMessage(context->logger() ....

If you are busy recently, I can take over the PR and let you review.

@xlz xlz mentioned this pull request Aug 16, 2015
@christiankerl
Copy link
Contributor Author

@xlz you can take over if you like. passing Freenect2 context basically changes WithLogger to a "WithContext" which somehow hides the intent that you just want to log something (imho). A simpler fix would be to pass a Logger**, which allows the logger to change without requiring notification of all WithLogger objects.

passing the logger/context to the ctors would require to change how/when PacketPipeline implementations create the objects (this was the reason for the "hack").

@xlz
Copy link
Member

xlz commented Aug 19, 2015

Agree. After another look, most classes do not hold a reference to the Freenect2 context, and do not need to.

@xlz
Copy link
Member

xlz commented Aug 19, 2015

OK, I forgot one thing. It is not just I want to log something. In the future there might be interoperation between OpenGL/OpenCL/CUDA/VAAPI etc, which requires coordination of API resources. This would need to put for example parent_opengl_context_ into Freenect2 as OpenCL/CUDA might access it.

Anyway (after a long hard look at the patch thinking about alternatives). It is painful to not use global state at all. Logging can appear anywhere in the code. So in theory WithLoggerImpl would be added or removed at will everywhere, and the logger reference would have to be passed everywhere. After you wrap it in Freenect2, and carefully pass it to every subclasses and friends, it is as good as a globally scoped variable except the scoping is done by hand. Passing Logger** in constructors or through onLoggerChanged() is the same thing only at different places.

The only use case of not using global state loggers is when the user creates two or more Freenect2 contexts, and sets different loggers for each context. I don't think this is an important enough use case to warrant messing up the codebase. There is already customization of the logger. Requiring the same logger for all Freenect2 contexts seems not unreasonable.

@xlz
Copy link
Member

xlz commented Aug 19, 2015

I also looked at roscpp. They use global variables to store loggers (contained in LogLocation).

@christiankerl
Copy link
Contributor Author

In the end I don't care. Change as you like I don't have time to work on this right now. However, the plumbing between opengl/opengl/cuda should/could be done in the packetpipeline.

@floe
Copy link
Contributor

floe commented Sep 4, 2015

Closing in favor of #364.

@floe floe closed this Sep 4, 2015
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants