Bug 41199 - [patch] Enhance logging system
Summary: [patch] Enhance logging system
Status: RESOLVED FIXED
Alias: None
Product: Telepathy
Classification: Unclassified
Component: tp-qt (show other bugs)
Version: git master
Hardware: All All
: medium enhancement
Assignee: Daniele E. Domenichelli
QA Contact: Telepathy bugs list
URL:
Whiteboard: review+
Keywords: patch
Depends on:
Blocks:
 
Reported: 2011-09-25 17:13 UTC by Daniele E. Domenichelli
Modified: 2011-10-06 13:19 UTC (History)
2 users (show)

See Also:
i915 platform:
i915 features:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Daniele E. Domenichelli 2011-09-25 17:13:15 UTC
In kde-telepathy we would like to be able to get the debug output from TpQt4 and redirect it in KDebug in order, for example, to be able to redirect all the output of the application together with a TpQt4 output to a file.

This patch[1] adds a new method setDebugCallback that accepts a function pointer to a method that returns the output stream for debugging information.

Default behavior is unchanged.

[1]https://gitorious.org/drdanz-telepathy-kde/telepathy-qt4/commits/logging_enhancement
Comment 1 Olli Salli 2011-09-26 00:07:09 UTC
Initially commented on this on IRC, attempting to use gkiagia as a proxy, but then read your line about this bug :)

09:44 < oggis_> ... that looks somewhat useful, but you can only do limited things with it, especially because it has to return the debug object by-value, so any arbitrary QDebug subclass of yours is going to be sliced into a base QDebug
09:45 < oggis_> so also, this tpDebugCallback proposed would actually lose the KDebug part of the constructed debug object and it'd turn into a bare QDebug instead (however much that matters)
09:51 < oggis_> ... and I don't understand at all what's the problem about changing them wrt enabledDebug/enabledWarning - the ABI they need to maintain is their function signature, and they would do that just fine by starting to construct a Tp::Debug which has a QDebug pushing stuff to a string - it's still a Debug which they can use to have their debug messages go somewhere, just the internal QDebug object is changed a bit
09:51 < oggis_> then, the debug dtor would relay that to the callback (one has to move the dtor impl to the .cpp though)

Perhaps better would actually be to call to a enabledDebug() - style function in the dtor, but still mostly implement it in the private header. This fn would dig the callback from the static variable and pass the string and type there, if there is a callback.

Some other things:

typedef QDebug (*debugCallbackType)(QtMsgType type);

We name all types InThisFashion. This one would be Tp::DebugCallback then - and with the lot more flexible string passing approach, that'd be:

typedef void (*DebugCallback)(QtMsgType type, const QString &message);

Called by the Tp::Debug dtor via a exported (but not declared in an installed header) function looking at the static var holding it. It has to be exported so that the inlined Tp::Debug dtor invoc in tp-qt4-farsight can use it too, just like enabledDebug() & enabledWarning().
Comment 2 George Kiagiadakis 2011-09-26 02:46:14 UTC
(In reply to comment #1)
> 09:45 < oggis_> so also, this tpDebugCallback proposed would actually lose the
> KDebug part of the constructed debug object and it'd turn into a bare QDebug
> instead (however much that matters)

fyi, KDebug is not a subclass of QDebug. It's another object that is used as a C++ syntax trick to pass the __FILE__ and __LINE__ constants to kDebugStream(). In the end, it returns a QDebug object constructed with the QDebug(QIODevice*) constructor, which then redirects everything to the QIODevice.

So, redirecting to a file with Daniele's approach would be something like:

static QIODevice *s_file; //or better, Q/K_GLOBAL_STATIC

QDebug tpDebugCallback(QtMsgType type) {
    //possibly redirect to a different file or /dev/null depending on the type
    return QDebug(s_file);
}

int main() {
   ...
   s_file = new QFile("/foo/bar");
   Tp::setDebugCallback(tpDebugCallback);
   ...
}

And it is not limited at all, since you can create a QIODevice subclass and do anything (see kdebug.cpp for examples).

That said, I am not particularly in favor of one approach over the other. I think both approaches are similar in terms of possibilities and ease of use.
Comment 3 Olli Salli 2011-09-26 02:57:16 UTC
(In reply to comment #2)
> (In reply to comment #1)
> > 09:45 < oggis_> so also, this tpDebugCallback proposed would actually lose the
> > KDebug part of the constructed debug object and it'd turn into a bare QDebug
> > instead (however much that matters)
> 
> fyi, KDebug is not a subclass of QDebug. It's another object that is used as a
> C++ syntax trick to pass the __FILE__ and __LINE__ constants to kDebugStream().
> In the end, it returns a QDebug object constructed with the QDebug(QIODevice*)
> constructor, which then redirects everything to the QIODevice.

Ah, I see. In any case, you can't pass these constants from your debug callback, because all you'd see would be your debug callback's source file and line number.

> 
> So, redirecting to a file with Daniele's approach would be something like:
> 
> static QIODevice *s_file; //or better, Q/K_GLOBAL_STATIC
> 
> QDebug tpDebugCallback(QtMsgType type) {
>     //possibly redirect to a different file or /dev/null depending on the type
>     return QDebug(s_file);
> }
> 
> int main() {
>    ...
>    s_file = new QFile("/foo/bar");
>    Tp::setDebugCallback(tpDebugCallback);
>    ...
> }
> 
> And it is not limited at all, since you can create a QIODevice subclass and do
> anything (see kdebug.cpp for examples).
> 
> That said, I am not particularly in favor of one approach over the other. I
> think both approaches are similar in terms of possibilities and ease of use.

A particular limitation with returning a QDebug object is that you don't know when the object will be destroyed, so

1) you can't use the QString overload of the QDebug ctor (when to send the string forward?)

2) even if you use the QIODevice overload with some QIODevice guaranteedly outliving the debug object (such as a static object), you'll lose the boundaries between the debug messages - those being signaled by (Q)Debug object destruction. Note that some debug messages are legitimately multi-line. This might or might not be a problem to you, but I'd rather preserve them if anybody wants to do anything more specific than raw output to console or a file with them. (Think sending to an event log with timestamps per warning event, for example).
Comment 4 Daniele E. Domenichelli 2011-09-26 04:31:39 UTC
> 1) you can't use the QString overload of the QDebug ctor (when to send the
> string forward?)

The problem of passing the QString to the constructor of QDebug in enabledDebug/enabledWarning is that at the end of the method the string will be something like "tp-qt4 " PACKAGE_VERSION " DEBUG:" and I see no way to return the string after the operator<<() has been called for all the debug or to know when the string has been filled with the debug info.

Moreover if I create the QString inside enabledDebug it will be destroyed when the method exits, causing sigsegv for the following operator<<()s.

So you can either:
a) Use a pointer and allocate it on the heap, but it will be likely to leak the string because I see no way to know when it can be destroyed
b) Pass the string to the enabledDebug method, but it will break ABI
c) Use a static QString, but it might be a issue for multithreaded apps.


> 2) even if you use the QIODevice overload with some QIODevice guaranteedly
> outliving the debug object (such as a static object), you'll lose the
> boundaries between the debug messages - those being signaled by (Q)Debug
> object destruction. Note that some debug messages are legitimately
> multi-line. This might or might not be a problem to you, but I'd rather
> preserve them if anybody wants to do anything more specific than raw output
> to console or a file with them. (Think sending to an event log with
> timestamps per warning event, for example).

In my opinion this approach is safer because it simply consists in redirecting the debug into another QDebug, handled by the main application instead of by the library itself... The library doesn't need to care about when this QDebug is destroyed, because it will be destroyed like every other QDebug when it goes out of scope, that means after all the operator<<() are called.
You will still get the multiline debug in just one QDebug, exactly in the same way that you get it using qDebug() in enabledDebug.
Until your output is generated by just one debug() call, then it will be redirected all together in the QDebug returned by the callback method.
Comment 5 Olli Salli 2011-09-26 06:46:50 UTC
(In reply to comment #4)
> > 1) you can't use the QString overload of the QDebug ctor (when to send the
> > string forward?)
> 
> The problem of passing the QString to the constructor of QDebug in
> enabledDebug/enabledWarning is that at the end of the method the string will be
> something like "tp-qt4 " PACKAGE_VERSION " DEBUG:" and I see no way to return
> the string after the operator<<() has been called for all the debug or to know
> when the string has been filled with the debug info.
> 
> Moreover if I create the QString inside enabledDebug it will be destroyed when
> the method exits, causing sigsegv for the following operator<<()s.
> 
> So you can either:
> a) Use a pointer and allocate it on the heap, but it will be likely to leak the
> string because I see no way to know when it can be destroyed
> b) Pass the string to the enabledDebug method, but it will break ABI
> c) Use a static QString, but it might be a issue for multithreaded apps.

Yes, which is why I said that you can't use that ctor.

> 
> 
> > 2) even if you use the QIODevice overload with some QIODevice guaranteedly
> > outliving the debug object (such as a static object), you'll lose the
> > boundaries between the debug messages - those being signaled by (Q)Debug
> > object destruction. Note that some debug messages are legitimately
> > multi-line. This might or might not be a problem to you, but I'd rather
> > preserve them if anybody wants to do anything more specific than raw output
> > to console or a file with them. (Think sending to an event log with
> > timestamps per warning event, for example).
> 
> In my opinion this approach is safer because it simply consists in redirecting
> the debug into another QDebug, handled by the main application instead of by
> the library itself... The library doesn't need to care about when this QDebug
> is destroyed, because it will be destroyed like every other QDebug when it goes
> out of scope, that means after all the operator<<() are called.
> You will still get the multiline debug in just one QDebug, exactly in the same
> way that you get it using qDebug() in enabledDebug.
> Until your output is generated by just one debug() call, then it will be
> redirected all together in the QDebug returned by the callback method.

If you take care in reading what I wrote, both approaches in implementing the debug callback are faulty to me because the callback's role is wrong, and neither was proposed by me. 1 and 2 in my previous post are two specific problems in the approach where your "debug callback" constructs the QDebug instance i.e. rationale AGAINST that approach completely.

Are you following me with the (to me, anyway) still most flexible approach? I even described the implementation and the specific signature for the callback in comment 1. Having reasoned that such an approach is possible with no added complexity, I'm definitely not going to ever apply any patch based on an approach where I can readily identify these drawbacks.

Otherwise, I'm going to implement the more flexible approach myself, but can't give you any guarantees on WHEN that would happen.
Comment 6 Daniele E. Domenichelli 2011-09-26 15:17:59 UTC
I see at least 2 problems that add a lot of complexity in comparison to the first approach:

1) enableDebug returns a Tp::Debug by value, and this means that (depending on
   the compiler?) a copy of the object is created and then destroyed the first
   one destroyed when it goes out of scope. Therefore having a hook in the
   destructor of Tp::Debug means that the callback will be called at least
   twice (once per copy of the Tp::Debug)

2) Tp::Debug will have to store internally the QString. This QDebug(QString*)
   ctor doesn't allow to set a QtMsgType so it will have to be stored in
   Tp::Debug as well. The QDebug(QString*) constructor requires that the string
   is constructed before the QDebug in Tp::Debug ctors. Copy constructor and
   operator= cannot simply copy the QDebug* but must copy these as well. 
   Moreover they cannot copy the QDebug because the stream of the second will
   point at the QString in the first whose life might be shorter. It should
   create a new QDebug to its own QString and feed it with the other Tp::Debug's
   QString.

Anyway I tried to do it, but to keep the things as simple as possible, I
stored everything in a refcounted struct and kept a Tp::SharedPtr in Tp::Debug
class.
The callback function is called by the struct dtor instead of by Tp::Debug dtor.
Anyway I'm not sure if I can use the Tp::SharedPtr here... is there any reason
why I shouldn't?

Branch: https://gitorious.org/drdanz-telepathy-kde/telepathy-qt4/commits/logging_enhancement2

(if you change your mind and decide that you like the QDebug approach more I updated the logging_enhancement branch fixing the name of the function pointer type)
Comment 7 Daniele E. Domenichelli 2011-09-26 15:56:56 UTC
Sorry there was a bug, it should be fixed now
Comment 8 Olli Salli 2011-09-28 05:07:57 UTC
(In reply to comment #6)
> I see at least 2 problems that add a lot of complexity in comparison to the
> first approach:
> 
> 1) enableDebug returns a Tp::Debug by value, and this means that (depending on
>    the compiler?) a copy of the object is created and then destroyed the first
>    one destroyed when it goes out of scope. Therefore having a hook in the
>    destructor of Tp::Debug means that the callback will be called at least
>    twice (once per copy of the Tp::Debug)

Ahm, true, I overlooked this initial instance existing (and no, it doesn't depend on the compiler, the copy constructor and dtor being invoked when returning a non-POD value is a C++ language requirement AFAIK). As an empty debug message doesn't make sense, this could be alternatively solved by just skipping the callback invocation if the debug message is empty in the dtor. Of course, at the moment, the tp-qt4 <version> prefix is initially streamed to the debug object so it's non-empty already in enabledDebug(), but that could change - just prepend it to the string when forwarding to the callback instead (requires implementing the dtor in the .cpp, having access to config-version.h).

> 
> 2) Tp::Debug will have to store internally the QString. This QDebug(QString*)
>    ctor doesn't allow to set a QtMsgType so it will have to be stored in
>    Tp::Debug as well. The QDebug(QString*) constructor requires that the string
>    is constructed before the QDebug in Tp::Debug ctors. Copy constructor and
>    operator= cannot simply copy the QDebug* but must copy these as well. 
>    Moreover they cannot copy the QDebug because the stream of the second will
>    point at the QString in the first whose life might be shorter. It should
>    create a new QDebug to its own QString and feed it with the other
> Tp::Debug's
>    QString.

Yeah, my first hunch would be the string as a by-value member, and the QDebug (like now) as heap - then the string both is initialized first and deleted later. Copy ctor needs to copy the string (in initializer list preferably) and construct a new QDebug for the new instance, just like it does now.

QDebug needs to be heap-allocated in any case because it has been shown to have a very significant construction and destruction overhead (involving calls to get the current system time etc for whichever reason?!), which must be able to skipped completely when debug is disabled at runtime. For reference, this overhead is what causes the tp-qt4 unit tests to run about 10% faster when debug is disabled at runtime vs if it's enabled, and within 1% of how fast it runs if debug is disabled at compile time and all the debug operator<< calls get inlined to nothing.

This performance factor is actually rather important, because logging has found to be a major contributor to battery mobile drain etc whenever we get woken up for some event, print a debug for it but otherwise handle it relatively cheaply.

> 
> Anyway I tried to do it, but to keep the things as simple as possible, I
> stored everything in a refcounted struct and kept a Tp::SharedPtr in Tp::Debug
> class.
> The callback function is called by the struct dtor instead of by Tp::Debug
> dtor.
> Anyway I'm not sure if I can use the Tp::SharedPtr here... is there any reason
> why I shouldn't?

I see no functional problem with using Tp::SharedPtr, but it will add a performance overhead (both due to the added level of memory access indirection, and maintaining the reference count). This overhead must be avoided at least for the case where debug is disabled at runtime, but please investigate whether the solution with moving the prefix to the callback invocation time and skipping the initial empty debug message invocation would be clean enough, as it wouldn't need this overhead at all even with debug enabled.

The initial empty QString being copied is essentially free (the one in the instance local to enabledDebug()/enabledWarning()) as it'll be a Null QString, which doesn't need even the shared data refcount operations, rather than just an empty but non-null string (which does). That is, if the prefixing is moved to the point in time where the callback is invoked.

> 
> Branch:
> https://gitorious.org/drdanz-telepathy-kde/telepathy-qt4/commits/logging_enhancement2
> 
> (if you change your mind and decide that you like the QDebug approach more I
> updated the logging_enhancement branch fixing the name of the function pointer
> type)

Sorry, but I won't change my mind, having realized the drawback of losing the debug message boundaries implied in the approach that requires you to use QIODevice.

If you find the approach I suggested above for avoiding the need for a reference counting scheme too convoluted after implementing it, here's a few improvements needed for the current reference-counted implementation:
 - You don't need the current Debug copy ctor and operator= at all, they're exactly what the compiler would (perhaps more efficiently) generate for you. I believe you need them for any non-SharedPtr approach, though.
 - Debug::Private needs to be exported, because inline functions in Debug (that is, the ctors, the operator= and the dtor) use it, and hence tp-qt4-farsight needs to be able to link to it them (as the code invoking the ctor and dtor will then be in the tp-qt4-farsight library binary). Please attempt a build with export directive based symbol visibility enabled and all the tp-qt4-farsight deps installed with any approach to verify you got these things right.
 - An another way to solve the above issue: move the ctor and dtor implementations of Private to be inline in the -internal.h. Then there are no symbols generated for the Private class in the tp-qt4 main library at all, and then you can make the class NO_EXPORT. This requires the use of a small exported utility function digging the static debug callback variable out of the library though, like I suggested before. This would additionally make the dtor invocations able to be inlined wherever debug is used, and hence faster.
 - For clarity, Q_DISABLE_COPY Private, because copying it would mess it up (the first copy would delete the shared qdebug pointer and the second would still keep the same pointer, which'd dangle). With a shared pointer scheme for holding the Private, you don't need it to be copiable at all, so this is not a problem.
 - const QString& is not tp-qt4 style, const QString & is, even when there is no param name
 - I believe all the && p->debug branches are useless in the debug functions, as a Private instance always has a non-null Debug. You can verify by running this under make lcov-check with debug enabled and disabled at runtime - with debug and warnings enabled, the action is always invoked, and with them disabled the if condition short-circuits out already because the Private pointer is null

Otherwise looks good. It gave me an idea though, which makes me feel even better about the "only add the tp-qt4 DEBUG prefix when invoking the callback" approach. If we do that, we could pass the library name, the version and the debug message in separate params - and allow the receiver to build whichever format out of it they want (including the current, by using the message type param as well for printing DEBUG/WARNING).

That avoids a string copy + concatenation from our side for each debug message forwarded, but also allows the receiver to handle them separately. For example, it might be useful to omit the prefix, when you're going to push them to a tp-qt4 specific log category, perhaps even further split to debug/warning, already preserving this information. This'd allow you to enable/disable tp-qt4 debugs and warnings separately from KDebugDialog for each application separately, and not have redundant crap in the debug printouts.
Comment 9 Daniele E. Domenichelli 2011-09-30 14:04:30 UTC
I had to fight for hours against a stupid linkage problem (for some reason the linker doesn't like the extern function pointer in the unnamed namespace), but here[1] is a new patch that solves the problems checking if the string is empty instead of using shared pointers...

I also added the library name and version to the callback, removed the Private structure and hopefully resolved the other problems you pointed out.


[1]https://gitorious.org/drdanz-telepathy-kde/telepathy-qt4/commits/logging_enhancement
Comment 10 Olli Salli 2011-10-04 03:30:00 UTC
(In reply to comment #9)
> I had to fight for hours against a stupid linkage problem (for some reason the
> linker doesn't like the extern function pointer in the unnamed namespace), but
> here[1] is a new patch that solves the problems checking if the string is empty
> instead of using shared pointers...

Yes, the whole intent of the unnamed namespace concept in C++ is to mangle the symbol name in a compile unit (a .cpp file + what it includes, pretty much) specific fashion. Hence, extern linking from another compile unit will fail to find the symbol. The symbol will be in the .so, but its name will have some random crap added to it and hence it won't be found (but it won't conflict with symbols for other variables and functions with the same name either).

Also, there are other problems with sharing global variables between shared libraries, in initialization, in particular ordering. That's one reason why I suggested making the dtor call some small exported utility function which does the actual job of invoking the function pointer with the message. The other is:

debug-internal.h

25	25	
26	#include "config-version.h"
26	27	

This will cause the whole library to be recompiled when just the library version has been changed, because mostly everything includes debug-internal.h, and config-version.h changes when the version changes. I specifically split the version out of config.h so that this wouldn't happen. Note that there are two version number bumps in our standard review procedure and a full tp-qt4 recompile takes 5-10 minutes, so a full recompile on each version number bump is a rather frustrating issue.

This can be avoided if the exported utility function for invoking the ctor just takes the message type and debug message contents as a param. Being implemented in debug.cpp (but NOT in the anonymous namespace), it can access config-version.h and hence still pass the library name and version without debug-internal.h including that header.

40	    inline Debug(const Debug &a) : type(a.type), debug(new QDebug(&msg))

If a doesn't have a debug object (i.e. debug is disabled at runtime and enabledDebug() has used the default constructor), we have to prevent constructing a QDebug instance and streaming the message to it, like the old copy ctor did. This to avoid the prohibitive QDebug creation and destruction costs. Otherwise, I like your idea to use the streaming operator to shovel the old instance's current contents to the new one, as that ensures our debug instance writes to the string correctly etc. THOUGH: please verify it doesn't put "" around the original string as I think it might do. That would be ugly.

The assignment operator OTOH already looks good in this respect.

Otherwise looks good now, except that I don't see any way to restore the default debug behavior after e.g. setting a temporary callback for the duration of one operation in an application (or when some log capture option has been enabled). While exporting defaultDebugCallback in the public debug header (why does it need to be exported in the .so if it's just used for initializing the function pointer in the .cpp btw? or does it?) would be one solution, I think cleaner would be to document passing 0 (NULL) to setDebugCallback as restoring the default behavior, as it has no sensible meaning otherwise.

defaultDebugCallback being installed public API wouldn't make much sense to me; it being just a print formatting function.

This would also simplify the internals: you could just zero-init the debug callback function pointer. The magic new function which invokes the user-set debug callback if there is one, filling in the version info etc, would then just do what defaultDebugCallback being the callback currently does if the set callback is 0.

That'd also be, again, faster, because it doesn't go through the relocation table. Making defaultDebugCallback a non-exported inline function in the anon ns in debug.cpp (only present when debugging is enabled at compile time) would also achieve the same effect, if you feel this would make the body or role of the new magic invoker function too convoluted.

One thing in its implementation too:

qDebug() << qPrintable(libraryName) << qPrintable(libraryVersion) << "DEBUG:" << msg;

the library name and version are in the ASCII subset anyway. qPrintable will be a needless memory allocation and conversion, having no effect on the output. Or does that somehow get rid of the QDebug behavior of putting "" around printed QStrings? You can get rid of that by not making QStrings out of them in the first place (also needless memory alloc and copy), but just using preprocessor string concatenation like the old code did, as that yields a C string literal, not a QString.

With these refactors, please verify the library still compiles and works fine even if debugging is disabled at compile time (ENABLE_DEBUG_OUTPUT cmake variable). And when it's enabled at compile time, that both runtime enable and disable work, with the former producing sensible debug output with no formatting issues like stray " characters.

You can verify the runtime debug disable behavior by adjusting Test::initTestCaseImpl() in tests/lib/test.cpp, and running make check.
Comment 11 Daniele E. Domenichelli 2011-10-04 12:17:01 UTC
New version pushed (always here [1])


(In reply to comment #10)
> THOUGH: please verify it doesn't
> put "" around the original string as I think it might do. That would be ugly.
[...]
> One thing in its implementation too:
> 
> qDebug() << qPrintable(libraryName) << qPrintable(libraryVersion) << "DEBUG:"
> << msg;
> 
> the library name and version are in the ASCII subset anyway. qPrintable will be
> a needless memory allocation and conversion, having no effect on the output. Or
> does that somehow get rid of the QDebug behavior of putting "" around printed
> QStrings? You can get rid of that by not making QStrings out of them in the
> first place (also needless memory alloc and copy), but just using preprocessor
> string concatenation like the old code did, as that yields a C string literal,
> not a QString.

Yes, that's the only way that I found to get rid of the "" around the QStrings, if you have any other suggestions on how to do it I'll be happy to change it because it looks ugly to me too...
The previous version used to print inside "" just the debug message, but I got rid of that in the same way:

qDebug() << qPrintable(libraryName) << qPrintable(libraryVersion) << "DEBUG:" << qPrintable(msg);


> With these refactors, please verify the library still compiles and works fine
> even if debugging is disabled at compile time (ENABLE_DEBUG_OUTPUT cmake
> variable). And when it's enabled at compile time, that both runtime enable and
> disable work, with the former producing sensible debug output with no
> formatting issues like stray " characters.
> 
> You can verify the runtime debug disable behavior by adjusting
> Test::initTestCaseImpl() in tests/lib/test.cpp, and running make check.


Verified ENABLE_DEBUG_OUTPUT=OFF and tested that both runtime enable and disable work, but tbh I couldn't do it with the tests because I cannot enable the normal output... Anyway I tested it with kde-telepathy file transfer handler enabling and disabling debug and warnings with Tp::enableDebug() and Tp::enableWarnings(), and setting/unsetting the callback with Tp::setDebugCallback and it behaves exactly as expected.


[1]https://gitorious.org/drdanz-telepathy-kde/telepathy-qt4/commits/logging_enhancement
Comment 12 Olli Salli 2011-10-05 06:53:52 UTC
(In reply to comment #11)
> New version pushed (always here [1])
> 
> 
> (In reply to comment #10)
> > THOUGH: please verify it doesn't
> > put "" around the original string as I think it might do. That would be ugly.
> [...]
> > One thing in its implementation too:
> > 
> > qDebug() << qPrintable(libraryName) << qPrintable(libraryVersion) << "DEBUG:"
> > << msg;
> > 
> > the library name and version are in the ASCII subset anyway. qPrintable will be
> > a needless memory allocation and conversion, having no effect on the output. Or
> > does that somehow get rid of the QDebug behavior of putting "" around printed
> > QStrings? You can get rid of that by not making QStrings out of them in the
> > first place (also needless memory alloc and copy), but just using preprocessor
> > string concatenation like the old code did, as that yields a C string literal,
> > not a QString.
> 
> Yes, that's the only way that I found to get rid of the "" around the QStrings,
> if you have any other suggestions on how to do it I'll be happy to change it
> because it looks ugly to me too...

For the default debug behavior, you can get rid of it for the lib name and version, and gain some performance via the way I suggested before: make debugCallback = NULL make invokeDefaultCallback() utilize the default behavior (instead of just setDebugCallback() having those semantics). Whether you then do

if (debugCallback) {
  debugCallback(QLatin1String("tp-qt4"), PACKAGE_VERSION, type, msg);
} else {
  defaultDebug(type, msg);
}

or write the code of defaultDebug inline in the else branch, you can implement prefixing the library name and version by preprocessor string concatenation:

TELEPATHY_QT4_NO_EXPORT void defaultDebug(QtMsgType type, const QString &msg)
{
  if (type == QtDebugMsg) {
     qDebug() << "tp-qt4 " PACKAGE_VERSION " DEBUG:" << qPrintable(msg);
  } else {
     qWarning() << "tp-qt4 " PACKAGE_VERSION " WARN:" << qPrintable(msg);
  }
}

Note the use of qWarning (to preserve previous behavior even when a non-default qt message handler is installed) and how we can this way prevent constructing QStrings and having to convert them back to const char * in the console charset for both the library name (which, here, we know) and the version (which we, again, know, without invokeDebugCallback passing it to us).

But doesn't the copy ctor:

51	                debug = new QDebug(&msg);
52	                (*debug) << a.msg;
47	53	

also surround a.msg with ""? I don't think the library actually currently uses the copy ctor though with a non-empty string - but you should verify that it works properly for non-empty strings too for completeness, so this doesn't cause confusion in the future.

Otherwise looks good to me now. Just these improvements here and we can merge with confidence that the behavior is also performance wise retained at the previous level, but with the added flexibility of specifying a debug callback.

> Verified ENABLE_DEBUG_OUTPUT=OFF and tested that both runtime enable and
> disable work, but tbh I couldn't do it with the tests because I cannot enable
> the normal output... Anyway I tested it with kde-telepathy file transfer

Yeah make check redirects stderr from the test binaries. I mainly meant that you check that it doesn't crash or burn, or even fail to compile with any selected behavior. However the individual testcase targets, like make check-AccountBasics, don't redirect so if you want to look at debug output you can try those out.
Comment 13 Daniele E. Domenichelli 2011-10-05 08:46:41 UTC
Updated and tested.

By the way, in the test directory there are 3 tests (test-key-file, test-manager-file, test-profile) failing, but they fail also on master branch.
Comment 14 Olli Salli 2011-10-06 13:19:39 UTC
(In reply to comment #13)
> Updated and tested.

Thanks! Looks good now. I merged it now. Except I changed a small detail: I used the DebugCallback typedef for declaring the debugCallback global variable in debug.cpp instead of duplicating the signature there.

Good work! This will be in the 0.7.3 release. I'll kick Andre to make that release happen...

> 
> By the way, in the test directory there are 3 tests (test-key-file,
> test-manager-file, test-profile) failing, but they fail also on master branch.

Yes, this is definitely not something related to your changes. But OOI, how are they failing to be exact? We should fix them - but for me they seem to work fine at the moment, so I need more info to enable me to do that. In fact, please file another bug detailing how exactly they fail, so we can close this one.


Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.