Bug 88896

Summary: QDBusConnection::call eats 100% CPU then eventually times out
Product: dbus Reporter: Ralf Habacker <ralf.habacker>
Component: coreAssignee: D-Bus Maintainers <dbus>
Status: RESOLVED NOTOURBUG QA Contact: D-Bus Maintainers <dbus>
Severity: normal    
Priority: medium CC: a.brooks, thiago
Version: 1.8   
Hardware: Other   
OS: Linux (All)   
Whiteboard:
i915 platform: i915 features:
Attachments: Modified testcase to print some stats
cmake build file
dbus hack to enable/disable verbose infos on runtime
Interface test app
cmake build file (update 1)
dbus hack to enable verbose mode in client library on runtime
Add methods 'EnableVerbose' and 'DisableVerbose' to dbus-daemon org.freedesktop.DBus interface when compiled with DBUS_ENABLE_VERBOSE_MODE (update 1)
Add org.freedesktop.DBus.Verbose interface to dbus-daemon when compiled with DBUS_ENABLE_VERBOSE_MODE.
dbus monitor log file
Add serial fetch support to libqt5 dbus-message (need to be moved to libqt5 bug tracker)
test case using low level dbus api
cmake build file (update 2)
python testcase
dbus-monitor: Convert remaining hard tabs to 8 space
dbus-monitor: Add timestamp to --monitor mode
dbus- monitor: Keep term in 'dest' in monitor output in sync with watch expression
dbus-monitor: Keep parameter list of method returns in --monitor mode in sync with --profile mode.
dbus-monitor: Add timestamp to --monitor mode (update 1)
dbus- monitor: Keep term in 'dest' in monitor output in sync with watch expression
dbus-monitor: Add timestamp to --monitor mode (update 2)
dbus-monitor: Add timestamp to --monitor mode (rebased)
dbus-monitor: Add timestamp to --monitor mode.
dbus-monitor: Keep term 'dest' in --monitor output in sync with related watch expression.

Description Ralf Habacker 2015-02-01 13:08:49 UTC
Created attachment 113013 [details]
Modified testcase to print some stats

On http://lists.freedesktop.org/archives/dbus/2015-January/016523.html Alex Brooks reported a problem probably located in libdbus.

With the modified testcase appended to this bug, it could be shown (on opensuse 13.1 x86_64) that the problem happens exactly after a dedicated number of calls. 

300271 502463 1 signalInfo rssi=-54
300272 502464 0 signalInfo rssi=-54
300273 502466 0 signalInfo rssi=-54
Error: wpa_supplicant DBus error in signalPoll: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
Comment 1 Ralf Habacker 2015-02-01 13:09:16 UTC
Created attachment 113014 [details]
cmake build file
Comment 2 Ralf Habacker 2015-02-01 13:54:27 UTC
Created attachment 113015 [details] [review]
dbus hack to enable/disable verbose infos on runtime
Comment 3 Ralf Habacker 2015-02-03 10:12:13 UTC
Created attachment 113094 [details]
Interface test app
Comment 4 Ralf Habacker 2015-02-03 10:12:40 UTC
Created attachment 113095 [details]
cmake build file (update 1)
Comment 5 Ralf Habacker 2015-02-03 13:20:01 UTC
Comment on attachment 113015 [details] [review]
dbus hack to enable/disable verbose infos on runtime

running a dbus-daemon with this patch applied and called 'EnableVerbose' immediatly before the problem occurs did not show any problems inside dbus-daemon
Comment 6 Ralf Habacker 2015-02-03 13:27:39 UTC
Created attachment 113110 [details] [review]
dbus hack to enable verbose mode in client library on runtime
Comment 7 Ralf Habacker 2015-02-03 17:19:05 UTC
Created attachment 113129 [details] [review]
Add methods 'EnableVerbose' and 'DisableVerbose' to dbus-daemon org.freedesktop.DBus interface when compiled with DBUS_ENABLE_VERBOSE_MODE (update 1)

enable methods only when compiled with DBUS_ENABLE_VERBOSE_MODE
Comment 8 Ralf Habacker 2015-02-04 19:26:15 UTC
(In reply to Ralf Habacker from comment #7)
> Created attachment 113129 [details] [review] [review]
> Add methods 'EnableVerbose' and 'DisableVerbose' to dbus-daemon
> org.freedesktop.DBus interface when compiled with DBUS_ENABLE_VERBOSE_MODE
> (update 1)
> 
> enable methods only when compiled with DBUS_ENABLE_VERBOSE_MODE

This (or similar named) methods may be a good extension for tracking long time running issues as reported by this bug. Client apps could trigger verbose mode on special conditions on runtime to avoid huge verbose log files.
I'm not sure it the used interface is a good choice or if they are better placed in a different interface like org.freedesktop.DBus.Verbose or org.freedesktop.DBus.Debug
Comment 9 Simon McVittie 2015-02-04 19:34:54 UTC
(In reply to Ralf Habacker from comment #0)
> With the modified testcase appended to this bug, it could be shown (on
> opensuse 13.1 x86_64) that the problem happens exactly after a dedicated
> number of calls. 

Is it repeatably the 502467th call that fails? How predictable is this?

Without having looked into this in any detail, I would speculate that there might be a reference leak or something, either in QtDBus or libdbus.

Is this reproducible by doing equivalent things using libdbus or GDBus?
Comment 10 Simon McVittie 2015-02-04 19:37:57 UTC
(In reply to Ralf Habacker from comment #8)
> This (or similar named) methods may be a good extension for tracking long
> time running issues as reported by this bug.

I definitely don't want this on the o.fd.DBus interface.

It could maybe go in Monitoring, or on a new interface, or we could consider renaming o.fd.DBus.Debug.Stats to just o.fd.DBus.Debug and putting it there.

I don't think dbus_setenv() is a good API for propagating verbosity down into libdbus: dbus_setenv() is explicitly not thread-safe (just like setenv()), so it's a poor choice for applications to call. If it's only for the benefit of the dbus-daemon, we could add _dbus_global_set_verbose (dbus_bool_t) or something.
Comment 11 Ralf Habacker 2015-02-04 21:04:33 UTC
(In reply to Simon McVittie from comment #9)
> (In reply to Ralf Habacker from comment #0)
> > With the modified testcase appended to this bug, it could be shown (on
> > opensuse 13.1 x86_64) that the problem happens exactly after a dedicated
> > number of calls. 
> 
> Is it repeatably the 502467th call that fails? How predictable is this?
Exactly 300273. See 
http://lists.freedesktop.org/archives/dbus/2015-January/016528.html
and 
http://lists.freedesktop.org/archives/dbus/2015-February/016542.html
> 
> Without having looked into this in any detail, I would speculate that there
> might be a reference leak or something, either in QtDBus or libdbus.
> 
> Is this reproducible by doing equivalent things using libdbus or GDBus?
Not checked yet because of missing example.  

At http://lists.freedesktop.org/archives/dbus/2015-February/016546.html it is documentated that this problem affects only some interfaces in wpa_supplicant. Interfaces inside dbus-daemon and main interfaces of wpa_supplicants works without any problem.
Comment 12 Ralf Habacker 2015-02-12 23:06:11 UTC
(In reply to Simon McVittie from comment #10)
> (In reply to Ralf Habacker from comment #8)
> > This (or similar named) methods may be a good extension for tracking long
> > time running issues as reported by this bug.
> 
> I definitely don't want this on the o.fd.DBus interface.
> 
agree'd

> or on a new interface 

I think o.fd.DBus.Verbose would be good because this feature directly depends on configure option ENABLE_VERBOSE_MODE

Also having a separate interface makes room for additional verbose related methods in the future like verbose level or output channel
Comment 13 Ralf Habacker 2015-02-12 23:08:22 UTC
Created attachment 113425 [details] [review]
Add org.freedesktop.DBus.Verbose interface to dbus-daemon when compiled with DBUS_ENABLE_VERBOSE_MODE.
Comment 14 Ralf Habacker 2015-02-12 23:18:15 UTC
(In reply to Simon McVittie from comment #10)

> I don't think dbus_setenv() is a good API for propagating verbosity down
> into libdbus: dbus_setenv() is explicitly not thread-safe (just like
> setenv()), so it's a poor choice for applications to call.
yes it is a hack only used to take a look at the client side of libdbus on runtime.

> If it's only for the benefit of the dbus-daemon, we could add _dbus_global_set_verbose (dbus_bool_t) or something.

You are talking about an internal function _dbus_global_set_verbose added to libdbus ?
Comment 15 Ralf Habacker 2015-02-13 00:56:23 UTC
Created attachment 113427 [details]
dbus monitor log file

dbus-monitor dump: 

:1.1 is wpa_supplicant
:1.1186 is signalpoll test app

the last return before the error happens is 

method return sender=:1.1 -> dest=:1.1186 reply_serial=300285

note: the value is estimated because the QDBusMessage instance did not provide access to the reply serial to be more exaxt.  

At the estimated time of the error (dbus-monitor do not provide exact time stamps) wpa emits the following  message: 

method return sender=:1.1 -> dest=:1.8 reply_serial=126396
signal sender=:1.1 -> dest=(null destination) serial=1065762 path=/fi/epitest/hostap/WPASupplicant/Interfaces/28; interface=fi.epitest.hostap.WPASupplicant.Interface; member=Scanning
   boolean true

In the error case the test app continues to calls the signalPoll method and 
wpa_supplicant returns correct replies (according to dbus-monitor), but the reply is not routed back to the test app.
Comment 16 Simon McVittie 2015-02-13 10:16:05 UTC
Comment on attachment 113425 [details] [review]
Add org.freedesktop.DBus.Verbose interface to dbus-daemon when compiled with DBUS_ENABLE_VERBOSE_MODE.

Review of attachment 113425 [details] [review]:
-----------------------------------------------------------------

This patch seems fine for master.
Comment 17 Ralf Habacker 2015-02-13 10:21:25 UTC
Comment on attachment 113425 [details] [review]
Add org.freedesktop.DBus.Verbose interface to dbus-daemon when compiled with DBUS_ENABLE_VERBOSE_MODE.

committed to master
Comment 18 Ralf Habacker 2015-02-13 13:03:40 UTC
(In reply to Ralf Habacker from comment #15)

> note: the value is estimated because the QDBusMessage instance did not
> provide access to the reply serial to be more exaxt.  
> 
QDBusMessage source shows that QDBusMessage holds a DBusMessage instance named msg in its d pointer, which is unfortunally not accessable neither through the public QDBusMessage API nor by the QDebug operator>> or do I have overseen something important ? 

At least it would be nice to have the serial to be displayed by the QDebug operator>>.
Comment 19 Ralf Habacker 2015-02-14 00:17:18 UTC
Created attachment 113481 [details] [review]
Add serial fetch support to libqt5 dbus-message (need to be moved to libqt5 bug tracker)

(In reply to Ralf Habacker from comment #18)

> At least it would be nice to have the serial to be displayed by the QDebug
> operator>>.
in real this is operator<< 

>note: the value is estimated because the QDBusMessage instance did not provide >access to the reply serial to be more exaxt.  

With appended libqt5 dbus patch the test app returns accurate serial values when running with 

QDBUS_DEBUG=1 ./signalpoll -i <interface>

A. the last complete iteration is listed below:

A-send

QDBusConnectionPrivate(0x1b83ba0) sending message (blocking): QDBusMessage(type=MethodCall, service="fi.w1.wpa_supplicant1", path="/fi/w1/wpa_supplicant1/Interfaces/1", interface="fi.w1.wpa_supplicant1.Interface", member="SignalPoll", signature="", serial=0, contents=() )

A-return

QDBusConnectionPrivate(0x1b83ba0) got message reply (blocking): QDBusMessage(type=MethodReturn, service=":1.57", signature="v", serial=300283, contents=([Variant: [Argument: a{sv} {"rssi" = [Variant(int): -73], "linkspeed" = [Variant(int): 121], "noise" = [Variant(int): 9999], "frequency" = [Variant(uint): 2462], "width" = [Variant(QString): "40 MHz"], "avg-rssi" = [Variant(int): -72]}]]) )
300273 139636 1 signalInfo rssi=-73

B. here is the first failing iteration:

B-send:

QDBusConnectionPrivate(0x963ba0) sending message (blocking): QDBusMessage(type=MethodCall, service="fi.w1.wpa_supplicant1", path="/fi/w1/wpa_supplicant1/Interfaces/1", interface="fi.w1.wpa_supplicant1.Interface", member="SignalPoll", signature="", serial=0, contents=() )

B-return

Error: wpa_supplicant DBus error in signalPoll: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.


The related dbus-monitor log shows: 

A send:

method call sender=:1.5880 -> dest=fi.w1.wpa_supplicant1 serial=300283 path=/fi/w1/wpa_supplicant1/Interfaces/1; interface=fi.w1.wpa_supplicant1.Interface; member=SignalPoll

A-return:

method return sender=:1.57 -> dest=:1.5880 reply_serial=300283
   variant       array [
         dict entry(
            string "rssi"
            variant                int32 -73
         )
         dict entry(
            string "linkspeed"
            variant                int32 121
         )
         dict entry(
            string "noise"
            variant                int32 9999
         )
         dict entry(
            string "frequency"
            variant                uint32 2462
         )
         dict entry(
            string "width"
            variant                string "40 MHz"
         )
         dict entry(
            string "avg-rssi"
            variant                int32 -72
         )
      ]

B-send:

method call sender=:1.5880 -> dest=fi.w1.wpa_supplicant1 serial=300284 path=/fi/w1/wpa_supplicant1/Interfaces/1; interface=fi.w1.wpa_supplicant1.Interface; member=SignalPoll

B-return:

method return sender=:1.57 -> dest=:1.5880 reply_serial=300284
   variant       array [
         dict entry(
            string "rssi"
            variant                int32 -73
         )
         dict entry(
            string "linkspeed"
            variant                int32 121
         )
         dict entry(
            string "noise"
            variant                int32 9999
         )
         dict entry(
            string "frequency"
            variant                uint32 2462
         )
         dict entry(
            string "width"
            variant                string "40 MHz"
         )
         dict entry(
            string "avg-rssi"
            variant                int32 -72
         )
      ]

and so one: 

method call sender=:1.5880 -> dest=fi.w1.wpa_supplicant1 serial=300285 path=/fi/w1/wpa_supplicant1/Interfaces/1; interface=fi.w1.wpa_supplicant1.Interface; member=SignalPoll
method return sender=:1.57 -> dest=:1.5880 reply_serial=300285
   variant       array [
         dict entry(
            string "rssi"
            variant                int32 -70
         )

As already mentioned wpa_supplicant return method reply to *all* send messages, but they do not reach the initator.

Unfortunally dbus-monitor do not print any timestamp informations, which would make it able to see in the error case, if the method reply is returned immediatly or after the initial message sending has been timed out. 

For that purpose Will Thompson provides his extended dbus monitor named bustle http://willthompson.co.uk/bustle, which looks nice at a first look. Unfortunally bustle failed to load a generated log file with an "internal error" 

./bustle-pcap --system system-log.bustle
... wait long time. 

./bustle.sh system-log.bustle           
bustle: internal error: OtherName (BusName "fi.w1.wpa_supplicant1") in several apps: [(UniqueName (BusName ":1.57"),ApplicationInfo {aiColumn = CurrentColumn 645.0, aiCurrentNames = fromList [OtherName (BusName "fi.epitest.hostap.WPASupplicant"),OtherName (BusName "fi.w1.wpa_supplicant1")], aiEverNames = fromList [OtherName (BusName "fi.epitest.hostap.WPSupplicant"),OtherName (BusName "fi.w1.wpa_supplicant1")]}),(UniqueName (BusName ":fake.1"),ApplicationInfo {aiColumn = CurrentColumn 555.0, aiCurrentNames = fromList [OtherName (BusName "fi.w1.wpa_supplicant1")], aiEverNames = fromList [OtherName (BusName "fi.w1.wpa_supplicant1")]})]

May be adding timestamp display to dbus-monitor would be an alternative.

At least manual watching dbus-monitor was possible and showed that wpa_supplicant returns the reply immediatly.

Some additional notes:
1. In the error case other clients also calls methods and get replies from wpa_supplicant without any problem, so it looks that wpa_supplicant works as expected.

2. calling method SignalPoll with qdbus and dbus-send works with the following command line without any problem:

    qdbus --system fi.w1.wpa_supplicant1 /fi/w1/wpa_supplicant1/Interfaces/1 fi.w1.wpa_supplicant1.Interface.SignalPoll
    dbus-send --type=method_call  --system --print-reply=literal --dest=fi.w1.wpa_supplicant1 /fi/w1/wpa_supplicant1/Interfaces/1 fi.w1.wpa_supplicant1.Interface.SignalPoll

3. calling method SignalPoll with qdbusviewer returns "unable to find method SignalPoll on /fi/w1/wpa_supplicant1/Interfaces/1 in interface fi.w1.wpa_supplicant1.Interface

The main questions at this point are:

1. Why does the reply not reach the sender at this specific iteration and 
2. how can we track this.
Comment 20 Ralf Habacker 2015-02-15 20:27:40 UTC
Created attachment 113511 [details]
test case using low level dbus api

As Simon mentioned here is a test case using low level dbus api

You need to run initial testcase 
   signalpoll -i <interface> 

then setup interface in TEST_OBJ_PATH in signalpoll-c.c and recompile.
Comment 21 Ralf Habacker 2015-02-15 20:27:57 UTC
Created attachment 113512 [details]
cmake build file (update 2)
Comment 22 Ralf Habacker 2015-02-15 20:30:18 UTC
(In reply to Ralf Habacker from comment #20)
> Created attachment 113511 [details]
> test case using low level dbus api
> 
> As Simon mentioned here is a test case using low level dbus api
> 
The testcase do not show the problem. It runs up to the hardcoded limit of 500000 calls without any problems.
Comment 23 Ralf Habacker 2015-02-15 20:46:18 UTC
Created attachment 113513 [details]
python testcase
Comment 24 Ralf Habacker 2015-02-15 20:48:06 UTC
(In reply to Simon McVittie from comment #9)

> Without having looked into this in any detail, I would speculate that there
> might be a reference leak or something, either in QtDBus or libdbus.

initial testcase signalpoll eat's up to 185 MB of memory until it breaks. 

> Is this reproducible by doing equivalent things using libdbus 

no, see comment 22 (also not memory increase on run)

or GDBus?

no easy to use example found yet

Instead I tried a dbus-python testcase, which runs also without any problems.

Looks really like a reference leak in the original testcase.
Comment 25 Ralf Habacker 2015-02-15 20:55:15 UTC
(In reply to Ralf Habacker from comment #24)
> (In reply to Simon McVittie from comment #9)
> 
> > Without having looked into this in any detail, I would speculate that there
> > might be a reference leak or something, either in QtDBus or libdbus.
> 
> initial testcase signalpoll eat's up to 185 MB of memory until it breaks. 
> 
> > Is this reproducible by doing equivalent things using libdbus 
> 
> no, see comment 22 (also not memory increase on run)
> 
> or GDBus?
> 
> no easy to use example found yet
> 
> Instead I tried a dbus-python testcase, which runs also without any problems.
> 
> Looks really like a reference leak in the original testcase.

^C==28932== 
==28932== HEAP SUMMARY:
==28932==     in use at exit: 5,943,370 bytes in 41,542 blocks
==28932==   total heap usage: 475,898 allocs, 434,356 frees, 26,800,646 bytes allocated
==28932== 
==28932== 31 bytes in 1 blocks are possibly lost in loss record 48 of 309
==28932==    at 0x4C27D49: operator new(unsigned long) (in /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so)
==28932==    by 0x5C825C8: std::string::_Rep::_S_create(unsigned long, unsigned long, std::allocator<char> const&) (in /usr/lib64/libstdc++.so.6.0.18)
==28932==    by 0x5C82787: std::string::_M_mutate(unsigned long, unsigned long, unsigned long) (in /usr/lib64/libstdc++.so.6.0.18)
==28932==    by 0x5C82D2D: std::string::_M_replace_safe(unsigned long, unsigned long, char const*, unsigned long) (in /usr/lib64/libstdc++.so.6.0.18)
==28932==    by 0x40C489: main (signalpoll.cpp:175)
==28932== 
==28932== 60 bytes in 1 blocks are possibly lost in loss record 175 of 309
==28932==    at 0x4C27D49: operator new(unsigned long) (in /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so)
==28932==    by 0x5C825C8: std::string::_Rep::_S_create(unsigned long, unsigned long, std::allocator<char> const&) (in /usr/lib64/libstdc++.so.6.0.18)
==28932==    by 0x5C83D00: char* std::string::_S_construct<char const*>(char const*, char const*, std::allocator<char> const&, std::forward_iterator_tag) (in /usr/lib64/libstdc++.so.6.0.18)
==28932==    by 0x5C83DBC: std::basic_string<char, std::char_traits<char>, std::allocator<char> >::basic_string(char const*, unsigned long, std::allocator<char> const&) (in /usr/lib64/libstdc++.so.6.0.18)
==28932==    by 0x40D012: QByteArray::toStdString() const (in /home/ralf/src/dbus-testcase/build-qt-43550/signalpoll)
==28932==    by 0x40D302: QString::toStdString() const (in /home/ralf/src/dbus-testcase/build-qt-43550/signalpoll)
==28932==    by 0x40A721: getNetDevObjectPath(std::string const&, QDBusConnection const&) (signalpoll.cpp:57)
==28932==    by 0x40C5C1: main (signalpoll.cpp:195)
==28932== 
==28932== 5,481,535 (1,071,200 direct, 4,410,335 indirect) bytes in 10,300 blocks are definitely lost in loss record 309 of 309
==28932==    at 0x4C27D49: operator new(unsigned long) (in /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so)
==28932==    by 0x4E82360: ??? (in /usr/lib64/libQt5DBus.so.5.4.2)
==28932==    by 0x4E84778: QDBusArgument::beginMap() const (in /usr/lib64/libQt5DBus.so.5.4.2)
==28932==    by 0x40BD7E: signalPoll(QDBusInterface&) (signalpoll.cpp:136)
==28932==    by 0x40C7EE: main (signalpoll.cpp:223)
==28932== 
==28932== LEAK SUMMARY:
==28932==    definitely lost: 1,071,200 bytes in 10,300 blocks
==28932==    indirectly lost: 4,410,335 bytes in 30,900 blocks
==28932==      possibly lost: 91 bytes in 2 blocks
==28932==    still reachable: 461,744 bytes in 340 blocks
==28932==         suppressed: 0 bytes in 0 blocks
==28932== Reachable blocks (those to which a pointer was found) are not shown.
==28932== To see them, rerun with: --leak-check=full --show-reachable=yes
==28932== 
==28932== For counts of detected and suppressed errors, rerun with: -v
==28932== ERROR SUMMARY: 3 errors from 3 contexts (suppressed: 2 from 2)
Comment 26 Ralf Habacker 2015-02-15 21:09:53 UTC
(In reply to Ralf Habacker from comment #25)

this one is related

> ==28932== 5,481,535 (1,071,200 direct, 4,410,335 indirect) bytes in 10,300
> blocks are definitely lost in loss record 309 of 309
> ==28932==    at 0x4C27D49: operator new(unsigned long) (in
> /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so)
> ==28932==    by 0x4E82360: ??? (in /usr/lib64/libQt5DBus.so.5.4.2)
> ==28932==    by 0x4E84778: QDBusArgument::beginMap() const (in
> /usr/lib64/libQt5DBus.so.5.4.2)
> ==28932==    by 0x40BD7E: signalPoll(QDBusInterface&) (signalpoll.cpp:136)
> ==28932==    by 0x40C7EE: main (signalpoll.cpp:223)

According to http://doc.qt.io/qt-5/qdbusargument.html#beginMap-2 does the testcase source do not follow the example: there is no call to dbArg.endMap().

    const QVariant &var = result.arguments()[0].value<QDBusVariant>().variant();
    const QDBusArgument &dbArg = var.value<QDBusArgument>();
    
    // Iterate over it
    int rssi;
    int numEntries = 0;
    dbArg.beginMap();
    while ( !dbArg.atEnd() )
    {
        QString key;
        QVariant value;
        dbArg.beginMapEntry();
        dbArg >> key;
        dbArg >> value;
        dbArg.endMapEntry();
        numEntries++;

        if ( key == "rssi" )
        {
            rssi = value.toInt();
!here missing call to       dbArg.endMap();
            return rssi;
        }
    }
!here missing call to dbArg.endMap();


The question is if it would be good to deal with missing endMap() calls in the QDBusArgument class destructor like asserting or automatic endMap() call and print a warning to avoid such situations.
Comment 27 a.brooks 2015-02-16 03:39:26 UTC
Oops.
Thankyou very much for the hard work in tracking this down Ralf.
Comment 28 Ralf Habacker 2015-02-16 07:46:15 UTC
Comment on attachment 113481 [details] [review]
Add serial fetch support to libqt5 dbus-message (need to be moved to libqt5 bug tracker)

Patched moved to https://bugreports.qt.io/browse/QTBUG-44490
Comment 29 Ralf Habacker 2015-02-16 08:52:15 UTC
(In reply to Ralf Habacker from comment #19)

> Unfortunally dbus-monitor do not print any timestamp informations, which
> would make it able to see in the error case, if the method reply is returned
> immediatly or after the initial message sending has been timed out. 

For the record: This statement is true for the monitoring (--monitor) mode, which is the default. In the --profile mode the man page says that timestamps are printed like shown below:

sig     1424073195      232762  2       /org/freedesktop/DBus   org.freedesktop.DBus    NameAcquired
sig     1424073241      94169   78793   /org/freedesktop/UDisks2/drives/Samsung_SSD_840_EVO_250GB_S1DBNSBF836379E       org.freedesktop.DBus.Properties PropertiesChanged
sig     1424073241      130567  78795   /org/freedesktop/UDisks2/drives/Samsung_SSD_840_PRO_Series_S1ATNSAF181977L      org.freedesktop.DBus.Properties PropertiesChanged                                                                    
sig     1424073241      230140  78797   /org/freedesktop/UDisks2/drives/ST3250318AS_6VMQ2AWF    org.freedesktop.DBus.Properties PropertiesChanged                                                       

Unfortunally this mode do not have any header, which makes it hard to interpret columns content
Comment 30 Simon McVittie 2015-02-16 12:15:04 UTC
(In reply to Ralf Habacker from comment #19)
> For that purpose Will Thompson provides his extended dbus monitor named
> bustle http://willthompson.co.uk/bustle, which looks nice at a first look.
> Unfortunally bustle failed to load a generated log file with an "internal
> error" 
> 
> ./bustle-pcap --system system-log.bustle
> ... wait long time. 

FYI, in dbus >= 1.9.10, "bustle-pcap" is no longer necessary: "dbus-monitor --system --pcap > system-log.pcap" will produce a PCAP trace which can be read by Wireshark or Bustle.

I don't know enough about the internals of Bustle to know what was going on with that internal error.

> May be adding timestamp display to dbus-monitor would be an alternative.

I wouldn't object to adding something like "; time 1424073241.094169" to dbus-monitor's output; you'd probably need to add an optional struct timeval argument to print_message().

The stuff with a platform-dependent PROFILE_TIMED_FORMAT could be avoided by using printf ("%lu.%06lu", (unsigned long) t->tv_sec, (unsigned long) t->tv_usec) or similar.
Comment 31 Ralf Habacker 2015-02-17 07:45:28 UTC
Created attachment 113552 [details] [review]
dbus-monitor: Convert remaining hard tabs to 8 space
Comment 32 Ralf Habacker 2015-02-17 07:46:01 UTC
Created attachment 113553 [details] [review]
dbus-monitor: Add timestamp to --monitor mode
Comment 33 Ralf Habacker 2015-02-17 07:46:35 UTC
Created attachment 113554 [details] [review]
dbus- monitor: Keep term in 'dest' in monitor output in sync with watch expression
Comment 34 Ralf Habacker 2015-02-17 07:48:32 UTC
Created attachment 113555 [details] [review]
dbus-monitor:  Keep parameter list of method returns in --monitor mode in sync with --profile mode.
Comment 35 Simon McVittie 2015-02-17 10:43:57 UTC
Comment on attachment 113552 [details] [review]
dbus-monitor: Convert remaining hard tabs to 8 space

Review of attachment 113552 [details] [review]:
-----------------------------------------------------------------

Sure. Please use "git show --ignore-space-change 87654321" (where 87654321 is the commit sha1) before pushing, to confirm that this changed whitespace and nothing else.
Comment 36 Simon McVittie 2015-02-17 10:49:03 UTC
Comment on attachment 113553 [details] [review]
dbus-monitor: Add timestamp to --monitor mode

Review of attachment 113553 [details] [review]:
-----------------------------------------------------------------

::: tools/dbus-print-message.c
@@ +543,5 @@
>    if (!literal)
>      {
> +      struct timeval t;
> +
> +      if (gettimeofday (&t, NULL) < 0)

It seems bad for something called "print_message" to be assuming that the time now is the time of the message. This could be untrue if we teach dbus-monitor how to replay old "dbus-monitor --pcap" output, for instance.

dbus-print-message.c also doesn't have the Windows substitute for gettimeofday() that dbus-monitor.c does, unless you move it.

I would suggest giving print_message() an extra argument "const struct timeval *tv", making the condition below here be if (tv == NULL) { /* no time */ } else { /* time */ }, and leaving the gettimeofday in dbus-monitor.c.
Comment 37 Simon McVittie 2015-02-17 10:49:21 UTC
Comment on attachment 113554 [details] [review]
dbus- monitor: Keep term in 'dest' in monitor output in sync with watch expression

Review of attachment 113554 [details] [review]:
-----------------------------------------------------------------

OK
Comment 38 Simon McVittie 2015-02-17 10:49:37 UTC
Comment on attachment 113555 [details] [review]
dbus-monitor:  Keep parameter list of method returns in --monitor mode in sync with --profile mode.

Review of attachment 113555 [details] [review]:
-----------------------------------------------------------------

OK
Comment 39 Ralf Habacker 2015-02-17 15:31:13 UTC
(In reply to Simon McVittie from comment #36)

> I would suggest giving print_message() an extra argument "const struct
> timeval *tv", making the condition below here be if (tv == NULL) { /* no
> time */ } else { /* time */ }, and leaving the gettimeofday in
> dbus-monitor.c.

struct timeval is undefined in dbus-print-message.h|c :-(
Comment 40 Simon McVittie 2015-02-17 15:47:59 UTC
(In reply to Ralf Habacker from comment #39)
> struct timeval is undefined in dbus-print-message.h|c :-(

If that's the case, how can Attachment #113553 [details] possibly work?

It works in dbus-monitor, so you just need to move some inclusions into the .h - <time.h> and (for Unix only) <sys/time.h> look like likely candidates.
Comment 41 Ralf Habacker 2015-02-18 07:36:59 UTC
(In reply to Simon McVittie from comment #40)
> (In reply to Ralf Habacker from comment #39)
> > struct timeval is undefined in dbus-print-message.h|c :-(
> 
> If that's the case, how can Attachment #113553 [details] possibly work?
did not, because this bug is linux only, I created the first patch set on a linux only  environment. Double checked cross-compiling on refactoring. 
 
> It works in dbus-monitor, so you just need to move some inclusions into the
> .h - <time.h> and (for Unix only) <sys/time.h> look like likely candidates.

will try.
Comment 42 Ralf Habacker 2015-02-18 15:27:47 UTC
Created attachment 113621 [details] [review]
dbus-monitor: Add timestamp to --monitor mode (update 1)
Comment 43 Ralf Habacker 2015-02-18 15:28:13 UTC
Created attachment 113622 [details] [review]
dbus- monitor: Keep term in 'dest' in monitor output in sync with watch expression
Comment 44 Ralf Habacker 2015-02-18 15:30:13 UTC
Created attachment 113623 [details] [review]
dbus-monitor: Add timestamp to --monitor mode (update 2)

do not include unrelated gcc 4.9.2 fix
Comment 45 Simon McVittie 2015-02-18 20:18:23 UTC
Comment on attachment 113622 [details] [review]
dbus- monitor: Keep term in 'dest' in monitor output in sync with watch expression

Review of attachment 113622 [details] [review]:
-----------------------------------------------------------------

Sure, fine
Comment 46 Simon McVittie 2015-02-18 20:22:03 UTC
Comment on attachment 113623 [details] [review]
dbus-monitor: Add timestamp to --monitor mode (update 2)

Review of attachment 113623 [details] [review]:
-----------------------------------------------------------------

::: cmake/tools/CMakeLists.txt
@@ +62,5 @@
>  install_targets(/bin dbus-launch )
>  
>  add_executable(dbus-monitor ${dbus_monitor_SOURCES})
> +set_target_properties(dbus-monitor PROPERTIES COMPILE_FLAGS ${DBUS_INTERNAL_CLIENT_DEFINITIONS})
> +target_link_libraries(dbus-monitor ${DBUS_INTERNAL_LIBRARIES})

It'll need the equivalent change in Autotools-land for this to not be a build regression, and dbus-monitor will be rather larger as a result.

Since this dbus-monitor change is relatively low priority, I'd prefer to avoid this until I've been able to rebase Bug #83115, at which point the static vs. shared dichotomy will just go away.
Comment 47 Ralf Habacker 2015-02-23 21:03:27 UTC
Created attachment 113770 [details] [review]
dbus-monitor: Add timestamp to --monitor mode (rebased)
Comment 48 Simon McVittie 2015-02-24 11:55:33 UTC
Comment on attachment 113770 [details] [review]
dbus-monitor: Add timestamp to --monitor mode (rebased)

Review of attachment 113770 [details] [review]:
-----------------------------------------------------------------

(Committed your other two patches)

::: cmake/tools/CMakeLists.txt
@@ +62,4 @@
>  install_targets(/bin dbus-launch )
>  
>  add_executable(dbus-monitor ${dbus_monitor_SOURCES})
> +target_link_libraries(dbus-monitor ${DBUS_INTERNAL_LIBRARIES})

Now that #83115 has landed, this change is unnecessary - libdbus-1 is enough.

::: tools/dbus-monitor.c
@@ +97,2 @@
>  {
> +  printf ("%s\t%lu.%06lu", type, (unsigned long) sec, (unsigned long) usec);

minor: now that we're using a directly printf'able type (long) rather than standard library types like time_t, you can use %ld and not need the casts at all

@@ +141,5 @@
> +  if (sec == 0)
> +    {
> +      printf("un\n");
> +      return;
> +    }

I don't think you need this error-handling any more: _dbus_get_real_time() can't fail. If it returns wrong values for sec and/or usec we might as well just print them anyway.

(gettimeofday() can't fail either, according to POSIX...)

::: tools/dbus-print-message.c
@@ +529,4 @@
>  }
>  
>  void
> +print_message (DBusMessage *message, dbus_bool_t literal, long sec, long usec)

You seem to have forgotten the bit where print_message() actually does anything with sec/usec? :-)

::: tools/dbus-send.c
@@ +573,4 @@
>  
>        if (reply)
>          {
> +          print_message (reply, print_reply_literal, 0, 0);

Might as well call  _dbus_get_real_time() here too, since it's so easy to do now?
Comment 49 Simon McVittie 2015-02-24 11:57:26 UTC
Comment on attachment 113555 [details] [review]
dbus-monitor:  Keep parameter list of method returns in --monitor mode in sync with --profile mode.

applied
Comment 50 Simon McVittie 2015-02-24 12:17:04 UTC
Created attachment 113789 [details] [review]
dbus-monitor: Add timestamp to --monitor mode.

From: Ralf Habacker <ralf.habacker@freenet.de>

Use cross platform function _dbus_get_real_time() for fetching current time.

Bug: https://bugs.freedesktop.org/show_bug.cgi?id=88896
[smcv: use %ld to avoid needing casts; reinstate printing the timestamp;
libdbus-1 is sufficient now that fd.o#83115 is fixed; print timestamp for
non-literal dbus-send replies too]
Comment 51 Simon McVittie 2015-02-24 12:17:29 UTC
Created attachment 113790 [details] [review]
dbus-monitor: Keep term 'dest' in --monitor output in  sync with related watch expression.

From: Ralf Habacker <ralf.habacker@freenet.de>

[smcv: rebase onto differently indented version of previous commit]
Comment 52 Ralf Habacker 2015-02-24 12:29:20 UTC
You are going to perform the review ? I guess I should not review a patch I wrote :-)
Comment 53 Simon McVittie 2015-02-24 12:41:07 UTC
(In reply to Ralf Habacker from comment #52)
> You are going to perform the review ? I guess I should not review a patch I
> wrote :-)

I'm happy with those patches, if you're happy with the changes I made relative to your original versions. It's a team effort :-)
Comment 54 Ralf Habacker 2015-02-24 12:59:25 UTC
(In reply to Simon McVittie from comment #53)
> (In reply to Ralf Habacker from comment #52)
> > You are going to perform the review ? I guess I should not review a patch I
> > wrote :-)
> 
> I'm happy with those patches, if you're happy with the changes I made
> relative to your original versions. It's a team effort :-)

I'm happy with this changes :-)
Comment 55 Simon McVittie 2015-02-24 13:30:30 UTC
Comment on attachment 113789 [details] [review]
dbus-monitor: Add timestamp to --monitor mode.

applied
Comment 56 Simon McVittie 2015-02-24 13:30:45 UTC
Comment on attachment 113790 [details] [review]
dbus-monitor: Keep term 'dest' in --monitor output in  sync with related watch expression.

applied
Comment 57 Simon McVittie 2015-02-24 13:32:20 UTC
(In reply to Ralf Habacker from comment #54)
> I'm happy with this changes :-)

Merged them.

I think that's all your dbus-monitor enhancements merged, and the bug report for which you initially developed them turned out to be NOTOURBUG; closing it as such.

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.