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

Assert in libuv #110

Closed
raoulh opened this issue Jan 30, 2018 · 17 comments
Closed

Assert in libuv #110

raoulh opened this issue Jan 30, 2018 · 17 comments
Assignees
Labels

Comments

@raoulh
Copy link
Contributor

raoulh commented Jan 30, 2018

Hi,

I have a strange bug, and don't know if it's in uvw, libuv or my own code. I will explain here and maybe someone has any hints.

I have an Idle handle that start a process at some point. It works and at some random point in time my my code crashes with an assert exactly when the process is launched:

[INF] lua (ScriptExec.cpp:39) Starting script. (0xd7b480)
[INF] process (ExternProc.cpp:191) Starting process: /usr/bin/calaos_script --socket /tmp/calaos_proc_c79ad522-33ff-978a-3d31-08070a51c459_lua_21499 --namespace lua
calaos_server: ../libuv-1.19.1/src/unix/stream.c:1574: uv_read_start: Assertion `uv__stream_fd(stream) >= 0' failed.

What my code does is basically easy:

  • it create a uvw::ProcessHandle
  • setup uvw::ExitEvent and uvw::ErrorEvent for the process handle
  • then create a uvw::PipeHandle for communicating with the process
  • setup uvw::EndEvent and uvw::DataEvent for the pipe
  • spawn the process
  • start pipe->read() (aka. uv_read_start())

Full code of the function is here:
https://github.com/calaos/calaos_base/blob/master/src/bin/calaos_server/IO/ExternProc.cpp#L147

It works. Sometime it works for a long time (hours). And then it crashes with this backtrace:

Program received signal SIGABRT, Aborted.
__GI_raise (sig=sig@entry=6) at /usr/src/debug/glibc/2.25-r0/git/sysdeps/unix/sysv/linux/raise.c:51
51      }
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at /usr/src/debug/glibc/2.25-r0/git/sysdeps/unix/sysv/linux/raise.c:51
#1  0x000000310e23450a in __GI_abort () at /usr/src/debug/glibc/2.25-r0/git/stdlib/abort.c:89
#2  0x000000310e22bfe7 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x7ffff7deaca6 "uv__stream_fd(stream) >= 0",
    file=file@entry=0x7ffff7dea998 "../libuv-1.19.1/src/unix/stream.c", line=line@entry=1574, function=function@entry=0x7ffff7deae48 <__PRETTY_FUNCTION__.9160> "uv_read_start")
    at /usr/src/debug/glibc/2.25-r0/git/assert/assert.c:92
#3  0x000000310e22c092 in __GI___assert_fail (assertion=assertion@entry=0x7ffff7deaca6 "uv__stream_fd(stream) >= 0",
    file=file@entry=0x7ffff7dea998 "../libuv-1.19.1/src/unix/stream.c", line=line@entry=1574, function=function@entry=0x7ffff7deae48 <__PRETTY_FUNCTION__.9160> "uv_read_start")
    at /usr/src/debug/glibc/2.25-r0/git/assert/assert.c:101
#4  0x00007ffff7de316d in uv_read_start (stream=stream@entry=0xd8b418,
    alloc_cb=alloc_cb@entry=0x48ffe0 <uvw::Handle<uvw::PipeHandle, uv_pipe_s>::allocCallback(uv_handle_s*, unsigned long, uv_buf_t*)>,
    read_cb=read_cb@entry=0x498320 <uvw::StreamHandle<uvw::PipeHandle, uv_pipe_s>::readCallback(uv_stream_s*, long, uv_buf_t const*)>)
    at /usr/src/debug/libuv/1.19.1-r0/libuv-1.19.1/src/unix/stream.c:1574
#5  0x0000000000497bf9 in uvw::Handle<uvw::PipeHandle, uv_pipe_s>::invoke<int (*)(uv_stream_s*, void (*)(uv_handle_s*, unsigned long, uv_buf_t*), void (*)(uv_stream_s*, long, uv_buf_t const*)), uv_stream_s*, void (*)(uv_handle_s*, unsigned long, uv_buf_t*), void (*)(uv_stream_s*, long, uv_buf_t const*)>(int (*&&)(uv_stream_s*, void (*)(uv_handle_s*, unsigned long, uv_buf_t*), void (*)(uv_stream_s*, long, uv_buf_t const*)), uv_stream_s*&&, void (*&&)(uv_handle_s*, unsigned long, uv_buf_t*), void (*&&)(uv_stream_s*, long, uv_buf_t const*)) (f=<optimized out>, this=0xd8b3b0) at /usr/src/debug/calaos-server/1_3.0-rc1+r0+gitAUTOINC+19f8b098fd-r0/git/src/lib/uvw/src/uvw/handle.hpp:62
#6  uvw::StreamHandle<uvw::PipeHandle, uv_pipe_s>::read (this=0xd8b3b0)
    at /usr/src/debug/calaos-server/1_3.0-rc1+r0+gitAUTOINC+19f8b098fd-r0/git/src/lib/uvw/src/uvw/stream.hpp:228
#7  ExternProcServer::startProcess (this=0xd7b480, process=..., name=..., args=...)
    at /usr/src/debug/calaos-server/1_3.0-rc1+r0+gitAUTOINC+19f8b098fd-r0/git/src/bin/calaos_server/IO/ExternProc.cpp:193
#8  0x000000000062b8f3 in ScriptExec::ExecuteScriptDetached(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::function<void (bool)>, Params) (script=..., cb=..., env=...) at /usr/src/debug/calaos-server/1_3.0-rc1+r0+gitAUTOINC+19f8b098fd-r0/git/src/bin/calaos_server/LuaScript/ScriptExec.cpp:150
#9  0x000000000063c021 in Calaos::ActionScript::Execute (this=<optimized out>)
    at /usr/src/debug/calaos-server/1_3.0-rc1+r0+gitAUTOINC+19f8b098fd-r0/git/src/bin/calaos_server/Rules/ActionScript.cpp:39
#10 0x00000000006358f1 in Calaos::Rule::ExecuteActions (this=0xc441f0)
    at /usr/src/debug/calaos-server/1_3.0-rc1+r0+gitAUTOINC+19f8b098fd-r0/git/src/bin/calaos_server/Rule.cpp:148
#11 0x0000000000626eae in Calaos::ListeRule::ExecuteRuleSignal (this=this@entry=0x977980 <Calaos::ListeRule::Instance()::inst>, id=...)
    at /usr/src/debug/calaos-server/1_3.0-rc1+r0+gitAUTOINC+19f8b098fd-r0/git/src/bin/calaos_server/ListeRule.cpp:182
#12 0x00000000006241ce in Calaos::ListeRule::<lambda()>::operator() (__closure=0xd8b660)
    at /usr/src/debug/calaos-server/1_3.0-rc1+r0+gitAUTOINC+19f8b098fd-r0/git/src/bin/calaos_server/ListeRule.cpp:101
#13 sigc::adaptor_functor<Calaos::ListeRule::ExecuteRuleSignal(std::__cxx11::string)::<lambda()> >::operator() (this=0xd8b660)
    at /usr/include/sigc++-2.0/sigc++/adaptors/adaptor_trait.h:256
#14 sigc::internal::slot_call0<Calaos::ListeRule::ExecuteRuleSignal(std::__cxx11::string)::<lambda()>, void>::call_it(sigc::internal::slot_rep *) (rep=0xd8b630)
    at /usr/include/sigc++-2.0/sigc++/functors/slot.h:114
#15 0x0000000000670602 in sigc::slot0<void>::operator() (this=0xd8b608) at /usr/include/sigc++-2.0/sigc++/functors/slot.h:513
#16 Idler::<lambda()>::operator() (__closure=0xd8b608) at /usr/src/debug/calaos-server/1_3.0-rc1+r0+gitAUTOINC+19f8b098fd-r0/git/src/lib/Timer.cpp:136
#17 sigc::adaptor_functor<Idler::singleIdler(sigc::slot<void>)::<lambda()> >::operator() (this=0xd8b600) at /usr/include/sigc++-2.0/sigc++/adaptors/adaptor_trait.h:256
#18 sigc::internal::slot_call<Idler::singleIdler(sigc::slot<void>)::<lambda()>, void>::call_it(sigc::internal::slot_rep *) (rep=0xd8b5d0)
    at /usr/include/sigc++-2.0/sigc++/functors/slot.h:461
#19 0x000000000066f84a in sigc::internal::signal_emit0<void, sigc::nil>::emit (impl=0xd6ef20) at /usr/include/sigc++-2.0/sigc++/signal.h:794
#20 sigc::signal0<void, sigc::nil>::emit (this=<optimized out>) at /usr/include/sigc++-2.0/sigc++/signal.h:2800
#21 Idler::<lambda(const auto:32&, auto:33&)>::operator()<uvw::IdleEvent, uvw::IdleHandle> (__closure=<optimized out>)
    at /usr/src/debug/calaos-server/1_3.0-rc1+r0+gitAUTOINC+19f8b098fd-r0/git/src/lib/Timer.cpp:125
#22 std::_Function_handler<void(uvw::IdleEvent&, uvw::IdleHandle&), Idler::createIdler()::<lambda(const auto:32&, auto:33&)> >::_M_invoke(const std::_Any_data &, uvw::IdleEvent &, uvw::IdleHandle &) (__functor=..., __args#0=..., __args#1=...) at /usr/include/c++/6.3.0/functional:1731
#23 0x000000000066f95e in std::function<void (uvw::IdleEvent&, uvw::IdleHandle&)>::operator()(uvw::IdleEvent&, uvw::IdleHandle&) const (__args#1=..., __args#0=...,
    this=<optimized out>) at /usr/include/c++/6.3.0/functional:2127
#24 _ZZN3uvw7EmitterINS_10IdleHandleEE7HandlerINS_9IdleEventEE7publishES4_RS1_ENKUlOT_E_clIRSt4pairIbSt8functionIFvRS4_S6_EEEEEDaS8_ (element=..., __closure=<synthetic pointer>)
    at /usr/src/debug/calaos-server/1_3.0-rc1+r0+gitAUTOINC+19f8b098fd-r0/git/src/lib/uvw/src/uvw/emitter.hpp:118
#25 _ZSt8for_eachISt16reverse_iteratorISt14_List_iteratorISt4pairIbSt8functionIFvRN3uvw9IdleEventERNS4_10IdleHandleEEEEEEZNS4_7EmitterIS7_E7HandlerIS5_E7publishES5_S8_EUlOT_E_ET0_SI_SI_SL_ (__first=..., __last=..., __f=...) at /usr/include/c++/6.3.0/bits/stl_algo.h:3769
#26 0x000000000066fedd in uvw::Emitter<uvw::IdleHandle>::Handler<uvw::IdleEvent>::publish (ref=..., event=..., this=<optimized out>)
    at /usr/src/debug/calaos-server/1_3.0-rc1+r0+gitAUTOINC+19f8b098fd-r0/git/src/lib/uvw/src/uvw/emitter.hpp:123
#27 uvw::Emitter<uvw::IdleHandle>::publish<uvw::IdleEvent> (this=0xd8b268, event=...)
    at /usr/src/debug/calaos-server/1_3.0-rc1+r0+gitAUTOINC+19f8b098fd-r0/git/src/lib/uvw/src/uvw/emitter.hpp:166
#28 uvw::IdleHandle::startCallback (handle=<optimized out>) at /usr/src/debug/calaos-server/1_3.0-rc1+r0+gitAUTOINC+19f8b098fd-r0/git/src/lib/uvw/src/uvw/idle.hpp:40
#29 0x00007ffff7dde3c4 in uv__run_idle (loop=loop@entry=0x7ffff7ff2cc0 <default_loop_struct>) at /usr/src/debug/libuv/1.19.1-r0/libuv-1.19.1/src/unix/loop-watcher.c:68
#30 0x00007ffff7dd8175 in uv_run (loop=0x7ffff7ff2cc0 <default_loop_struct>, mode=mode@entry=UV_RUN_DEFAULT) at /usr/src/debug/libuv/1.19.1-r0/libuv-1.19.1/src/unix/core.c:361
#31 0x0000000000413e99 in uvw::Loop::run<(uvw::details::UVRunMode)0> (this=<optimized out>)
    at /usr/src/debug/calaos-server/1_3.0-rc1+r0+gitAUTOINC+19f8b098fd-r0/git/src/lib/uvw/src/uvw/loop.hpp:284
#32 main (argc=<optimized out>, argv=<optimized out>) at /usr/src/debug/calaos-server/1_3.0-rc1+r0+gitAUTOINC+19f8b098fd-r0/git/src/bin/calaos_server/main.cpp:185

When inspecting the stream->io_watcher.fd it is -1. So the assert is correct that the uv_read cannot start- But why is this sometime -1... I really don't know...

(gdb) p *stream
$1 = {data = 0xd8b3b0, loop = 0x7ffff7ff2cc0 <default_loop_struct>, type = UV_NAMED_PIPE, close_cb = 0x0, handle_queue = {0xd88488, 0xd8bb78}, u = {fd = 0, reserved = {0x0,
      0x0, 0x0, 0x0}}, next_closing = 0x0, flags = 8196, write_queue_size = 0, alloc_cb = 0x0, read_cb = 0x0, connect_req = 0x0, shutdown_req = 0x0, io_watcher = {
    cb = 0x7ffff7de2170 <uv__stream_io>, pending_queue = {0xd8b4a8, 0xd8b4a8}, watcher_queue = {0xd8b4b8, 0xd8b4b8}, pevents = 0, events = 0, fd = -1}, write_queue = {0xd8b4d8,
    0xd8b4d8}, write_completed_queue = {0xd8b4e8, 0xd8b4e8}, connection_cb = 0x0, delayed_error = 0, accepted_fd = -1, queued_fds = 0x0}

My question here is: do I need to setup something or check something prior starting pipe->read() ? Is it a bug in libuv? uvw?

Thank you very much for any pointer.

@skypjack
Copy link
Owner

It looks like the handle for the pipe is gone for some reasons.
uvw forwards the request to the underlying library and nothing more in case of a read. Moreover, the read is part of the stream class, not of the pipe itself. Therefore it's exactly the same read member function you have on a tcp handles and so on.

By looking at the code of libuv, I see that it sets the descriptor to -1 when the handle is closed (here is the link to the function uv__stream_close). uv__stream_close is invoked by uv__pipe_close. uv__pipe_close is invoked by uv_close. Finally, uv_close is invoked in uvw by means of the close member function of a handle.
On the other side, uvw never invokes explicitly close on a handle. It's in charge to the user to invoke it explicitly to close a handle. The documentation is pretty clear on this point.

Could it happen that you close the handle for some reasons (as an example, in case of errors) and then you try to reuse it when you should create a new one from scratch instead?

@raoulh
Copy link
Contributor Author

raoulh commented Jan 30, 2018

Actually I'm doing this:

    pipe = uvw::Loop::getDefault()->resource<uvw::PipeHandle>();
    process_exe->stdio(static_cast<uvw::FileHandle>(0), uvw::ProcessHandle::StdIO::IGNORE_STREAM);

    uv_stdio_flags f = (uv_stdio_flags)(UV_CREATE_PIPE | UV_READABLE_PIPE);
    uvw::Flags<uvw::ProcessHandle::StdIO> ff(f);
    process_exe->stdio(*pipe, ff);

    //When pipe is closed, remove it and close it
    pipe->once<uvw::EndEvent>([](const uvw::EndEvent &, auto &cl) { cl.close(); });
    pipe->on<uvw::DataEvent>([this](uvw::DataEvent &ev, auto &)
    {
        [...]
    });

    Utils::CStrArray arr(cmd);
    process_exe->spawn(arr.at(0), arr.data());
    pipe->read();

The only place where I'm closing the handle is for the uvw::EndEvent. I'm creating a new uvw::PipeHandle everytime I need to start the process. Is it ok like that?

@skypjack
Copy link
Owner

skypjack commented Jan 30, 2018

You should stop or close a handle in case of errors during a read too.
uvw doesn't do it internally, but libuv is explicit about that:

The callee is responsible for stopping closing the stream when an error happens by calling uv_read_stop() or uv_close(). Trying to read from the stream again is undefined.

Unfortunately the pipe shares part of its API with the stream and the documentation isn't that easy to follow.

It could happen that you're getting an error on your handle for unknown reasons (try to analyze the error code for that) and you don't close it.
Documentation mentions an undefined behavior, so who knows if this is the case.

After all, you are experiencing the problem during a read on an invalid descriptor.
It fits pretty well with the definition of undefined behavior. :-)

@skypjack skypjack self-assigned this Jan 30, 2018
@skypjack
Copy link
Owner

Actually, from here I see that your are ignoring errors on the pipe handle.
Probably I'd start listening to the ErrorEvent to know if something goes wrong during a read and debug it.

@skypjack
Copy link
Owner

I'm marking the issue as invalid for it doesn't look like it's due to a bug in uvw.
Keep me updated so that I can change the labels or close the issue if you find the root of the problem.
Thank you.

@raoulh
Copy link
Contributor Author

raoulh commented Jan 31, 2018

Thanks for all your pointers.

I tried to listen to ErrorEvent for the pipe, it did not trigger before asserting.

@skypjack
Copy link
Owner

skypjack commented Jan 31, 2018

Interesting. Neither the ErrorEvent nor the EndEvent trigger before the assert?

@raoulh
Copy link
Contributor Author

raoulh commented Jan 31, 2018

No, neither ErrorEvent nor the EndEvent are triggered.

I did some more test and found out that

process_exe->spawn(arr.at(0), arr.data());

is failing due to too many open files error. The problem was that the ErrorEvent is triggered directly in a lambda.
I think this API in uvw is not so nice. In libuv uv_spawn the error is directly returned, but in uvw the error has to be catched in an ErrorEvent, which is a bit more painful to write.

I close this bug, as it's not relevant.
Thank you for your anwsers.

@raoulh raoulh closed this as completed Jan 31, 2018
@skypjack
Copy link
Owner

@raoulh Any suggestion to change the API and make it more usable is welcome.
You are using the library in a real world project, so your feedback are highly appreciated.
Feel free to drop in a replacement for the current API and we can discuss it together.

@raoulh
Copy link
Contributor Author

raoulh commented Jan 31, 2018

It would have been better to be able to do something like:

exe = uvw::Loop::getDefault()->resource<uvw::ProcessHandle>();
exe->once<uvw::ErrorEvent>([this](const uvw::ErrorEvent &ev, auto &)
{
    process_exe->close();
});

[...] //setup pipe

if (!exe->spawn())
{
   //early failure, ErrorEvent is not called
   std::cout << "fail to start process: " << exe->errorMsg() << std::endl;
   exe->close();
}
else
{
   pipe->read();
}

But I don't know if it's a good idea to differenciate between error types. It makes sense when like in this example the pipe->read() call must be done only if exe->spawn() returns ok.

@raoulh
Copy link
Contributor Author

raoulh commented Jan 31, 2018

I also found why I was leaking fds... I did not close() the handle somewhere in case of ErrorEvent... That was not clear until you explained it here.
Thanks

@skypjack
Copy link
Owner

You are welcome. You know, you're skilled and when you pop up with an issue it's usually an interesting problem from which I can learn something. ;-)

But I don't know if it's a good idea to differenciate between error types. It makes sense when like in this example the pipe->read() call must be done only if exe->spawn() returns ok.

I suggest to not remove the ErrorEvent on the spawn to avoid breaking the current API.
However we could just add a return type to the function and both trigger the event and return the correct value.
This way both the approaches are possible and one can choose for the best time by time.

What about?

@raoulh
Copy link
Contributor Author

raoulh commented Jan 31, 2018

Glad to help :) That's also why I posted here in the first place.

About the return value and the ErrorEvent, that would mean the close() has to be done in the ErrorEvent only and not also after an error is returned from spawn (like in my example), or close() would be called twice, right?

@skypjack
Copy link
Owner

uvw never calls close and it won't do it any time soon.
That's because it stays true to how libuv works and with libuv it's in charge to the user to close a handle.
Moreover, from within the spawn member function I cannot say neither if the caller is getting the return value or if it's interested in the event nor what it's going to do with this information.

As a side note, did you see the walk member function of the Loop?
Probably it could help if you want to perform a cleanup once each N ticks.

@raoulh
Copy link
Contributor Author

raoulh commented Jan 31, 2018

Yes I know that libuv/uvw does not do any close itself. I was talking about my usage example above.

The walk function is nice, but I cannot use for cleaning things in my project.

@skypjack
Copy link
Owner

Oho, I got it now. Sorry. Yeah, right, it's better not to call close twice actually.
Honestly, libuv documentation isn't explicit about the results, but I wouldn't risk if possible. ;-)

@raoulh
Copy link
Contributor Author

raoulh commented Jan 31, 2018

I just checked the libuv code, it would assert() :)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

2 participants