Thread Rating:
  • 0 Votes - 0 Average
  • 1
  • 2
  • 3
  • 4
  • 5
Crash in DviSessionUpnp::~DviSessionUpnp()
07-10-2012, 10:07 PM
Post: #1
Crash in DviSessionUpnp::~DviSessionUpnp()
A user has reported an ohNet crash shortly after rebooting his NAS. The NAS reboot starts MinimServer automatically, and MinimServer creates an ohNet device stack. Shortly after this, there's a crash in ohNet with the following stack trace:

Stack: [0xe0ab5000,0xe0b35000], sp=0xe0b34068, free space=508k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
C [libc.so.6+0x661a1] malloc_usable_size+0x3f1
C [libc.so.6+0x67b75] malloc_set_state+0xe65
C [libc.so.6+0x67de9] cfree+0x89
C [libstdc++.so.6+0xb7d81] operator delete(void*)+0x21
C [libohNet.so+0x5c70e] OpenHome::Srs<65536u>::~Srs()+0x3e
C [libohNet.so+0x5b8dc] OpenHome::Net::DviSessionUpnp::~DviSessionUpnp()+0x12c
C [libohNet.so+0xa216a] OpenHome::SocketTcpServer::~SocketTcpServer()+0x9a
C [libohNet.so+0x53a58] OpenHome::Net::DviServer::Server::~Server()+0x28
C [libohNet.so+0x541d6] OpenHome::Net::DviServer::SubnetListChanged()+0x1a6
C [libohNet.so+0x543fd] OpenHome::MemberTranslator<OpenHome::Net::DviServer, void (OpenHome::Net::DviServer::*)()>::Thunk(OpenHome::Functor const&)+0x1d
C [libohNet.so+0x9a711] OpenHome::NetworkAdapterList::DoRunCallbacks(std::map<unsigned int, OpenHome::Functor, std::less<unsigned int>, std::allocator<std::pair<unsigned int const, OpenHome::Functor> > >&)+0x41
C [libohNet.so+0x9a784] OpenHome::NetworkAdapterList::RunCallbacks(std::map<unsigned int, OpenHome::Functor, std::less<unsigned int>, std::allocator<std::pair<unsigned int const, OpenHome::Functor> > >&)+0x34
C [libohNet.so+0x9a898] OpenHome::NetworkAdapterList::NotifySubnetsChanged()+0x18
C [libohNet.so+0x99b31] OpenHome::NetworkAdapterChangeNotifier::UpdateSubnet::Update(OpenHome::INetworkA​dapterChangeNotifier&)+0x11
C [libohNet.so+0x9b20c] OpenHome::NetworkAdapterChangeNotifier::Run()+0x6c
C [libohNet.so+0xb5e05] OpenHome::Thread::EntryPoint(void*)+0x25
C [libohNet.so+0xc2ad3] threadEntrypoint+0x53
C [libpthread.so.0+0x4fba] __pthread_initialize_minimal+0xbba

The failure (highlighted in red) seems to be in the

delete iReadBuffer;

call on line 512 of DviServerUpnp.cpp. This was triggered higher up the stack by the

delete server;

call on line 98 of DviServer.cpp (highlighted in blue).

The NAS on which the failure occurred has a dual Ethernet socket that was configured in failover mode, which means the ports are bonded together by the NAS with a single externally visible MAC address. Both ports were connected to the same switch.

The crash doesn't occur on every reboot, but it happens reasonably often. I asked the user to see if he could reproduce it with only a single Ethernet port connected. This produced a different error:

ERROR: Recursive lock attempted on mutex DSUM from thread NACN
Assertion failed. OpenHome/Thread.cpp:89

with no accompanying stack trace. I'm creating a separate thread to discuss why this assertion failure doesn't produce a stack trace on a Linux NAS.
Find all posts by this user
08-10-2012, 01:41 PM (This post was last modified: 08-10-2012 01:44 PM by simonc.)
Post: #2
RE: Crash in DviSessionUpnp::~DviSessionUpnp()
I can't see why ~DviSessionUpnp is failing. Would your user be willing to try out some builds with some logging?

As background, I think ohNet is being started up when the NAS has no network adapters available. OsNetworkListAdapters (in Os/Posix/Os.c) will then return the loopback adapter, even if you haven't explicitly asked for it. Later, one or more of the 'real' adapters become available. The normal subnet change code runs and ohNet updates its list of adapters. This time, OsNetworkListAdapters doesn't include loopback so client code has a scenario when one (or more) adapters have been added and one (loopback) has been removed. Its the removal of loopback you're seeing the crash inside.

I don't think the problem is double deletion of DviSessionUpnp. In my tests, Linux builds fail on this immediately so the deletion of iWriterBuffer should fail. This leaves two other possibilities - the address of iReadBuffer is changing or the contents around the address.

To help narrow the cause down, could you add logging which prints out the address of iReadBuffer after it is allocated in the DviSessionUpnp c'tor and before it is deleted in the d'tor? Something like
Log::Print("iReadBuffer allocated at %p\n", iReadBuffer);
should do it.
Find all posts by this user
08-10-2012, 04:02 PM
Post: #3
RE: Crash in DviSessionUpnp::~DviSessionUpnp()
(08-10-2012 01:41 PM)simonc Wrote:  I can't see why ~DviSessionUpnp is failing. Would your user be willing to try out some builds with some logging?

As background, I think ohNet is being started up when the NAS has no network adapters available. OsNetworkListAdapters (in Os/Posix/Os.c) will then return the loopback adapter, even if you haven't explicitly asked for it. Later, one or more of the 'real' adapters become available. The normal subnet change code runs and ohNet updates its list of adapters. This time, OsNetworkListAdapters doesn't include loopback so client code has a scenario when one (or more) adapters have been added and one (loopback) has been removed. Its the removal of loopback you're seeing the crash inside.

I don't think the problem is double deletion of DviSessionUpnp. In my tests, Linux builds fail on this immediately so the deletion of iWriterBuffer should fail. This leaves two other possibilities - the address of iReadBuffer is changing or the contents around the address.

To help narrow the cause down, could you add logging which prints out the address of iReadBuffer after it is allocated in the DviSessionUpnp c'tor and before it is deleted in the d'tor? Something like
Log::Print("iReadBuffer allocated at %p\n", iReadBuffer);
should do it.

Yes, I could do this. Another option is for me to try to replicate these conditions on my NAS by starting it with the Ethernet port disconnected and then connecting the port after the ohNet device stack has been created. I'll probably try this first.

Would it also be useful to log the addition and removal of adapters? It's possible that the user scenario is more complex than you've described. The failure was reported on a NAS with a bonded failover dual connection, so the startup sequence might be somewhat unusual. For example, multiple non-loopback adapters might be added, or an adapter might be added and then removed. Where is the best place to put print statements to log adapter additions and removals?
Find all posts by this user
08-10-2012, 04:15 PM
Post: #4
RE: Crash in DviSessionUpnp::~DviSessionUpnp()
(08-10-2012 04:02 PM)simoncn Wrote:  Yes, I could do this. Another option is for me to try to replicate these conditions on my NAS by starting it with the Ethernet port disconnected and then connecting the port after the ohNet device stack has been created. I'll probably try this first.

Yes, that would be useful if you could replicate the problem. I tried doing something similar on Windows (start a device stack running on all adapters with all adapters disabled, enable an adapter, watch loopback get removed and the enabled adapter added) but couldn't replicate the crash. Maybe you'll have more luck on Linux though...

(08-10-2012 04:02 PM)simoncn Wrote:  Would it also be useful to log the addition and removal of adapters? It's possible that the user scenario is more complex than you've described. The failure was reported on a NAS with a bonded failover dual connection, so the startup sequence might be somewhat unusual. For example, multiple non-loopback adapters might be added, or an adapter might be added and then removed. Where is the best place to put print statements to log adapter additions and removals?

Extra logging would be useful. If you add Debug::SetLevel(Debug::kTrace); to UpnpLibrary::Initialise you'll get a note of subnet changes. (This logging will either go to stdout or the callback you registered with InitParams.SetLogOutput)
Find all posts by this user


Forum Jump: