hypfvieh / dbus-java

Improved version of java DBus library provided by freedesktop.org (https://dbus.freedesktop.org/doc/dbus-java/)
https://hypfvieh.github.io/dbus-java/
MIT License
185 stars 73 forks source link

No reply from invoking method #54

Closed valliman closed 5 years ago

valliman commented 5 years ago

Hi,

I'm trying to access a service via dbus using your library. I am right now a bit stuck as the method which I am invoking is running into a "No reply within specified time" error. To narrow the issue down I first wanted to know whether my test code is correct.

My simple test code looks as follows: `public class Main {

public static void main(String[] args) {

    try (DBusConnection dbus = DBusConnection.getConnection(DBusConnection.DBusBusType.SYSTEM);) {

        dbus.requestBusName("at.valli.mesh");

        String busName = "org.bluez.mesh";
        String objectPath = "/org/bluez/mesh";
        Network1 mesh = dbus.getRemoteObject(busName, objectPath, Network1.class);

        TestApplication application = new TestApplication();
        dbus.exportObject(application.getObjectPath(), application);
        TestElement element1 = new TestElement(application.getObjectPath(), (byte) 0);
        TestElement element2 = new TestElement(application.getObjectPath(), (byte) 1);
        dbus.exportObject(element1.getObjectPath(), element1);
        dbus.exportObject(element2.getObjectPath(), element2);

        UUID uuid = UUID.randomUUID();

        mesh.Join(application, UUIDs.toBytes(uuid));

        Thread.sleep(30000);

        dbus.releaseBusName("at.valli.mesh");

    } catch (NoReply | DBusException | IOException e) {
        e.printStackTrace();
    } catch (InterruptedException e) {
        e.printStackTrace();
    }
}

}`

and the corresponding log output is as follows:

`13:18:05,277 DEBUG [main] o.f.d.c.Transport: Connecting to UNIX: {path=/var/run/dbus/system_bus_socket} 13:18:05,466 DEBUG [main] o.f.d.m.MethodCall: Creating message with serial 1 13:18:05,469 DEBUG [main] o.f.d.m.MethodCall: Appending sig: yyyy data: [66, 1, 0, 1] 13:18:05,470 DEBUG [main] o.f.d.m.MethodCall: Appending sig: ua(yv) data: [1, [[1, [o, /org/freedesktop/DBus]], [6, [s, org.freedesktop.DBus]], [2, [s, org.freedesktop.DBus]], [3, [s, Hello]]]] 13:18:05,471 DEBUG [main] o.f.d.m.MethodCall: Appended body, type: null start: 128 end: 128 size: 0 13:18:05,471 DEBUG [main] o.f.d.m.MethodCall: marshalled size ([0, 0, 0, 0]): 000000 00 00 00 00 ....

13:18:05,476 DEBUG [DBus Sender Thread-1] o.f.d.MessageWriter: <= MethodCall(0,1) { Path=>/org/freedesktop/DBus, Interface=>org.freedesktop.DBus, Member=>Hello, Destination=>org.freedesktop.DBus } { } 13:18:05,484 DEBUG [DBusConnection] o.f.d.MessageReader: => MethodReturn(1,1) { Reply Serial=>1, Destination=>:1.73, Sender=>org.freedesktop.DBus, Signature=>s } { :1.73 } 13:18:05,485 DEBUG [DBusConnection] o.f.d.c.i.DBusConnection: Handling incoming method return: MethodReturn(1,1) { Reply Serial=>1, Destination=>:1.73, Sender=>org.freedesktop.DBus, Signature=>s } { :1.73 } 13:18:05,485 DEBUG [main] o.f.d.m.MethodCall: Creating message with serial 2 13:18:05,486 DEBUG [main] o.f.d.m.MethodCall: Appending sig: yyyy data: [66, 1, 0, 1] 13:18:05,486 DEBUG [main] o.f.d.m.MethodCall: Appending arguments with signature: su 13:18:05,487 DEBUG [main] o.f.d.m.MethodCall: Appending sig: ua(yv) data: [2, [[1, [o, /org/freedesktop/DBus]], [6, [s, org.freedesktop.DBus]], [2, [s, org.freedesktop.DBus]], [3, [s, RequestName]], [8, [g, su]]]] 13:18:05,487 DEBUG [main] o.f.d.m.MethodCall: Appending sig: su data: [at.valli.mesh, 6] 13:18:05,502 DEBUG [main] o.f.d.m.MethodCall: Appended body, type: su start: 144 end: 172 size: 28 13:18:05,502 DEBUG [main] o.f.d.m.MethodCall: marshalled size ([0, 0, 0, 28]): 000000 00 00 00 1c ...

13:18:05,503 DEBUG [DBusConnection] o.f.d.MessageReader: => DBusSignal [clazz=null] 13:18:05,504 DEBUG [DBusConnection] o.f.d.c.i.DBusConnection: Handling incoming signal: 13:18:05,505 DEBUG [DBus Sender Thread-1] o.f.d.MessageWriter: <= MethodCall(0,2) { Path=>/org/freedesktop/DBus, Interface=>org.freedesktop.DBus, Member=>RequestName, Destination=>org.freedesktop.DBus, Signature=>su } { at.valli.mesh, 6 } 13:18:05,521 DEBUG [DBusConnection] o.f.d.MessageReader: => DBusSignal [clazz=null] 13:18:05,521 DEBUG [DBusConnection] o.f.d.c.i.DBusConnection: Handling incoming signal: 13:18:05,522 DEBUG [DBus Worker Thread-1] o.f.d.m.DBusSignal: Converting signal to type: class org.freedesktop.DBus$NameAcquired 13:18:05,522 DEBUG [DBus Worker Thread-1] o.f.d.m.DBusSignal: Creating signal of type class org.freedesktop.DBus$NameAcquired with parameters [/org/freedesktop/DBus, :1.73] 13:18:05,523 DEBUG [DBus Worker Thread-1] o.f.DBus$NameAcquired: Creating message with serial 3 13:18:05,523 DEBUG [DBus Worker Thread-1] o.f.DBus$NameAcquired: Appending sig: yyyy data: [66, 4, 0, 1] 13:18:05,533 DEBUG [DBus Worker Thread-1] o.f.DBus$NameAcquired: Appending sig: ua(yv) data: [4, [[1, [o, /org/freedesktop/DBus]], [2, [s, org.freedesktop.DBus]], [3, [s, NameAcquired]], [8, [g, s]]]] 13:18:05,532 DEBUG [DBus Worker Thread-2] o.f.d.m.DBusSignal: Converting signal to type: class org.freedesktop.DBus$NameAcquired 13:18:05,533 DEBUG [DBus Worker Thread-2] o.f.d.m.DBusSignal: Creating signal of type class org.freedesktop.DBus$NameAcquired with parameters [/org/freedesktop/DBus, at.valli.mesh] 13:18:05,534 DEBUG [DBus Worker Thread-2] o.f.DBus$NameAcquired: Creating message with serial 4 13:18:05,534 DEBUG [DBus Worker Thread-2] o.f.DBus$NameAcquired: Appending sig: yyyy data: [66, 4, 0, 1] 13:18:05,534 DEBUG [DBus Worker Thread-2] o.f.DBus$NameAcquired: Appending sig: ua(yv) data: [5, [[1, [o, /org/freedesktop/DBus]], [2, [s, org.freedesktop.DBus]], [3, [s, NameAcquired]], [8, [g, s]]]] 13:18:05,532 DEBUG [DBusConnection] o.f.d.MessageReader: => MethodReturn(1,4) { Reply Serial=>2, Destination=>:1.73, Sender=>org.freedesktop.DBus, Signature=>u } { 1 } 13:18:05,536 DEBUG [DBusConnection] o.f.d.c.i.DBusConnection: Handling incoming method return: MethodReturn(1,4) { Reply Serial=>2, Destination=>:1.73, Sender=>org.freedesktop.DBus, Signature=>u } { 1 } 13:18:05,544 DEBUG [main] o.f.d.m.ObjectTree: Adding /at/valli/mesh to object tree 13:18:05,568 DEBUG [main] o.f.d.m.ObjectTree: Adding /at/valli/mesh/element/0 to object tree 13:18:05,570 DEBUG [main] o.f.d.m.ObjectTree: Adding /at/valli/mesh/element/1 to object tree 13:18:05,603 DEBUG [main] o.f.d.m.MethodCall: Creating message with serial 5 13:18:05,604 DEBUG [main] o.f.d.m.MethodCall: Appending sig: yyyy data: [66, 1, 0, 1] 13:18:05,612 DEBUG [main] o.f.d.m.MethodCall: Appending arguments with signature: oay 13:18:05,612 DEBUG [main] o.f.d.m.MethodCall: Appending sig: ua(yv) data: [5, [[1, [o, /org/bluez/mesh]], [6, [s, org.bluez.mesh]], [2, [s, org.bluez.mesh.Network1]], [3, [s, Join]], [8, [g, oay]]]] 13:18:05,614 DEBUG [main] o.f.d.m.MethodCall: Appending sig: oay data: [/at/valli/mesh, [13, -20, -21, -22, -10, 34, 73, 5, -82, -109, -6, 38, 24, -42, -80, -121]] 13:18:05,614 DEBUG [main] o.f.d.m.MethodCall: Appended body, type: oay start: 128 end: 172 size: 44 13:18:05,620 DEBUG [main] o.f.d.m.MethodCall: marshalled size ([0, 0, 0, 44]): 000000 00 00 00 2c ...,

13:18:05,621 DEBUG [DBus Sender Thread-1] o.f.d.MessageWriter: <= MethodCall(0,5) { Path=>/org/bluez/mesh, Interface=>org.bluez.mesh.Network1, Member=>Join, Destination=>org.bluez.mesh, Signature=>oay } { /at/valli/mesh, [13, -20, -21, -22, -10, 34, 73, 5, -82, -109, -6, 38, 24, -42, -80, -121] } 13:18:25,624 DEBUG [main] o.f.d.c.i.DBusConnection: Disconnecting last remaining DBusConnection 13:18:25,625 DEBUG [main] o.f.d.e.Error: Creating message with serial 6 13:18:25,628 DEBUG [main] o.f.d.e.Error: Appending sig: yyyy data: [66, 3, 0, 1] 13:18:25,629 DEBUG [main] o.f.d.e.Error: Appending sig: ua(yv) data: [6, [[4, [s, org.freedesktop.DBus.Local.Disconnected]], [5, [u, 0]], [6, [s, org.freedesktop.DBus.Local]], [8, [g, s]]]] 13:18:25,635 DEBUG [main] o.f.d.e.Error: Appending sig: s data: [Disconnected] 13:18:25,636 DEBUG [main] o.f.d.c.i.DBusConnection: Sending disconnected signal 13:18:25,637 DEBUG [main] o.f.d.i.Local$Disconnected: Creating message with serial 7 13:18:25,641 DEBUG [main] o.f.d.i.Local$Disconnected: Appending sig: yyyy data: [66, 4, 0, 1] 13:18:25,642 DEBUG [main] o.f.d.i.Local$Disconnected: Appending sig: ua(yv) data: [8, [[1, [o, /]], [2, [s, org.freedesktop.DBus.Local]], [3, [s, Disconnected]]]] 13:18:25,643 DEBUG [main] o.f.d.c.i.DBusConnection: Handling incoming signal: 13:18:25,645 DEBUG [main] o.f.d.c.i.DBusConnection: Handling Disconnected signal from bus 13:18:25,646 DEBUG [main] o.f.d.e.Error: Creating message with serial 8 13:18:25,646 DEBUG [main] o.f.d.e.Error: Appending sig: yyyy data: [66, 3, 0, 1] 13:18:25,647 DEBUG [main] o.f.d.e.Error: Appending sig: ua(yv) data: [8, [[4, [s, org.freedesktop.DBus.Local.Disconnected]], [5, [u, 0]], [6, [s, org.freedesktop.DBus.Local]], [8, [g, s]]]] 13:18:25,650 DEBUG [main] o.f.d.e.Error: Appending sig: s data: [Disconnected] 13:18:25,652 DEBUG [main] o.f.d.c.i.DBusConnection: Handling Disconnected signal from bus 13:18:25,653 DEBUG [main] o.f.d.e.Error: Creating message with serial 9 13:18:25,653 DEBUG [main] o.f.d.e.Error: Appending sig: yyyy data: [66, 3, 0, 1] 13:18:25,658 DEBUG [main] o.f.d.e.Error: Appending sig: ua(yv) data: [9, [[4, [s, org.freedesktop.DBus.Local.Disconnected]], [5, [u, 0]], [6, [s, org.freedesktop.DBus.Local]], [8, [g, s]]]] 13:18:25,658 DEBUG [main] o.f.d.e.Error: Appending sig: s data: [Disconnected] 13:18:25,658 DEBUG [main] o.f.d.c.i.DBusConnection: Disconnecting Abstract Connection 13:18:25,659 DEBUG [main] o.f.d.c.Transport: Disconnecting Transport 13:18:25,659 DEBUG [main] c.a.m.u.UnixSocket: Closing socket 13:18:25,672 DEBUG [main] o.f.d.MessageWriter: Closing Message Writer org.freedesktop.dbus.errors.NoReply: No reply within specified time at org.freedesktop.dbus.RemoteInvocationHandler.executeRemoteMethod(RemoteInvocationHandler.java:160) at org.freedesktop.dbus.RemoteInvocationHandler.invoke(RemoteInvocationHandler.java:228) at com.sun.proxy.$Proxy19.Join(Unknown Source) at at.valli.Main.main(Main.java:34) 13:18:25,672 DEBUG [main] c.a.m.u.UnixSocket: Closing socket`

The method I want to invoked is defined as follows: void Join(object app_defined_root, array{byte}[16] uuid)

`

        <arg name="uuid" type="ay" direction="in"/>
    </method>`

I've mapped that with the help of the CodeGenerator to: void Join(DBusInterface app_defined_root, List<Byte> uuid);

Best regards valli

hypfvieh commented 5 years ago

I think your interface definition is not valid. From my experience with bluez ble implementation (see: bluez-dbus), I guess it should be:

void Join(DBusPath app_defined_root, byte[] uuid);

Also be sure that the objectPath and dbusName are valid and available (e.g. using d-feet).

valliman commented 5 years ago

Thank you for your quick response.

I used d-feet and checked whether the objectPath and dbusName is correct and that seems fine.

I can see the Join method with d-feet: Join(Object Path app, Array of [Byte] uuid) -> ()

I've changed the interfaces as suggested by you above, and use as DBusPath the object path of my application object. In the end I am still unlucky. Is there some way to get more debug information or a better guess on what is goring wrong?

Best regards valli

hypfvieh commented 5 years ago

Could you please show your Network1 interface class?

valliman commented 5 years ago

I'v used the documentation provided here: https://git.kernel.org/pub/scm/bluetooth/bluez.git/tree/doc/mesh-api.txt

`package org.bluez.mesh;

import org.freedesktop.dbus.DBusPath; import org.freedesktop.dbus.annotations.MethodError; import org.freedesktop.dbus.annotations.MethodNoReply; import org.freedesktop.dbus.interfaces.DBusInterface; import java.util.List; import org.freedesktop.dbus.types.UInt64;

public interface Network1 extends DBusInterface {

void Join(DBusPath app_defined_root, byte[] uuid);

void Cancel();

AttachTuple Attach(DBusPath app_defined_root, UInt64 token);

void Leave(UInt64 token);

UInt64 CreateNetwork(DBusInterface app_root, byte[] uuid);

UInt64 ImportLocalNode(String json_data);

}`

hypfvieh commented 5 years ago

I've played around with the mesh stuff, but I don't get it to work. I use the latest git version of it, because it seems that the mesh part got a lot of updates in the past few month after release of 5.50.

But when I call "Join" the daemon hangs. Debugging output of mesh daemon is more than useless. After the "Join" call the registered dbus name is disappearing and the daemon can only be stopped using kill -9.

For me it looks like the whole mesh stuff is pretty buggy. As I don't have a clou how to work with this mesh stuff, I would suggest that you first try to use the meshctl commandline tool provided by bluez. If you get this running (I don't), it may help to find what's wrong with dbus-java or your code.

valliman commented 5 years ago

Hi, thanks for your reply. I observed exactly the same behavior concerning the daemon going to stuck mode. I will try to contact some of the mesh developers to get some help on their side.

:)

valliman commented 5 years ago

Hi hypfvieh,

I did not have that much progress. I found out that my ObjectManager interface was not published correctly, therefore the meshd could not look-up the required interfaces on the bus as explained in the doc under Mesh Application Hierachy.

What I am curious about is the uint8 type which is mentioned on the Element1 interface for the Index property. Is it sufficient to map this to a Byte or would this require a new UInt8 implementation?

Best regards valli

hypfvieh commented 5 years ago

uint8 is not a valid DBus type. The DBus specs only mention uint8 once and that's for the SIGNATURE type (see: https://dbus.freedesktop.org/doc/dbus-specification.html#container-types).

A java byte is indeed something different, as it has a different range. While uint8 is 0..255, java byte is -127..128. So maybe it is the wrong type...

Anyways, as the uint8 type has no specific encoding literal (like "s" for String) on the DBus interface, bluez-mesh will have to something compatible like "y" which would be a byte in java or use something different like "n" or "q".

I'm pretty busy atm so I don't have the time to investigate what is really used by bluez-mesh, so you may have a look yourself.

valliman commented 5 years ago

Hi,

I checked the spec above and saw that the fixed, basic | BYTE | 121 (ASCII 'y') | 8-bit unsigned integer which is anyway mapped to a byte

I progressed with my test code up to the point where the meshd crashes due to malloc error (on invoking Join). Just to be sure that it is no meshd issue I got a python sample up and running which does the same Network1.Join code with the same data. I verified that using dbus-monitor --system. The output of using python and java code looks the same. The outcome is quite different, on python side the meshd it continues, using java it is aborted with an error on malloc.

Using TRACE logging I traced the following lines on sending side:

14:55:17,475 DEBUG [DBus Sender Thread-1] o.f.d.MessageWriter: <= MethodCall(0,6) { Path=>/org/bluez/mesh, Interface=>org.bluez.mesh.Network1, Member=>Join, Destination=>org.bluez.mesh, Signature=>oay } { /at/valli/9c791e887acb42e595abab75cb74d774, [-100, 121, 30, -120, 122, -53, 66, -27, -107, -85, -85, 117, -53, 116, -41, 116] }
14:55:17,475 DEBUG [DBus Sender Thread-1] o.f.d.MessageWriter: Writing all 40 buffers simultaneously to Unix Socket
14:55:17,475 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([66, 1, 0, 1]):000000   42 01 00 01                                            B...              

14:55:17,475 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([0, 0, 0, 68]):000000   00 00 00 44                                            ...D              

14:55:17,475 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([0, 0, 0, 6]):000000    00 00 00 06                                            ....              

14:55:17,475 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([0, 0, 0, 105]):000000  00 00 00 69                                            ...i              

14:55:17,475 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([1]):000000 01                                                     .                 

14:55:17,475 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([1, 111, 0]):000000 01 6f 00                                               .o.               

14:55:17,475 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([0, 0, 0, 15]):000000   00 00 00 0f                                            ....              

14:55:17,475 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([47, 111, 114, 103, 47, 98, 108, 117, 101, 122, 47, 109, 101, 115, 104]):000000 2f 6f 72 67 2f 62 6c 75 65 7a 2f 6d 65 73 68           /org/bluez/mesh   

14:55:17,475 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([0]):000000 00                                                     .                 

14:55:17,475 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([6]):000000 06                                                     .                 

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([1, 115, 0]):000000 01 73 00                                               .s.               

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([0, 0, 0, 14]):000000   00 00 00 0e                                            ....              

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([111, 114, 103, 46, 98, 108, 117, 101, 122, 46, 109, 101, 115, 104]):000000 6f 72 67 2e 62 6c 75 65 7a 2e 6d 65 73 68              org.bluez.mesh    

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([0]):000000 00                                                     .                 

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([0]):000000 00                                                     .                 

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([2]):000000 02                                                     .                 

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([1, 115, 0]):000000 01 73 00                                               .s.               

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([0, 0, 0, 23]):000000   00 00 00 17                                            ...              

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([111, 114, 103, 46, 98, 108, 117, 101, 122, 46, 109, 101, 115, 104, 46, 78, 101, 116, 119, 111, 114, 107, 49]):000000   6f 72 67 2e 62 6c 75 65 7a 2e 6d 65 73 68 2e 4e 65 74  org.bluez.mesh.Net
000012  77 6f 72 6b 31                                         work1             

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([0]):000000 00                                                     .                 

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([3]):000000 03                                                     .                 

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([1, 115, 0]):000000 01 73 00                                               .s.               

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([0, 0, 0, 4]):000000    00 00 00 04                                            ....              

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([74, 111, 105, 110]):000000 4a 6f 69 6e                                            Join              

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([0]):000000 00                                                     .                 

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([0, 0, 0]):000000   00 00 00                                               ...               

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([8]):000000 08                                                     .                 

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([1, 103, 0]):000000 01 67 00                                               .g.               

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([3, 111, 97, 121, 0]):000000    03 6f 61 79 00                                         .oay.             

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([0, 0, 0, 0, 0, 0, 0]):000000   00 00 00 00 00 00 00                                   .......           

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([0, 0, 0, 42]):000000   00 00 00 2a                                            ...*              

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([47, 97, 116, 47, 118, 97, 108, 108, 105, 47, 57, 99, 55, 57, 49, 101, 56, 56, 55, 97, 99, 98, 52, 50, 101, 53, 57, 53, 97, 98, 97, 98, 55, 53, 99, 98, 55, 52, 100, 55, 55, 52]):000000    2f 61 74 2f 76 61 6c 6c 69 2f 39 63 37 39 31 65 38 38  /at/valli/9c791e88
000012  37 61 63 62 34 32 65 35 39 35 61 62 61 62 37 35 63 62  7acb42e595abab75cb
000024  37 34 64 37 37 34                                      74d774            

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([0]):000000 00                                                     .                 

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([0]):000000 00                                                     .                 

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([0, 0, 0, 16]):000000   00 00 00 10                                            ....              

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: ([-100, 121, 30, -120, 122, -53, 66, -27, -107, -85, -85, 117, -53, 116, -41, 116]):000000   9c 79 1e 88 7a cb 42 e5 95 ab ab 75 cb 74 d7 74        .y.z.B....u.t.t  

14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: (null):
14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: (null):
14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: (null):
14:55:17,476 TRACE [DBus Sender Thread-1] o.f.d.MessageWriter: (null):

On meshd side I added some debug output and I can see that a message with the following header and body size (in bytes) is received.

header: 2130706448 body: 1140850688

That would be more than 1 gb body and more than 2 gb header ... that's very odd ... and explains why the daemon crashes on memory allocation.

I am using a debian Jessie installation, is there some incompatibiliy with that quite old os version and the Java library?

hypfvieh commented 5 years ago

I don't think it has something to do with the debian version. On my machine it also fails (Ubuntu 16.04 using lastest GIT snapshots of bluez and ELL).

For me it looks like the problem already appears in the ELL-Library not in bluez. It's likely an integer overflow caused by the parser of the dbus message.

I tried to call 'cancel' on the Network1 interface to ensure the issue is not caused by the parameters provided to Join (quick side note: you passing in a UUID as byte-array which is to large, UUID class generated 36 byte uuids, while Join only wants 16 bytes).

Calling cancel without anything to cancel should result in an exception (see: mesh.c, line ~610). But when calling cancel the daemon stucks like using join.

I then turned on Dbus-Debugging in mesh (using -b parameter, which is not explained in help output but you'll find it when looking at main.c). I re-tried my test, but did not even see that the message is getting far enough to get logged by bluez-mesh.

So for me it looks like the problem is caused in the ELL-library.

ELL differs between two variants of DBus messages. Message which uses GVariant (16 byte header) and the non-GVariant (12 byte header, used by dbus-java).

As dbus-java is working fine with other services (like bluez itself or network-manager), I can only guess that your python script is doing something else than dbus-java.

Does it send GVariant messages? Can you provide your sample code?

valliman commented 5 years ago

Hi,

Hi,

looks like tricky one so far. Thank you for helping so far. I used the python sample code located here https://github.com/SilvairGit/bluetooth-meshd-example

Best regards valli

hypfvieh commented 5 years ago

Ok, I think a got a bit further on this one...

After thinking about the large header/body size you reported, I was pretty sure that this is some integer overflow.

But after debugging a bit further, it seems to be an issue with the endianess of the used messages. It seems like ELL expects litte-endian (at least on my machine), while dbus-java is using big-endian. That means byte order is different and so a small number in big-endian will be large in litte-endian.

After changing the (sadly hardcoded) big-endian to little-endian in dbus-java, it seems to work (more debug output from mesh).

I'll take a look if we can get rid of the hardcoded big-endian crap ...

Anyways I would expect ELL to except both endianesses and convert between them, because the endianess used on a message is signaled by the first byte of the header (capital B for BIG, lower L for little). dbus-java should already be able to handle that, but the created messages are always big-endian atm.

valliman commented 5 years ago

Hi David,

I just did a bit of digging concerning endianess and ell. It seems that ell uses a pre-processor instruction to define the dbus endianess, based on the native byte order of the system. So on runtime it supports only one version of endianess. Sadly that check is done about 100 lines after the memory is allocated and debug message would be printed then.

I assume based on that information the java library code should be changed to use native byte order as well. It seems that Java even supports to determine that. See https://stackoverflow.com/questions/9431526/find-endianness-of-system-in-java

What do you think about that?

Best regards valli

hypfvieh commented 5 years ago

I just pushed some changes.

Endianness is now automatically chosen based on used system/architecture, but it is also possible to use a specific endianness by using DBusConnection.setEndianness(byte) before calling DBusConnection.getConnection/newConnection.

valliman commented 5 years ago

Hi,

this definitely improved the situation. Communication works now on bus-level. I have to do some further investigation on how to properly interact with the mesh daemon, but that's another topic.

Thank you for your support so far.

hypfvieh commented 5 years ago

ok, I'll close this ticket now, as the main cause for this issue has been resolved in my eyes.