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

instabilities #55

Closed
folkertvanheusden opened this issue Jul 31, 2021 · 21 comments
Closed

instabilities #55

folkertvanheusden opened this issue Jul 31, 2021 · 21 comments

Comments

@folkertvanheusden
Copy link
Contributor

folkertvanheusden commented Jul 31, 2021

I notice that quite often connections "go away". I'm trying to figure this out.
For this, I collect the odd things I notice (errors, etc.).

Jul 31 17:56:30 lappiemctopface rtpmidid[135084]: #033[0;34m[2021-07-31T15:56:25Z] [rtpmidid.cpp:275]#033[0m Found client to delete: alsa port 3. Deletes all known addreses.
Jul 31 17:56:30 lappiemctopface rtpmidid[135084]: #033[0;34m[2021-07-31T15:56:25Z] [rtpmidid.cpp:574]#033[0m Removing peer from known peers list. Port 3
Jul 31 17:57:53 lappiemctopface rtpmidid[135084]: #033[0;34m[2021-07-31T15:57:48Z] [rtpclient.cpp:156]#033[0m MIDI PORT at port 39352
Jul 31 17:57:53 lappiemctopface rtpmidid[135084]: #033[0;34m[2021-07-31T15:57:48Z] [rtpclient.cpp:182]#033[0m Connecting control port 39352 to ESP-76E44C.dhcp.nurd.space:123
Jul 31 20:24:43 lappiemctopface rtpmidid[162733]: #033[0;34m[2021-07-31T18:24:27Z] [rtpclient.cpp:156]#033[0m MIDI PORT at port 38608
Jul 31 20:24:43 lappiemctopface rtpmidid[162733]: #033[0;34m[2021-07-31T18:24:27Z] [rtpclient.cpp:182]#033[0m Connecting control port 38608 to 192.168.122.178:5004
Jul 31 20:24:43 lappiemctopface rtpmidid[162733]: #033[0;34m[2021-07-31T18:24:27Z] [rtpclient.cpp:188]#033[0m Connecting midi port 38609 to 192.168.122.178:5005
Jul 31 20:32:34 lappiemctopface rtpmidid[162733]: #033[0;31m[2021-07-31T18:32:34Z] [rtpmidid.cpp:479]#033[0m There is no peer but I received an event! This situation should NEVER happen. File a bug. Port 3
Jul 31 20:32:36 lappiemctopface rtpmidid[162733]: message repeated 6 times: [ #033[0;31m[2021-07-31T18:32:34Z] [rtpmidid.cpp:479]#033[0m There is no peer but I received an event! This situation should NEVER happen. File a bug. Port 3]
Jul 31 20:32:36 lappiemctopface rtpmidid[162733]: #033[0;31m[2021-07-31T18:32:35Z] [rtpmidid.cpp:479]#033[0m There is no peer but I received an event! This situation should NEVER happen. File a bug. Port 3
Jul 31 20:32:36 lappiemctopface rtpmidid[162733]: message repeated 10 times: [ #033[0;31m[2021-07-31T18:32:35Z] [rtpmidid.cpp:479]#033[0m There is no peer but I received an event! This situation should NEVER happen. File a bug. Port 3]
Jul 31 20:32:36 lappiemctopface rtpmidid[162733]: #033[0;31m[2021-07-31T18:32:36Z] [rtpmidid.cpp:479]#033[0m There is no peer but I received an event! This situation should NEVER happen. File a bug. Port 3
Jul 31 20:32:36 lappiemctopface rtpmidid[162733]: message repeated 13 times: [ #033[0;31m[2021-07-31T18:32:36Z] [rtpmidid.cpp:479]#033[0m There is no peer but I received an event! This situation should NEVER happen. File a bug. Port 3]
@folkertvanheusden folkertvanheusden changed the title "There is no peer but I received an event! This situation should NEVER happen. File a bug. Port 3" instabilities Aug 2, 2021
@folkertvanheusden
Copy link
Contributor Author

folkertvanheusden commented Aug 2, 2021

[2021-08-02T20:42:41Z] [rtppeer.cpp:348] Send CK0 to lappiemctopface/VMPK Out
[2021-08-02T20:42:41Z] [rtppeer.cpp:289] Latency lappiemctopface/VMPK Out: 5.10 ms (client / 2)
[2021-08-02T20:42:41Z] [poller.cpp:200] Catched exception at poller: Try to access end of buffer at 1

That's when talking to a https://github.com/lathoub/Arduino-AppleMIDI-Library

They're generated when the arduino sends data via wifi through rtpmidid. The other direction works fine.

dump.pcap.gz

23:16:32.256251 IP 192.168.65.158.33935 > 192.168.65.156.5005: UDP, length 36
	0x0000:  4500 0040 8521 4000 4011 b100 c0a8 419e  E..@.!@.@.....A.
	0x0010:  c0a8 419c 848f 138d 002c 0b16 ffff 434b  ..A......,....CK
	0x0020:  0000 b331 0200 0000 0000 0000 0061 ba52  ...1.........a.R
	0x0030:  0000 0000 008f e92c 0000 0000 0061 ba8a  .......,.....a..
23:16:32.689443 IP 192.168.65.156.5005 > 192.168.65.158.33935: UDP, length 16
	0x0000:  4500 002c 0b21 0000 ff11 ac14 c0a8 419c  E..,.!........A.
	0x0010:  c0a8 419e 138d 848f 0018 33a0 8061 79ea  ..A.......3..ay.
	0x0020:  008f f32c 2522 d83c 0390 407f            ...,%".<..@.
23:16:32.690897 IP 192.168.65.156.5005 > 192.168.65.158.33935: UDP, length 0
	0x0000:  4500 001c 0b22 0000 ff11 ac23 c0a8 419c  E....".....#..A.
	0x0010:  c0a8 419e 138d 848f 0008 6336            ..A.......c6
23:16:32.895381 IP 192.168.65.156.5005 > 192.168.65.158.33935: UDP, length 16
	0x0000:  4500 002c 0b23 0000 ff11 ac12 c0a8 419c  E..,.#........A.
	0x0010:  c0a8 419e 138d 848f 0018 27e4 8061 79eb  ..A.......'..ay.
	0x0020:  008f ff66 2522 d83c 0390 4000            ...f%".<..@.
23:16:32.896669 IP 192.168.65.156.5005 > 192.168.65.158.33935: UDP, length 0
	0x0000:  4500 001c 0b24 0000 ff11 ac21 c0a8 419c  E....$.....!..A.
	0x0010:  c0a8 419e 138d 848f 0008 6336            ..A.......c6

@folkertvanheusden
Copy link
Contributor Author

I ran rtpmidid in valgrind. When I pressed ctrl+c at some point, I got:

==25410== Invalid read of size 1
==25410==    at 0x2255FA: std::less<unsigned char>::operator()(unsigned char const&, unsigned char const&) const (stl_function.h:386)
==25410==    by 0x22B98F: std::_Rb_tree<unsigned char, std::pair<unsigned char const, rtpmidid::client_info>, std::_Select1st<std::pair<unsigned char const, rtpmidid::client_info> >, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::_M_lower_bound(std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> >*, std::_Rb_tree_node_base*, unsigned char const&) (stl_tree.h:1935)
==25410==    by 0x22AE82: std::_Rb_tree<unsigned char, std::pair<unsigned char const, rtpmidid::client_info>, std::_Select1st<std::pair<unsigned char const, rtpmidid::client_info> >, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::lower_bound(unsigned char const&) (stl_tree.h:1277)
==25410==    by 0x2267C4: std::map<unsigned char, rtpmidid::client_info, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::lower_bound(unsigned char const&) (stl_map.h:1259)
==25410==    by 0x223C68: std::map<unsigned char, rtpmidid::client_info, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::operator[](unsigned char&&) (stl_map.h:517)
==25410==    by 0x21B0FB: rtpmidid::rtpmidid_t::disconnect_client(int, int) (rtpmidid.cpp:310)
==25410==    by 0x21AC75: rtpmidid::rtpmidid_t::connect_client(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, int)::{lambda(rtpmidid::rtppeer::disconnect_reason_e)#2}::operator()(rtpmidid::rtppeer::disconnect_reason_e) const (rtpmidid.cpp:301)
==25410==    by 0x220FAB: void std::__invoke_impl<void, rtpmidid::rtpmidid_t::connect_client(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, int)::{lambda(rtpmidid::rtppeer::disconnect_reason_e)#2}&, rtpmidid::rtppeer::disconnect_reason_e>(std::__invoke_other, rtpmidid::rtpmidid_t::connect_client(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, int)::{lambda(rtpmidid::rtppeer::disconnect_reason_e)#2}&, rtpmidid::rtppeer::disconnect_reason_e&&) (invoke.h:60)
==25410==    by 0x21FAD0: std::enable_if<is_invocable_r_v<void, rtpmidid::rtpmidid_t::connect_client(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, int)::{lambda(rtpmidid::rtppeer::disconnect_reason_e)#2}&, rtpmidid::rtppeer::disconnect_reason_e>, std::enable_if>::type std::__invoke_r<void, rtpmidid::rtpmidid_t::connect_client(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, int)::{lambda(rtpmidid::rtppeer::disconnect_reason_e)#2}&, rtpmidid::rtppeer::disconnect_reason_e>(void&&, (rtpmidid::rtpmidid_t::connect_client(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, int)::{lambda(rtpmidid::rtppeer::disconnect_reason_e)#2}&)...) (invoke.h:110)
==25410==    by 0x21DCAB: std::_Function_handler<void (rtpmidid::rtppeer::disconnect_reason_e), rtpmidid::rtpmidid_t::connect_client(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, int)::{lambda(rtpmidid::rtppeer::disconnect_reason_e)#2}>::_M_invoke(std::_Any_data const&, rtpmidid::rtppeer::disconnect_reason_e&&) (std_function.h:291)
==25410==    by 0x2726C7: std::function<void (rtpmidid::rtppeer::disconnect_reason_e)>::operator()(rtpmidid::rtppeer::disconnect_reason_e) const (std_function.h:622)
==25410==    by 0x271187: signal_t<rtpmidid::rtppeer::disconnect_reason_e>::operator()(rtpmidid::rtppeer::disconnect_reason_e) (signal.hpp:40)
==25410==  Address 0x53b4670 is 32 bytes inside a block of size 128 free'd
==25410==    at 0x4845B0F: operator delete(void*, unsigned long) (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==25410==    by 0x216121: __gnu_cxx::new_allocator<std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> > >::deallocate(std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> >*, unsigned long) (new_allocator.h:133)
==25410==    by 0x215DAA: std::allocator_traits<std::allocator<std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> > > >::deallocate(std::allocator<std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> > >&, std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> >*, unsigned long) (alloc_traits.h:492)
==25410==    by 0x215B28: std::_Rb_tree<unsigned char, std::pair<unsigned char const, rtpmidid::client_info>, std::_Select1st<std::pair<unsigned char const, rtpmidid::client_info> >, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::_M_put_node(std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> >*) (stl_tree.h:588)
==25410==    by 0x2158B9: std::_Rb_tree<unsigned char, std::pair<unsigned char const, rtpmidid::client_info>, std::_Select1st<std::pair<unsigned char const, rtpmidid::client_info> >, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::_M_drop_node(std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> >*) (stl_tree.h:655)
==25410==    by 0x21558D: std::_Rb_tree<unsigned char, std::pair<unsigned char const, rtpmidid::client_info>, std::_Select1st<std::pair<unsigned char const, rtpmidid::client_info> >, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::_M_erase(std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> >*) (stl_tree.h:1921)
==25410==    by 0x21539F: std::_Rb_tree<unsigned char, std::pair<unsigned char const, rtpmidid::client_info>, std::_Select1st<std::pair<unsigned char const, rtpmidid::client_info> >, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::~_Rb_tree() (stl_tree.h:991)
==25410==    by 0x215251: std::map<unsigned char, rtpmidid::client_info, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::~map() (stl_map.h:302)
==25410==    by 0x21531F: rtpmidid::rtpmidid_t::~rtpmidid_t() (rtpmidid.hpp:58)
==25410==    by 0x21501E: main (main.cpp:61)
==25410==  Block was alloc'd at
==25410==    at 0x4842FB3: operator new(unsigned long) (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==25410==    by 0x2371FF: __gnu_cxx::new_allocator<std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> > >::allocate(unsigned long, void const*) (new_allocator.h:115)
==25410==    by 0x2355F8: std::allocator_traits<std::allocator<std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> > > >::allocate(std::allocator<std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> > >&, unsigned long) (alloc_traits.h:460)
==25410==    by 0x2316C8: std::_Rb_tree<unsigned char, std::pair<unsigned char const, rtpmidid::client_info>, std::_Select1st<std::pair<unsigned char const, rtpmidid::client_info> >, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::_M_get_node() (stl_tree.h:584)
==25410==    by 0x22AEC4: std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> >* std::_Rb_tree<unsigned char, std::pair<unsigned char const, rtpmidid::client_info>, std::_Select1st<std::pair<unsigned char const, rtpmidid::client_info> >, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::_M_create_node<std::piecewise_construct_t const&, std::tuple<unsigned char const&>, std::tuple<> >(std::piecewise_construct_t const&, std::tuple<unsigned char const&>&&, std::tuple<>&&) (stl_tree.h:634)
==25410==    by 0x226880: std::_Rb_tree_iterator<std::pair<unsigned char const, rtpmidid::client_info> > std::_Rb_tree<unsigned char, std::pair<unsigned char const, rtpmidid::client_info>, std::_Select1st<std::pair<unsigned char const, rtpmidid::client_info> >, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::_M_emplace_hint_unique<std::piecewise_construct_t const&, std::tuple<unsigned char const&>, std::tuple<> >(std::_Rb_tree_const_iterator<std::pair<unsigned char const, rtpmidid::client_info> >, std::piecewise_construct_t const&, std::tuple<unsigned char const&>&&, std::tuple<>&&) (stl_tree.h:2461)
==25410==    by 0x223B43: std::map<unsigned char, rtpmidid::client_info, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::operator[](unsigned char const&) (stl_map.h:501)
==25410==    by 0x21A764: rtpmidid::rtpmidid_t::add_rtpmidi_client(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) (rtpmidid.cpp:245)
==25410==    by 0x219FEE: rtpmidid::rtpmidid_t::setup_mdns()::{lambda(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)#1}::operator()(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) const (rtpmidid.cpp:213)
==25410==    by 0x220A20: void std::__invoke_impl<void, rtpmidid::rtpmidid_t::setup_mdns()::{lambda(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)#1}&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&>(std::__invoke_other, rtpmidid::rtpmidid_t::setup_mdns()::{lambda(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)#1}&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) (invoke.h:60)
==25410==    by 0x21F225: std::enable_if<is_invocable_r_v<void, rtpmidid::rtpmidid_t::setup_mdns()::{lambda(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)#1}&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&>, std::enable_if>::type std::__invoke_r<void, rtpmidid::rtpmidid_t::setup_mdns()::{lambda(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)#1}&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&>(void&&, (rtpmidid::rtpmidid_t::setup_mdns()::{lambda(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)#1}&)...) (invoke.h:110)
==25410==    by 0x21D631: std::_Function_handler<void (std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&), rtpmidid::rtpmidid_t::setup_mdns()::{lambda(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)#1}>::_M_invoke(std::_Any_data const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) (std_function.h:291)
==25410== 
==25410== Invalid read of size 8
==25410==    at 0x215879: std::_Rb_tree<unsigned char, std::pair<unsigned char const, rtpmidid::client_info>, std::_Select1st<std::pair<unsigned char const, rtpmidid::client_info> >, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::_S_left(std::_Rb_tree_node_base*) (stl_tree.h:790)
==25410==    by 0x22B9AA: std::_Rb_tree<unsigned char, std::pair<unsigned char const, rtpmidid::client_info>, std::_Select1st<std::pair<unsigned char const, rtpmidid::client_info> >, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::_M_lower_bound(std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> >*, std::_Rb_tree_node_base*, unsigned char const&) (stl_tree.h:1936)
==25410==    by 0x22AE82: std::_Rb_tree<unsigned char, std::pair<unsigned char const, rtpmidid::client_info>, std::_Select1st<std::pair<unsigned char const, rtpmidid::client_info> >, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::lower_bound(unsigned char const&) (stl_tree.h:1277)
==25410==    by 0x2267C4: std::map<unsigned char, rtpmidid::client_info, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::lower_bound(unsigned char const&) (stl_map.h:1259)
==25410==    by 0x223C68: std::map<unsigned char, rtpmidid::client_info, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::operator[](unsigned char&&) (stl_map.h:517)
==25410==    by 0x21B0FB: rtpmidid::rtpmidid_t::disconnect_client(int, int) (rtpmidid.cpp:310)
==25410==    by 0x21AC75: rtpmidid::rtpmidid_t::connect_client(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, int)::{lambda(rtpmidid::rtppeer::disconnect_reason_e)#2}::operator()(rtpmidid::rtppeer::disconnect_reason_e) const (rtpmidid.cpp:301)
==25410==    by 0x220FAB: void std::__invoke_impl<void, rtpmidid::rtpmidid_t::connect_client(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, int)::{lambda(rtpmidid::rtppeer::disconnect_reason_e)#2}&, rtpmidid::rtppeer::disconnect_reason_e>(std::__invoke_other, rtpmidid::rtpmidid_t::connect_client(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, int)::{lambda(rtpmidid::rtppeer::disconnect_reason_e)#2}&, rtpmidid::rtppeer::disconnect_reason_e&&) (invoke.h:60)
==25410==    by 0x21FAD0: std::enable_if<is_invocable_r_v<void, rtpmidid::rtpmidid_t::connect_client(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, int)::{lambda(rtpmidid::rtppeer::disconnect_reason_e)#2}&, rtpmidid::rtppeer::disconnect_reason_e>, std::enable_if>::type std::__invoke_r<void, rtpmidid::rtpmidid_t::connect_client(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, int)::{lambda(rtpmidid::rtppeer::disconnect_reason_e)#2}&, rtpmidid::rtppeer::disconnect_reason_e>(void&&, (rtpmidid::rtpmidid_t::connect_client(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, int)::{lambda(rtpmidid::rtppeer::disconnect_reason_e)#2}&)...) (invoke.h:110)
==25410==    by 0x21DCAB: std::_Function_handler<void (rtpmidid::rtppeer::disconnect_reason_e), rtpmidid::rtpmidid_t::connect_client(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, int)::{lambda(rtpmidid::rtppeer::disconnect_reason_e)#2}>::_M_invoke(std::_Any_data const&, rtpmidid::rtppeer::disconnect_reason_e&&) (std_function.h:291)
==25410==    by 0x2726C7: std::function<void (rtpmidid::rtppeer::disconnect_reason_e)>::operator()(rtpmidid::rtppeer::disconnect_reason_e) const (std_function.h:622)
==25410==    by 0x271187: signal_t<rtpmidid::rtppeer::disconnect_reason_e>::operator()(rtpmidid::rtppeer::disconnect_reason_e) (signal.hpp:40)
==25410==  Address 0x53b4660 is 16 bytes inside a block of size 128 free'd
==25410==    at 0x4845B0F: operator delete(void*, unsigned long) (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==25410==    by 0x216121: __gnu_cxx::new_allocator<std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> > >::deallocate(std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> >*, unsigned long) (new_allocator.h:133)
==25410==    by 0x215DAA: std::allocator_traits<std::allocator<std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> > > >::deallocate(std::allocator<std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> > >&, std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> >*, unsigned long) (alloc_traits.h:492)
==25410==    by 0x215B28: std::_Rb_tree<unsigned char, std::pair<unsigned char const, rtpmidid::client_info>, std::_Select1st<std::pair<unsigned char const, rtpmidid::client_info> >, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::_M_put_node(std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> >*) (stl_tree.h:588)
==25410==    by 0x2158B9: std::_Rb_tree<unsigned char, std::pair<unsigned char const, rtpmidid::client_info>, std::_Select1st<std::pair<unsigned char const, rtpmidid::client_info> >, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::_M_drop_node(std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> >*) (stl_tree.h:655)
==25410==    by 0x21558D: std::_Rb_tree<unsigned char, std::pair<unsigned char const, rtpmidid::client_info>, std::_Select1st<std::pair<unsigned char const, rtpmidid::client_info> >, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::_M_erase(std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> >*) (stl_tree.h:1921)
==25410==    by 0x21539F: std::_Rb_tree<unsigned char, std::pair<unsigned char const, rtpmidid::client_info>, std::_Select1st<std::pair<unsigned char const, rtpmidid::client_info> >, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::~_Rb_tree() (stl_tree.h:991)
==25410==    by 0x215251: std::map<unsigned char, rtpmidid::client_info, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::~map() (stl_map.h:302)
==25410==    by 0x21531F: rtpmidid::rtpmidid_t::~rtpmidid_t() (rtpmidid.hpp:58)
==25410==    by 0x21501E: main (main.cpp:61)
==25410==  Block was alloc'd at
==25410==    at 0x4842FB3: operator new(unsigned long) (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==25410==    by 0x2371FF: __gnu_cxx::new_allocator<std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> > >::allocate(unsigned long, void const*) (new_allocator.h:115)
==25410==    by 0x2355F8: std::allocator_traits<std::allocator<std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> > > >::allocate(std::allocator<std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> > >&, unsigned long) (alloc_traits.h:460)
==25410==    by 0x2316C8: std::_Rb_tree<unsigned char, std::pair<unsigned char const, rtpmidid::client_info>, std::_Select1st<std::pair<unsigned char const, rtpmidid::client_info> >, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::_M_get_node() (stl_tree.h:584)
==25410==    by 0x22AEC4: std::_Rb_tree_node<std::pair<unsigned char const, rtpmidid::client_info> >* std::_Rb_tree<unsigned char, std::pair<unsigned char const, rtpmidid::client_info>, std::_Select1st<std::pair<unsigned char const, rtpmidid::client_info> >, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::_M_create_node<std::piecewise_construct_t const&, std::tuple<unsigned char const&>, std::tuple<> >(std::piecewise_construct_t const&, std::tuple<unsigned char const&>&&, std::tuple<>&&) (stl_tree.h:634)
==25410==    by 0x226880: std::_Rb_tree_iterator<std::pair<unsigned char const, rtpmidid::client_info> > std::_Rb_tree<unsigned char, std::pair<unsigned char const, rtpmidid::client_info>, std::_Select1st<std::pair<unsigned char const, rtpmidid::client_info> >, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::_M_emplace_hint_unique<std::piecewise_construct_t const&, std::tuple<unsigned char const&>, std::tuple<> >(std::_Rb_tree_const_iterator<std::pair<unsigned char const, rtpmidid::client_info> >, std::piecewise_construct_t const&, std::tuple<unsigned char const&>&&, std::tuple<>&&) (stl_tree.h:2461)
==25410==    by 0x223B43: std::map<unsigned char, rtpmidid::client_info, std::less<unsigned char>, std::allocator<std::pair<unsigned char const, rtpmidid::client_info> > >::operator[](unsigned char const&) (stl_map.h:501)
==25410==    by 0x21A764: rtpmidid::rtpmidid_t::add_rtpmidi_client(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) (rtpmidid.cpp:245)
==25410==    by 0x219FEE: rtpmidid::rtpmidid_t::setup_mdns()::{lambda(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)#1}::operator()(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) const (rtpmidid.cpp:213)
==25410==    by 0x220A20: void std::__invoke_impl<void, rtpmidid::rtpmidid_t::setup_mdns()::{lambda(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)#1}&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&>(std::__invoke_other, rtpmidid::rtpmidid_t::setup_mdns()::{lambda(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)#1}&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) (invoke.h:60)
==25410==    by 0x21F225: std::enable_if<is_invocable_r_v<void, rtpmidid::rtpmidid_t::setup_mdns()::{lambda(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)#1}&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&>, std::enable_if>::type std::__invoke_r<void, rtpmidid::rtpmidid_t::setup_mdns()::{lambda(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)#1}&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&>(void&&, (rtpmidid::rtpmidid_t::setup_mdns()::{lambda(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)#1}&)...) (invoke.h:110)
==25410==    by 0x21D631: std::_Function_handler<void (std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&), rtpmidid::rtpmidid_t::setup_mdns()::{lambda(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)#1}>::_M_invoke(std::_Any_data const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) (std_function.h:291)

@folkertvanheusden
Copy link
Contributor Author

folkertvanheusden commented Aug 2, 2021

This is an example of a disappearing service.
I had a '' and a ''. As soon as I connected them (in a patchbay program), the following scrolled by in the rtpmidid output:

[2021-08-02T21:20:55Z] [mdns_rtpmidi.cpp:235] Discovered service 'AppleMIDI-ESP8266' of type '_apple-midi._udp' in domain 'local'
[2021-08-02T21:20:55Z] [rtpmidid.cpp:243] New alsa port: 3, connects to host: 192.168.65.156, port: 5004, name: AppleMIDI-ESP8266
[2021-08-02T21:20:56Z] [mdns_rtpmidi.cpp:58] Service '/Client39/EntryGroup1' successfully established
[2021-08-02T21:20:56Z] [mdns_rtpmidi.cpp:284] (Browser) NEW: service 'lappiemctopface' of type '_apple-midi._udp' in domain 'local'
[2021-08-02T21:20:56Z] [mdns_rtpmidi.cpp:284] (Browser) NEW: service 'lappiemctopface' of type '_apple-midi._udp' in domain 'local'
[2021-08-02T21:20:56Z] [mdns_rtpmidi.cpp:284] (Browser) NEW: service 'lappiemctopface' of type '_apple-midi._udp' in domain 'local'
[2021-08-02T21:20:56Z] [mdns_rtpmidi.cpp:284] (Browser) NEW: service 'lappiemctopface' of type '_apple-midi._udp' in domain 'local'
[2021-08-02T21:20:56Z] [mdns_rtpmidi.cpp:231] Received own announcement
[2021-08-02T21:20:56Z] [mdns_rtpmidi.cpp:231] Received own announcement
[2021-08-02T21:20:56Z] [mdns_rtpmidi.cpp:231] Received own announcement
[2021-08-02T21:20:56Z] [mdns_rtpmidi.cpp:231] Received own announcement
[2021-08-02T21:21:53Z] [aseq.cpp:123] New ALSA connection from port ESI MIDIMATE eX-ESI MIDIMATE eX MIDI 1 (20:0)
[2021-08-02T21:21:53Z] [rtpmidid.cpp:249] Callback on subscribe at rtpmidid: ESI MIDIMATE eX-ESI MIDIMATE eX MIDI 1
[2021-08-02T21:21:53Z] [rtpclient.cpp:77] Try connect to service at 192.168.65.156:5004
[2021-08-02T21:21:53Z] [rtpclient.cpp:99] Try connect to resolved name: 192.168.65.156:5004
[2021-08-02T21:21:53Z] [rtpclient.cpp:118] Connected to resolved name: 192.168.65.156:5004
[2021-08-02T21:21:53Z] [rtpclient.cpp:126] Control port, local: 32769, remote at 192.168.65.156:5004
[2021-08-02T21:21:53Z] [rtpclient.cpp:156] MIDI PORT at port 32769
[2021-08-02T21:21:53Z] [rtpclient.cpp:182] Connecting control port 32769 to 192.168.65.156:5004
[2021-08-02T21:21:58Z] [rtpmidid.cpp:313] Disconnect signal: 4
[2021-08-02T21:21:58Z] [rtpmidid.cpp:341] Timeout. Not trying again.
[2021-08-02T21:21:58Z] [rtpmidid.cpp:574] Removing peer from known peers list. Port 3
[2021-08-02T21:21:58Z] [rtppeer.cpp:50] ~rtppeer 'lappiemctopface/ESI MIDIMATE eX-ESI MIDIMATE eX MIDI 1' (local) <-> '' (remote)

"ESI MIDIMATE eX-ESI MIDIMATE eX MIDI 1" is a midi-to-usb-interface on my laptop, 192.168.65.156:5004 is the 'AppleMIDI-ESP8266'.

Now what I find puzzling is why this is printed:

[2021-08-02T21:21:53Z] [rtpclient.cpp:126] Control port, local: 32769, remote at 192.168.65.156:5004
[2021-08-02T21:21:53Z] [rtpclient.cpp:156] MIDI PORT at port 32769

Here the control port and the midi-port are the same port?
This is with this version by the way:

commit adbe2c53fba5a5c46b1f3f67496b88c6f7cc81bf (HEAD)
Author: David Moreno <dmoreno@coralbits.com>
Date:   Fri Jul 23 19:51:32 2021 +0200

so without any modifications by me.

In lib/rtpclient.cpp, there's

void rtpclient::connect_to(const std::string &address,
                           const std::string &port) {

and at line 154 you see:

    ::getsockname(control_socket, (struct sockaddr *)&servaddr, &len);
    auto midi_port = htons(servaddr.sin6_port);
    DEBUG("MIDI PORT at port {}", midi_port);

Shouldn't that be "::getsockname(midi_socket, (struct sockaddr *)&servaddr, &len);" ?

Also some debug output a few lines below is wrong I believe.

If you agree (see) I can do a pull-request.

I also see something crash at the other end (the arduino, well esp8266) so something might be wrong at the other end as well. Or rtpmidid is sending something invalid?

@folkertvanheusden
Copy link
Contributor Author

folkertvanheusden commented Aug 8, 2021

update: there is NO difference between ethernet and wifi. It still may be a timing problem, not perse a too long latency (over vpn worked fine for example (aprox. 100ms latency)).

From what I saw in the source code, it is avahi telling rtpmidi that the other end is gone.

How does it handle packet loss? At home I have about 2.1% packetloss (wifi or ethernet(-over-power), both not 100% reliable - strangely enough 0% packet loss over vpn).

@folkertvanheusden
Copy link
Contributor Author

folkertvanheusden commented Aug 8, 2021

Also strange: sometimes connecting some source to a local fluidsynth works fine ONLY if I also connect it to an other service. See screendumps to see what I mean.

This gives silence:

silence

This works fine:

works-fine

Note that connecting the arduino source to a windows pc (from windows) works fine as well.

@davidmoreno
Copy link
Owner

I also detected the other day something similar, but thought it was related to disconnection. My case was connecting to two alsa ports, and disconnecting one of them. Then no data is sent until another port is connected. Do you think that could be your case as well?

@davidmoreno
Copy link
Owner

update: there is NO difference between ethernet and wifi. It still may be a timing problem, not perse a too long latency (over vpn worked fine for example (aprox. 100ms latency)).

From what I saw in the source code, it is avahi telling rtpmidi that the other end is gone.

How does it handle packet loss? At home I have about 2.1% packetloss (wifi or ethernet(-over-power), both not 100% reliable - strangely enough 0% packet loss over vpn).

On VPN quite probably the VPN (wireguard) itself is doing some packet resend. Is the VPN directly to the rtpmidid computer?

There is no rtpmidi resend support, for that packet loss, whats needed is the journaling support, which is not finished yet. Are you just using a LAN for rtpmidi? or souring though internet or something? 2.1% packet loss is a lot for a LAN IMHO. For me I have 0% (or not quite sure how to check it, 0 packets drops at ifconfig)

@folkertvanheusden
Copy link
Contributor Author

I also detected the other day something similar, but thought it was related to disconnection. My case was connecting to two alsa ports, and disconnecting one of them. Then no data is sent until another port is connected. Do you think that could be your case as well?

Yes. And also that it did not start to work before I connect two.

@folkertvanheusden
Copy link
Contributor Author

On VPN quite probably the VPN (wireguard) itself is doing some packet resend. Is the VPN directly to the rtpmidid computer?

I use tinc; its endpoint is on a virtual machine. Other virtual machines (on the same server) run rtpmidi, usually with my 'metronoom' test-program.

There is no rtpmidi resend support, for that packet loss, whats needed is the journaling support, which is not finished yet. Are you just using a LAN for rtpmidi? or souring though internet or something? 2.1% packet loss is a lot for a LAN IMHO. For me I have 0% (or not quite sure how to check it, 0 packets drops at ifconfig)

Well it depends. I tested it again and this time I've got 0% packet loss on wifi. The ethernet is over power in my living room, and that's somewhat comparable to ethernet over radio (wifi) and thus prone to packet loss.
But also without packetloss the problems occure.

@folkertvanheusden
Copy link
Contributor Author

I also detected the other day something similar, but thought it was related to disconnection. My case was connecting to two alsa ports, and disconnecting one of them. Then no data is sent until another port is connected. Do you think that could be your case as well?

Yes. And also that it did not start to work before I connect two.

Oh and note: in this example, 'neo' and 'arduino' are directly on the same switch (no vpn, wifi or eop in between).
Unfortunately I can't remember if 'lappiemctopface' was on wifi or lan at that time (maybe add a hint for which interface one is connected in the name?).

@folkertvanheusden
Copy link
Contributor Author

Please check this logging: it appears that suddenly rtpmidid decides there's a timeout and disconnects.

river_rtpmidi_fail.txt

@folkertvanheusden
Copy link
Contributor Author

I did a quick rtpmidi implementation to debug the problems. Now especially at the beginning but also during the session I often receive 'ICMP Destination unreachable' messages. I think that's a bit strange as rtpmidid is supposed to always be listening on those 2 ports?

08:53:03.553474 IP 192.168.64.100 > 192.168.65.205: ICMP 192.168.64.100 udp port 36775 unreachable, length 48
08:53:03.599573 IP 192.168.64.100 > 192.168.65.205: ICMP 192.168.64.100 udp port 36775 unreachable, length 48

Network trace: rtpmidi.pcap.zip

@davidmoreno
Copy link
Owner

Its strange that it happens only on port 5004, but it was properly used before.. On a moment I thouhg t it it could be caused byt the network packet losses you were experiencing, but the ICMP message is sent by the proper OS.. so it should be ok.

Maybe some timing when creating the ports? I think we create one first and then the second after the first is connected. Maybe we can create them both at the same time so its ready for later? But it does not make sense as some packets seem to arrive and others not.

anyway t seems to be totally related to the journaling, as its on feedback packets that it gets the errors.

I would try to create some test program that is able to reproduce the problem reliablily, so we can fix it completely.

@folkertvanheusden
Copy link
Contributor Author

folkertvanheusden commented Aug 13, 2021

I'll put my test-program on-line: https://github.com/folkertvanheusden/frtpm

It hardcoded listens on port 5004/5005 and creates an ALSA port on which everything is outputted.

rtmidid-cli create rftpm ...IP-ADDRESS... 5004

should work.

The two problems I see with that program:

  • strange icmp port unreachable messages
  • runs for ages and then suddenly rtpmidid sends a 'BY' without any further logging:
    Aug 13 11:58:26 belle rtpmidid[2483910]: [0] [rtppeer.cpp:350] Send CK0 to frtpm_lappiemctopface
    Aug 13 11:58:26 belle rtpmidid[2483910]: [3] [rtppeer.cpp:291] Latency frtpm_lappiemctopface: 5.90 ms (client / 2)

@folkertvanheusden
Copy link
Contributor Author

In void rtppeer::parse_midi(io_bytes_reader &buffer) there's this code:

  buffer.read_uint8(); // Ignore RTP header flags (Byte 0)
  auto rtpmidi_id = buffer.read_uint8();
  if (rtpmidi_id != 0x61) { // next Byte: Payload type

Shouldn't you mask off the 7th bit? Because that contains 'M', indicating if there's MIDI data and that can be set as well I believe:

| M               |   8   | Has MIDI data.                                                                                                           |
| PT              | 9-15  | Payload type. Always 0x61. MIDI.                                                                                         |

(from docs/RFC6295_notes.md).

From 'RFC 6295':

"For native streams, the M bit MUST be set to 1 if the MIDI
   command section has a non-zero LEN field and MUST be set to 0
   otherwise."

@folkertvanheusden
Copy link
Contributor Author

folkertvanheusden commented Aug 19, 2021

I have a 'DOREMiDi' which is a converter between midi and rtpmidi/apple-midi.
It is an appliance running on some kind of microcontroller (boots instantly).
It connects fine with windows but with rtpmidi I've got it to connect sofar only once. I started a post about this earlier and then deleted but that was too soon :-)

[3] [rtpmidid.cpp:243] New alsa port: 8, connects to host: 192.168.65.184, port: 5006, name: DOREMiDi-MIDI
[0] [mdns_rtpmidi.cpp:265] Discovered service 'belle' of type '_apple-midi._udp' in domain 'local'
[0] [mdns_rtpmidi.cpp:265] Discovered service 'metronoom' of type '_apple-midi._udp' in domain 'local'
[0] [mdns_rtpmidi.cpp:265] Discovered service 'neo' of type '_apple-midi._udp' in domain 'local'
[0] [mdns_rtpmidi.cpp:265] Discovered service 'cameras4' of type '_apple-midi._udp' in domain 'local'
[0] [mdns_rtpmidi.cpp:265] Discovered service 'metronoom_river' of type '_apple-midi._udp' in domain 'local'
[0] [mdns_rtpmidi.cpp:265] Discovered service 'river' of type '_apple-midi._udp' in domain 'local'
[3] [mdns_rtpmidi.cpp:64] Service '/Client33/EntryGroup1' successfully established
[3] [mdns_rtpmidi.cpp:316] (Browser) NEW: service 'lappiemctopface' of type '_apple-midi._udp' in domain 'local'
[3] [mdns_rtpmidi.cpp:316] (Browser) NEW: service 'lappiemctopface' of type '_apple-midi._udp' in domain 'local'
[3] [mdns_rtpmidi.cpp:316] (Browser) NEW: service 'lappiemctopface' of type '_apple-midi._udp' in domain 'local'
[3] [mdns_rtpmidi.cpp:316] (Browser) NEW: service 'lappiemctopface' of type '_apple-midi._udp' in domain 'local'
[3] [mdns_rtpmidi.cpp:316] (Browser) NEW: service 'lappiemctopface' of type '_apple-midi._udp' in domain 'local'
[3] [mdns_rtpmidi.cpp:316] (Browser) NEW: service 'lappiemctopface' of type '_apple-midi._udp' in domain 'local'
[3] [mdns_rtpmidi.cpp:316] (Browser) NEW: service 'lappiemctopface' of type '_apple-midi._udp' in domain 'local'
[0] [mdns_rtpmidi.cpp:261] Received own announcement
[0] [mdns_rtpmidi.cpp:261] Received own announcement
[0] [mdns_rtpmidi.cpp:261] Received own announcement
[0] [mdns_rtpmidi.cpp:261] Received own announcement
[0] [mdns_rtpmidi.cpp:261] Received own announcement
[0] [mdns_rtpmidi.cpp:261] Received own announcement
[0] [mdns_rtpmidi.cpp:261] Received own announcement
[3] [aseq.cpp:128] New ALSA connection from port Midi Through-Midi Through Port-0 (14:0)
[0] [rtpmidid.cpp:249] Callback on subscribe at rtpmidid: Midi Through-Midi Through Port-0
[0] [rtpclient.cpp:80] Try connect to service at 192.168.65.184:5006
[0] [rtpclient.cpp:104] Try connect to resolved name: 192.168.65.184:5006
[0] [rtpclient.cpp:124] Connected to resolved name: 192.168.65.184:5006
[0] [rtpclient.cpp:132] Control port, local: 33165, remote at 192.168.65.184:5006
[0] [rtpclient.cpp:162] MIDI PORT at port 33166
[0] [rtpclient.cpp:188] Connecting midi port 33166 to 192.168.65.184:5007
[0] [rtpmidid.cpp:313] Disconnect signal: 4
[1] [rtpmidid.cpp:341] Timeout (during setup). Not trying again.
[0] [rtpmidid.cpp:595] Removing peer from known peers list. Port 8
[0] [rtppeer.cpp:52] ~rtppeer 'lappiemctopface/Midi Through-Midi Through Port-0' (local) <-> '' (remote)

192.168.65.184 is the IP address of the doremidi appliance.


Also when it works then that is only for a bit of time:

[0] [rtppeer.cpp:401] Long header, 63 bytes long
[3] [mdns_rtpmidi.cpp:330] (Browser) REMOVE: service 'DOREMiDi-MIDI' of type '_apple-midi._udp' in domain 'local'
[3] [rtpmidid.cpp:269] Removing rtp midi client DOREMiDi-MIDI
[0] [rtpmidid.cpp:275] Found client to delete: alsa port 7. Deletes all known addreses.
[0] [rtpmidid.cpp:595] Removing peer from known peers list. Port 7
[0] [rtpmidid.cpp:313] Disconnect signal: 3
[0] [rtppeer.cpp:52] ~rtppeer 'lappiemctopface/aseqdump' (local) <-> 'DOREMiDi-MIDI' (remote)
[3] [mdns_rtpmidi.cpp:316] (Browser) NEW: service 'DOREMiDi-MIDI' of type '_apple-midi._udp' in domain 'local'
[0] [mdns_rtpmidi.cpp:265] Discovered service 'DOREMiDi-MIDI' of type '_apple-midi._udp' in domain 'local'

The windows system which is also listening to it, still plays its notes. So mdns_rtpmidi.cpp should not disconnect (imho) while notes still come in.

@folkertvanheusden
Copy link
Contributor Author

folkertvanheusden commented Aug 20, 2021

The arduino AND the DOREMiDi (according to tcpdump) just don't respond to the invitation request. Requests look sane (also according to wireshark).

So we have two cases:

@folkertvanheusden
Copy link
Contributor Author

folkertvanheusden commented Aug 20, 2021

Sometimes when rtpmidid decides to remove an rtp-midi-source, it goes into a loop doing only this:

recvfrom(18, 0x7ffe4f8c2800, 1500, MSG_DONTWAIT, 0x7ffe4f8c27c0, [28]) = -1 EBADF (Bad file descriptor)
epoll_wait(3, [{events=EPOLLIN, data={u32=10, u64=10}}], 10, -1) = 1
#0  0x00007f57ac4a32a0 in ?? () from /lib/x86_64-linux-gnu/libgcc_s.so.1
#1  0x00007f57ac4a49f2 in _Unwind_RaiseException () from /lib/x86_64-linux-gnu/libgcc_s.so.1
#2  0x00007f57ac55b7fc in __cxa_throw () from /lib/x86_64-linux-gnu/libstdc++.so.6
#3  0x000056392b9486e7 in rtpmidid::rtpclient::data_ready (this=0x56392c81f120, port=rtpmidid::rtppeer::MIDI_PORT)
    at /home/folkert/t/rtpmidid/lib/rtpclient.cpp:283
#4  0x000056392b946ed7 in operator() (__closure=0x56392c851858) at /home/folkert/t/rtpmidid/lib/rtpclient.cpp:163
#5  0x000056392b94a544 in std::__invoke_impl<void, rtpmidid::rtpclient::connect_to(const string&, const string&)::<lambda(int)>&, int>(std::__invoke_other, struct {...} &) (__f=...) at /usr/include/c++/10/bits/invoke.h:60
#6  0x000056392b9499a6 in std::__invoke_r<void, rtpmidid::rtpclient::connect_to(const string&, const string&)::<lambda(int)>&, int>(struct {...} &) (
    __fn=...) at /usr/include/c++/10/bits/invoke.h:110
#7  0x000056392b948f8e in std::_Function_handler<void(int), rtpmidid::rtpclient::connect_to(const string&, const string&)::<lambda(int)> >::_M_invoke(const std::_Any_data &, int &&) (__functor=..., __args#0=@0x7ffe4f8c2ec4: 10) at /usr/include/c++/10/bits/std_function.h:291
#8  0x000056392b963900 in std::function<void (int)>::operator()(int) const (this=0x56392c851858, __args#0=10)
    at /usr/include/c++/10/bits/std_function.h:622
#9  0x000056392b961107 in rtpmidid::poller_t::wait (this=0x56392b9b91a8 <rtpmidid::poller>) at /home/folkert/t/rtpmidid/lib/poller.cpp:202
#10 0x000056392b8e705f in main (argc=1, argv=0x7ffe4f8c3468) at /home/folkert/t/rtpmidid/src/main.cpp:65

This is a 100% CPU loop which takes a systemlogger with it (also uses 100% CPU) logging this:

aug 20 15:35:18 lappiemctopface rtpmidid[25781]: [poller.cpp:204] Caught exception at poller: Error reading from rtppeer DOREMiDi-MIDI:5006

#73 fixes it in that invalid fds are removed from the poller set but it should be investigated why it was closed and not removed in the first place I guess.
Oh it also "fixes" this:

aug 20 16:26:15 lappiemctopface rtpmidid[29846]: [poller.cpp:204] Caught exception at poller: Try to access end of buffer at 1, forgetting fd 10.

@folkertvanheusden
Copy link
Contributor Author

Aug 20 23:06:40 lappiemctopface rtpmidid[33230]: [poller.cpp:204] Caught exception at poller: Filedescriptor 30 for �#003���U, forgetting fd 24.

Looks as if thread A removes something while B is still referring to it.

@folkertvanheusden
Copy link
Contributor Author

folkertvanheusden commented Aug 27, 2021

When connected to a Apple MacBook (both directly on same networkswitch, no wifi or anything), things (like my metronoom-program) sometimes crash (in the librtpmidid library). In the network-trace most of the note-on/off are "malformed" according to wireshark.

e.g.:

#0  0x00007f65bf4b81d4 in rtpmidid::rtppeer::is_connected (this=0x0) at /home/folkert/t/rtpmidid/include/rtpmidid/rtppeer.hpp:98
#1  0x00007f65bf4b69cb in rtpmidid::rtppeer::send_midi (this=0x0, events=...) at /home/folkert/t/rtpmidid/lib/rtppeer.cpp:443
#2  0x00007f65bf4cb3fc in rtpmidid::rtpserver::send_midi_to_all_peers (this=0x55fec4e5f7a0, buffer=...)
    at /home/folkert/t/rtpmidid/lib/rtpserver.cpp:355
#3  0x000055fec3e74a05 in send(rtpmidid::rtpserver*, unsigned char) ()
#4  0x000055fec3e74bc3 in timer_handler(sigval) ()
#5  0x00007f65bf44ba7c in timer_sigev_thread (arg=<optimized out>) at ../sysdeps/unix/sysv/linux/timer_routines.c:55
#6  0x00007f65bf1f8450 in start_thread (arg=0x7f65be308640) at pthread_create.c:473
#7  0x00007f65bf118d53 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

and:

[2021-08-26T22:48:47Z] [rtppeer.cpp:551] I got data from seqnum 1. 1 channels.
[2021-08-26T22:48:47Z] [rtppeer.cpp:555] Parse channel pkg 0
[2021-08-26T22:48:47Z] [rtppeer.cpp:572] Chapters: 00001000
[2021-08-26T22:48:47Z] [rtppeer.cpp:587] Parse chapter N, channel 0
[2021-08-26T22:48:47Z] [rtppeer.cpp:596] 125 note on count, 1 noteoff count
[2021-08-26T22:48:47Z] [rtppeer.cpp:505] Send feedback to the other end. Journal parsed. Seqnum 1
[2021-08-26T22:48:47Z] [rtppeer.cpp:365] Got feedback until package 45909 / 45909. No journal, so ignoring.
Segmentation fault (core dumped)

(gdb) bt
#0  0x00007fb2ab2c836f in rtpmidid::rtppeer::send_midi(rtpmidid::io_bytes_reader const&) () from /lib/librtpmidid.so.0
#1  0x00007fb2ab2d078c in rtpmidid::rtpserver::send_midi_to_all_peers(rtpmidid::io_bytes_reader const&) () from /lib/librtpmidid.so.0
#2  0x0000559b0f19da05 in send(rtpmidid::rtpserver*, unsigned char) ()
#3  0x0000559b0f19dbc3 in timer_handler(sigval) ()
#4  0x00007fb2ab2b3a7c in timer_sigev_thread (arg=<optimized out>) at ../sysdeps/unix/sysv/linux/timer_routines.c:55
#5  0x00007fb2ab060450 in start_thread (arg=0x7fb2aa170640) at pthread_create.c:473
#6  0x00007fb2aaf80d53 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

mac.pcap.zip

@davidmoreno
Copy link
Owner

I don't really know if finally fixed in latest version, as I dont have access to DOREMIDI. If still broken, please open a new issue.

Thanks for the report and all the information.

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

No branches or pull requests

2 participants