0

Many `nameOwnerChanged`calls in AboutServiceImpl

asked 2014-05-16 03:28:04 -0800

PierreR gravatar image

I have a simple application in java, which uses AboutService. When looking at the logs, I see dozens of calls to MyBusListener.nameOwnerChanged, even when nothing is happening (not joining new sessions, not sending signals, not calling alljoyn methods, etc.).

If I understand correctly, these calls mean that a well-known name is "moving" from one unique-name to another (or is being created or removed). But I definitely does not understand why this would happen.

here is a small example of what I see in the logs.

ioeAboutServiceImplDebug: MyBusListener.nameOwnerChanged(:RT342Q5X.1, null, :RT342Q5X.1)
ioeAboutServiceImplDebug: MyBusListener.nameOwnerChanged(:RT342Q5X.2, null, :RT342Q5X.2)
ioeAboutServiceImplDebug: MyBusListener.nameOwnerChanged(:L9nlTezc.1, null, :L9nlTezc.1)
ioeAboutServiceImplDebug: MyBusListener.nameOwnerChanged(org.alljoyn.sl.xL9nlTezc.x0, null, :L9nlTezc.1)
ioeAboutServiceImplDebug: MyBusListener.nameOwnerChanged(:RT342Q5X.1, :RT342Q5X.1, null)
ioeAboutServiceImplDebug: MyBusListener.nameOwnerChanged(:RT342Q5X.2, :RT342Q5X.2, null)
ioeAboutServiceImplDebug: MyBusListener.nameOwnerChanged(org.alljoyn.sl.xL9nlTezc.x0, :L9nlTezc.1, null)
ioeAboutServiceImplDebug: MyBusListener.nameOwnerChanged(:L9nlTezc.1, :L9nlTezc.1, null)
ioeAboutServiceImplDebug: MyBusListener.foundAdvertisedName: ':L9nlTezc.2'
ioeAboutServiceImplDebug: MyBusListener.nameOwnerChanged(:L9nlTezc.1, null, :L9nlTezc.1)
ioeAboutServiceImplDebug: MyBusListener.nameOwnerChanged(org.alljoyn.sl.xL9nlTezc.x0, null, :L9nlTezc.1)
onAnnouncement :L9nlTezc.2 - 777 [Lorg.alljoyn.services.common.BusObjectDescription;@77932b46
ioeAboutServiceImplDebug: MyBusListener.nameOwnerChanged(org.alljoyn.sl.xL9nlTezc.x0, :L9nlTezc.1, null)
ioeAboutServiceImplDebug: MyBusListener.nameOwnerChanged(:L9nlTezc.1, :L9nlTezc.1, null)

I'm not sure if it is a problem, but I'd like to understand what's happening behind the scene.

edit retag flag offensive close merge delete

Comments

I have noticed the same issue, I really don´t understand why this is happening but, your app will run normally I think that it is not something critical

pmais ( 2014-05-23 09:27:53 -0800 )edit

2 answers

Sort by » oldest newest most voted
3

answered 2014-05-27 08:40:30 -0800

georgen gravatar image

updated 2014-05-28 09:33:37 -0800

As noted by tmalsbar this is a issue that has been reported. The issue is due to the library code logging debug information to stdout that should not be logged.

There is a way to override the debugging information as was done in this sample code.

create a generic logger that does nothing.

then set that as the aboutService Logger. This will override the output.

aboutService = AboutServiceImpl.getInstance();
System.out.println("starting about service in client mode");
aboutService.setLogger(new SampleLogger());

the ticket ASACORE-117 has been marked as fixed and this should not be an issue for the next release.

Why all the NameOwnerChanged signals? (edit May 28, 2014)

The NameOwnerChanged signal is a very common signal it occurs every time a name is obtained or lost from the Routing Node.

using the debug output that you posted I will do my best to explain why you are seeing so many names.

ioeAboutServiceImplDebug: MyBusListener.nameOwnerChanged(:RT342Q5X.1, null, :RT342Q5X.1)
ioeAboutServiceImplDebug: MyBusListener.nameOwnerChanged(:RT342Q5X.2, null, :RT342Q5X.2)

this is most likely the Routing Node and the Leaf node of your application. Since the most common configuration of a AllJoyn enabled application is to use a Routing Node bundled in with the application. When you start you are getting the unique name of the Routing Node :RT342Q5X.1 and the unique name of your application :RT342Q5X.2. A minimum of two NameOwnerChange signals are expected for any application.

Most of the rest of the NameOwnerChange signals are a result of the sessionless signals system. The way that sessionless signals work. They advertise a name org.alljoyn.sl.x<unique name w/o ':'>.x<serial Number of the signal>. The routing node always looks for session less signals. When a sessionless signal is found a quick connection is formed with the remote routing node and the any information regarding that signal is transferred to the local Routing node. Then the connection is dropped.

The org.alljoyn.sl name was found and a conection with :L9nlTezc.1 was formed. Two names are transferred from the remote routing node. The Unique bus Name :L9nlTezc.1 and the alias org.alljoyn.sl.xL9nlTezc.x0

ioeAboutServiceImplDebug: MyBusListener.nameOwnerChanged(:L9nlTezc.1, null, :L9nlTezc.1)
ioeAboutServiceImplDebug: MyBusListener.nameOwnerChanged(org.alljoyn.sl.xL9nlTezc.x0, null, :L9nlTezc.1)

Once the transfer of information about the sessionless signal is completed the connection is dropped. If no other connections with the remote routing node exist all information about that remote routing node is cleared from the local routing node. This shows up as another pair of NameOwnerChanged Signals.

ioeAboutServiceImplDebug: MyBusListener.nameOwnerChanged(:L9nlTezc.1, :L9nlTezc.1, null)
ioeAboutServiceImplDebug: MyBusListener.nameOwnerChanged(org.alljoyn.sl.xL9nlTezc.x0, :L9nlTezc.1, null)

This quick addition and subtraction of nameOwnerChanged signals is a result of the sessionless signal mechanism. Sessionless signals have been optimized to only transfer names related with the sessionless signals. To reduce network traffic.

Under most circumstances. When a session is formed between two routing nodes all bus names are transferred between the the ... (more)

edit flag offensive delete publish link more

Comments

That's exactly what I'm doing to avoid polluting my logs with all these messages ! But my question is not really about why it's logged, but more about why do all these name changes occur, even when I'm not doing anything ?

PierreR ( 2014-05-28 00:26:53 -0800 )edit

edited the answer to addressed your question.

georgen ( 2014-05-28 09:34:15 -0800 )edit
2

answered 2014-05-23 18:07:51 -0800

This is a side effect of how the Announce sessionless signal is received (you can tell from the org.alljoyn.sl. name that is being logged). There is an open ticket against this issue: https://jira.allseenalliance.org/browse/ASACORE-117 .

edit flag offensive delete publish link more
Login/Signup to Answer

Question Tools

Follow
4 followers

Stats

Asked: 2014-05-16 03:28:04 -0800

Seen: 350 times

Last updated: May 28 '14