search

danbarua / NEventSocket

A reactive FreeSwitch eventsocket library for Modern .Net
Mozilla Public License 2.0
74 stars 37 forks source link

OutboundListener event-lock #37

Closed RobThree closed 8 years ago

RobThree commented 8 years ago

I'm trying to bridge a channel using an OutboundListener but am having, so far, not much luck. As soon as I pick up the ringing phone the channel is gone. While looking for a solution I came across this:

Note about async mode If you are using async, you need to pay attention to potential race condition. The commands you send may not execute in sequential order. You may force the command to wait:

sendmsg 
call-command: set
execute-app-name: foo=bar\n\n
event-lock:true

Source

And:

Q: Can I bridge a call with an Outbound socket? Yes you can, simple execute a 'Bridge'

sendmsg 
call-command: execute
execute-app-name: bridge
execute-app-arg: {ignore_early_media=true}sofia/gateway/myGW/177808
event-lock: true

The event-lock is key here, if you don't have it set, other events you might have sent can terminate the call, even if you've sent them before the bridge command. Remember that if you want to hangup the call when the bridge completes, either look for the event [CHANNEL_UNBRIDGE], or send a hangup event after the bridge.

Source

Looking at the bridge implementation it seems to me that the eventlock argument is not passed (e.g. defaults to false) to the ExecuteApplication method.

Could it be that this is my problem? If not, could you maybe show a simple example on how to bridge a channel with an OutboundListener?

I'll post my code as soon as I have created a stripped-down version to easily reproduce; may take a bit though :wink:

danbarua commented 8 years ago

can you post some trace-level logs? No problems doing originating and bridging here.

danbarua commented 8 years ago

Also it's worth inspecting the hangup cause of the BridgeResult and turn on debug-level logging on FreeSwitch - I've sometimes seen FreeSwitch didn't like something I'd configured with media codecs (memory is a little fuzzy on this one) so it would hang up with "Incompatible Destination" when I answered the call.

RobThree commented 8 years ago

I am working on a simplified testcase, but meanwhile here's a log from what I got so far:

NEventSocket.OutboundListener|New Connection from x.x.x.x:40051
NEventSocket.OutboundSocket (1)|EventSocket initialized
NEventSocket.OutboundSocket (1)|Sending [connect]
NEventSocket.OutboundSocket|NEventSocket.OutboundSocket Worker Thread 1 started
NEventSocket.OutboundSocket (1)|Messages Received [command/reply].
NEventSocket.OutboundSocket (1)|CommandReply received [+OK] for [connect]
NEventSocket.OutboundSocket (1)|Sending [linger]
NEventSocket.OutboundSocket (1)|Messages Received [command/reply].
NEventSocket.OutboundSocket (1)|CommandReply received [+OK will linger] for [linger]
NEventSocket.OutboundSocket (1)|Sending [event plain CHANNEL_PROGRESS CHANNEL_BRIDGE CHANNEL_UNBRIDGE CHANNEL_ANSWER CHANNEL_HANGUP DTMF]
NEventSocket.OutboundSocket (1)|Messages Received [command/reply].
NEventSocket.OutboundSocket (1)|CommandReply received [+OK event listener enabled plain] for [event plain CHANNEL_PROGRESS CHANNEL_BRIDGE CHANNEL_UNBRIDGE CHANNEL_ANSWER CHANNEL_HANGUP DTMF]
NEventSocket.OutboundSocket (1)|Sending [filter Unique-ID c52d91f1-e35f-4fa9-b0e8-0317aaa316f1]
NEventSocket.OutboundSocket (1)|Messages Received [command/reply].
NEventSocket.OutboundSocket (1)|CommandReply received [+OK filter added. [Unique-ID]=[c52d91f1-e35f-4fa9-b0e8-0317aaa316f1]] for [filter Unique-ID c52d91f1-e35f-4fa9-b0e8-0317aaa316f1]
NEventSocket.OutboundSocket (1)|Sending [filter Other-Leg-Unique-ID c52d91f1-e35f-4fa9-b0e8-0317aaa316f1]
NEventSocket.OutboundSocket (1)|Messages Received [command/reply].
NEventSocket.OutboundSocket (1)|CommandReply received [+OK filter added. [Other-Leg-Unique-ID]=[c52d91f1-e35f-4fa9-b0e8-0317aaa316f1]] for [filter Other-Leg-Unique-ID c52d91f1-e35f-4fa9-b0e8-0317aaa316f1]
NEventSocket.OutboundSocket (1)|Sending [filter Channel-Call-UUID c52d91f1-e35f-4fa9-b0e8-0317aaa316f1]
NEventSocket.OutboundSocket (1)|Messages Received [command/reply].
NEventSocket.OutboundSocket (1)|CommandReply received [+OK filter added. [Channel-Call-UUID]=[c52d91f1-e35f-4fa9-b0e8-0317aaa316f1]] for [filter Channel-Call-UUID c52d91f1-e35f-4fa9-b0e8-0317aaa316f1]
NEventSocket.Channels.Channel|Channel [c52d91f1-e35f-4fa9-b0e8-0317aaa316f1] subscriptions initialized
NEventSocket.OutboundSocket (1)|Sending [event plain CHANNEL_PROGRESS CHANNEL_BRIDGE CHANNEL_UNBRIDGE CHANNEL_ANSWER CHANNEL_HANGUP DTMF CHANNEL_EXECUTE_COMPLETE]
NEventSocket.OutboundSocket (1)|Messages Received [command/reply].
NEventSocket.OutboundSocket (1)|CommandReply received [+OK event listener enabled plain] for [event plain CHANNEL_PROGRESS CHANNEL_BRIDGE CHANNEL_UNBRIDGE CHANNEL_ANSWER CHANNEL_HANGUP DTMF CHANNEL_EXECUTE_COMPLETE]
NEventSocket.OutboundSocket (1)|Sending [sendmsg c52d91f1-e35f-4fa9-b0e8-0317aaa316f1
Event-UUID: d65206f3-096b-4bfa-bb17-74e645648ba7
call-command: execute
execute-app-name: answer
]
NEventSocket.OutboundSocket (1)|Messages Received [command/reply].
NEventSocket.OutboundSocket (1)|CommandReply received [+OK] for [sendmsg c52d91f1-e35f-4fa9-b0e8-0317aaa316f1
Event-UUID: d65206f3-096b-4bfa-bb17-74e645648ba7
call-command: execute
execute-app-name: answer
]
NEventSocket.OutboundSocket (1)|Messages Received [text/event-plain].
NEventSocket.Channels.Channel|Channel [c52d91f1-e35f-4fa9-b0e8-0317aaa316f1] Answered
NEventSocket.OutboundSocket (1)|Messages Received [text/event-plain].
NEventSocket.OutboundSocket (1)|c52d91f1-e35f-4fa9-b0e8-0317aaa316f1 ChannelExecuteComplete [Answered answer _none_]
NEventSocket.Channels.Channel|Channel c52d91f1-e35f-4fa9-b0e8-0317aaa316f1 is attempting a bridge to sofia/wan/102@***;fs_path=sip:x.x.x.x
NEventSocket.OutboundSocket (1)|Sending [api uuid_setvar_multi c52d91f1-e35f-4fa9-b0e8-0317aaa316f1 continue_on_fail='true';hangup_after_bridge='false';ignore_display_updates='true';]
NEventSocket.OutboundSocket (1)|Messages Received [api/response].
NEventSocket.OutboundSocket (1)|ApiResponse received [+OK] for [uuid_setvar_multi c52d91f1-e35f-4fa9-b0e8-0317aaa316f1 continue_on_fail='true';hangup_after_bridge='false';ignore_display_updates='true';]
NEventSocket.OutboundSocket (1)|Sending [sendmsg c52d91f1-e35f-4fa9-b0e8-0317aaa316f1
Event-UUID: fa838b16-e6dd-415f-a255-66f0d845b9fb
call-command: execute
execute-app-name: bridge
content-type: text/plain
content-length: 231

{ignore_early_media='true',leg_timeout='60',origination_caller_id_name='*FOO!*',origination_caller_id_number='',origination_uuid='228f7988-7f6d-4bbf-8326-ec635c611ec8'}sofia/wan/102@***;fs_path=sip:x.x.x.x
]
NEventSocket.OutboundSocket (1)|Messages Received [command/reply].
NEventSocket.OutboundSocket (1)|CommandReply received [+OK] for [sendmsg c52d91f1-e35f-4fa9-b0e8-0317aaa316f1
Event-UUID: fa838b16-e6dd-415f-a255-66f0d845b9fb
call-command: execute
execute-app-name: bridge
content-type: text/plain
content-length: 231

{ignore_early_media='true',leg_timeout='60',origination_caller_id_name='*FOO!*',origination_caller_id_number='',origination_uuid='228f7988-7f6d-4bbf-8326-ec635c611ec8'}sofia/wan/102@***;fs_path=sip:x.x.x.x
]
NEventSocket.OutboundSocket (1)|Messages Received [text/event-plain].
NEventSocket.OutboundSocket (1)|Messages Received [text/event-plain].
NEventSocket.OutboundSocket (1)|Messages Received [text/event-plain].
NEventSocket.Channels.Channel|Channel [c52d91f1-e35f-4fa9-b0e8-0317aaa316f1] Bridged to [228f7988-7f6d-4bbf-8326-ec635c611ec8] CHANNEL_BRIDGE
NEventSocket.OutboundSocket (1)|Sending [api uuid_dump 228f7988-7f6d-4bbf-8326-ec635c611ec8]
NEventSocket.OutboundSocket (1)|Bridge [c52d91f1-e35f-4fa9-b0e8-0317aaa316f1 - 228f7988-7f6d-4bbf-8326-ec635c611ec8] complete - 228f7988-7f6d-4bbf-8326-ec635c611ec8
NEventSocket.Channels.Channel|Channel c52d91f1-e35f-4fa9-b0e8-0317aaa316f1 bridge complete True SUCCESS
NEventSocket.OutboundSocket (1)|Messages Received [api/response].
NEventSocket.OutboundSocket (1)|ApiResponse received CHANNEL_DATA for [uuid_dump 228f7988-7f6d-4bbf-8326-ec635c611ec8]
NEventSocket.OutboundSocket (1)|Sending [filter Unique-ID 228f7988-7f6d-4bbf-8326-ec635c611ec8]
NEventSocket.OutboundSocket (1)|Messages Received [command/reply].
NEventSocket.OutboundSocket (1)|CommandReply received [+OK filter added. [Unique-ID]=[228f7988-7f6d-4bbf-8326-ec635c611ec8]] for [filter Unique-ID 228f7988-7f6d-4bbf-8326-ec635c611ec8]
NEventSocket.OutboundSocket (1)|Sending [filter Other-Leg-Unique-ID 228f7988-7f6d-4bbf-8326-ec635c611ec8]
NEventSocket.OutboundSocket (1)|Messages Received [command/reply].
NEventSocket.OutboundSocket (1)|CommandReply received [+OK filter added. [Other-Leg-Unique-ID]=[228f7988-7f6d-4bbf-8326-ec635c611ec8]] for [filter Other-Leg-Unique-ID 228f7988-7f6d-4bbf-8326-ec635c611ec8]
NEventSocket.OutboundSocket (1)|Sending [filter Channel-Call-UUID 228f7988-7f6d-4bbf-8326-ec635c611ec8]
NEventSocket.OutboundSocket (1)|Messages Received [command/reply].
NEventSocket.OutboundSocket (1)|CommandReply received [+OK filter added. [Channel-Call-UUID]=[228f7988-7f6d-4bbf-8326-ec635c611ec8]] for [filter Channel-Call-UUID 228f7988-7f6d-4bbf-8326-ec635c611ec8]
NEventSocket.OutboundSocket (1)|Messages Received [text/event-plain].
NEventSocket.Channels.BridgedChannel|Channel [228f7988-7f6d-4bbf-8326-ec635c611ec8] Hangup Detected [OriginatorCancel]
NEventSocket.OutboundSocket (1)|Messages Received [text/event-plain].
NEventSocket.Channels.Channel|Channel [c52d91f1-e35f-4fa9-b0e8-0317aaa316f1] Unbridged from [228f7988-7f6d-4bbf-8326-ec635c611ec8] ORIGINATOR_CANCEL
NEventSocket.OutboundSocket (1)|Messages Received [text/event-plain].
NEventSocket.OutboundSocket (1)|c52d91f1-e35f-4fa9-b0e8-0317aaa316f1 ChannelExecuteComplete [Answered bridge _none_]
NEventSocket.OutboundSocket (1)|Messages Received [text/event-plain].
NEventSocket.Channels.Channel|Channel [c52d91f1-e35f-4fa9-b0e8-0317aaa316f1] Hangup Detected [NormalClearing]
NEventSocket.OutboundSocket (1)|Messages Received [text/event-plain].
NEventSocket.OutboundSocket (1)|Messages Received [text/disconnect-notice].
NEventSocket.OutboundSocket|Channel c52d91f1-e35f-4fa9-b0e8-0317aaa316f1 Disconnect Notice  received.

The cause seems to be NormalClearing...

edit

Hmmm, just noticed the Hangup Detected [OriginatorCancel]...

danbarua commented 8 years ago

Aha.. Check timeouts? Try grabbing the latest unstable package off MyGet. There are N different variables for setting timeouts for each different situation! Still working them all out!

RobThree commented 8 years ago

Already running build 2.0.0-build00200.

It's the end of the workday here (actually, 2 hours past for normal people :stuck_out_tongue_winking_eye: ) but will get back with a decent testcase / repro as soon as possible.

RobThree commented 8 years ago

Code to repro (may not be the best code but should work?):

using NEventSocket;
using NEventSocket.FreeSwitch;
using System;
using System.Reactive.Linq;

namespace NEventSocketIssue37
{
    class Program
    {
        static void Main(string[] args)
        {
            var profile = "PROFILE-HERE";
            var user = "USER-HERE";  // I used 102 here
            var domain = "DOMAIN-HERE;
            var fspath = "FS-IP-HERE";

            var listener = new OutboundListener(8084);

            listener.Channels.Subscribe(async channel =>
            {

                var bridgeOptions = new BridgeOptions()
                {
                    UUID = Guid.NewGuid().ToString(),
                    IgnoreEarlyMedia = true,
                    ContinueOnFail = true,
                    HangupAfterBridge = false,
                    TimeoutSeconds = 60,
                };

                await channel.Answer();
                await channel.BridgeTo($"sofia/{profile}/{user}@{domain};fs_path=sip:{fspath}", bridgeOptions);

                Console.WriteLine($"Bridged: {channel.IsBridged}");

                await channel.Sleep(10000);

                await channel.Hangup(HangupCause.NormalClearing);
            });

            listener.Start();
            Console.ReadKey();
        }
    }
}

Start app:

19:59:31.9069 Listener Started on Port 8084

Pick up 101 and dial 102 (actually doesn't matter since we hard-coded the dest.)

19:59:35.7782 New Connection from x.x.x.x:46781
19:59:35.7883 EventSocket initialized
19:59:35.7883 Sending [connect]
19:59:35.8112 NEventSocket.OutboundSocket Worker Thread 1 started
19:59:35.8452 Messages Received [command/reply].
19:59:35.8523 CommandReply received [+OK] for [connect]
19:59:35.8523 Sending [linger]
19:59:35.8523 Messages Received [command/reply].
19:59:35.8523 CommandReply received [+OK will linger] for [linger]
19:59:35.8664 Sending [event plain CHANNEL_PROGRESS CHANNEL_BRIDGE CHANNEL_UNBRIDGE CHANNEL_ANSWER CHANNEL_HANGUP DTMF]
19:59:35.8664 Messages Received [command/reply].
19:59:35.8664 CommandReply received [+OK event listener enabled plain] for [event plain CHANNEL_PROGRESS CHANNEL_BRIDGE CHANNEL_UNBRIDGE CHANNEL_ANSWER CHANNEL_HANGUP DTMF]
19:59:35.8664 Sending [filter Unique-ID 4f3cf545-9a87-45ef-966b-3003474656ee]
19:59:35.8664 Messages Received [command/reply].
19:59:35.8664 CommandReply received [+OK filter added. [Unique-ID]=[4f3cf545-9a87-45ef-966b-3003474656ee]] for [filter Unique-ID 4f3cf545-9a87-45ef-966b-3003474656ee]
19:59:35.8664 Sending [filter Other-Leg-Unique-ID 4f3cf545-9a87-45ef-966b-3003474656ee]
19:59:35.8664 Messages Received [command/reply].
19:59:35.8664 CommandReply received [+OK filter added. [Other-Leg-Unique-ID]=[4f3cf545-9a87-45ef-966b-3003474656ee]] for [filter Other-Leg-Unique-ID 4f3cf545-9a87-45ef-966b-3003474656ee]
19:59:35.8664 Sending [filter Channel-Call-UUID 4f3cf545-9a87-45ef-966b-3003474656ee]
19:59:35.8664 Messages Received [command/reply].
19:59:35.8664 CommandReply received [+OK filter added. [Channel-Call-UUID]=[4f3cf545-9a87-45ef-966b-3003474656ee]] for [filter Channel-Call-UUID 4f3cf545-9a87-45ef-966b-3003474656ee]
19:59:35.8664 Channel [4f3cf545-9a87-45ef-966b-3003474656ee] subscriptions initialized
19:59:35.8664 Sending [event plain CHANNEL_PROGRESS CHANNEL_BRIDGE CHANNEL_UNBRIDGE CHANNEL_ANSWER CHANNEL_HANGUP DTMF CHANNEL_EXECUTE_COMPLETE]
19:59:35.8664 Messages Received [command/reply].
19:59:35.8664 CommandReply received [+OK event listener enabled plain] for [event plain CHANNEL_PROGRESS CHANNEL_BRIDGE CHANNEL_UNBRIDGE CHANNEL_ANSWER CHANNEL_HANGUP DTMF CHANNEL_EXECUTE_COMPLETE]
19:59:35.8664 Sending [sendmsg 4f3cf545-9a87-45ef-966b-3003474656ee
Event-UUID: 914f863f-c420-46c5-ba78-d2368338cd27
call-command: execute
execute-app-name: answer
]
19:59:35.8664 Messages Received [command/reply].
19:59:35.8664 CommandReply received [+OK] for [sendmsg 4f3cf545-9a87-45ef-966b-3003474656ee
Event-UUID: 914f863f-c420-46c5-ba78-d2368338cd27
call-command: execute
execute-app-name: answer
]
19:59:35.9174 Messages Received [text/event-plain].
19:59:35.9174 Channel [4f3cf545-9a87-45ef-966b-3003474656ee] Answered
19:59:35.9174 Messages Received [text/event-plain].
19:59:35.9174 4f3cf545-9a87-45ef-966b-3003474656ee ChannelExecuteComplete [Answered answer _none_]
19:59:35.9284 Channel 4f3cf545-9a87-45ef-966b-3003474656ee is attempting a bridge to sofia/xxx/102@xxx.xxx;fs_path=sip:x.x.x.x
19:59:35.9284 Sending [api uuid_setvar_multi 4f3cf545-9a87-45ef-966b-3003474656ee continue_on_fail='true';hangup_after_bridge='false';]
19:59:35.9284 Messages Received [api/response].
19:59:35.9284 ApiResponse received [+OK] for [uuid_setvar_multi 4f3cf545-9a87-45ef-966b-3003474656ee continue_on_fail='true';hangup_after_bridge='false';]
19:59:35.9284 Sending [sendmsg 4f3cf545-9a87-45ef-966b-3003474656ee
Event-UUID: 395e7fdc-a2c5-4230-a304-3fe17c422844
call-command: execute
execute-app-name: bridge
content-type: text/plain
content-length: 163

{origination_uuid='26ff3a28-73c3-4b8a-bac5-aa565d33b496',ignore_early_media='true',leg_timeout='60'}sofia/xxx/102@xxx.xxx;fs_path=sip:x.x.x.x
]
19:59:35.9284 Messages Received [command/reply].
19:59:35.9284 CommandReply received [+OK] for [sendmsg 4f3cf545-9a87-45ef-966b-3003474656ee
Event-UUID: 395e7fdc-a2c5-4230-a304-3fe17c422844
call-command: execute
execute-app-name: bridge
content-type: text/plain
content-length: 163

{origination_uuid='26ff3a28-73c3-4b8a-bac5-aa565d33b496',ignore_early_media='true',leg_timeout='60'}sofia/xxx/102@xxx.xxx;fs_path=sip:x.x.x.x
]
19:59:36.0025 Messages Received [text/event-plain].

Pick up 102:

19:59:39.3192 Messages Received [text/event-plain].
19:59:39.3387 Messages Received [text/event-plain].
19:59:39.3387 Channel [4f3cf545-9a87-45ef-966b-3003474656ee] Bridged to [26ff3a28-73c3-4b8a-bac5-aa565d33b496] CHANNEL_BRIDGE
19:59:39.3387 Sending [api uuid_dump 26ff3a28-73c3-4b8a-bac5-aa565d33b496]
19:59:39.3387 Bridge [4f3cf545-9a87-45ef-966b-3003474656ee - 26ff3a28-73c3-4b8a-bac5-aa565d33b496] complete - 26ff3a28-73c3-4b8a-bac5-aa565d33b496
19:59:39.3387 Channel 4f3cf545-9a87-45ef-966b-3003474656ee bridge complete True SUCCESS
19:59:39.3387 Messages Received [api/response].
19:59:39.3387 ApiResponse received CHANNEL_DATA for [uuid_dump 26ff3a28-73c3-4b8a-bac5-aa565d33b496]
19:59:39.3387 Sending [sendmsg 4f3cf545-9a87-45ef-966b-3003474656ee
Event-UUID: 904517ee-429c-463c-a65e-644dc9de253a
call-command: execute
execute-app-name: sleep
content-type: text/plain
content-length: 5

10000
]
19:59:39.3387 Messages Received [command/reply].
19:59:39.3387 CommandReply received [+OK] for [sendmsg 4f3cf545-9a87-45ef-966b-3003474656ee
Event-UUID: 904517ee-429c-463c-a65e-644dc9de253a
call-command: execute
execute-app-name: sleep
content-type: text/plain
content-length: 5

10000
]
19:59:39.3387 Sending [filter Unique-ID 26ff3a28-73c3-4b8a-bac5-aa565d33b496]
19:59:39.3387 Messages Received [command/reply].
19:59:39.3387 CommandReply received [+OK filter added. [Unique-ID]=[26ff3a28-73c3-4b8a-bac5-aa565d33b496]] for [filter Unique-ID 26ff3a28-73c3-4b8a-bac5-aa565d33b496]
19:59:39.3387 Sending [filter Other-Leg-Unique-ID 26ff3a28-73c3-4b8a-bac5-aa565d33b496]
19:59:39.3507 Messages Received [command/reply].
19:59:39.3507 CommandReply received [+OK filter added. [Other-Leg-Unique-ID]=[26ff3a28-73c3-4b8a-bac5-aa565d33b496]] for [filter Other-Leg-Unique-ID 26ff3a28-73c3-4b8a-bac5-aa565d33b496]
19:59:39.3507 Sending [filter Channel-Call-UUID 26ff3a28-73c3-4b8a-bac5-aa565d33b496]
19:59:39.3507 Messages Received [command/reply].
19:59:39.3507 CommandReply received [+OK filter added. [Channel-Call-UUID]=[26ff3a28-73c3-4b8a-bac5-aa565d33b496]] for [filter Channel-Call-UUID 26ff3a28-73c3-4b8a-bac5-aa565d33b496]
19:59:39.3727 Messages Received [text/event-plain].
19:59:39.3727 Channel [26ff3a28-73c3-4b8a-bac5-aa565d33b496] Hangup Detected [OriginatorCancel]
19:59:39.3927 Messages Received [text/event-plain].
19:59:39.3927 Channel [4f3cf545-9a87-45ef-966b-3003474656ee] Unbridged from [26ff3a28-73c3-4b8a-bac5-aa565d33b496] ORIGINATOR_CANCEL
19:59:39.3927 Messages Received [text/event-plain].
19:59:39.3967 4f3cf545-9a87-45ef-966b-3003474656ee ChannelExecuteComplete [Answered bridge _none_]
danbarua commented 8 years ago

I would turn up debug level logging on FreeSwitch and investigate that. Also I find sngrep invaluable for troubleshooting.

I suspect it's something funky to do with your topology.

danbarua commented 8 years ago

I've got a similar issue with codec negotiation - definitely check sngrep for your SIP tracing.

RobThree commented 8 years ago

I haven't been working on it for a bit; will get back to you soon :+1:

danbarua commented 8 years ago

@RobThree sounds like a FreeSwitch config/environment issue - ping me and get me in Gitter when you get round to re-visiting this