Disconnected on every attempt to reply

classic Classic list List threaded Threaded
6 messages Options
Reply | Threaded
Open this post in threaded view
|

Disconnected on every attempt to reply

P. Durante
Hi,
I'm having a hard time trying to figure out why I get disconnected
from the bus everytime I try to reply to a message, I'm using some
pure C++ bindings I wrote myself, and in order to investigate this
issue, I put together a small program which does nothing more than
sending back every message received, unchanged, here's the debug
output (I hope it's readable)

$ ./echo
dbus|registering interface org.emptyspace.echo
dbus|:1.13: adding filter
dbus|registering stubs for connection 0x8065ae8
dbus|adding watch 0x80657a8
dbus|adding watch 0x80657d0
dbus|adding timeout 0x8065fa8 with interval 25000
dbus|removing timeout 0x8065fa8
dbus|:1.13: added match rule destination=':1.13'
dbus|registering local object /org/emptyspace/echo
dbus|adding timeout 0x8065d90 with interval 25000
dbus|removing timeout 0x8065d90
dbus|:1.13: added match rule type='method_call',interface='org.emptyspace.echo'
dbus|:1.13: registering bus name org.emptyspace
dbus|adding timeout 0x8065d90 with interval 25000
dbus|removing timeout 0x8065d90
dbus|adding timeout 0x8065d90 with interval 25000
dbus|removing timeout 0x8065d90
dbus|:1.13: added match rule destination='org.emptyspace'
    |entering loop
    |1 descriptor ready
dbus|watch 0x80657d0 ready (R___)
dbus|dispatching on 0x8065ae8   <-- connection dispatch
dbus|got message from org.emptyspace for object /org/emptyspace/echo
<-- message filtered and sent to my C++ object
dbus|all dispatching done on 0x8065ae8 <-- dispatch status changed
<-- dbus_connection_send()
    |2 descriptors ready <-- from main loop
dbus|removing watch 0x80657d0
dbus|removing watch 0x80657a8 <-- removes both? WHY!?
dbus|some dispatching to do on 0x8065ae8 <-- dispatch status changed
dbus|watch 0x80657d0 ready (R_H_) <-- means POLLIN || POLLHUP
dbus|dispatching on 0x8065ae8 <-- dbus_connection_dispatch
dbus|0x8065ae8 disconnected by local bus
dbus|all dispatching done on 0x8065ae8

here you see, I get the message, craft a reply ( using nothing more
than dbus_message_new_return_message(original_message); ) and send it
back over the same connection I read it from, and after
dbus_connection_send, BANG! I'm out..
I can't recompile dbus with more verbosity since, if I do, neither
HAL, nor the dbus-utils won't work anymore (don't know why, seems the
ubuntu version was built with some arcane settings I can't figure
out), so my question is, what are the possible reasons for getting
disconnected ?

the source code is here
http://svn.berlios.de/viewcvs/bluetool/trunk/cbus/echo/
and the bindings are in the parent dir (the code is very unclean, sorry)

while for sending messages I just do
$ dbus-send --system --type=method_call --print-reply
--dest=org.emptyspace /org/emptyspace/echo org.emptyspace.echo.echo

and this is the configuration file
<policy context="default">
        <allow own="org.emptyspace"/>
        <allow send_destination="org.emptyspace.echo"/>
        <allow send_interface="org.emptyspace.echo"/>
        <allow receive_interface="org.emptyspace.echo"/>
        <allow receive_sender="org.emptyspace.echo"/>
        <allow send_path="/org/emptyspace/echo"/>
</policy>

(I allowed everything I could allow..)

thanks in advance,
Paul
--
dbus mailing list
[hidden email]
http://lists.freedesktop.org/mailman/listinfo/dbus
Reply | Threaded
Open this post in threaded view
|

Re: Disconnected on every attempt to reply

Havoc Pennington
On Mon, 2005-08-08 at 16:24 +0200, P. Durante wrote:

>
> here you see, I get the message, craft a reply ( using nothing more
> than dbus_message_new_return_message(original_message); ) and send it
> back over the same connection I read it from, and after
> dbus_connection_send, BANG! I'm out..
> I can't recompile dbus with more verbosity since, if I do, neither
> HAL, nor the dbus-utils won't work anymore (don't know why, seems the
> ubuntu version was built with some arcane settings I can't figure
> out), so my question is, what are the possible reasons for getting
> disconnected ?
>

Normally disconnection is done when the bus decides you are looking
"malicious" by sending things that are not well-formed.

We try to instead have libdbus print a warning when you do this, so it's
easier to debug, but the warning-printing code isn't as rigorous as the
bus's validation code.

Typical ways to send a not-well-formed message are to break the naming
rules for methods/interfaces/paths/etc. or to omit a required message
field. Another possibility is a bug in libdbus.

You get kicked off rather than an error for security paranoia reasons.

If you figure out what the problem is we can add a warning on the client
side to help future programmers.

Havoc


--
dbus mailing list
[hidden email]
http://lists.freedesktop.org/mailman/listinfo/dbus
Reply | Threaded
Open this post in threaded view
|

Re: Disconnected on every attempt to reply

P. Durante
Hi,
trying to figure out the problem, I enabled debug output (at last!),
here's what I see when I send the reply (sorry for the length)

27025:   LOCK: dbus_connection_send
27025: Message 0x806b998 (2 (null) no interface no member 's') for
:1.21 added to outgoing queue 0x8065ae8, 1 pending to send

from the docs, only method_call and signal messages are supposed to
have the path/interface/member fields set, right ? so since this is a
method_return (type = 2) everything's fine

27025: Message 0x806b998 serial is 6
....
27025:  wrote 81 bytes of 81
27025: Message 0x806b998 (2 (null) no interface no member 's') removed
from outgoing queue 0x8065ae8, 0 left to send
....
27025: Notifying of change to dispatch status of 0x8065ae8 now 1 (complete)

the message is actually written!!!!
but then

....
27025: Disconnected from remote app

setting the daemon to verbose, after some crawling I saw (this is
output from the daemon, not my program)
27141: have 81 bytes, need body 9 + header 72 = 81
27141: validating body from pos 0 len 81 sig 'yyyyuua(yv)'
27141: p = 0x80b46bf end = 0x80b46e1 claimed_len 1
27141: initially caching field 6
27141: initially caching field 5
27141: Field 5 was invalid
27141: Failed to load header for new message code 16
27141:    0     0x80b4690:  'l' 0x02 0x01 0x01 BE: 1812070657 LE: 16843372
27141:    4     0x80b4694: 0x09 0x00 0x00 0x00 BE: 150994944 LE: 9
u64: 0x90101026c dbl: 1.91063e-313
27141:    8     0x80b4698: 0x06 0x00 0x00 0x00 BE: 100663296 LE: 6
27141:   12     0x80b469c:  '7' 0x00 0x00 0x00 BE: 922746880 LE: 55
u64: 0x3700000006 dbl: 1.1671e-312
27141:   16     0x80b46a0: 0x06 0x01  's' 0x00 BE: 100758272 LE: 7536902
27141:   20     0x80b46a4: 0x04 0x00 0x00 0x00 BE: 67108864 LE: 4 u64:
0x400730106 dbl: 8.49171e-314
27141:   24     0x80b46a8:  ':'  '1'  '.'  '1' BE: 976301617 LE: 825110842
27141:   28     0x80b46ac: 0x00 0x00 0x00 0x00 BE: 0 LE: 0 u64:
0x312e313a dbl: 4.07659e-315
27141:   32     0x80b46b0: 0x05 0x01  'u' 0x00 BE: 83981568 LE: 7667973
27141:   36     0x80b46b4: 0x00 0x00 0x00 0x00 BE: 0 LE: 0 u64:
0x750105 dbl: 3.78848e-317
27141:   40     0x80b46b8: 0x08 0x01  'g' 0x00 BE: 134309632 LE: 6750472
27141:   44     0x80b46bc: 0x01  's' 0x00 0x00 BE: 24313856 LE: 29441
u64: 0x730100670108 dbl: 6.24737e-310
27141:   48     0x80b46c0: 0x07 0x01  's' 0x00 BE: 117535488 LE: 7536903
27141:   52     0x80b46c4: 0x0e 0x00 0x00 0x00 BE: 234881024 LE: 14
u64: 0xe00730107 dbl: 2.97117e-313
27141:   56     0x80b46c8:  'o'  'r'  'g'  '.' BE: 1869768494 LE: 778531439
27141:   60     0x80b46cc:  'e'  'm'  'p'  't' BE: 1701671028 LE:
1953525093 u64: 0x74706d652e67726f dbl: 7.52737e+252
27141:   64     0x80b46d0:  'y'  's'  'p'  'a' BE: 2037608545 LE: 1634759545
27141:   68     0x80b46d4:  'c'  'e' 0x00 0x00 BE: 1667563520 LE:
25955 u64: 0x656361707379 dbl: 5.50772e-310
27141:   72     0x80b46d8: 0x04 0x00 0x00 0x00 BE: 67108864 LE: 4
27141:   76     0x80b46dc:  'S'  'U'  'X'  '!' BE: 1398102049 LE:
559437139 u64: 0x2158555300000004 dbl: 4.75755e-148
27141:   80     0x80b46e0: 0x00
27141: Corrupted message stream, disconnecting

so, how do I decipher this output to find the real problem ?

thanks in advance,
Paul

On 8/8/05, Havoc Pennington <[hidden email]> wrote:

> On Mon, 2005-08-08 at 16:24 +0200, P. Durante wrote:
> >
> > here you see, I get the message, craft a reply ( using nothing more
> > than dbus_message_new_return_message(original_message); ) and send it
> > back over the same connection I read it from, and after
> > dbus_connection_send, BANG! I'm out..
> > I can't recompile dbus with more verbosity since, if I do, neither
> > HAL, nor the dbus-utils won't work anymore (don't know why, seems the
> > ubuntu version was built with some arcane settings I can't figure
> > out), so my question is, what are the possible reasons for getting
> > disconnected ?
> >
>
> Normally disconnection is done when the bus decides you are looking
> "malicious" by sending things that are not well-formed.
>
> We try to instead have libdbus print a warning when you do this, so it's
> easier to debug, but the warning-printing code isn't as rigorous as the
> bus's validation code.
>
> Typical ways to send a not-well-formed message are to break the naming
> rules for methods/interfaces/paths/etc. or to omit a required message
> field. Another possibility is a bug in libdbus.
>
> You get kicked off rather than an error for security paranoia reasons.
>
> If you figure out what the problem is we can add a warning on the client
> side to help future programmers.
>
> Havoc
>
>
>
--
dbus mailing list
[hidden email]
http://lists.freedesktop.org/mailman/listinfo/dbus
Reply | Threaded
Open this post in threaded view
|

Re: Disconnected on every attempt to reply

Havoc Pennington
On Mon, 2005-08-08 at 19:44 +0200, P. Durante wrote:
> 27141: Field 5 was invalid

Field 5 is the reply serial (see dbus-protocol.h)

> 27141: Failed to load header for new message code 16

and code 16 is DBUS_INVALID_BAD_SERIAL (see dbus-marshal-validate.h)

Sorry, the verbose output isn't very user-friendly ;-)

The only invalid serial is 0, so somehow we're getting that.

I see your source code is printing the serial on the client side - is it
0 at that point?

> 27141:   32     0x80b46b0: 0x05 0x01  'u' 0x00 BE: 83981568 LE: 7667973
> 27141:   36     0x80b46b4: 0x00 0x00 0x00 0x00 BE: 0 LE: 0 u64:
> 0x750105 dbl: 3.78848e-317

This looks like field code 5, length of signature 1, signature 'u', nul
termination, uint32 value of 0.

dbus_message_new_method_return() should be setting the serial to
whatever the serial of the method call was, so not sure what happened.

Havoc


--
dbus mailing list
[hidden email]
http://lists.freedesktop.org/mailman/listinfo/dbus
Reply | Threaded
Open this post in threaded view
|

Re: Disconnected on every attempt to reply

P. Durante
Hi again,

On 8/9/05, Havoc Pennington <[hidden email]> wrote:
> On Mon, 2005-08-08 at 19:44 +0200, P. Durante wrote:
> > 27141: Field 5 was invalid
>
> Field 5 is the reply serial (see dbus-protocol.h)
>
> > 27141: Failed to load header for new message code 16
>
> and code 16 is DBUS_INVALID_BAD_SERIAL (see dbus-marshal-validate.h)

righty, I found out this myself tonight reversing the code :), what
about printing the actual symbol name instead of a cryptic '16' next
time ?

>
> Sorry, the verbose output isn't very user-friendly ;-)
>
> The only invalid serial is 0, so somehow we're getting that.
>
> I see your source code is printing the serial on the client side - is it
> 0 at that point?
>
> > 27141:   32     0x80b46b0: 0x05 0x01  'u' 0x00 BE: 83981568 LE: 7667973
> > 27141:   36     0x80b46b4: 0x00 0x00 0x00 0x00 BE: 0 LE: 0 u64:
> > 0x750105 dbl: 3.78848e-317
>
> This looks like field code 5, length of signature 1, signature 'u', nul
> termination, uint32 value of 0.
>
> dbus_message_new_method_return() should be setting the serial to
> whatever the serial of the method call was, so not sure what happened.
>

I caught the problem yesterday, and I feel  sooo dumb right now,
basically, this was the constructor of the DBus::Message class

Message::Message( DBusMessage* m )
{
        _message = dbus_message_copy(m._message);
}

you will immediately spot that this resets the message serial to 0 (I
found this out only after re-reading the whole documentation :-( ) so,
when I created the reply with

ReturnMessage::ReturnMessage( const CallMessage& callee )
{
        _message = dbus_message_new_method_return(callee._message);
}

it ended up having (of course) a null serial !

now I've corrected with

Message::Message( DBusMessage* m )
{
        _message = m;
        ref();
}

just two crappy lines fixed the whole thing, sorry for bothering you
for such a stupid error,

thanks again,
Paul

> Havoc
>
>
>
--
dbus mailing list
[hidden email]
http://lists.freedesktop.org/mailman/listinfo/dbus
Reply | Threaded
Open this post in threaded view
|

Re: Disconnected on every attempt to reply

Havoc Pennington
On Tue, 2005-08-09 at 13:05 +0200, P. Durante wrote:
> righty, I found out this myself tonight reversing the code :), what
> about printing the actual symbol name instead of a cryptic '16' next
> time ?

Well, I don't put a lot of energy into engineering the debug spew. The
correct failure mode would be to have the client side print a warning
(added in CVS).

Bugs don't have a habit of explaining themselves in detail, fixing the
bug is normally a better use of time... ;-)

> just two crappy lines fixed the whole thing, sorry for bothering you
> for such a stupid error,

It comes out well because now we can modify the code to print a warning
in this case, and you've saved some future programmer a lot of time.

Havoc


--
dbus mailing list
[hidden email]
http://lists.freedesktop.org/mailman/listinfo/dbus