Discussion:
[recon-devel] no audio without TURN
Daniel Pocock
2014-03-19 15:11:04 UTC
Permalink
I've observed that with NatTraversalMode undefined (so it uses
ConversationProfile::NoNatTraversal) reConServer does not send out RTP

Two users are both connected and sending RTP to reConServer correctly.
reCon seems to drop the audio streams and not send anything out.

The logs show "starting to send for 3 codecs" from RemoteParticipant.cxx

The corresponding logs from sipxtapi don't give any specific errors
although the 127.0.0.1 in there (see attached) looks a little odd. One
of the clients is a local softphone on the same host as reCon, but the
SDP contains the proper IP address, not 127.0.0.1.

The hosts are on a 10.x.x.x private subnet and can all reach each other
without NAT issues.

The audio streams do appear if I use UdpAlloc mode (reTurnServer
relaying the media)

When I tested reCon last year I had issues like this and I found that
defining DISABLE_FLOWMANAGER_IF_NO_NAT_TRAVERSAL would help. This time,
it has not helped though.
Daniel Pocock
2014-03-20 14:19:20 UTC
Permalink
I've looked at this more closely, ...
Post by Daniel Pocock
I've observed that with NatTraversalMode undefined (so it uses
ConversationProfile::NoNatTraversal) reConServer does not send out RTP
Two users are both connected and sending RTP to reConServer correctly.
reCon seems to drop the audio streams and not send anything out.
The logs show "starting to send for 3 codecs" from RemoteParticipant.cxx
The corresponding logs from sipxtapi don't give any specific errors
although the 127.0.0.1 in there (see attached) looks a little odd. One
of the clients is a local softphone on the same host as reCon, but the
SDP contains the proper IP address, not 127.0.0.1.
The hosts are on a 10.x.x.x private subnet and can all reach each other
without NAT issues.
The audio streams do appear if I use UdpAlloc mode (reTurnServer
relaying the media)
When I tested reCon last year I had issues like this and I found that
defining DISABLE_FLOWMANAGER_IF_NO_NAT_TRAVERSAL would help. This time,
it has not helped though.
Actually, adding CPPFLAGS="-DDISABLE_FLOWMANAGER_IF_NO_NAT_TRAVERSAL"
does still make it work for the no-STUN server case but I'm not sure if
this flag is meant to be used in this way or just for troubleshooting.
Should we be releasing librecon compiled with this flag?

I made two calls, one without that flag and one with that flag and then
ran diff over the logs. When it is not compiled with that flag, I see
this warning in the log:

RemoteParticipant.cxx:634 | RemoteParticipant::unhold exception:
DialogUsage::Exception Can't provide an offer @ InviteSession.cxx:479

and in the log from the other test (where the compile flag has been
used) there is a debug message:

RemoteParticipant.cxx:1580 | adjustRTPStreams: handle=1, found media
line in local sdp, mediaType=AUDIO, transportType=RTP/AVP,
numConnections=1, port=17384

Looking at the sipXtapi logfile, I notice that for the case where recon
fails to send audio, it has "Start Sending audio RTP/RTCP codec: 0 ....
addres: 127.0.0.1 send ports: 0, 0" but for the second test, where it
succeeds, the sipXtapi log has the correct IP addresses and ports

The exception / warning suggests that setProposedSdp was called too
early or something else is wrong somewhere in the code - but there are
no other differences in the logs before that warning (except trivial
things like port numbers)

Scott, can you let me know more about this
DISABLE_FLOWMANAGER_IF_NO_NAT_TRAVERSAL flag? I feel this should work
regardless of how the flag is set.
Scott Godin
2014-03-20 15:32:36 UTC
Permalink
The DISABLE_FLOWMANAGER_IF_NO_NAT_TRAVERSAL was more for testing. Your
scenario should work both with and without this defined. We should fix the
code to make things work without this define enabled.

Scott
Post by Daniel Pocock
I've looked at this more closely, ...
Post by Daniel Pocock
I've observed that with NatTraversalMode undefined (so it uses
ConversationProfile::NoNatTraversal) reConServer does not send out RTP
Two users are both connected and sending RTP to reConServer correctly.
reCon seems to drop the audio streams and not send anything out.
The logs show "starting to send for 3 codecs" from RemoteParticipant.cxx
The corresponding logs from sipxtapi don't give any specific errors
although the 127.0.0.1 in there (see attached) looks a little odd. One
of the clients is a local softphone on the same host as reCon, but the
SDP contains the proper IP address, not 127.0.0.1.
The hosts are on a 10.x.x.x private subnet and can all reach each other
without NAT issues.
The audio streams do appear if I use UdpAlloc mode (reTurnServer
relaying the media)
When I tested reCon last year I had issues like this and I found that
defining DISABLE_FLOWMANAGER_IF_NO_NAT_TRAVERSAL would help. This time,
it has not helped though.
Actually, adding CPPFLAGS="-DDISABLE_FLOWMANAGER_IF_NO_NAT_TRAVERSAL"
does still make it work for the no-STUN server case but I'm not sure if
this flag is meant to be used in this way or just for troubleshooting.
Should we be releasing librecon compiled with this flag?
I made two calls, one without that flag and one with that flag and then
ran diff over the logs. When it is not compiled with that flag, I see
and in the log from the other test (where the compile flag has been
RemoteParticipant.cxx:1580 | adjustRTPStreams: handle=1, found media
line in local sdp, mediaType=AUDIO, transportType=RTP/AVP,
numConnections=1, port=17384
Looking at the sipXtapi logfile, I notice that for the case where recon
fails to send audio, it has "Start Sending audio RTP/RTCP codec: 0 ....
addres: 127.0.0.1 send ports: 0, 0" but for the second test, where it
succeeds, the sipXtapi log has the correct IP addresses and ports
The exception / warning suggests that setProposedSdp was called too
early or something else is wrong somewhere in the code - but there are
no other differences in the logs before that warning (except trivial
things like port numbers)
Scott, can you let me know more about this
DISABLE_FLOWMANAGER_IF_NO_NAT_TRAVERSAL flag? I feel this should work
regardless of how the flag is set.
_______________________________________________
recon-devel mailing list
List Archive: http://list.resiprocate.org/archive/recon-devel/
Daniel Pocock
2014-03-20 16:41:12 UTC
Permalink
Post by Scott Godin
The DISABLE_FLOWMANAGER_IF_NO_NAT_TRAVERSAL was more for testing.
Your scenario should work both with and without this defined. We
should fix the code to make things work without this define enabled.
I looked at the unfiltered logs now (not just the librecon logs) and I
see this from dum just before the warning from recon:

InviteSession.cxx:478 | Incorrect state to provideOffer: UAS_Accepted

The sequence of events:

- participant 1 (p1) calls in
- recon auto-answers and puts p1 on hold
- p2 calls in
- recon auto-answers
- recon tries to un-hold p1
- then the error occurs

Should dum allow the provideOffer call in this state?

I grepped the logs for state transitions and it looks suspicious. As
well as the warnings, I notice that in the case where it fails, some
handle=3 is being created (even though there are only two participants):

INFO | 20140320-143924.083 | InviteSession.cxx:2753 | Transition UAS_Start -> UAS_Offer
INFO | 20140320-143924.104 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=1 to state=Accepted
INFO | 20140320-143924.104 | InviteSession.cxx:2753 | Transition UAS_Offer -> UAS_OfferProvidedAnswer
INFO | 20140320-143924.104 | InviteSession.cxx:2753 | Transition UAS_OfferProvidedAnswer -> UAS_Accepted
INFO | 20140320-143924.104 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=1 to state=Connected
INFO | 20140320-143925.492 | InviteSession.cxx:2753 | Transition UAS_Start -> UAS_Offer
WARNING | 20140320-143925.493 | InviteSession.cxx:478 | Incorrect state to provideOffer: UAS_Accepted
WARNING | 20140320-143925.516 | RemoteParticipant.cxx:634 | RemoteParticipant::unhold exception: DialogUsage::Exception Can't provide an offer @ InviteSession.cxx:479
INFO | 20140320-143925.534 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=2 to state=Accepted
INFO | 20140320-143925.534 | InviteSession.cxx:2753 | Transition UAS_Offer -> UAS_OfferProvidedAnswer
INFO | 20140320-143925.543 | InviteSession.cxx:2753 | Transition UAS_OfferProvidedAnswer -> UAS_Accepted
INFO | 20140320-143925.544 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=2 to state=Connected
INFO | 20140320-143925.555 | InviteSession.cxx:2753 | Transition UAS_Accepted -> InviteSession::Connected
INFO | 20140320-143925.555 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=2 to state=Connected
INFO | 20140320-143931.461 | InviteSession.cxx:2753 | Transition UAS_Start -> UAS_Offer
INFO | 20140320-143931.473 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=3 to state=Accepted
INFO | 20140320-143931.474 | InviteSession.cxx:2753 | Transition UAS_Offer -> UAS_OfferProvidedAnswer
INFO | 20140320-143931.483 | InviteSession.cxx:2753 | Transition UAS_OfferProvidedAnswer -> UAS_Accepted
INFO | 20140320-143931.484 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=3 to state=Connected
INFO | 20140320-143931.495 | InviteSession.cxx:2753 | Transition UAS_Accepted -> InviteSession::Connected
INFO | 20140320-143931.495 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=3 to state=Connected
INFO | 20140320-143940.600 | InviteSession.cxx:2753 | Transition InviteSession::Connected -> InviteSession::Terminated
INFO | 20140320-143940.600 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=2 to state=Terminating
INFO | 20140320-143941.842 | InviteSession.cxx:2753 | Transition InviteSession::Connected -> InviteSession::Terminated
INFO | 20140320-143941.842 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=3 to state=Terminating
WARNING | 20140320-143941.842 | InviteSession.cxx:478 | Incorrect state to provideOffer: UAS_Accepted
WARNING | 20140320-143941.842 | RemoteParticipant.cxx:589 | RemoteParticipant::hold exception: DialogUsage::Exception Can't provide an offer @ InviteSession.cxx:479
INFO | 20140320-143956.105 | InviteSession.cxx:2753 | Transition UAS_Accepted -> InviteSession::Terminated
INFO | 20140320-143956.105 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=1 to state=Terminating




and here is the sequence of transitions where it does work (notice it is in the InviteSession::Connected state when provideOffer is called):



INFO | 20140320-144233.605 | InviteSession.cxx:2753 | Transition UAS_Start -> UAS_Offer
INFO | 20140320-144233.625 | InviteSession.cxx:2753 | Transition UAS_Offer -> UAS_OfferProvidedAnswer
INFO | 20140320-144233.625 | InviteSession.cxx:2753 | Transition UAS_OfferProvidedAnswer -> UAS_Accepted
INFO | 20140320-144233.626 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=1 to state=Connected
INFO | 20140320-144233.626 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=1 to state=Accepted
INFO | 20140320-144233.628 | InviteSession.cxx:2753 | Transition UAS_Accepted -> InviteSession::Connected
INFO | 20140320-144233.628 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=1 to state=Connected
INFO | 20140320-144240.575 | InviteSession.cxx:2753 | Transition UAS_Start -> UAS_Offer
INFO | 20140320-144240.575 | InviteSession.cxx:2753 | Transition InviteSession::Connected -> InviteSession::SentReinvite
INFO | 20140320-144240.585 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=1 to state=Unholding
INFO | 20140320-144240.605 | InviteSession.cxx:2753 | Transition UAS_Offer -> UAS_OfferProvidedAnswer
INFO | 20140320-144240.615 | InviteSession.cxx:2753 | Transition UAS_OfferProvidedAnswer -> UAS_Accepted
INFO | 20140320-144240.615 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=2 to state=Connected
INFO | 20140320-144240.615 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=2 to state=Accepted
INFO | 20140320-144240.618 | InviteSession.cxx:2753 | Transition UAS_Accepted -> InviteSession::Connected
INFO | 20140320-144240.618 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=2 to state=Connected
INFO | 20140320-144241.155 | InviteSession.cxx:2753 | Transition InviteSession::SentReinvite -> InviteSession::Connected
INFO | 20140320-144241.156 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=1 to state=Connected
INFO | 20140320-144250.084 | InviteSession.cxx:2753 | Transition InviteSession::Connected -> InviteSession::Terminated
INFO | 20140320-144250.084 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=1 to state=Terminating
INFO | 20140320-144250.084 | InviteSession.cxx:2753 | Transition InviteSession::Connected -> InviteSession::SentReinvite
INFO | 20140320-144250.085 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=2 to state=Holding
INFO | 20140320-144251.227 | InviteSession.cxx:2753 | Transition InviteSession::SentReinvite -> InviteSession::Connected
INFO | 20140320-144251.228 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=2 to state=Connected
INFO | 20140320-144251.406 | InviteSession.cxx:2753 | Transition InviteSession::Connected -> InviteSession::Terminated
INFO | 20140320-144251.406 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=2 to state=Terminating
Scott Godin
2014-03-20 16:53:46 UTC
Permalink
It is not valid to provide an offer when in the UAS_Accepted state. If we
wanted to accept the API call, we would need to queue the sending of the
offer until the ACK arrives.

We sit in the UAS_Accepted state after we send the 200 until we get the ACK
back. We should try and understand why we aren't getting the ACK.

Scott
Post by Scott Godin
The DISABLE_FLOWMANAGER_IF_NO_NAT_TRAVERSAL was more for testing. Your
scenario should work both with and without this defined. We should fix the
code to make things work without this define enabled.
I looked at the unfiltered logs now (not just the librecon logs) and I see
InviteSession.cxx:478 | Incorrect state to provideOffer: UAS_Accepted
- participant 1 (p1) calls in
- recon auto-answers and puts p1 on hold
- p2 calls in
- recon auto-answers
- recon tries to un-hold p1
- then the error occurs
Should dum allow the provideOffer call in this state?
I grepped the logs for state transitions and it looks suspicious. As well
as the warnings, I notice that in the case where it fails, some handle=3 is
INFO | 20140320-143924.083 | InviteSession.cxx:2753 | Transition UAS_Start -> UAS_Offer
INFO | 20140320-143924.104 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=1 to state=Accepted
INFO | 20140320-143924.104 | InviteSession.cxx:2753 | Transition UAS_Offer -> UAS_OfferProvidedAnswer
INFO | 20140320-143924.104 | InviteSession.cxx:2753 | Transition UAS_OfferProvidedAnswer -> UAS_Accepted
INFO | 20140320-143924.104 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=1 to state=Connected
INFO | 20140320-143925.492 | InviteSession.cxx:2753 | Transition UAS_Start -> UAS_Offer
WARNING | 20140320-143925.493 | InviteSession.cxx:478 | Incorrect state to provideOffer: UAS_Accepted
INFO | 20140320-143925.534 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=2 to state=Accepted
INFO | 20140320-143925.534 | InviteSession.cxx:2753 | Transition UAS_Offer -> UAS_OfferProvidedAnswer
INFO | 20140320-143925.543 | InviteSession.cxx:2753 | Transition UAS_OfferProvidedAnswer -> UAS_Accepted
INFO | 20140320-143925.544 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=2 to state=Connected
INFO | 20140320-143925.555 | InviteSession.cxx:2753 | Transition UAS_Accepted -> InviteSession::Connected
INFO | 20140320-143925.555 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=2 to state=Connected
INFO | 20140320-143931.461 | InviteSession.cxx:2753 | Transition UAS_Start -> UAS_Offer
INFO | 20140320-143931.473 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=3 to state=Accepted
INFO | 20140320-143931.474 | InviteSession.cxx:2753 | Transition UAS_Offer -> UAS_OfferProvidedAnswer
INFO | 20140320-143931.483 | InviteSession.cxx:2753 | Transition UAS_OfferProvidedAnswer -> UAS_Accepted
INFO | 20140320-143931.484 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=3 to state=Connected
INFO | 20140320-143931.495 | InviteSession.cxx:2753 | Transition UAS_Accepted -> InviteSession::Connected
INFO | 20140320-143931.495 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=3 to state=Connected
INFO | 20140320-143940.600 | InviteSession.cxx:2753 | Transition InviteSession::Connected -> InviteSession::Terminated
INFO | 20140320-143940.600 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=2 to state=Terminating
INFO | 20140320-143941.842 | InviteSession.cxx:2753 | Transition InviteSession::Connected -> InviteSession::Terminated
INFO | 20140320-143941.842 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=3 to state=Terminating
WARNING | 20140320-143941.842 | InviteSession.cxx:478 | Incorrect state to provideOffer: UAS_Accepted
INFO | 20140320-143956.105 | InviteSession.cxx:2753 | Transition UAS_Accepted -> InviteSession::Terminated
INFO | 20140320-143956.105 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=1 to state=Terminating
INFO | 20140320-144233.605 | InviteSession.cxx:2753 | Transition UAS_Start -> UAS_Offer
INFO | 20140320-144233.625 | InviteSession.cxx:2753 | Transition UAS_Offer -> UAS_OfferProvidedAnswer
INFO | 20140320-144233.625 | InviteSession.cxx:2753 | Transition UAS_OfferProvidedAnswer -> UAS_Accepted
INFO | 20140320-144233.626 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=1 to state=Connected
INFO | 20140320-144233.626 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=1 to state=Accepted
INFO | 20140320-144233.628 | InviteSession.cxx:2753 | Transition UAS_Accepted -> InviteSession::Connected
INFO | 20140320-144233.628 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=1 to state=Connected
INFO | 20140320-144240.575 | InviteSession.cxx:2753 | Transition UAS_Start -> UAS_Offer
INFO | 20140320-144240.575 | InviteSession.cxx:2753 | Transition InviteSession::Connected -> InviteSession::SentReinvite
INFO | 20140320-144240.585 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=1 to state=Unholding
INFO | 20140320-144240.605 | InviteSession.cxx:2753 | Transition UAS_Offer -> UAS_OfferProvidedAnswer
INFO | 20140320-144240.615 | InviteSession.cxx:2753 | Transition UAS_OfferProvidedAnswer -> UAS_Accepted
INFO | 20140320-144240.615 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=2 to state=Connected
INFO | 20140320-144240.615 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=2 to state=Accepted
INFO | 20140320-144240.618 | InviteSession.cxx:2753 | Transition UAS_Accepted -> InviteSession::Connected
INFO | 20140320-144240.618 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=2 to state=Connected
INFO | 20140320-144241.155 | InviteSession.cxx:2753 | Transition InviteSession::SentReinvite -> InviteSession::Connected
INFO | 20140320-144241.156 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=1 to state=Connected
INFO | 20140320-144250.084 | InviteSession.cxx:2753 | Transition InviteSession::Connected -> InviteSession::Terminated
INFO | 20140320-144250.084 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=1 to state=Terminating
INFO | 20140320-144250.084 | InviteSession.cxx:2753 | Transition InviteSession::Connected -> InviteSession::SentReinvite
INFO | 20140320-144250.085 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=2 to state=Holding
INFO | 20140320-144251.227 | InviteSession.cxx:2753 | Transition InviteSession::SentReinvite -> InviteSession::Connected
INFO | 20140320-144251.228 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=2 to state=Connected
INFO | 20140320-144251.406 | InviteSession.cxx:2753 | Transition InviteSession::Connected -> InviteSession::Terminated
INFO | 20140320-144251.406 | RemoteParticipant.cxx:272 | RemoteParticipant::stateTransition of handle=2 to state=Terminating
Daniel Pocock
2014-03-20 17:14:39 UTC
Permalink
Post by Scott Godin
It is not valid to provide an offer when in the UAS_Accepted state.
If we wanted to accept the API call, we would need to queue the
sending of the offer until the ACK arrives.
We sit in the UAS_Accepted state after we send the 200 until we get
the ACK back. We should try and understand why we aren't getting the ACK.
Ok, I've looked more closely

We do get the ACK after sending the OK three times, about a 1.5 second
delay for the ACK. That is from a local softphone on the same machine,
not sure why it does the ACK so slowly, maybe doing some STUN checks

Anyhow, this is where it becomes interesting: in those recon logs, it
has actually created another RemoteParticipant, handle=2, for the same
caller (first caller).

handle=3 is actually participant 2 (second caller)

handle=1 is somehow left in a bad state after the slow ACK or something
else which I haven't identified yet
Daniel Pocock
2014-03-20 19:18:08 UTC
Permalink
Post by Scott Godin
It is not valid to provide an offer when in the UAS_Accepted state.
If we wanted to accept the API call, we would need to queue the
sending of the offer until the ACK arrives.
We sit in the UAS_Accepted state after we send the 200 until we get
the ACK back. We should try and understand why we aren't getting the
ACK.
Turns out the client had wrongly sent a second INVITE one second after
the first INVITE. The original INVITE was never canceled or anything.
It was a red herring and didn't occur when tested again - so it has
nothing to do with the real issue (recon not sending audio to the
non-TURN clients)

I then started to focus on the RTP handling code and that took me to
TurnAsyncSocket - I discovered one of the sending methods appeared to be
incomplete and I came up with a small patch that resolves it.

Can you please have a look (it is already committed) and let me know if
that is the right place to handle it and whether you agree with using
sendToUnframed() to send out the packet?

For example, it appears that it could also check this in the send()
method and call sendToUnframed() from there to avoid passing through
dispatch() twice - but that would also make it less obvious/less
readable in doSendFramed()

Loading...