Project

General

Profile

Actions

Bug #7749

closed

Crash (SEGV) when using WFileUpload within WQApplication

Added by Chris Sykes over 3 years ago. Updated over 3 years ago.

Status:
Closed
Priority:
High
Assignee:
Roel Standaert
Target version:
Start date:
10/06/2020
Due date:
% Done:

0%

Estimated time:

Description

Description

We've been seeing crashes when uploading larger files with WFileUpload
from within a WQApplication (as per the wtwithqt example).

We first saw these on Wt 3.3.8, and they still occur on Wt 3.7.0.

It looks to me like the issue is a data-race / thread synchronisation problem.
More details are provided below, and I've attached a minimal project that
reproduces the crash for me.

Issue #6548 contains stack-traces of the crash when I first noticed this on Wt 3.3.8.

Environment

  • Fedora 31 x86_64
  • Wt 3.7.0
  • Qt 5.13.2

Steps to reproduce the crash

  1. Unpack the attached example project.
  2. Build the code

    $ mkdir build && cd build
    $ cmake ..
    $ make -j 4

  3. Start the example server

    $ cd .. # out of build dir, back into source.
    $ ./run build/upload-recreate

  4. In the browser window, click "Browse" and select a
    large file (e.g. > 100 MiB). I see the crash on
    most uploads.

App console output:

[2020-Oct-06 16:30:36.646810] 1633202 - [debug] "WQApplication: [thread] handling event"
[2020-Oct-06 16:30:36.646820] 1633202 - [debug] "WQApplication: [thread] done handling event"
[2020-Oct-06 16:30:36.646824] 1633202 - [debug] "WQApplication: [thread] signaling event done"
[2020-Oct-06 16:30:36.646832] 1633202 [/ oRm722jntsoq5tnZ] [debug] "WQApplication: notifying thread"
[2020-Oct-06 16:30:36.646845] 1633202 - [debug] "WQApplication: [thread] handling event"
[2020-Oct-06 16:30:36.646854] 1633202 - [debug] "WQApplication: [thread] done handling event"
[2020-Oct-06 16:30:36.646858] 1633202 - [debug] "WQApplication: [thread] signaling event done"
[2020-Oct-06 16:30:36.654864] 1633202 [/ oRm722jntsoq5tnZ] [debug] "WQApplication: notifying thread"
[2020-Oct-06 16:30:36.654941] 1633202 - [debug] "WQApplication: [thread] handling event"
./run: line 14: 1633202 Segmentation fault      (core dumped) "$APP" --docroot="$PWD;/resources" --http-address "$ADDR" --http-port "$PORT"

gdb stack trace:

(gdb) info threads
  Id   Target Id                                             Frame 
  1    Thread 0x7ffff3f7fc80 (LWP 1633820) "upload-recreate" 0x00007ffff6728412 in sigtimedwait() from /lib64/libc.so.6
  2    Thread 0x7fffe6f86700 (LWP 1633821) "upload-recreate" 0x00007ffff7a1fd45 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  3    Thread 0x7fffe6785700 (LWP 1633822) "upload-recreate" 0x00007ffff7a23610 in __lll_lock_wait () from /lib64/libpthread.so.0
  4    Thread 0x7fffe5f84700 (LWP 1633823) "upload-recreate" 0x00007ffff7a1fd45 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  5    Thread 0x7fffe5783700 (LWP 1633824) "upload-recreate" 0x00007ffff67ec9fe in epoll_wait() from /lib64/libc.so.6
* 6    Thread 0x7fffe4f82700 (LWP 1633835) "QThread"         std::_Rb_tree<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, Wt::WResource*>, std::_Select1st<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, Wt::WResource*> >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, Wt::WResource*> > >::_M_lower_bound (this=<optimized out>, 
    __k=<error reading variable: Cannot access memory at address 0x7fffe45bf018>, 
    __y=0x7fffe000c3a8, __x=0x7fffd4005f90) at /usr/include/c++/9/bits/stl_tree.h:1945



(gdb) bt
#0  std::_Rb_tree<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, Wt::WResource*>, std::_Select1st<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, Wt::WResource*> >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, Wt::WResource*> > >::_M_lower_bound (this=<optimized out>,
    __k=<error reading variable: Cannot access memory at address 0x7fffe45bf018>,
    __y=0x7fffe000c3a8, __x=0x7fffd4005f90) at /usr/include/c++/9/bits/stl_tree.h:1945
#1  std::_Rb_tree<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, Wt::WResource*>, std::_Select1st<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, Wt::WResource*> >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, Wt::WResource*> > >::find (__k=<error reading variable: Cannot access memory at address 0x7fffe45bf018>,
    this=0x7fffe000c3a0) at /usr/include/c++/9/bits/stl_tree.h:2570
#2  std::map<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, Wt::WResource*, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, Wt::WResource*> > >::find (
    __x=<error reading variable: Cannot access memory at address 0x7fffe45bf018>,
    this=0x7fffe000c3a0) at /usr/include/c++/9/bits/stl_map.h:1194
#3  Wt::WApplication::decodeExposedResource (this=this@entry=0x7fffe000be30,
    resourceKey=<error reading variable: Cannot access memory at address 0x7fffe45bf018>)
    at ../src/Wt/WApplication.C:886
#4  0x00007ffff7516a0c in Wt::WebController::updateResourceProgress (this=<optimized out>,
    request=0x7fffe00070a0, current=90946977, total=342288591)  
    at ../src/web/WebController.C:474
#5  0x00007ffff7528dfc in boost::function0<void>::operator() (this=<optimized out>)
    at /usr/include/boost/function/function_template.hpp:677
#6  Wt::WebSession::notify (this=0x7fffe00044a0, event=...) at ../src/web/WebSession.C:2240
#7  0x0000000000489e23 in Wt::WQApplication::realNotify(Wt::WEvent const&) ()
#8  0x000000000048661f in Wt::DispatchThread::doEvent() ()
#9  0x0000000000485f20 in Wt::DispatchObject::onEvent() ()
#10 0x000000000046c945 in Wt::DispatchObject::qt_static_metacall(QObject*, QMetaObject::Call, int, void**) ()
#11 0x00007ffff7d007fa in QObject::event(QEvent*) () from /lib64/libQt5Core.so.5
#12 0x00007ffff7cd53b5 in doNotify(QObject*, QEvent*) () from /lib64/libQt5Core.so.5
#13 0x00007ffff7cd5448 in QCoreApplication::notifyInternal2(QObject*, QEvent*) ()

Files

upload-recreate.tar.gz (8.07 KB) upload-recreate.tar.gz Minimal project for reproduction Chris Sykes, 10/06/2020 05:57 PM
CMakeCache.txt (35 KB) CMakeCache.txt Chris Sykes, 10/29/2020 01:33 PM
upload-recreate.memcheck.qt.log (466 KB) upload-recreate.memcheck.qt.log Chris Sykes, 11/16/2020 05:36 PM
upload-recreate.memcheck.log (2.88 KB) upload-recreate.memcheck.log Chris Sykes, 11/16/2020 05:36 PM
upload-recreate.memcheck.log.gz (15.8 KB) upload-recreate.memcheck.log.gz Chris Sykes, 12/01/2020 05:56 PM
Actions #1

Updated by Chris Sykes over 3 years ago

I believe this is a data race/synchronisation issue because it does not reproduce every time (perhaps 75% of the time using a 135 MiB file).

Also, I'm unable to reproduce the crash if I change the thread pool size from 4 to 1 in main.cpp:

   99         server->ioService().setThreadCount(1);

The other visible difference after making that change is that the upload progress % shown in the web app now updates during the upload.

With the thread pool count set at 4, the upload progress stays at 0% throughout the upload, then jumps to "upload complete".

Actions #2

Updated by Chris Sykes over 3 years ago

I've not (yet) been able to reproduce the crash when using a WApplication rather than a WQAppliction,
so the issue is either caused by or significantly worsened by the WtQt integration.

When using WQApplication, the crash reproduces with the DispatchThread running the Qt event loop AND
also when running DispatchThread::myExec().

Actions #3

Updated by Roel Standaert over 3 years ago

  • Status changed from New to Resolved

I pushed a commit that should normally resolve this issue.

Actions #4

Updated by Roel Standaert over 3 years ago

  • Target version set to 4.5.0
Actions #5

Updated by Chris Sykes over 3 years ago

I've tested the proposed patch, but unfortunately it doesn't resolve the issue(s) for me.

I see the same behaviour whether running 3.7.0 + 20e2eed4 cherry-picked, or
the head of the wt3 branch (which contains a few other changes on top of 3.7.0).

Observed behaviour with the patch:

The file uploads no longer work at all.

The POST request is rejected with a 413 (payload too large?) error:

127.0.0.1 - - [2020-Oct-28 18:51:28.732008] "POST /?wtd=nn7lS8UN89FAVetW&request=resource&resource=ouzmv18&rand=1 HTTP/1.1" 413 115

I get the same error even with really tiny files (just a few bytes). I'm guessing that
the header parsing in WebController::requestDataReceived was serving a purpose
after all.

With just the wtwithqt portion of the patch

I undid the web/WebController.C hunk of the patch, leaving the wtwithqt changes intact and re-tested.

Now the file uploads work again (no 413 errors), but I can reproduce the segfault when the server thread pool size is > 1.

Actions #6

Updated by Chris Sykes over 3 years ago

My theory in #6548 was that the segfault dereferencing *resourceE (std::string)
was caused by the referenced string being invalidated when the containing
vector<std::string> in the ParameterMap was realloc'd (and moved).

The ParameterMap was full of duplicate parameter values, with a new dup added for
every block transferred in the upload.

I reverted the change to web/WebController.C, and instead patched Wt/Http/Request.C
such that Request::parseFormUrlEncoded avoids appending duplicate parameter values:

commit ae68e7e3bc68ac94250f79d64bb3da28eb0473b4
Author: Chris Sykes <chris.sykes@m-flow-tech.com>
Date:   Wed Oct 28 20:13:29 2020 +0000

    Request::parseFormUrlEncoded: only append changed values.

    Avoid appending parameter values if they're unchanged.

diff --git a/src/Wt/Http/Request.C b/src/Wt/Http/Request.C
index b11d5880..1fe6c518 100644
--- a/src/Wt/Http/Request.C
+++ b/src/Wt/Http/Request.C
@@ -383,6 +383,15 @@ Request::~Request()
 #endif
 }

+static void addIfChanged(std::vector<std::string> &values,
+                         const std::string &value)
+{
+    if (values.empty() || values.back() != value) {
+        values.push_back(value);
+    }
+}
+
+
 #ifndef WT_TARGET_JAVA
 void Request::parseFormUrlEncoded(const std::string& s,
                  ParameterMap& parameters)
@@ -395,7 +404,7 @@ void Request::parseFormUrlEncoded(const std::string& s,
    next = s.length();
       std::string key = s.substr(pos, next - pos);
       Utils::inplaceUrlDecode(key);
-      parameters[key].push_back(std::string());
+      addIfChanged(parameters[key], std::string());
       pos = next + 1;
     } else {
       std::size_t amp = s.find('&', next + 1);
@@ -408,7 +417,7 @@ void Request::parseFormUrlEncoded(const std::string& s,
       std::string value = s.substr(next + 1, amp - (next + 1));
       Utils::inplaceUrlDecode(value);

-      parameters[key].push_back(value);
+      addIfChanged(parameters[key], value);
       pos = amp + 1;
     }
   }

With this applied, my upload-recreate ran cleanly for 20 consecutive uploads of a 342 MiB file.
Usually it'd crash during almost every upload.

However, I'm not happy that this is actually fixing the underlying issue.

There must still be some unsafe/unsynchronised access to that ParameterMap (and values therein)
for WebController::updateResourceProgress to be working with a pointer that gets invalidated
by WebController::requestDataReceived() when it calls Request::parseFormUrlEncoded().

Actions #7

Updated by Roel Standaert over 3 years ago

You're seeing these issues with the example you posted? I can't reproduce it myself anymore. I take it you're still using Fedora to test this? Is that version 31 still or are you now on 32 or 33? What browser are you seeing this issue with? How are you building Wt?

Actions #8

Updated by Roel Standaert over 3 years ago

Ok I can reproduce this now.

Actions #9

Updated by Chris Sykes over 3 years ago

Yes, I see the crash with the example project I posted (it helps to use a really big file!),
and am still running Fedora 31 for the moment.

It reproduces for me with Wt built in Debug and RelWithDebugInfo modes.

I've attached my cmake cache for a debug build in case it helps.

My primary browser is Firefox, currently v82.0 (as packaged by Fedora).

Actions #10

Updated by Roel Standaert over 3 years ago

My latest commits should address this.

Updated by Chris Sykes over 3 years ago

Thanks Roel.

I retested with Wt 3.7.0 + your latest commits (which all apply cleanly to wt3):

  • 0001-Addressing-issue-7749-and-6548.patch
  • 0002-Readded-parsing-in-requestDataReceived-because-we-do.patch
  • 0003-parseFormUrlEncoded-skip-empty-parameters.patch
  • 0004-Issue-7749-ensure-that-request-parameters-are-parsed.patch

With them, I can no longer reproduce the crash during file-upload.

However, as I mentioned in #note-6, I don't think this fixes the actual race
condition, it just makes it much harder to hit.

I ran the patched upload-recreate and Wt under valgrind (just memcheck,
not helgrind or drd) and it complains about use-after-frees with very
similar stack traces to those seen in the original crash report:

==1338919== Thread 6 QThread:
==1338919== Invalid read of size 8
==1338919==    at 0x6832C82: std::_Rb_tree<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > >, std::_Select1st<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > > >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > > > >::_M_begin() const (in /usr/local/lib/libwt.so.3.7.0)
==1338919==    by 0x6832799: std::_Rb_tree<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > >, std::_Select1st<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > > >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > > > >::find(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) const (in /usr/local/lib/libwt.so.3.7.0)
==1338919==    by 0x6831CA6: std::map<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > > > >::find(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) const (in /usr/local/lib/libwt.so.3.7.0)
==1338919==    by 0x6E0BC70: Wt::WebRequest::getParameterValues(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) const (in /usr/local/lib/libwt.so.3.7.0)
==1338919==    by 0x6E0BC18: Wt::WebRequest::getParameter(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) const (in /usr/local/lib/libwt.so.3.7.0)
==1338919==    by 0x6E00C77: Wt::WebController::updateResourceProgress(Wt::WebRequest*, unsigned long, unsigned long) (in /usr/local/lib/libwt.so.3.7.0)
==1338919==    by 0x6E09598: boost::_mfi::mf3<void, Wt::WebController, Wt::WebRequest*, unsigned long, unsigned long>::operator()(Wt::WebController*, Wt::WebRequest*, unsigned long, unsigned long) const (in /usr/local/lib/libwt.so.3.7.0)

   ...

==1338919==  Address 0xaa6d170 is 48 bytes inside a block of size 248 free'd
==1338919==    at 0x483B0D6: operator delete(void*, unsigned long) (vg_replace_malloc.c:593)
==1338919==    by 0x7B35C00: http::server::HTTPRequest::~HTTPRequest() (in /usr/local/lib/libwthttp.so.3.7.0)
==1338919==    by 0x7BCFB9C: http::server::WtReply::consumeRequestBody(char const*, char const*, http::server::Request::State) (in /usr/local/lib/libwthttp.so.3.7.0)
==1338919==    by 0x7BCF6BD: http::server::WtReply::consumeData(char const*, char const*, http::server::Request::State) (in /usr/local/lib/libwthttp.so.3.7.0)
==1338919==    by 0x7B64485: http::server::RequestParser::parseBody(http::server::Request&, boost::shared_ptr<http::server::Reply>, char*&, char*) (in /usr/local/lib/libwthttp.so.3.7.0)
==1338919==    by 0x7B1B207: http::server::Connection::handleReadBody(boost::shared_ptr<http::server::Reply>) (in /usr/local/lib/libwthttp.so.3.7.0)
==1338919==    by 0x7B1BA94: http::server::Connection::handleReadBody(boost::shared_ptr<http::server::Reply>, boost::system::error_code const&, unsigned long) (in /usr/local/lib/libwthttp.so.
3.7.0)
==1338919==    by 0x7BC9C34: void boost::_mfi::mf3<void, http::server::Connection, boost::shared_ptr<http::server::Reply>, boost::system::error_code const&, unsigned long>::call<boost::shared
_ptr<http::server::TcpConnection>, boost::shared_ptr<http::server::Reply>, boost::system::error_code const, unsigned long>(boost::shared_ptr<http::server::TcpConnection>&, void const*, boost:
:shared_ptr<http::server::Reply>&, boost::system::error_code const&, unsigned long&) const (in /usr/local/lib/libwthttp.so.3.7.0)
==1338919==    by 0x7BC984F: void boost::_mfi::mf3<void, http::server::Connection, boost::shared_ptr<http::server::Reply>, boost::system::error_code const&, unsigned long>::operator()<boost::
shared_ptr<http::server::TcpConnection> >(boost::shared_ptr<http::server::TcpConnection>&, boost::shared_ptr<http::server::Reply>, boost::system::error_code const&, unsigned long) const (in /
usr/local/lib/libwthttp.so.3.7.0)
==1338919==    by 0x7BC93FD: void boost::_bi::list4<boost::_bi::value<boost::shared_ptr<http::server::TcpConnection> >, boost::_bi::value<boost::shared_ptr<http::server::Reply> >, boost::arg<
1> (*)(), boost::arg<2> (*)()>::operator()<boost::_mfi::mf3<void, http::server::Connection, boost::shared_ptr<http::server::Reply>, boost::system::error_code const&, unsigned long>, boost::_b
i::rrlist2<boost::system::error_code const&, unsigned long const&> >(boost::_bi::type<void>, boost::_mfi::mf3<void, http::server::Connection, boost::shared_ptr<http::server::Reply>, boost::sy
stem::error_code const&, unsigned long>&, boost::_bi::rrlist2<boost::system::error_code const&, unsigned long const&>&, int) (in /usr/local/lib/libwthttp.so.3.7.0)
==1338919==    by 0x7BC90E1: void boost::_bi::bind_t<void, boost::_mfi::mf3<void, http::server::Connection, boost::shared_ptr<http::server::Reply>, boost::system::error_code const&, unsigned 
long>, boost::_bi::list4<boost::_bi::value<boost::shared_ptr<http::server::TcpConnection> >, boost::_bi::value<boost::shared_ptr<http::server::Reply> >, boost::arg<1> (*)(), boost::arg<2> (*)
()> >::operator()<boost::system::error_code const&, unsigned long const&>(boost::system::error_code const&, unsigned long const&) (in /usr/local/lib/libwthttp.so.3.7.0)
==1338919==    by 0x7BC8DCA: boost::asio::detail::binder2<boost::_bi::bind_t<void, boost::_mfi::mf3<void, http::server::Connection, boost::shared_ptr<http::server::Reply>, boost::system::erro
r_code const&, unsigned long>, boost::_bi::list4<boost::_bi::value<boost::shared_ptr<http::server::TcpConnection> >, boost::_bi::value<boost::shared_ptr<http::server::Reply> >, boost::arg<1> 
(*)(), boost::arg<2> (*)()> >, boost::system::error_code, unsigned long>::operator()() (in /usr/local/lib/libwthttp.so.3.7.0)
==1338919==  Block was alloc'd at
==1338919==    at 0x4839E86: operator new(unsigned long) (vg_replace_malloc.c:342)
==1338919==    by 0x7BCFA4E: http::server::WtReply::consumeRequestBody(char const*, char const*, http::server::Request::State) (in /usr/local/lib/libwthttp.so.3.7.0)
==1338919==    by 0x7BCF6BD: http::server::WtReply::consumeData(char const*, char const*, http::server::Request::State) (in /usr/local/lib/libwthttp.so.3.7.0)
==1338919==    by 0x7B64485: http::server::RequestParser::parseBody(http::server::Request&, boost::shared_ptr<http::server::Reply>, char*&, char*) (in /usr/local/lib/libwthttp.so.3.7.0)
==1338919==    by 0x7B1B207: http::server::Connection::handleReadBody(boost::shared_ptr<http::server::Reply>) (in /usr/local/lib/libwthttp.so.3.7.0)
==1338919==    by 0x7B1A9EB: http::server::Connection::handleReadRequest0() (in /usr/local/lib/libwthttp.so.3.7.0)
==1338919==    by 0x7B1B002: http::server::Connection::handleReadRequest(boost::system::error_code const&, unsigned long) (in /usr/local/lib/libwthttp.so.3.7.0)

If I edit change the upload-recreate project to use WApplication directly rather than WQApplication,
and repeat the valgrind run, I see no such errors reported.

Full valgrind log files are attached.

Actions #12

Updated by Roel Standaert over 3 years ago

I see, there's a use-after free of the request itself it seems?

So this may be really 3 issues in one, and 2 of them have been fixed.

Actions #13

Updated by Chris Sykes over 3 years ago

I see, there's a use-after free of the request itself it seems?

Yes, it could well be,

Unfortunately I don't understand how Wt manages the lifetime of a request object.

Is each request (effectively) moved to a thread in the asio pool, then processed and then freed by that thread?

Actions #14

Updated by Roel Standaert over 3 years ago

  • Status changed from Resolved to Feedback

You did add the fix for the spurious wakeups to your DispatchThread, right? Just want to make sure of that.

Unlike in Qt nothing is really tied to a thread in Wt, but a request is normally only handled by one thread at a time, and it is deleted whenever that request is considered "done".

Could you do a Debug build? I think that'll make it so we have line numbers in the memcheck output. There are two situations in which the delete of a request happens in the consumeRequestBody function. One is when requestDataReceived returns false (in which case a 413 status code is returned to the client), the other is when we're in an error state, in which case some other 4XX or 5XX status code is returned.

I'm thinking possibly a delayed updateResourceProgress for requestDataReceived call N-1 that executes right after requestDataReceived call N deletes the request due to an error?

Actions #15

Updated by Chris Sykes over 3 years ago

You did add the fix for the spurious wakeups to your DispatchThread, right? Just want to make sure of that.

Yes, I copied over the wtwithqt updates into my recreate project.

I'll double check this for you though.

Could you do a Debug build?

Absolutely, but will probably not have results before tomorrow as I'm a bit tied up by something else ATM.

Actions #16

Updated by Roel Standaert over 3 years ago

  • Target version changed from 4.5.0 to 4.6.0
Actions #17

Updated by Chris Sykes over 3 years ago

Sorry for the delay in responding.

I've reproduced the errors using a RelWithDebInfo build.

Here's an extract (with the boost::asio part of the trace removed for brevity), I'll attach the full log in case it's useful:

==4105013== Invalid read of size 8
==4105013==    at 0x5832E2E: find (stl_tree.h:2570)
==4105013==    by 0x5832E2E: find (stl_map.h:1194)
==4105013==    by 0x5832E2E: Wt::WebRequest::getParameterValues(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) const (WebRequest.C:184)
==4105013==    by 0x5832F28: Wt::WebRequest::getParameter(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) const (WebRequest.C:176)
==4105013==    by 0x582DA4E: Wt::WebController::updateResourceProgress(Wt::WebRequest*, unsigned long, unsigned long) (WebController.C:473)
==4105013==    by 0x583FE5B: operator() (function_template.hpp:763)
==4105013==    by 0x583FE5B: Wt::WebSession::notify(Wt::WEvent const&) (WebSession.C:2240)
==4105013==    by 0x489E26: Wt::WQApplication::realNotify(Wt::WEvent const&) (in /home/chris.sykes/Projects/meter/upload-recreate/build/upload-recreate)
==4105013==    by 0x486622: Wt::DispatchThread::doEvent() (in /home/chris.sykes/Projects/meter/upload-recreate/build/upload-recreate)
==4105013==    by 0x485F1F: Wt::DispatchObject::onEvent() (in /home/chris.sykes/Projects/meter/upload-recreate/build/upload-recreate)
==4105013==    by 0x46C944: Wt::DispatchObject::qt_static_metacall(QObject*, QMetaObject::Call, int, void**) (in /home/chris.sykes/Projects/meter/upload-recreate/build/upload-recreate)
==4105013==    by 0x4B137F9: QObject::event(QEvent*) (in /usr/lib64/libQt5Core.so.5.13.2)
==4105013==    by 0x4AE83B4: ??? (in /usr/lib64/libQt5Core.so.5.13.2)
==4105013==    by 0x4AE8447: QCoreApplication::notifyInternal2(QObject*, QEvent*) (in /usr/lib64/libQt5Core.so.5.13.2)
==4105013==    by 0x4AEB48A: QCoreApplicationPrivate::sendPostedEvents(QObject*, int, QThreadData*) (in /usr/lib64/libQt5Core.so.5.13.2)
==4105013==  Address 0x89a9af0 is 48 bytes inside a block of size 248 free'd
==4105013==    at 0x483B0D6: operator delete(void*, unsigned long) (vg_replace_malloc.c:593)
==4105013==    by 0x5BC6D19: http::server::WtReply::~WtReply() (WtReply.C:64)
==4105013==    by 0x5BC7028: http::server::WtReply::~WtReply() (WtReply.C:78)
==4105013==    by 0x46E1C2: boost::detail::sp_counted_base::release() (in /home/chris.sykes/Projects/meter/upload-recreate/build/upload-recreate)
==4105013==    by 0x5B5AB4A: ~shared_count (shared_count.hpp:426)
==4105013==    by 0x5B5AB4A: ~shared_ptr (shared_ptr.hpp:341)
==4105013==    by 0x5B5AB4A: reset (shared_ptr.hpp:693)
==4105013==    by 0x5B5AB4A: http::server::Connection::stop() (Connection.C:114)
==4105013==    by 0x5BC0535: http::server::TcpConnection::stop() (TcpConnection.C:55)
==4105013==    by 0x5B6430A: call<boost::shared_ptr<http::server::Connection> > (mem_fn_template.hpp:40)
==4105013==    by 0x5B6430A: operator()<boost::shared_ptr<http::server::Connection> > (mem_fn_template.hpp:55)
==4105013==    by 0x5B6430A: operator()<boost::_mfi::mf0<void, http::server::Connection>, boost::_bi::list0> (bind.hpp:259)
==4105013==    by 0x5B6430A: operator() (bind.hpp:1294)

  ...

==4105013==  Block was alloc'd at
==4105013==    at 0x4839E86: operator new(unsigned long) (vg_replace_malloc.c:342)
==4105013==    by 0x5BC80F4: http::server::WtReply::consumeRequestBody(char const*, char const*, http::server::Request::State) (WtReply.C:185)
==4105013==    by 0x5BC8618: http::server::WtReply::consumeData(char const*, char const*, http::server::Request::State) (WtReply.C:145)
==4105013==    by 0x5B882F7: http::server::RequestParser::parseBody(http::server::Request&, boost::shared_ptr<http::server::Reply>, char*&, char*) (RequestParser.C:218)
==4105013==    by 0x5B5C851: http::server::Connection::handleReadBody(boost::shared_ptr<http::server::Reply>) (Connection.C:308)
==4105013==    by 0x5B5CB4C: http::server::Connection::handleReadRequest0() (Connection.C:231)
==4105013==    by 0x5BC4231: call<boost::shared_ptr<http::server::TcpConnection>, const boost::system::error_code, long unsigned int> (mem_fn_template.hpp:271)
==4105013==    by 0x5BC4231: operator()<boost::shared_ptr<http::server::TcpConnection> > (mem_fn_template.hpp:286)
==4105013==    by 0x5BC4231: operator()<boost::_mfi::mf2<void, http::server::Connection, const boost::system::error_code&, long unsigned int>, boost::_bi::rrlist2<const boost::system::error_code&, long unsigned int const&> > (bind.hpp:398)
==4105013==    by 0x5BC4231: operator()<const boost::system::error_code&, long unsigned int const&> (bind.hpp:1318)
==4105013==    by 0x5BC4231: operator() (bind_handler.hpp:164)

I don't see the errors on every file upload, so attempted several before terminating the process.

Memcheck command line:

valgrind \
    --track-fds=yes \
    --track-origins=yes \
    --tool=memcheck \
    --leak-check=full \
    --leak-resolution=high \
    --log-file=upload-recreate.memcheck.log \
    ./build/upload-recreate --docroot="$PWD;/resources" --http-address 127.0.0.1 --http-port 8080

Just to reiterate, I'm unable to reproduce these errors using a variant
of my test app that inherits WApplication rather than WQApplication.

Actions #18

Updated by Roel Standaert over 3 years ago

  • Tracker changed from Support to Bug
  • Status changed from Feedback to Implemented @Emweb
  • Assignee set to Roel Standaert
  • Target version changed from 4.6.0 to 4.5.0

A fix is currently under review and should be on its way for release in Wt 4.5.0.

Actions #19

Updated by Roel Standaert over 3 years ago

It will be backported to Wt 3 as well. This will likely be the last release of Wt 3.

Actions #20

Updated by Roel Standaert over 3 years ago

  • Status changed from Implemented @Emweb to Resolved

I pushed what should hopefully be the final fix for this issue.

Actions #21

Updated by Roel Standaert over 3 years ago

  • Status changed from Resolved to Closed
Actions

Also available in: Atom PDF