search

sippy / go-b2bua

The GO port of the Sippy B2BUA
BSD 2-Clause "Simplified" License
61 stars 16 forks source link

voiptests fail: RTP session is attempted to be deleted before it's created #3

Closed sobomax closed 6 years ago

sobomax commented 6 years ago

Hi, we have seen this weird issue on the latest voiptests run here:

https://travis-ci.org/sippy/voiptests/jobs/338230478

go-b2bua is trying to delete RTP session before it allocates it:

324 00:00:06.451/DBUG:GLOBAL:get_command: received command "984048856af367c5c634c21d9b3c1e09 D )VN~C5GHh44YeMZh"O3g4ZF03jZBT\P>@ndCe>O2H3{y\PUYe-0 f0072e20c037b89f144f693fcbc5ba24 e4307521e5f67bf7ab826902cde53b3d"
325 00:00:06.451/INFO:GLOBAL:handle_command: delete request failed: session )VN~C5GHh44YeMZh"O3g4ZF03jZBT\P>@ndCe>O2H3{y\PUYe-0, tags f0072e20c037b89f144f693fcbc5ba24/e4307521e5f67bf7ab826902cde53b3d not found
326 00:00:06.451/DBUG:GLOBAL:rtpc_doreply: sending reply "E50\n"

Some 0.4 second later:

335 00:00:06.823/DBUG:GLOBAL:get_command: received command "b43e3a9b0bc98ba6957ea71d88b6b26f UR127.0.0.1 )VN~C5GHh44YeMZh"O3g4ZF03jZBT\P>@ndCe>O2H3{y\PUYe-0 225.152.201.188 63304 f0072e20c037b89f144f693fcbc5ba24 unix:/home/travis/build/sippy/voiptests/b2bua.sock r%2038"
336 00:00:06.823/INFO:GLOBAL:rtpp_command_ul_handle: new IPv4/IPv4 session )VN~C5GHh44YeMZh"O3g4ZF03jZBT\P>@ndCe>O2H3{y\PUYe-0, tag f0072e20c037b89f144f693fcbc5ba24 requested, type strong
337 00:00:06.823/INFO:)VN~C5GHh44YeMZh"O3g4ZF03jZBT\P>@ndCe>O2H3{y\PUYe-0:rtpp_command_ul_handle: new session on IPv4 port 12398 created, tag f0072e20c037b89f144f693fcbc5ba24
338 00:00:06.823/INFO:)VN~C5GHh44YeMZh"O3g4ZF03jZBT\P>@ndCe>O2H3{y\PUYe-0:rtpp_command_ul_handle: setting timeout handler
339 00:00:06.823/INFO:)VN~C5GHh44YeMZh"O3g4ZF03jZBT\P>@ndCe>O2H3{y\PUYe-0:rtpp_stream_prefill_addr: pre-filling caller's RTP address with 225.152.201.188:63304
340 00:00:06.823/INFO:)VN~C5GHh44YeMZh"O3g4ZF03jZBT\P>@ndCe>O2H3{y\PUYe-0:rtpp_stream_prefill_addr: pre-filling caller's RTCP address with 225.152.201.188:63305
341 00:00:06.823/DBUG:GLOBAL:rtpc_doreply: sending reply "12398 127.0.0.1\n"
sobomax commented 6 years ago

Seems to be pretty reproducible, not every run but every few runs it blows with the same symptoms:

https://travis-ci.org/sippy/voiptests/jobs/338693592

   315  00:00:06.382/DBUG:GLOBAL:get_command: received command "15ae094e1a7a7fb82b657b753938f51a D Xn+T`9RpO<"F8WZ{8jTJz9_gF):'Gsi`@VR-?Mlik7MAbnRUv-0 c565b16cdaa1f4e7e580af3e2a98c09f 89700ac888ce1d9e6183fa3fdc352234"
   316  00:00:06.382/INFO:GLOBAL:handle_command: delete request failed: session Xn+T`9RpO<"F8WZ{8jTJz9_gF):'Gsi`@VR-?Mlik7MAbnRUv-0, tags c565b16cdaa1f4e7e580af3e2a98c09f/89700ac888ce1d9e6183fa3fdc352234 not found
   317  00:00:06.382/DBUG:GLOBAL:rtpc_doreply: sending reply "E50\n"
349 00:00:06.832/DBUG:GLOBAL:get_command: received command "88f4208e50f2f1e72e00bd6c64b4adf6 U6R[::1] Xn+T`9RpO<"F8WZ{8jTJz9_gF):'Gsi`@VR-?Mlik7MAbnRUv-0 2001:0:0:0:fbf0:215c:da44:0 19768 c565b16cdaa1f4e7e580af3e2a98c09f unix:/home/travis/build/sippy/voiptests/b2bua.sock r%2034"
   350  00:00:06.832/INFO:GLOBAL:rtpp_command_ul_handle: new IPv6/IPv6 session Xn+T`9RpO<"F8WZ{8jTJz9_gF):'Gsi`@VR-?Mlik7MAbnRUv-0, tag c565b16cdaa1f4e7e580af3e2a98c09f requested, type strong
   351  00:00:06.832/INFO:Xn+T`9RpO<"F8WZ{8jTJz9_gF):'Gsi`@VR-?Mlik7MAbnRUv-0:rtpp_command_ul_handle: new session on IPv6 port 13156 created, tag c565b16cdaa1f4e7e580af3e2a98c09f
   352  00:00:06.832/INFO:Xn+T`9RpO<"F8WZ{8jTJz9_gF):'Gsi`@VR-?Mlik7MAbnRUv-0:rtpp_command_ul_handle: setting timeout handler
   353  00:00:06.832/INFO:Xn+T`9RpO<"F8WZ{8jTJz9_gF):'Gsi`@VR-?Mlik7MAbnRUv-0:rtpp_stream_prefill_addr: pre-filling caller's RTP address with [2001::fbf0:215c:da44:0]:19768
   354  00:00:06.832/INFO:Xn+T`9RpO<"F8WZ{8jTJz9_gF):'Gsi`@VR-?Mlik7MAbnRUv-0:rtpp_stream_prefill_addr: pre-filling caller's RTCP address with [2001::fbf0:215c:da44:0]:19769
   355  00:00:06.832/DBUG:GLOBAL:rtpc_doreply: sending reply "13156 ::1 6\n"
bambyster commented 6 years ago

The order of commands to the rtpproxy is now enforced within a single session. The issue is now gone in my tests.

Thank you!