Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Crash with curl 7.67.0 #681

Closed
falconindy opened this issue Nov 7, 2019 · 7 comments
Labels

Comments

@falconindy
Copy link

@falconindy falconindy commented Nov 7, 2019

Bug report

Describe the bug

mpd crashes when stopping a stream. Steps to reproduce:

mpc add https://listen.moe/stream; mpc play; sleep 1; mpc stop

Expected Behavior

mpd stops playing without crashing.

Actual Behavior

Despite this being only reproducible with curl 7.67.0, I don't see any evidence in stack traces that it's actually curl's fault. I think the new shared object has merely pushed some things around in memory enough to trigger a use-after-free in mpd code.

Version

 [mad] mp3 mp2
 [mpg123] mp3
 [vorbis] ogg oga
 [oggflac] ogg oga
 [flac] flac
 [opus] opus ogg oga
 [sndfile] wav aiff aif au snd paf iff svx sf voc w64 pvf xi htk caf sd2
 [audiofile] wav au aiff aif
 [dsdiff] dff
 [dsf] dsf
 [hybrid_dsd] m4a
 [faad] aac
 [mpcdec] mpc
 [wavpack] wv
 [modplug] 669 amf ams dbm dfm dsm far it med mdl mod mtm mt2 okt s3m stm ult umx xm
 [mikmod] amf dsm far gdm imf it med mod mtm s3m stm stx ult uni xm
 [wildmidi] mid
 [fluidsynth] mid
 [ffmpeg] 16sv 3g2 3gp 4xm 8svx aa3 aac ac3 adx afc aif aifc aiff al alaw amr anim apc ape asf atrac au aud avi avm2 avs bap bfi c93 cak cin cmv cpk daud dct divx dts dv dvd dxa eac3 film flac flc fli fll flx flv
 g726 gsm gxf iss m1v m2v m2t m2ts m4a m4b m4v mad mj2 mjpeg mjpg mka mkv mlp mm mmf mov mp+ mp1 mp2 mp3 mp4 mpc mpeg mpg mpga mpp mpu mve mvi mxf nc nsv nut nuv oga ogm ogv ogx oma ogg omg opus psp pva qcp qt r3
d ra ram rl2 rm rmvb roq rpl rvc shn smk snd sol son spx str swf tak tgi tgq tgv thp ts tsp tta xa xvid uv uv2 vb vid vob voc vp6 vmd wav webm wma wmv wsaud wsvga wv wve
 [gme] ay gbs gym hes kss nsf nsfe sap spc vgm vgz
 [pcm]

Filters:
 libsamplerate soxr

Tag plugins:
 id3tag

Output plugins:
 shout null fifo pipe alsa ao oss openal solaris pulse jack httpd recorder

Encoder plugins:
 null vorbis opus lame twolame wave flac

Archive plugins:
 [bz2] bz2
 [zzip] zip
 [iso] iso

Input plugins:
 file archive alsa tidal qobuz curl ffmpeg smbclient nfs mms cdio_paranoia

Playlist plugins:
 extm3u m3u pls xspf asx rss soundcloud flac cue embcue

Protocols:
 file:// alsa:// tidal:// qobuz:// http:// https:// gopher:// rtp:// rtsp:// rtmp:// rtmpt:// rtmps:// smb:// nfs:// mms:// mmsh:// mmst:// mmsu:// cdda://

Other features:
 avahi dbus udisks epoll icu inotify ipv6 systemd tcp un

Log

[Switching to thread 3 (Thread 0x7fffe60f0700 (LWP 300588))]
#0  CurlRequest::FinishBody (this=0x7fffd0000b60) at ../src/lib/curl/Request.cxx:159                                                                                                                                
159             handler.OnEnd();                                                                                                                                                                                    
(gdb) bt                                                                                                                                                                                                            
#0  CurlRequest::FinishBody (this=0x7fffd0000b60) at ../src/lib/curl/Request.cxx:159                      
#1  CurlRequest::FinishBody (this=0x7fffd0000b60) at ../src/lib/curl/Request.cxx:151                      
#2  CurlRequest::Done (result=CURLE_OK, this=0x7fffd0000b60) at ../src/lib/curl/Request.cxx:176
#3  CurlGlobal::ReadInfo (this=<optimized out>) at ../src/lib/curl/Global.cxx:217                         
#4  CurlGlobal::ReadInfo (this=0x555555733e30) at ../src/lib/curl/Global.cxx:205                                                                                                                                    
#5  BindMethodDetail::BindMethodWrapperGenerator2<CurlGlobal, void (CurlGlobal::*)(), &CurlGlobal::ReadInfo, void>::Invoke (_instance=0x555555733e30) at ../src/util/BindMethod.hxx:147                             
#6  0x000055555562307c in BoundMethod<void ()>::operator()() const (this=<optimized out>, this=<optimized out>, this=<optimized out>) at ../src/util/BindMethod.hxx:76                                              
#7  DeferEvent::RunDeferred (this=0x555555733e38) at ../src/event/DeferEvent.hxx:66
#8  EventLoop::HandleDeferred (this=this@entry=0x555555701bf0) at ../src/event/Loop.cxx:269
#9  0x0000555555623113 in EventLoop::OnSocketReady (this=0x555555701bf0, flags=<optimized out>) at ../src/event/Loop.cxx:281
#10 0x000055555562580f in SocketMonitor::Dispatch (flags=<optimized out>, this=<optimized out>) at ../src/event/SocketMonitor.cxx:37                                                                                
#11 EventLoop::Run (this=0x555555701bf0) at ../src/event/Loop.cxx:214                                                                                                                                               
#12 0x0000555555642936 in EventThread::Run (this=0x555555701bf0) at ../src/event/Thread.cxx:65            
#13 BindMethodDetail::BindMethodWrapperGenerator2<EventThread, void (EventThread::*)(), &EventThread::Run, void>::Invoke (_instance=0x555555701bf0) at ../src/util/BindMethod.hxx:147
#14 0x0000555555622784 in BoundMethod<void ()>::operator()() const (this=<optimized out>, this=<optimized out>, this=<optimized out>) at ../src/util/BindMethod.hxx:76
#15 Thread::Run (this=0x555555701d58) at ../src/thread/Thread.cxx:63         
#16 Thread::ThreadProc (ctx=0x555555701d58) at ../src/thread/Thread.cxx:92
#17 0x00007ffff46df4cf in start_thread () from /usr/lib/libpthread.so.0                                   
#18 0x00007ffff7ee22d3 in clone () from /usr/lib/libc.so.6                                                

At this point handler (from frame 0) points to a garbage address, e.g. 0x1000400070007.

And if I compile with ASAN, it points to a heap use-after-free in MPD code at the same object:

==308378==ERROR: AddressSanitizer: heap-use-after-free on address 0x62300000fd68 at pc 0x55555582cad2 bp 0x7fffe22cfea0 sp 0x7fffe22cfe90
READ of size 4 at 0x62300000fd68 thread T2 (io)
    #0 0x55555582cad1 in CurlGlobal::ReadInfo() ../src/lib/curl/Global.cxx:214                                                                                                                                      
    #1 0x55555582cad1 in BindMethodDetail::BindMethodWrapperGenerator2<CurlGlobal, void (CurlGlobal::*)(), &CurlGlobal::ReadInfo, void>::Invoke(void*) ../src/util/BindMethod.hxx:147
    #2 0x5555558455d1 in BoundMethod<void ()>::operator()() const ../src/util/BindMethod.hxx:77
    #3 0x5555558455d1 in DeferEvent::RunDeferred() ../src/event/DeferEvent.hxx:66                      
    #4 0x5555558455d1 in EventLoop::HandleDeferred() ../src/event/Loop.cxx:269
    #5 0x5555558458e9 in EventLoop::OnSocketReady(unsigned int) ../src/event/Loop.cxx:281
    #6 0x555555854473 in SocketMonitor::Dispatch(unsigned int) ../src/event/SocketMonitor.cxx:37
    #7 0x555555854473 in EventLoop::Run() ../src/event/Loop.cxx:214
    #8 0x5555558d303e in EventThread::Run() ../src/event/Thread.cxx:65
    #9 0x5555558d303e in BindMethodDetail::BindMethodWrapperGenerator2<EventThread, void (EventThread::*)(), &EventThread::Run, void>::Invoke(void*) ../src/util/BindMethod.hxx:147
    #10 0x5555558436ff in BoundMethod<void ()>::operator()() const ../src/util/BindMethod.hxx:77
    #11 0x5555558436ff in Thread::Run() ../src/thread/Thread.cxx:63
    #12 0x5555558436ff in Thread::ThreadProc(void*) ../src/thread/Thread.cxx:92
    #13 0x7ffff213a4ce in start_thread (/usr/lib/../lib/libpthread.so.0+0x94ce)
    #14 0x7ffff74ad2d2 in clone (/usr/lib/libc.so.6+0xff2d2
@ml-

This comment has been minimized.

Copy link

@ml- ml- commented Nov 7, 2019

Additional detail: It crashes when stopping a https stream. This does not happen with http streams.

@falconindy

This comment has been minimized.

Copy link
Author

@falconindy falconindy commented Nov 8, 2019

I guess I've misappropriated the ASAN complaint. It's not complaining about reading crap from the same object, but if I try to print the address of the CURLMsg* that it points to (Global.cxx:214), then I get an address such as 0x62300000fd68 (seems legit given the stack frame addresses?), and then ASAN fails elsewhere, such as:

READ of size 4 at 0x62300000fd68 thread T2 (io)                                                           
    #0 0x55555582da94 in CurlRequest::FinishBody() ../src/lib/curl/Request.cxx:155
    #1 0x55555582da94 in CurlRequest::Done(CURLcode) ../src/lib/curl/Request.cxx:176
    #2 0x55555582da94 in CurlGlobal::ReadInfo() ../src/lib/curl/Global.cxx:218                                                                                                                                      
    #3 0x55555582da94 in BindMethodDetail::BindMethodWrapperGenerator2<CurlGlobal, void (CurlGlobal::*)(), &CurlGlobal::ReadInfo, void>::Invoke(void*) ../src/util/BindMethod.hxx:147
    #4 0x5555558465a1 in BoundMethod<void ()>::operator()() const ../src/util/BindMethod.hxx:77
    #5 0x5555558465a1 in DeferEvent::RunDeferred() ../src/event/DeferEvent.hxx:66                                                                                                                                   
    #6 0x5555558465a1 in EventLoop::HandleDeferred() ../src/event/Loop.cxx:269
    #7 0x5555558468b9 in EventLoop::OnSocketReady(unsigned int) ../src/event/Loop.cxx:281
    #8 0x555555855443 in SocketMonitor::Dispatch(unsigned int) ../src/event/SocketMonitor.cxx:37
    #9 0x555555855443 in EventLoop::Run() ../src/event/Loop.cxx:214
    #10 0x5555558d400e in EventThread::Run() ../src/event/Thread.cxx:65
    #11 0x5555558d400e in BindMethodDetail::BindMethodWrapperGenerator2<EventThread, void (EventThread::*)(), &EventThread::Run, void>::Invoke(void*) ../src/util/BindMethod.hxx:147
    #12 0x5555558446cf in BoundMethod<void ()>::operator()() const ../src/util/BindMethod.hxx:77
    #13 0x5555558446cf in Thread::Run() ../src/thread/Thread.cxx:63
    #14 0x5555558446cf in Thread::ThreadProc(void*) ../src/thread/Thread.cxx:92
    #15 0x7ffff213a4ce in start_thread (/usr/lib/../lib/libpthread.so.0+0x94ce)
    #16 0x7ffff74ad2d2 in clone (/usr/lib/libc.so.6+0xff2d2)  

So, I'm still unconvinced this is a curl problem.

@eworm-de

This comment has been minimized.

Copy link
Contributor

@eworm-de eworm-de commented Nov 8, 2019

Caused by this curl commit: curl/curl@59041f0

@MaxKellermann

This comment has been minimized.

Copy link
Member

@MaxKellermann MaxKellermann commented Nov 8, 2019

Valgrind:

 Invalid read of size 8
    at 0x50A5271: curl_multi_info_read (in /usr/local/stow/curl1.67/lib/libcurl.so.4.6.0)
    by 0x1BDC86: CurlGlobal::ReadInfo() (Global.cxx:212)
    by 0x1BE013: BindMethodDetail::BindMethodWrapperGenerator2<CurlGlobal, void (CurlGlobal::*)(), &CurlGlobal::ReadInfo, void>::Invoke(void*) (BindMethod.hxx:147)
    by 0x19EB0D: BoundMethod<void ()>::operator()() const (BindMethod.hxx:77)
    by 0x1A47B5: DeferEvent::RunDeferred() (DeferEvent.hxx:66)
    by 0x1A43A7: EventLoop::HandleDeferred() (Loop.cxx:269)
    by 0x1A442D: EventLoop::OnSocketReady(unsigned int) (Loop.cxx:281)
    by 0x19EF3F: SocketMonitor::Dispatch(unsigned int) (SocketMonitor.cxx:37)
    by 0x1A40C6: EventLoop::Run() (Loop.cxx:214)
    by 0x1A36E6: EventThread::Run() (Thread.cxx:65)
    by 0x15BC5D: BindMethodDetail::BindMethodWrapperGenerator2<EventThread, void (EventThread::*)(), &EventThread::Run, void>::Invoke(void*) (BindMethod.hxx:147)
    by 0x19EB0D: BoundMethod<void ()>::operator()() const (BindMethod.hxx:77)
  Address 0x144bee70 is 80 bytes inside a block of size 5,984 free'd
    at 0x48389AB: free (vg_replace_malloc.c:530)
    by 0x50944CE: Curl_close (in /usr/local/stow/curl1.67/lib/libcurl.so.4.6.0)
    by 0x50A01C5: curl_easy_cleanup (in /usr/local/stow/curl1.67/lib/libcurl.so.4.6.0)
    by 0x1BF07C: CurlEasy::~CurlEasy() (Easy.hxx:70)
    by 0x1BE548: CurlRequest::FreeEasy() (Request.cxx:117)
    by 0x1BE2B1: CurlRequest::~CurlRequest() (Request.cxx:72)
    by 0x1C6BF7: CurlInputStream::FreeEasy() (CurlInputPlugin.cxx:174)
    by 0x1C6C38: CurlInputStream::FreeEasyIndirect()::{lambda()#1}::operator()() const (CurlInputPlugin.cxx:182)
    by 0x1C82B7: std::_Function_handler<void (), CurlInputStream::FreeEasyIndirect()::{lambda()#1}>::_M_invoke(std::_Any_data const&) (std_function.h:297)
    by 0x2AC5BF: std::function<void ()>::operator()() const (std_function.h:687)
    by 0x2AC490: BlockingCallMonitor::RunDeferred() (Call.cxx:68)
    by 0x2AC5E2: BindMethodDetail::BindMethodWrapperGenerator2<BlockingCallMonitor, void (BlockingCallMonitor::*)(), &BlockingCallMonitor::RunDeferred, void>::Invoke(void*) (BindMethod.hxx:147)

From a first glance, this looks like a CURL bug, but I'll investigate.

@MaxKellermann

This comment has been minimized.

Copy link
Member

@MaxKellermann MaxKellermann commented Nov 8, 2019

curl/curl@59041f0 introduces a new bug.
What happens here is that MPD closes an ongoing HTTP request. To do this, it first calls curl_multi_remove_handle() to unregister the request and then calls curl_easy_cleanup() to free the request.
However, during curl_multi_remove_handle(), before the multi pointer gets cleared, CURL's on_stream_close() gets invoked by libnghttp2:

#0  0x00007ffff77313ff in on_stream_close (session=0x7fffd40e1430, stream_id=1, error_code=5, userp=0x7fffd400a690) at http2.c:827
#1  0x00007fffef988710 in  () at /usr/lib/x86_64-linux-gnu/libnghttp2.so.14
#2  0x00007fffef98a99e in  () at /usr/lib/x86_64-linux-gnu/libnghttp2.so.14
#3  0x00007fffef98ba75 in  () at /usr/lib/x86_64-linux-gnu/libnghttp2.so.14
#4  0x00007fffef98cac9 in nghttp2_session_send () at /usr/lib/x86_64-linux-gnu/libnghttp2.so.14
#5  0x00007ffff7732020 in Curl_http2_done (conn=0x7fffd400a690, premature=true) at http2.c:1202
#6  0x00007ffff76e19bd in Curl_http_done (conn=0x7fffd400a690, status=CURLE_OK, premature=true) at http.c:1620
#7  0x00007ffff770c399 in multi_done (data=0x7fffd4004b00, status=CURLE_OK, premature=true) at multi.c:556
#8  0x00007ffff770c80b in curl_multi_remove_handle (multi=0x5555558f3a70, data=0x7fffd4004b00) at multi.c:714
#9  0x00005555556097f1 in CurlGlobal::Remove(void*) (this=0x5555558f3420, easy=0x7fffd4004b00) at ../../src/lib/curl/Global.cxx:183
#10 0x000055555560a443 in CurlRequest::Stop() (this=0x7fffd4004970) at ../../src/lib/curl/Request.cxx:98
#11 0x000055555560a515 in CurlRequest::FreeEasy() (this=0x7fffd4004970) at ../../src/lib/curl/Request.cxx:116
#12 0x000055555560a2b2 in CurlRequest::~CurlRequest() (this=0x7fffd4004970, __in_chrg=<optimized out>) at ../../src/lib/curl/Request.cxx:72

So now on_stream_close() calls Curl_expire() which registers timers, to be unregistered by Curl_expire_clear(). However, at this point, curl_multi_remove_handle() is still on the stack, and has already called Curl_expire_clear(), and will not do it again:
https://github.com/curl/curl/blob/2e9b725f67d49a9d7a1f053fe52dd4920c9ab1ad/lib/multi.c#L698-L714
The following curl_easy_cleanup() call will then free an object which remains linked inside the CURLM object.

Not a MPD bug.

@falconindy

This comment has been minimized.

Copy link
Author

@falconindy falconindy commented Nov 8, 2019

Thanks for digging further. Will follow up with curl folks.

@MaxKellermann

This comment has been minimized.

Copy link
Member

@MaxKellermann MaxKellermann commented Nov 11, 2019

CURL bug was fixed: curl/curl#4583

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
4 participants
You can’t perform that action at this time.