Thread Rating:
  • 0 Votes - 0 Average
  • 1
  • 2
  • 3
  • 4
  • 5
Logging calls removed from ohNet runtime
03-11-2017, 05:25 PM
Post: #1
Logging calls removed from ohNet runtime
I am trying to move up to the current level of ohNet. The C++ logging APIs have changed and this requires changes to the C and Java bindings. I have implemented these changes (patch in preparation) and I have been able to get MinimServer running on 1.17.2735.

The next problem for me is the removal (commenting out) of a number of logging calls that are crucial for MinimServer debugging of ohNet-related runtime issues. Specifically, Network.cpp has 65 calls to LOG( or Log( and all of these are now commented out. Could these be reinstated, perhaps as LOG_TRACE calls? I would be happy to provide a patch for this.
Find all posts by this user
15-11-2017, 02:51 PM
Post: #2
RE: Logging calls removed from ohNet runtime
(03-11-2017 05:25 PM)simoncn Wrote:  I am trying to move up to the current level of ohNet. The C++ logging APIs have changed and this requires changes to the C and Java bindings. I have implemented these changes (patch in preparation) and I have been able to get MinimServer running on 1.17.2735.

The next problem for me is the removal (commenting out) of a number of logging calls that are crucial for MinimServer debugging of ohNet-related runtime issues. Specifically, Network.cpp has 65 calls to LOG( or Log( and all of these are now commented out. Could these be reinstated, perhaps as LOG_TRACE calls? I would be happy to provide a patch for this.

Were there particular lines you found helpful? I never found any use for it - Network level logging was incredibly verbose and didn't give any hint about which of the dozens of networking threads was running. We'd assumed that no-one could be relying on it so apologies if this has caused you problems.
Find all posts by this user
15-11-2017, 05:14 PM (This post was last modified: 15-11-2017 05:53 PM by simoncn.)
Post: #3
RE: Logging calls removed from ohNet runtime
(15-11-2017 02:51 PM)simonc Wrote:  Were there particular lines you found helpful? I never found any use for it - Network level logging was incredibly verbose and didn't give any hint about which of the dozens of networking threads was running. We'd assumed that no-one could be relying on it so apologies if this has caused you problems.

I will provide a patch for the temporary changes that I have made locally to add back the required logging calls. This will take a few days as I will be away from home until the weekend.

MinimServer adds thread and timestamp information to the messages sent by ohNet, so the resulting log output looks something like this:

Code:
16:56:48.759 main: ohNet: NetworkAdapter added: Software Loopback Interface 1(127.0.0.1)
16:56:48.759 main: ohNet: NetworkAdapter added: Intel(R) WiFi Link 5300 AGN(192.168.0.14)
16:56:48.760 main: OhNetService: library initialized
16:56:48.791 main: OhNetService: setting library single subnet 192.168.0.0
16:56:48.791 main: ohNet: Subnet changed: Intel(R) WiFi Link 5300 AGN(192.168.0.14)
16:56:48.791 main: OhNetService: creating DeviceStack
16:56:48.794 main: ohNet: OpenHome/Network.cpp:534: SocketTcpServer::SocketTcpServer
16:56:48.794 main: ohNet: OpenHome/Network.cpp:18: SocketCreate  ST = 1,
16:56:48.795 main: ohNet: OpenHome/Network.cpp:20: SocketCreate  Socket H = 375396736
16:56:48.795 main: ohNet: OpenHome/Network.cpp:319: Socket::Bind H = 375396736
16:56:48.795 main: ohNet: OpenHome/Network.cpp:332: Socket::GetPort H = 375396736
16:56:48.795 main: ohNet: OpenHome/Network.cpp:342: Socket::Listen H = 375396736 S = 128
16:56:48.796 main: ohNet: OpenHome/Network.cpp:425: SocketTcp::SocketTcp
16:56:48.796 main: ohNet: OpenHome/Network.cpp:425: SocketTcp::SocketTcp
16:56:48.797 main: ohNet: OpenHome/Network.cpp:425: SocketTcp::SocketTcp
16:56:48.797 main: ohNet: OpenHome/Network.cpp:425: SocketTcp::SocketTcp
16:56:48.797 main: ohNet: OpenHome/Network.cpp:425: SocketTcp::SocketTcp
16:56:48.797 main: ohNet: OpenHome/Network.cpp:546: SocketTcpServer::Add
16:56:48.797 main: ohNet: OpenHome/Network.cpp:425: SocketTcp::SocketTcp
16:56:48.797 main: ohNet: OpenHome/Network.cpp:546: SocketTcpServer::Add
16:56:48.797 main: ohNet: OpenHome/Network.cpp:425: SocketTcp::SocketTcp
16:56:48.798 Thread-8: ohNet: OpenHome/Network.cpp:610: >SocketTcpSession::Start()
16:56:48.798 Thread-8: ohNet: OpenHome/Network.cpp:561: SocketTcpServer::Accept
16:56:48.798 Thread-8: ohNet: OpenHome/Network.cpp:352: Socket::Accept H = 375396736
16:56:48.798 Thread-9: ohNet: OpenHome/Network.cpp:610: >SocketTcpSession::Start()
16:56:48.798 Thread-9: ohNet: OpenHome/Network.cpp:561: SocketTcpServer::Accept
16:56:48.798 main: ohNet: OpenHome/Network.cpp:546: SocketTcpServer::Add
16:56:48.798 main: ohNet: OpenHome/Network.cpp:425: SocketTcp::SocketTcp
16:56:48.798 main: ohNet: OpenHome/Network.cpp:546: SocketTcpServer::Add
16:56:48.799 main: ohNet: OpenHome/Network.cpp:534: SocketTcpServer::SocketTcpServer
16:56:48.799 main: ohNet: OpenHome/Network.cpp:18: SocketCreate  ST = 1,
16:56:48.799 Thread-10: ohNet: OpenHome/Network.cpp:610: >SocketTcpSession::Start()
16:56:48.800 Thread-10: ohNet: OpenHome/Network.cpp:561: SocketTcpServer::Accept
16:56:48.800 Thread-11: ohNet: OpenHome/Network.cpp:610: >SocketTcpSession::Start()
16:56:48.800 Thread-11: ohNet: OpenHome/Network.cpp:561: SocketTcpServer::Accept
16:56:48.800 main: ohNet: OpenHome/Network.cpp:20: SocketCreate  Socket H = 375397120
16:56:48.800 main: ohNet: OpenHome/Network.cpp:319: Socket::Bind H = 375397120
16:56:48.800 main: ohNet: OpenHome/Network.cpp:332: Socket::GetPort H = 375397120
16:56:48.800 main: ohNet: OpenHome/Network.cpp:342: Socket::Listen H = 375397120 S = 128
16:56:48.803 main: ohNet: OpenHome/Network.cpp:425: SocketTcp::SocketTcp
16:56:48.803 main: ohNet: OpenHome/Network.cpp:425: SocketTcp::SocketTcp
16:56:48.803 main: ohNet: OpenHome/Network.cpp:425: SocketTcp::SocketTcp
16:56:48.803 main: ohNet: OpenHome/Network.cpp:425: SocketTcp::SocketTcp
16:56:48.803 main: ohNet: OpenHome/Network.cpp:425: SocketTcp::SocketTcp
16:56:48.803 main: ohNet: OpenHome/Network.cpp:546: SocketTcpServer::Add
16:56:48.804 main: ohNet: OpenHome/Network.cpp:425: SocketTcp::SocketTcp
16:56:48.804 main: ohNet: OpenHome/Network.cpp:546: SocketTcpServer::Add
16:56:48.804 main: ohNet: OpenHome/Network.cpp:425: SocketTcp::SocketTcp
16:56:48.804 Thread-12: ohNet: OpenHome/Network.cpp:610: >SocketTcpSession::Start()
16:56:48.804 Thread-12: ohNet: OpenHome/Network.cpp:561: SocketTcpServer::Accept
16:56:48.804 Thread-12: ohNet: OpenHome/Network.cpp:352: Socket::Accept H = 375397120
16:56:48.804 Thread-13: ohNet: OpenHome/Network.cpp:610: >SocketTcpSession::Start()
16:56:48.805 Thread-13: ohNet: OpenHome/Network.cpp:561: SocketTcpServer::Accept
16:56:48.805 main: ohNet: OpenHome/Network.cpp:546: SocketTcpServer::Add
16:56:48.805 main: ohNet: OpenHome/Network.cpp:425: SocketTcp::SocketTcp
16:56:48.805 Thread-14: ohNet: OpenHome/Network.cpp:610: >SocketTcpSession::Start()
16:56:48.805 Thread-14: ohNet: OpenHome/Network.cpp:561: SocketTcpServer::Accept
16:56:48.805 main: ohNet: OpenHome/Network.cpp:546: SocketTcpServer::Add
16:56:48.806 main: ohNet: > DviSubscriptionManager: creating 4 publisher threads
16:56:48.806 Thread-15: ohNet: OpenHome/Network.cpp:610: >SocketTcpSession::Start()
16:56:48.806 Thread-15: ohNet: OpenHome/Network.cpp:561: SocketTcpServer::Accept
16:56:48.810 main: OhNetService: device factory created
16:56:48.810 main: Monitor: creating device c8faefb2-987c-4e53-b2b0-09f4985efa84
16:56:48.810 main: OhNetService: creating standard device
16:56:48.838 main: ohNet: OpenHome/Network.cpp:697: > SocketUdpBase::SocketUdpBase
16:56:48.838 main: ohNet: OpenHome/Network.cpp:18: SocketCreate  ST = 2,
16:56:48.838 main: ohNet: OpenHome/Network.cpp:20: SocketCreate  Socket H = 376213488
16:56:48.839 main: ohNet: OpenHome/Network.cpp:699: < SocketUdpBase::SocketUdpBase H = 376213488
16:56:48.839 main: ohNet: OpenHome/Network.cpp:801: > SocketUdpMulticast::SocketUdpMulticast I = 100007f, E = faffffef:1900
16:56:48.839 main: ohNet: OpenHome/Network.cpp:332: Socket::GetPort H = 376213488
16:56:48.839 main: ohNet: OpenHome/Network.cpp:809: < SocketUdpMulticast::SocketUdpMulticast H = 376213488, I = 100007f, A = faffffef, P = 1900
16:56:48.839 main: ohNet: OpenHome/Network.cpp:704: > SocketUdp::SetTtl T = 2
16:56:48.839 main: ohNet: OpenHome/Network.cpp:706: < SocketUdp::SetTtl
16:56:48.839 main: ohNet: OpenHome/Network.cpp:697: > SocketUdpBase::SocketUdpBase
16:56:48.840 main: ohNet: OpenHome/Network.cpp:18: SocketCreate  ST = 2,
16:56:48.840 Thread-16: ohNet: OpenHome/Network.cpp:727: > SocketUdpBase::Receive
16:56:48.840 Thread-16: ohNet: OpenHome/Network.cpp:306: Socket::ReceiveFrom H = 376213488
16:56:48.840 main: ohNet: OpenHome/Network.cpp:20: SocketCreate  Socket H = 376213512
16:56:48.840 main: ohNet: OpenHome/Network.cpp:699: < SocketUdpBase::SocketUdpBase H = 376213512
16:56:48.840 main: ohNet: OpenHome/Network.cpp:801: > SocketUdpMulticast::SocketUdpMulticast I = e00a8c0, E = faffffef:1900
16:56:48.840 main: ohNet: OpenHome/Network.cpp:332: Socket::GetPort H = 376213512
16:56:48.840 main: ohNet: OpenHome/Network.cpp:809: < SocketUdpMulticast::SocketUdpMulticast H = 376213512, I = e00a8c0, A = faffffef, P = 1900
16:56:48.841 main: ohNet: OpenHome/Network.cpp:704: > SocketUdp::SetTtl T = 2
16:56:48.841 main: ohNet: OpenHome/Network.cpp:706: < SocketUdp::SetTtl

The threads are indicated by "main" and "Thread-nn".

I had a few spare minutes before getting ready to leave, so here is the patch. Smile


Attached File(s)
.zip  logging.zip (Size: 3.29 KB / Downloads: 1)
Find all posts by this user
15-11-2017, 09:50 PM
Post: #4
RE: Logging calls removed from ohNet runtime
Here is the patch for the changes to the Java and C bindings. The following file is added:

OpenHome\Net\Bindings\Java\org\openhome\net\core\DebugSeverity.java

The following files are changed:

OpenHome\Net\Bindings\Java\org\openhome\net\core\DebugLevel.java
OpenHome\Net\Bindings\Java\org\openhome\net\core\Library.java
OpenHome\Net\Bindings\Java\Library.c
OpenHome\Net\Bindings\Java\Library.h
OpenHome\Net\Bindings\C\OhNetC.cpp
OpenHome\Net\Bindings\C\OhNet.h

Any Java application that uses the logging APIs will need to be recompiled because the changes are not binary compatible.


Attached File(s)
.zip  bindings.zip (Size: 4.37 KB / Downloads: 2)
Find all posts by this user
16-11-2017, 03:30 PM
Post: #5
RE: Logging calls removed from ohNet runtime
I've applied both of these patches now
Find all posts by this user
16-11-2017, 10:29 PM
Post: #6
RE: Logging calls removed from ohNet runtime
(16-11-2017 03:30 PM)simonc Wrote:  I've applied both of these patches now

Thanks very much!
Find all posts by this user
21-11-2017, 12:49 PM
Post: #7
RE: Logging calls removed from ohNet runtime
It looks like the bindings.zip patch was not applied completely. The patch changed DebugLevel.java to use 64-bit bitmask values (as used by the ohNet runtime) but the change that was applied leaves the values as 32-bit. This means that any logging settings with values over 1<<31 are not accessible from Java.

At present, the values that are not accessible are CpDeviceDv (1<<62) and AdapterChange (1<<63). I presume it is possible that more such values could be added in the future. Is there a reason why these values are not made accessible from Java?

Also, this file previously defined the constant DebugLevel.All (0x7FFFFFFF). This constant has been removed and there is now no DebugLevel.All value. MinimServer depends on the DebugLevel.All value. Is there a reason why this was removed?
Find all posts by this user
21-11-2017, 04:48 PM
Post: #8
RE: Logging calls removed from ohNet runtime
(21-11-2017 12:49 PM)simoncn Wrote:  It looks like the bindings.zip patch was not applied completely. The patch changed DebugLevel.java to use 64-bit bitmask values (as used by the ohNet runtime) but the change that was applied leaves the values as 32-bit. This means that any logging settings with values over 1<<31 are not accessible from Java.

At present, the values that are not accessible are CpDeviceDv (1<<62) and AdapterChange (1<<63). I presume it is possible that more such values could be added in the future. Is there a reason why these values are not made accessible from Java?

Also, this file previously defined the constant DebugLevel.All (0x7FFFFFFF). This constant has been removed and there is now no DebugLevel.All value. MinimServer depends on the DebugLevel.All value. Is there a reason why this was removed?

Sorry about that - it wasn't deliberate. I've never been able to automatically apply your patches so need to manually reapply the changes. I didn't quite get it right last time. I've applied the missing changes locally so they'll make it onto github soon.
Find all posts by this user
21-11-2017, 06:15 PM (This post was last modified: 21-11-2017 08:09 PM by simoncn.)
Post: #9
RE: Logging calls removed from ohNet runtime
Sorry to hear about the problem with the patches and all the extra work you have been doing. To apply the patches automatically, you need to do the following:

patch -p0 oldfile patchfile -o newfile

I have tried this with the DebugLevel.java.diff file in bindings.zip and it applied the patch with no errors or problems.

If this doesn't work for you, please let me know and I will do my best to fix the problem.
Find all posts by this user


Forum Jump: