Error Thunder: free(): invalid pointer

[laurence-ejraee]

Hi, just looking for any guidance on an error we encounter very rarely.

Does anyone know anything about this error log:
Thunder[3221]: *** Error in '/applications/wpebrowser/usr/bin/Thunder': free(): invalid pointer: 0x0000007f740dc618 ***

The error occurs after we activate and deactivate the Thunder plugins we are using many times e.g. > 10000 times.
In this case it seems to have happened around the time DisplayInfo plugin is being deactivated. And the error leads to a segmentation fault in Thunder causing the framework to crash entirely:
Thunder[3221]: Thunder shutting down due to a segmentation fault. All relevant data dumped

Any help or information at all is very much appreciated as this is a very difficult issue to debug.
Thanks.

[pwielders]

Is this happening in R4 or in R5? We patched R4.4.2 forsveral edge cases where, during closing down, a dangling reference cuased segmentation fault crashed. 4.4.3 and onwards should have resolved these crashes..

[laurence-ejraee]

Still seen in R5.
We also hit another error message for same case which might provide more help:
*** Error in '/applications/wpebrowser/usr/bin/WPEFramework': corrupted double-linked list: 0x00000000015652f0 ***

I believe the issue might be related to plugins running as outofprocess true / Mode: local, but this is just our current theory.

[laurence-ejraee]

We have enabled debug build for wpeframework and we see this trace in crash case:

===== $$ [1292]: ASSERT [./com/IUnknown.h:291] (reader.Length() >= (sizeof(RPC::instance_id)))
[IPCConnector.h:595](Element)<1292><1>: Unexpected response message for ID [2].

[Link.h:141](Element)<1292><1>: Could not get an element.
 0
0         0x7fa5d398b8 GetCallStack + 72
1         0x7fa5d39aa0 DumpCallStack + 72
2         0x7fa5ed0bf0 WPEFramework::ProxyStub::UnknownProxy::Complete(WPEFramework::Core::FrameType<(unsigned short)512>::Reader&) const + 144
3         0x7fa2bb6180 WPEFramework::ProxyStub::UnknownProxyType<WPEFramework::Exchange::IContentDecryption>::Complete(WPEFramework::Core::FrameType<(unsigned short)512>::Reader&) const + 32
4         0x7fa2bb5b7c WPEFramework::ProxyStubs::ExchangeContentDecryptionProxy::Deinitialize(WPEFramework::PluginHost::IShell*) + 168
5         0x7f98208478 WPEFramework::Plugin::OCDM::Deinitialize(WPEFramework::PluginHost::IShell*) + 168
6             0x4ca6b0 /applications/wpebrowser/usr/bin/WPEFramework() [0x4ca6b0]
7         0x7f98ed0220 WPEFramework::Plugin::XappClient::StopPlugins() + 2124
8         0x7f98ed1640 WPEFramework::Plugin::XappClient::SetBrowserState(WPEFramework::Exchange::IXappClient::XappClientBrowserState) + 196
9         0x7fa2c2324c /applications/wpebrowser/usr/lib/wpeframework/proxystubs/libWPEFrameworkMarshallings.so(+0x1e024c) [0x7fa2c2324c]
10        0x7fa2c232b8 /applications/wpebrowser/usr/lib/wpeframework/proxystubs/libWPEFrameworkMarshallings.so(+0x1e02b8) [0x7fa2c232b8]
11        0x7fa2c25e18 WPEFramework::ProxyStub::UnknownStubType<WPEFramework::Exchange::IXappClient, &WPEFramework::ProxyStubs::ExchangeXappClientStubMethods>::Handle(unsigned short, WPEFramework::Core::ProxyType<WPEFramework::Core::IPCChannel>&, WPEFramework::Core::ProxyType<WPEFramework::Core::IPCMessageType<2u, WPEFramework::RPC::Data::Input, WPEFramework::RPC::Data::Output> >&) + 160
12        0x7fa5ede0a0 WPEFramework::RPC::Administrator::Invoke(WPEFramework::Core::ProxyType<WPEFramework::Core::IPCChannel>&, WPEFramework::Core::ProxyType<WPEFramework::Core::IPCMessageType<2u, WPEFramework::RPC::Data::Input, WPEFramework::RPC::Data::Output> >&) + 172
13            0x4d0124 WPEFramework::RPC::Job::Invoke(WPEFramework::Core::ProxyType<WPEFramework::Core::IPCChannel>&, WPEFramework::Core::ProxyType<WPEFramework::Core::IIPC>&) + 168
14            0x4cff40 /applications/wpebrowser/usr/bin/WPEFramework() [0x4cff40]
15            0x4cea04 /applications/wpebrowser/usr/bin/WPEFramework() [0x4cea04]
16            0x4cf8a4 /applications/wpebrowser/usr/bin/WPEFramework() [0x4cf8a4]
17            0x4b5dec /applications/wpebrowser/usr/bin/WPEFramework() [0x4b5dec]
18        0x7fa594c224 __libc_start_main + 220
[IPCConnector.h:619](Flush)<43168><1>: Flushing the IPC mechanims. 619
[Communicator.cpp:483](StateChange)<43168><1>: Connection to the server is down
[IUnknown.h:283](Invoke)<1288><1>: IPC method invokation failed for 0xD7, error: 11

Seems to crash during deactivation of OCDM plugin, but is there anything else interesting from this log?
Thanks again

[laurence-ejraee]

Hi,
We have used gdb to look at the stack after a crash is seen and we get this:

(gdb) 
#0  0x0000007fb
799a260 in pthread_cond_wait () from <...>/romfs/lib64/libpthread.so.0
#1  0x0000007fb7c9f8ec in WPEFramework::Core::Event::Lock() () from <...>/romfs/applications/wpebrowser/usr/lib/libWPEFrameworkCore.so.1
#2  0x0000007fb7c9f994 in WPEFramework::Core::Event::Lock(unsigned int) () from <...>/romfs/applications/wpebrowser/usr/lib/libWPEFrameworkCore.so.1
#3  0x0000007fb7fb869c in WPEFramework::Core::IPCChannelType<WPEFramework::Core::SocketPort, WPEFramework::Core::Void>::IPCTrigger::Wait(unsigned int) ()
   from <...>/romfs/applications/wpebrowser/usr/lib/libMetroClientInterface.so.1
#4  0x0000007fb7fb753c in WPEFramework::Core::IPCChannelType<WPEFramework::Core::SocketPort, WPEFramework::Core::Void>::Execute(WPEFramework::Core::ProxyType<WPEFramework::Core::IIPC>&, unsigned int) ()
   from <...>/romfs/applications/wpebrowser/usr/lib/libMetroClientInterface.so.1
#5  0x0000007fb7dd5f00 in unsigned int WPEFramework::Core::IPCChannel::Invoke<WPEFramework::Core::IPCMessageType<2u, WPEFramework::RPC::Data::Input, WPEFramework::RPC::Data::Output> >(WPEFramework::Core::ProxyType<WPEFramework::Core::IPCMessageType<2u, WPEFramework::RPC::Data::Input, WPEFramework::RPC::Data::Output> >&, unsigned int) () from <...>/romfs/applications/wpebrowser/usr/lib/libWPEFrameworkCOM.so.1
#6  0x0000007fb7dd4ed8 in WPEFramework::ProxyStub::UnknownProxy::Invoke(WPEFramework::Core::ProxyType<WPEFramework::Core::IPCMessageType<2u, WPEFramework::RPC::Data::Input, WPEFramework::RPC::Data::Output> >&, unsigned int) const ()
   from <...>/romfs/applications/wpebrowser/usr/lib/libWPEFrameworkCOM.so.1
#7  0x0000007fb7dd4cf4 in WPEFramework::ProxyStub::UnknownProxy::Release() const ()
   from <...>/romfs/applications/wpebrowser/usr/lib/libWPEFrameworkCOM.so.1
#8  0x0000007fb68f7fb0 in WPEFramework::ProxyStub::UnknownProxyType<WPEFramework::Exchange::IXappClient>::Release() const ()
   from <...>/romfs/applications/wpebrowser/usr/lib/wpeframework/proxystubs/libWPEFrameworkMarshallings.so
#9  0x0000007fb7faf2b8 in metro_client_set_browser_state () from <...>/romfs/applications/wpebrowser/usr/lib/libMetroClientInterface.so.1
#10 0x0000000000400bdc in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

The WPEFramework::Core::Event::Lock() is pointing to code: https://github.com/rdkcentral/Thunder/blob/master/Source/core/Sync.cpp#L867
nResult = (pthread_cond_wait(&m_syncCondition, &m_syncAdminLock) == 0 ? Core::ERROR_NONE : Core::ERROR_GENERAL);

When searching online it seems crashes can be seen in rare cases when using pthread_cond_wait in certain cases. And the crash we are experiencing similarly happens rarely.
Could there be a bug here in wpeframework with the usage of pthread_cond_wait ?

Any help is appreciated!
Thanks again.

[pwielders]

I think the first crash report is very helpfull. The mentioning of:
===== $$ [1292]: ASSERT [./com/IUnknown.h:291] (reader.Length() >= (sizeof(RPC::instance_id)))
IPCConnector.h:595<1292><1>: Unexpected response message for ID [2].
Tells us that the channel (COMRPC connection to the OCDM process) is closed "prior" to sending all data hence why the response of the invoke is a partial package. I can imagine that this is a very time related issue and thus occures very rarly. In it self a good catch. I guess the ASSERT is a bit of a happy-day scenario ASSERT.

During our QA cycles we focused more on the non-happu day scenarios. What if the connection breaks before the whole package is send, I guess your case, we need to be resiliant in those cases as well hence why these asserts have now been turned into if's. See master.

So I guess, as you are probably working on R2, and I strongly encourage you to upgrade to R5 ;-) you need to backport some of those fixes. In R5 the ASSERT you have in your BT, does not exist anymore, because the Invoke now checks, before continuing, if the package received is complete and if not, it does not even process it because the link is broken, A COMRPC error is returned (one of the reasons why we introduced Core::hresult ;-) )

So I think we might be facing a different issue in R5, than in R2. In R2, the callstacks given above with the assert, make sure that the package is checked (w.r.t. size) before continue processing and do not ASSERT if it is a partial package.

If you can make Callstacks with this issue for R5, Happy to guide you further to a solution..

[laurence-ejraee]

Thanks for your response, your help with this is very valuable!

I have tested on R5 and generated crash logs using wpeframework debug build type.

bool CDMi::WideVine::Widevine15Decryptor_Provision(): handleProvisioningResponse Passed! ===== $$ [39474]: ASSERT [FrameworkRPC.cpp:1370] (subSystem->IsActive(PluginHost::ISubSystem::DECRYPTION) == false)
[..../usr/lib/libThunderCore.so.5]:[DumpCallStack]:[68]
[..../usr/lib/thunder/plugins/libThunderOCDM.so]:[Thunder::Plugin::OCDMImplementation::InitializeAsync()]:[3800]
[..../usr/lib/thunder/plugins/libThunderOCDM.so]:[Thunder::Plugin::OCDMImplementation::AsyncInitThread::Dispatch()]:[32]
[..../usr/lib/thunder/plugins/libThunderOCDM.so]:[Thunder::Core::ThreadPool::JobType<Thunder::Plugin::OCDMImplementation::AsyncInitThread&>::Worker::Dispatch()]:[60]
[ThunderPlugin]:[Thunder::Core::ThreadPool::Minion::Process()]:[280]
[ThunderPlugin]:[]:[-1]
[ThunderPlugin]:[]:[-1]
[ThunderPlugin]:[]:[-1]
[/lib64/libc.so.6]:[__libc_start_main]:[220]
pure virtual method called
terminate called without an active exception
===== $$ [2858]: ASSERT [../../../host/aarch64-buildroot-linux-gnu/sysroot/usr/include/Thunder/core/Frame.h:914] ((offset + Frame::RealSize<TYPENAME>()) <= _size)
[..../usr/lib/libThunderCore.so.5]:[DumpCallStack]:[68]
[..../usr/lib/thunder/proxystubs/libThunderMarshalling.so]:[Thunder::Exchange::IXappClient::XappClientReturn Thunder::Core::FrameType<512u, true, unsigned int>::Reader::Number<Thunder::Exchange::IXappClient::XappClientReturn>() const]:[272]
[..../usr/lib/thunder/proxystubs/libThunderMarshalling.so]:
<....>
[/lib64/libc.so.6]:[__libc_start_main]:[220]
Aborted
# 
# 

Any insight? Thanks again!