[Freeswitch-users] FreeSwitch and Exchange 2007

Sun Jun 21 14:23:45 PDT 2009

The Windows Application Log shows this, however:

1331177817

1

APPCRASH

Not available

0

FreeSwitch.exe

0.0.0.0

4a316e86

MSVCR90.dll

9.0.30729.4918

49d43da7

c0000005

0003b590

From: freeswitch-users-bounces at lists.freeswitch.org [mailto:freeswitch-users-bounces at lists.freeswitch.org] On Behalf Of Michael Jerris
Sent: Sunday, June 21, 2009 4:31 PM
To: freeswitch-users at lists.freeswitch.org
Subject: Re: [Freeswitch-users] FreeSwitch and Exchange 2007

If this is still the case with current svn trunk, please get a backtrace and post it to http://jira.freeswitch.org

On Jun 21, 2009, at 3:51 PM, "Drago Totev" <drago at windstream.net> wrote:

After days of running around clueless, I have no other option but to ask the community for help one last time…

Here is what happens:

1.       FS sends INVITE

2.       Exchange answers with “302 Moved Temporarily”

3.       FS bombs and closes

    Request-Line: INVITE sip:4783874764 at 10.0.0.71;transport=tcp SIP/2.0

    Message Header

        Via: SIP/2.0/TCP 10.8.4.3;branch=z9hG4bKQcm1vS26UU3KF

        Max-Forwards: 68

        From: "MILLEDGEVL   GA" <sip:4782512197 at 10.8.4.3>;tag=Qr4j0XX18XD1m

            SIP Display info: "MILLEDGEVL   GA" 

            SIP from address: sip:4782512197 at 10.8.4.3

            SIP tag: Qr4j0XX18XD1m

        To: <sip:4783874764 at 10.0.0.71>

            SIP to address: sip:4783874764 at 10.0.0.71

        Call-ID: 4cdf31d7-d93e-122c-9f93-11adca034915

        CSeq: 116688296 INVITE

        Contact: <sip:gw+um.gmc.cc.ga.us at 10.8.4.3:5060;transport=tcp>

            Contact Binding: <sip:gw+um.gmc.cc.ga.us at 10.8.4.3:5060;transport=tcp>

        User-Agent: FreeSWITCH-mod_sofia/1.0.trunk-13754M

        Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO, PUBLISH

        Supported: timer, precondition, path, replaces

        Allow-Events: talk, presence, dialog, call-info, sla, include-session-description, presence.winfo, message-summary, refer

        Privacy: none

        Content-Type: application/sdp

        Content-Disposition: session

        Content-Length: 236

        P-Asserted-Identity: "MILLEDGEVL   GA" <sip:4782512197 at 10.8.4.3>

    Message Body

    Status-Line: SIP/2.0 100 Trying

    Message Header

        FROM: "MILLEDGEVL   GA"<sip:4782512197 at 10.8.4.3>;tag=Qr4j0XX18XD1m

            SIP Display info: "MILLEDGEVL   GA"

            SIP from address: sip:4782512197 at 10.8.4.3

            SIP tag: Qr4j0XX18XD1m

        TO: <sip:4783874764 at 10.0.0.71>

            SIP to address: sip:4783874764 at 10.0.0.71

        CSEQ: 116688296 INVITE

        CALL-ID: 4cdf31d7-d93e-122c-9f93-11adca034915

        VIA: SIP/2.0/TCP 10.8.4.3;branch=z9hG4bKQcm1vS26UU3KF

        CONTENT-LENGTH: 0

    Status-Line: SIP/2.0 302 Moved Temporarily

    Message Header

        FROM: "MILLEDGEVL   GA"<sip:4782512197 at 10.8.4.3>;tag=Qr4j0XX18XD1m

            SIP Display info: "MILLEDGEVL   GA"

            SIP from address: sip:4782512197 at 10.8.4.3

            SIP tag: Qr4j0XX18XD1m

        TO: <sip:4783874764 at 10.0.0.71>;tag=27df6afe0

            SIP to address: sip:4783874764 at 10.0.0.71

            SIP tag: 27df6afe0

        CSEQ: 116688296 INVITE

        CALL-ID: 4cdf31d7-d93e-122c-9f93-11adca034915

        VIA: SIP/2.0/TCP 10.8.4.3;branch=z9hG4bKQcm1vS26UU3KF

        CONTACT: <sip:4783874764 at 10.0.0.71:5065;transport=tcp>

            Contact Binding: <sip:4783874764 at 10.0.0.71:5065;transport=tcp>

        CONTENT-LENGTH: 0

        SERVER: RTCC/3.0.0.0

    Request-Line: ACK sip:4783874764 at 10.0.0.71;transport=tcp SIP/2.0

    Message Header

        Via: SIP/2.0/TCP 10.8.4.3;branch=z9hG4bKQcm1vS26UU3KF

        Max-Forwards: 68

        From: "MILLEDGEVL   GA" <sip:4782512197 at 10.8.4.3>;tag=Qr4j0XX18XD1m

            SIP Display info: "MILLEDGEVL   GA" 

            SIP from address: sip:4782512197 at 10.8.4.3

            SIP tag: Qr4j0XX18XD1m

        To: <sip:4783874764 at 10.0.0.71>;tag=27df6afe0

            SIP to address: sip:4783874764 at 10.0.0.71

            SIP tag: 27df6afe0

        Call-ID: 4cdf31d7-d93e-122c-9f93-11adca034915

        CSeq: 116688296 ACK

        Content-Length: 0

Here is the FS log beginning the the processing of the call:

2009-06-21 15:49:18.636018 [NOTICE] switch_channel.c:602 New Channel sofia/external/4782512197 at 209.249.3.59 [637f8a72-8034-254f-9937-b321c0d87414]

2009-06-21 15:49:18.636018 [DEBUG] sofia.c:3210 Channel sofia/external/4782512197 at 209.249.3.59 entering state [received][100]

2009-06-21 15:49:18.636018 [DEBUG] sofia.c:3217 Remote SDP:

v=0

o=NXT02 19785 8060 IN IP4 209.249.3.59

s=sip call

c=IN IP4 209.249.3.60

t=0 0

m=audio 36292 RTP/AVP 0 18 101

a=rtpmap:0 PCMU/8000

a=rtpmap:18 G729/8000

a=fmtp:18 annexb=no

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-15

2009-06-21 15:49:18.636018 [DEBUG] sofia_glue.c:3079 Audio Codec Compare [PCMU:0:8000:0]/[PCMU:0:8000:20]

2009-06-21 15:49:18.637018 [DEBUG] sofia_glue.c:2037 Set Codec sofia/external/4782512197 at 209.249.3.59 PCMU/8000 20 ms 160 samples

2009-06-21 15:49:18.637018 [DEBUG] sofia_glue.c:3039 Set 2833 dtmf payload to 101

2009-06-21 15:49:18.637018 [DEBUG] switch_core_state_machine.c:397 (sofia/external/4782512197 at 209.249.3.59) Running State Change CS_NEW

2009-06-21 15:49:18.637018 [DEBUG] switch_core_state_machine.c:403 (sofia/external/4782512197 at 209.249.3.59) State NEW

2009-06-21 15:49:18.637018 [DEBUG] sofia.c:3376 (sofia/external/4782512197 at 209.249.3.59) State Change CS_NEW -> CS_INIT

2009-06-21 15:49:18.637018 [DEBUG] switch_core_session.c:933 Send signal sofia/external/4782512197 at 209.249.3.59 [BREAK]

2009-06-21 15:49:18.647018 [DEBUG] switch_core_state_machine.c:397 (sofia/external/4782512197 at 209.249.3.59) Running State Change CS_INIT

2009-06-21 15:49:18.647018 [DEBUG] switch_core_state_machine.c:480 (sofia/external/4782512197 at 209.249.3.59) State INIT

2009-06-21 15:49:18.647018 [DEBUG] mod_sofia.c:83 sofia/external/4782512197 at 209.249.3.59 SOFIA INIT

2009-06-21 15:49:18.647018 [DEBUG] mod_sofia.c:111 (sofia/external/4782512197 at 209.249.3.59) State Change CS_INIT -> CS_ROUTING

2009-06-21 15:49:18.647018 [DEBUG] switch_core_session.c:933 Send signal sofia/external/4782512197 at 209.249.3.59 [BREAK]

2009-06-21 15:49:18.647018 [DEBUG] switch_core_state_machine.c:480 (sofia/external/4782512197 at 209.249.3.59) State INIT going to sleep

2009-06-21 15:49:18.647018 [DEBUG] switch_core_state_machine.c:397 (sofia/external/4782512197 at 209.249.3.59) Running State Change CS_ROUTING

2009-06-21 15:49:18.647018 [DEBUG] switch_core_state_machine.c:483 (sofia/external/4782512197 at 209.249.3.59) State ROUTING

2009-06-21 15:49:18.647018 [DEBUG] mod_sofia.c:130 sofia/external/4782512197 at 209.249.3.59 SOFIA ROUTING

2009-06-21 15:49:18.647018 [DEBUG] switch_core_state_machine.c:78 sofia/external/4782512197 at 209.249.3.59 Standard ROUTING

2009-06-21 15:49:18.647018 [INFO] mod_dialplan_xml.c:252 Processing MILLEDGEVL   GA->4783874190 in context public

Dialplan: sofia/external/4782512197 at 209.249.3.59 parsing [public->unloop] continue=false

Dialplan: sofia/external/4782512197 at 209.249.3.59 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false

Dialplan: sofia/external/4782512197 at 209.249.3.59 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false

Dialplan: sofia/external/4782512197 at 209.249.3.59 parsing [public->outside_call] continue=true

Dialplan: sofia/external/4782512197 at 209.249.3.59 Absolute Condition [outside_call]

Dialplan: sofia/external/4782512197 at 209.249.3.59 Action set(outside_call=true)

Dialplan: sofia/external/4782512197 at 209.249.3.59 parsing [public->call_debug] continue=true

Dialplan: sofia/external/4782512197 at 209.249.3.59 Regex (PASS) [call_debug] ${call_debug}(true) =~ /^true$/ break=never

Dialplan: sofia/external/4782512197 at 209.249.3.59 Action info()

Dialplan: sofia/external/4782512197 at 209.249.3.59 parsing [public->public_extensions] continue=false

Dialplan: sofia/external/4782512197 at 209.249.3.59 Regex (FAIL) [public_extensions] destination_number(4783874190) =~ /^(10[01][0-9])$/ break=on-false

Dialplan: sofia/external/4782512197 at 209.249.3.59 parsing [public->Local_UM] continue=false

Dialplan: sofia/external/4782512197 at 209.249.3.59 Regex (PASS) [Local_UM] ${sip_to_user}(4783874764) =~ /^(4783874764)$/ break=on-false

Dialplan: sofia/external/4782512197 at 209.249.3.59 Action bridge({absolute_codec_string=PCMA}sofia/gateway/um.gmc.cc.ga.us/4783874764)

2009-06-21 15:49:18.647018 [DEBUG] switch_core_state_machine.c:114 (sofia/external/4782512197 at 209.249.3.59) State Change CS_ROUTING -> CS_EXECUTE

2009-06-21 15:49:18.647018 [DEBUG] switch_core_session.c:933 Send signal sofia/external/4782512197 at 209.249.3.59 [BREAK]

2009-06-21 15:49:18.647018 [DEBUG] switch_core_state_machine.c:483 (sofia/external/4782512197 at 209.249.3.59) State ROUTING going to sleep

2009-06-21 15:49:18.647018 [DEBUG] switch_core_state_machine.c:397 (sofia/external/4782512197 at 209.249.3.59) Running State Change CS_EXECUTE

2009-06-21 15:49:18.647018 [DEBUG] switch_core_state_machine.c:490 (sofia/external/4782512197 at 209.249.3.59) State EXECUTE

2009-06-21 15:49:18.647018 [DEBUG] mod_sofia.c:173 sofia/external/4782512197 at 209.249.3.59 SOFIA EXECUTE

2009-06-21 15:49:18.647018 [DEBUG] switch_core_state_machine.c:151 sofia/external/4782512197 at 209.249.3.59 Standard EXECUTE

EXECUTE sofia/external/4782512197 at 209.249.3.59 set(outside_call=true)

2009-06-21 15:49:18.647018 [DEBUG] mod_dptools.c:748 sofia/external/4782512197 at 209.249.3.59 SET [outside_call]=[true]

EXECUTE sofia/external/4782512197 at 209.249.3.59 info()

2009-06-21 15:49:18.648018 [INFO] mod_dptools.c:946 CHANNEL_DATA:

Channel-State: [CS_EXECUTE]

Channel-State-Number: [4]

Channel-Name: [sofia/external/4782512197 at 209.249.3.59]

Unique-ID: [637f8a72-8034-254f-9937-b321c0d87414]

Call-Direction: [inbound]

Presence-Call-Direction: [inbound]

Answer-State: [ringing]

Channel-Read-Codec-Name: [PCMU]

Channel-Read-Codec-Rate: [8000]

Channel-Write-Codec-Name: [PCMU]

Channel-Write-Codec-Rate: [8000]

Caller-Username: [4782512197]

Caller-Dialplan: [XML]

Caller-Caller-ID-Name: [MILLEDGEVL   GA]

Caller-Caller-ID-Number: [4782512197]

Caller-Network-Addr: [209.249.3.59]

Caller-Destination-Number: [4783874190]

Caller-Unique-ID: [637f8a72-8034-254f-9937-b321c0d87414]

Caller-Source: [mod_sofia]

Caller-Context: [public]

Caller-Channel-Name: [sofia/external/4782512197 at 209.249.3.59]

Caller-Profile-Index: [1]

Caller-Profile-Created-Time: [1245613758636018]

Caller-Channel-Created-Time: [1245613758636018]

Caller-Channel-Answered-Time: [0]

Caller-Channel-Progress-Time: [0]

Caller-Channel-Progress-Media-Time: [0]

Caller-Channel-Hangup-Time: [0]

Caller-Channel-Transfer-Time: [0]

Caller-Screen-Bit: [true]

Caller-Privacy-Hide-Name: [false]

Caller-Privacy-Hide-Number: [false]

variable_sip_received_ip: [209.249.3.59]

variable_sip_received_port: [5060]

variable_sip_via_protocol: [udp]

variable_sip_from_user: [4782512197]

variable_sip_from_uri: [4782512197 at 209.249.3.59]

variable_sip_from_host: [209.249.3.59]

variable_sip_from_user_stripped: [4782512197]

variable_sip_from_tag: [3454602382-411732]

variable_sofia_profile_name: [external]

variable_sip_cid_type: [pid]

variable_sip_req_user: [gw+Broadvox]

variable_sip_req_port: [5080]

variable_sip_req_uri: [gw+Broadvox at 71.29.0.61:5080]

variable_sip_req_host: [71.29.0.61]

variable_sip_to_user: [4783874764]

variable_sip_to_port: [5060]

variable_sip_to_uri: [4783874764 at 209.249.3.56:5060]

variable_sip_to_host: [209.249.3.56]

variable_sip_contact_user: [4782512197]

variable_sip_contact_port: [5060]

variable_sip_contact_uri: [4782512197 at 209.249.3.59:5060]

variable_sip_contact_host: [209.249.3.59]

variable_channel_name: [sofia/external/4782512197 at 209.249.3.59]

variable_sip_call_id: [6891536-3454602382-411724 at NXT02.broadvox.net]

variable_sip_via_host: [209.249.3.59]

variable_sip_via_port: [5060]

variable_max_forwards: [69]

variable_sip_call_info: [<sip:209.249.3.59>;method="NOTIFY;Event=telephone-event;Duration=1000"]

variable_sip_gateway: [Broadvox]

variable_switch_r_sdp: [v=0

o=NXT02 19785 8060 IN IP4 209.249.3.59

s=sip call

c=IN IP4 209.249.3.60

t=0 0

m=audio 36292 RTP/AVP 0 18 101

a=rtpmap:0 PCMU/8000

a=rtpmap:18 G729/8000

a=fmtp:18 annexb=no

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-15

]

variable_remote_media_ip: [209.249.3.60]

variable_remote_media_port: [36292]

variable_read_codec: [PCMU]

variable_read_rate: [8000]

variable_write_codec: [PCMU]

variable_write_rate: [8000]

variable_endpoint_disposition: [RECEIVED]

variable_outside_call: [true]

variable_current_application: [info]

EXECUTE sofia/external/4782512197 at 209.249.3.59 bridge({absolute_codec_string=PCMA}sofia/gateway/um.gmc.cc.ga.us/4783874764)

2009-06-21 15:49:18.648018 [DEBUG] switch_ivr_originate.c:1017 variable string 0 = [absolute_codec_string=PCMA]

2009-06-21 15:49:18.648018 [NOTICE] switch_channel.c:602 New Channel sofia/internal/4783874764 [34ad0b66-9324-604e-931a-d0e6468ce858]

2009-06-21 15:49:18.648018 [DEBUG] mod_sofia.c:2737 (sofia/internal/4783874764) State Change CS_NEW -> CS_INIT

2009-06-21 15:49:18.648018 [DEBUG] switch_core_session.c:933 Send signal sofia/internal/4783874764 [BREAK]

2009-06-21 15:49:18.650018 [DEBUG] switch_core_state_machine.c:397 (sofia/internal/4783874764) Running State Change CS_INIT

2009-06-21 15:49:18.650018 [DEBUG] switch_core_state_machine.c:480 (sofia/internal/4783874764) State INIT

2009-06-21 15:49:18.650018 [DEBUG] mod_sofia.c:83 sofia/internal/4783874764 SOFIA INIT

2009-06-21 15:49:18.650018 [DEBUG] mod_sofia.c:111 (sofia/internal/4783874764) State Change CS_INIT -> CS_ROUTING

2009-06-21 15:49:18.650018 [DEBUG] switch_core_session.c:933 Send signal sofia/internal/4783874764 [BREAK]

2009-06-21 15:49:18.650018 [DEBUG] switch_core_state_machine.c:480 (sofia/internal/4783874764) State INIT going to sleep

2009-06-21 15:49:18.650018 [DEBUG] switch_core_state_machine.c:397 (sofia/internal/4783874764) Running State Change CS_ROUTING

2009-06-21 15:49:18.650018 [DEBUG] switch_core_state_machine.c:483 (sofia/internal/4783874764) State ROUTING

2009-06-21 15:49:18.650018 [DEBUG] mod_sofia.c:130 sofia/internal/4783874764 SOFIA ROUTING

2009-06-21 15:49:18.650018 [DEBUG] switch_ivr_originate.c:63 (sofia/internal/4783874764) State Change CS_ROUTING -> CS_CONSUME_MEDIA

2009-06-21 15:49:18.650018 [DEBUG] switch_core_session.c:933 Send signal sofia/internal/4783874764 [BREAK]

2009-06-21 15:49:18.650018 [DEBUG] switch_core_state_machine.c:483 (sofia/internal/4783874764) State ROUTING going to sleep

2009-06-21 15:49:18.650018 [DEBUG] switch_core_state_machine.c:397 (sofia/internal/4783874764) Running State Change CS_CONSUME_MEDIA

2009-06-21 15:49:18.650018 [DEBUG] switch_core_state_machine.c:502 (sofia/internal/4783874764) State CONSUME_MEDIA

2009-06-21 15:49:18.651018 [DEBUG] sofia.c:3210 Channel sofia/internal/4783874764 entering state [calling][0]

Will trade my first born for little help J

Drago

From: freeswitch-users-bounces at lists.freeswitch.org [mailto:freeswitch-users-bounces at lists.freeswitch.org] On Behalf Of Drago Totev
Sent: Sunday, June 14, 2009 7:11 PM
To: freeswitch-users at lists.freeswitch.org
Subject: [Freeswitch-users] FreeSwitch and Exchange 2007

Hello everyone,

I am trying to set a test environment with FS and Exchange 2007.

Followed the instructions listed here: http://wiki.freeswitch.org/wiki/Exchange_2007_UM and it does not seem to work. Thus far I use the default settings, one ATA registered and confirmed to work.

According external source:

“MS Exchange does not understand 'From' fields with domain name in the address (example: field containing <sip:100 at 3CXPhoneSystem> address).The ‘From’ field’s address to be in the format ‘<sip:DN at IP:Port>’; otherwise, MS Exchange drops the call.”

I don’t know if this is the only problem… However, I see exactly this behavior:

“PBX initiates call to MS Exchange by sending a SIP INVITE message to the 5060 port of MS Exchange. MS Exchange sends 302 (Moved Temporarily) response to PBX asking to repeat INVITE to a different port (5065 for example). After PBX repeats the INVITE sending, the call is established.”

After “302 (Moved Temporarily”, FreeSwitch bombs and closes without any record in the log.

Can someone help with working configuration, please? Exchange 2007 UM role Version: 08.01.0359.002

Thanks in advance.

Drago

_______________________________________________
Freeswitch-users mailing list
Freeswitch-users at lists.freeswitch.org
http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
http://www.freeswitch.org

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20090621/ea5968f1/attachment-0002.html 