search

alongubkin / phonertc

WebRTC for Cordova apps - No longer active
http://phonertc.io
Apache License 2.0
867 stars 305 forks source link

iOS Error: "ICE Connection failed!" Assertion Error when connecting to FreeSWITCH #28

Closed lylepratt closed 10 years ago

lylepratt commented 10 years ago

Was just doing some testing to try to get SIP.js Web talking to iOS running SIP.js over PhoneRTC. The call sets up fine, but I never get any Audio and after a few more seconds, PhoneRTC crashes on iOS with this error:

Related tickets: alongubkin/phonertc#27 joseph-onsip/sipjs-cordova#2 Related contributors: @joseph-onsip @egreenmachine @alongubkin

iOS Crash Logs

2014-07-02 14:34:53.318 HelloCordova[163:1f13] PCO onIceConnectionChange. 4
2014-07-02 14:34:53.319 HelloCordova[163:1f13] *** Assertion failure in -[PCObserver peerConnection:iceConnectionChanged:], /Users/lyle/Desktop/Ubuntu/sipjs-cordova/platforms/ios/HelloCordova/Plugins/com.dooble.phonertc/PhoneRTCDelegate.m:321
2014-07-02 14:34:53.322 HelloCordova[163:1f13] *** Terminating app due to uncaught exception 'NSInternalInconsistencyException', reason: 'ICE Connection failed!'
*** First throw call stack:
(0x2f8cbfd3 0x3a142ccf 0x2f8cbead 0x30278d5b 0xfdf2b 0x501207 0x458d07 0x458d45 0x4d0f63 0x4d1275 0x3635a3 0x38c799 0x38b529 0x21a177 0x25564d 0x255577 0x25546f 0x3a76e919 0x3a76e88b 0x3a76caa4)
libc++abi.dylib: terminating with uncaught exception of type NSException

Code Assertion Block:

- (void)peerConnection:(RTCPeerConnection *)peerConnection
  iceConnectionChanged:(RTCICEConnectionState)newState {
    NSLog(@"PCO onIceConnectionChange. %d", newState);
    NSAssert(newState != RTCICEConnectionFailed, @"ICE Connection failed!");
}

FreeSWITCH Logs

2014-07-02 19:32:15.954490 [NOTICE] switch_channel.c:1053 New Channel sofia/internal/lylepratt-1111@redacted.com [92e4cac0-021f-11e4-9f63-079e26694766]
2014-07-02 19:32:16.954476 [INFO] mod_dialplan_xml.c:558 Processing Lyle Pratt <lylepratt-1111>->user-lylepratt-1234 in context public
2014-07-02 19:32:16.954476 [NOTICE] switch_channel.c:1053 New Channel sofia/internal/sip:j4jk0pi6@67.78.97.126:54476 [937cb4b6-021f-11e4-9f6c-079e26694766]
2014-07-02 19:32:17.074486 [NOTICE] sofia.c:6253 Ring-Ready sofia/internal/sip:j4jk0pi6@67.78.97.126:54476!
2014-07-02 19:32:17.074486 [NOTICE] mod_sofia.c:2029 Ring-Ready sofia/internal/lylepratt-1111@redacted.com!
2014-07-02 19:32:17.074486 [NOTICE] switch_ivr_originate.c:527 Ring Ready sofia/internal/lylepratt-1111@redacted.com!
2014-07-02 19:32:39.314494 [WARNING] switch_core_media.c:2548 NO candidate ACL defined, Defaulting to wan.auto
2014-07-02 19:32:39.314494 [NOTICE] switch_core_media.c:2586 Save audio Candidate cid: 1 proto: udp type: host addr: 192.168.34.228:62396
2014-07-02 19:32:39.314494 [NOTICE] switch_core_media.c:2586 Save audio Candidate cid: 1 proto: udp type: host addr: 192.168.56.1:54842
2014-07-02 19:32:39.314494 [NOTICE] switch_core_media.c:2581 Choose audio Candidate cid: 1 proto: udp type: srflx addr: 67.78.97.126:62396
2014-07-02 19:32:39.314494 [NOTICE] switch_core_media.c:2675 No audio RTCP candidate found; defaulting to the same as RTP [67.78.97.126:62396]
2014-07-02 19:32:39.314494 [NOTICE] switch_core_media.c:2710 setting remote audio ice addr to 67.78.97.126:62396 based on candidate
2014-07-02 19:32:39.314494 [NOTICE] switch_core_media.c:2730 setting remote rtcp audio addr to 67.78.97.126:62396 based on candidate
2014-07-02 19:32:39.314494 [INFO] switch_core_media.c:5017 Activating Audio ICE
2014-07-02 19:32:39.314494 [NOTICE] switch_rtp.c:3775 Activating RTP audio ICE: L3qAO3T4nrydOMWu:l5JcLPs7U5aWH4oi 67.78.97.126:62396
2014-07-02 19:32:39.334493 [INFO] switch_core_media.c:5060 Activating RTCP PORT 62396
2014-07-02 19:32:39.334493 [INFO] switch_core_media.c:5068 Skipping RTCP ICE (Same as RTP)
2014-07-02 19:32:39.334493 [INFO] switch_rtp.c:2878 Activate RTP/RTCP audio DTLS server
2014-07-02 19:32:39.334493 [NOTICE] sofia.c:6988 Channel [sofia/internal/sip:j4jk0pi6@67.78.97.126:54476] has been answered
2014-07-02 19:32:39.334493 [INFO] switch_core_media.c:5060 Activating RTCP PORT 1
2014-07-02 19:32:39.334493 [INFO] switch_rtp.c:2878 Activate RTP/RTCP audio DTLS client
2014-07-02 19:32:39.334493 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/lylepratt-1111@redacted.com!
2014-07-02 19:32:39.334493 [NOTICE] switch_ivr_originate.c:3493 Channel [sofia/internal/lylepratt-1111@redacted.com] has been answered
2014-07-02 19:32:39.554524 [INFO] switch_rtp.c:2701 Changing audio DTLS state from HANDSHAKE to SETUP
2014-07-02 19:32:39.554524 [INFO] switch_rtp.c:2609 audio Fingerprint Verified.
2014-07-02 19:32:39.554524 [INFO] switch_rtp.c:3151 Activating Audio Secure RTP SEND
2014-07-02 19:32:39.554524 [INFO] switch_rtp.c:3129 Activating Audio Secure RTP RECV
2014-07-02 19:32:39.554524 [INFO] switch_rtp.c:2649 Changing audio DTLS state from SETUP to READY
2014-07-02 19:33:32.374477 [NOTICE] sofia.c:927 Hangup sofia/internal/sip:j4jk0pi6@67.78.97.126:54476 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2014-07-02 19:33:32.394536 [NOTICE] switch_core_session.c:1611 Session 6 (sofia/internal/sip:j4jk0pi6@67.78.97.126:54476) Ended
2014-07-02 19:33:32.394536 [NOTICE] switch_core_session.c:1615 Close Channel sofia/internal/sip:j4jk0pi6@67.78.97.126:54476 [CS_DESTROY]
2014-07-02 19:33:32.394536 [NOTICE] switch_core_state_machine.c:313 sofia/internal/lylepratt-1111@redacted.com has executed the last dialplan instruction, hanging up.
2014-07-02 19:33:32.394536 [NOTICE] switch_core_state_machine.c:315 Hangup sofia/internal/lylepratt-1111@redacted.com [CS_EXECUTE] [NORMAL_CLEARING]
2014-07-02 19:33:32.394536 [NOTICE] switch_core_session.c:1611 Session 5 (sofia/internal/lylepratt-1111@redacted.com) Ended
2014-07-02 19:33:32.394536 [NOTICE] switch_core_session.c:1615 Close Channel sofia/internal/lylepratt-1111@redacted.com [CS_DESTROY]
2014-07-02 19:34:22.714489 [NOTICE] switch_channel.c:1053 New Channel sofia/internal/lylepratt-1111@redacted.com [de72bb3c-021f-11e4-9f81-079e26694766]
2014-07-02 19:34:23.694477 [INFO] mod_dialplan_xml.c:558 Processing Lyle Pratt <lylepratt-1111>->user-lylepratt-1234 in context public
2014-07-02 19:34:23.694477 [NOTICE] switch_channel.c:1053 New Channel sofia/internal/sip:j4jk0pi6@67.78.97.126:54476 [df090678-021f-11e4-9f8a-079e26694766]
2014-07-02 19:34:23.794486 [NOTICE] sofia.c:6253 Ring-Ready sofia/internal/sip:j4jk0pi6@67.78.97.126:54476!
2014-07-02 19:34:23.794486 [NOTICE] mod_sofia.c:2029 Ring-Ready sofia/internal/lylepratt-1111@redacted.com!
2014-07-02 19:34:23.794486 [NOTICE] switch_ivr_originate.c:527 Ring Ready sofia/internal/lylepratt-1111@redacted.com!
2014-07-02 19:34:36.474741 [WARNING] switch_core_media.c:2548 NO candidate ACL defined, Defaulting to wan.auto
2014-07-02 19:34:36.474741 [NOTICE] switch_core_media.c:2586 Save audio Candidate cid: 1 proto: udp type: host addr: 192.168.34.228:52253
2014-07-02 19:34:36.474741 [NOTICE] switch_core_media.c:2586 Save audio Candidate cid: 1 proto: udp type: host addr: 192.168.56.1:64386
2014-07-02 19:34:36.474741 [NOTICE] switch_core_media.c:2581 Choose audio Candidate cid: 1 proto: udp type: srflx addr: 67.78.97.126:52253
2014-07-02 19:34:36.474741 [NOTICE] switch_core_media.c:2675 No audio RTCP candidate found; defaulting to the same as RTP [67.78.97.126:52253]
2014-07-02 19:34:36.474741 [NOTICE] switch_core_media.c:2710 setting remote audio ice addr to 67.78.97.126:52253 based on candidate
2014-07-02 19:34:36.474741 [NOTICE] switch_core_media.c:2730 setting remote rtcp audio addr to 67.78.97.126:52253 based on candidate
2014-07-02 19:34:36.474741 [INFO] switch_core_media.c:5017 Activating Audio ICE
2014-07-02 19:34:36.474741 [NOTICE] switch_rtp.c:3775 Activating RTP audio ICE: om0pqb9pCUsWEk5d:HuVXP4GOXs8ycjwA 67.78.97.126:52253
2014-07-02 19:34:36.474741 [INFO] switch_core_media.c:5060 Activating RTCP PORT 52253
2014-07-02 19:34:36.474741 [INFO] switch_core_media.c:5068 Skipping RTCP ICE (Same as RTP)
2014-07-02 19:34:36.474741 [INFO] switch_rtp.c:2878 Activate RTP/RTCP audio DTLS server
2014-07-02 19:34:36.474741 [NOTICE] sofia.c:6988 Channel [sofia/internal/sip:j4jk0pi6@67.78.97.126:54476] has been answered
2014-07-02 19:34:36.494504 [INFO] switch_core_media.c:5060 Activating RTCP PORT 1
2014-07-02 19:34:36.494504 [INFO] switch_rtp.c:2878 Activate RTP/RTCP audio DTLS client
2014-07-02 19:34:36.494504 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/lylepratt-1111@redacted.com!
2014-07-02 19:34:36.494504 [NOTICE] switch_ivr_originate.c:3493 Channel [sofia/internal/lylepratt-1111@redacted.com] has been answered
2014-07-02 19:34:36.754480 [INFO] switch_rtp.c:2701 Changing audio DTLS state from HANDSHAKE to SETUP
2014-07-02 19:34:36.754480 [INFO] switch_rtp.c:2609 audio Fingerprint Verified.
2014-07-02 19:34:36.754480 [INFO] switch_rtp.c:3151 Activating Audio Secure RTP SEND
2014-07-02 19:34:36.754480 [INFO] switch_rtp.c:3129 Activating Audio Secure RTP RECV
2014-07-02 19:34:36.754480 [INFO] switch_rtp.c:2649 Changing audio DTLS state from SETUP to READY
2014-07-02 19:35:45.174488 [NOTICE] sofia.c:927 Hangup sofia/internal/sip:j4jk0pi6@67.78.97.126:54476 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2014-07-02 19:35:45.194498 [NOTICE] switch_core_session.c:1611 Session 8 (sofia/internal/sip:j4jk0pi6@67.78.97.126:54476) Ended
2014-07-02 19:35:45.194498 [NOTICE] switch_core_session.c:1615 Close Channel sofia/internal/sip:j4jk0pi6@67.78.97.126:54476 [CS_DESTROY]
2014-07-02 19:35:45.194498 [NOTICE] switch_core_state_machine.c:313 sofia/internal/lylepratt-1111@redacted.com has executed the last dialplan instruction, hanging up.
2014-07-02 19:35:45.194498 [NOTICE] switch_core_state_machine.c:315 Hangup sofia/internal/lylepratt-1111@redacted.com [CS_EXECUTE] [NORMAL_CLEARING]
2014-07-02 19:35:45.194498 [NOTICE] switch_core_session.c:1611 Session 7 (sofia/internal/lylepratt-1111@redacted.com) Ended
2014-07-02 19:35:45.194498 [NOTICE] switch_core_session.c:1615 Close Channel sofia/internal/lylepratt-1111@redacted.com [CS_DESTROY]
alongubkin commented 10 years ago

Uh, does FreeSwitch actually create a TURN server?

lylepratt commented 10 years ago

Erhm. I'm not really sure....but it worked on Android.

alongubkin commented 10 years ago

With PhoneRTC?

lylepratt commented 10 years ago

Yep! Using @joseph-onsip 's sipjs-cordova library. https://github.com/joseph-onsip/sipjs-cordova

I'm happy to provide any additional details. I'm pretty new to the inner workings of WebRTC, especially in conjunction with FreeSWITCH, so my apologies if I'm a little ignorant.

egreenmachine commented 10 years ago

Hey Lyle,

Did you try it with commit 6531d095a0a25ceb0844023d355730a3cb9d1a5f ?

lylepratt commented 10 years ago

@egreenmachine yeah, unfortunately the same thing happens.

alongubkin commented 10 years ago

It might be possible that the internalSctpDataChannels constraint is what causing this in iOS.

https://github.com/alongubkin/phonertc/blob/master/src/ios/PhoneRTCPlugin.m#L58

Can you show some more iOS WebRTC logs?

lylepratt commented 10 years ago

I tried with a TURN server and seem to get the same error.

alongubkin commented 10 years ago

Then the problem is probably with your signaling. Can you show us some of your code?

lylepratt commented 10 years ago

I'm using sip.js for signaling. I'm slowly wrapping my head around it, but I don't have enough knowledge yet to figure out what in the signaling could be wrong.

@joseph-onsip do you have any input on this? Should I have opened this ticket in https://github.com/joseph-onsip/sipjs-cordova instead of here?

josephfrazier commented 10 years ago

If you create your SIP.UA with traceSip: true as one of the parameters, it will print sent/received messages to the JS console, so you can then paste them here.

EDIT: Ugh, replying by email doesn't let me use Markdown, even if I edit it later.

On Thu, Jul 3, 2014 at 11:47 AM, Lyle Pratt notifications@github.com wrote:

I'm using sip.js for signaling. I'm slowly wrapping my head around it, but I don't have enough knowledge yet to figure out what in the signaling could be wrong.

@joseph-onsip https://github.com/joseph-onsip do you have any input on this? Should I have opened this ticket in https://github.com/joseph-onsip/sipjs-cordova instead of here?

— Reply to this email directly or view it on GitHub https://github.com/alongubkin/phonertc/issues/28#issuecomment-47947292.

lylepratt commented 10 years ago

Here is the full log from console with traceSip: true:

2014-07-03 09:42:33.992 HelloCordova[429:60b] Multi-tasking -> Device: YES, App: YES
2014-07-03 09:42:34.034 HelloCordova[429:60b] Unlimited access to network resources
2014-07-03 09:42:34.047 HelloCordova[429:60b] 

Started backup to iCloud! Please be careful.
Your application might rejected by Apple if you store too much data.
For more information please read "iOS Data Storage Guidelines"
You could find it at the following address https://developer.apple.com/icloud/documentation/data-storage/ .

2014-07-03 09:42:35.772 HelloCordova[429:60b] Resetting plugins due to page load.
2014-07-03 09:42:36.927 HelloCordova[429:60b] Finished load of: file:///var/mobile/Applications/FCED5567-5DE0-4A6B-9A00-CB1B12047594/HelloCordova.app/www/index.html
WebRtc VoiceEngine codecs:
ISAC/16000/1 (103)
PCMU/8000/1 (0)
PCMA/8000/1 (8)
Warning(webrtcvoiceengine.cc:476): Unexpected codec: PCMU/8000/2 (110)
Warning(webrtcvoiceengine.cc:476): Unexpected codec: PCMA/8000/2 (118)
ILBC/8000/1 (102)
G722/16000/1 (9)
Warning(webrtcvoiceengine.cc:476): Unexpected codec: G722/16000/2 (119)
opus/48000/2 (111)
CN/8000/1 (13)
CN/16000/1 (105)
CN/32000/1 (106)
telephone-event/8000/1 (126)
red/8000/1 (127)
WebRtcVideoEngine::WebRtcVideoEngine
webrtc: (vie_impl.cc:133): SetTraceFilter: filter: 8206
webrtc: (vie_impl.cc:138): SetTraceCallback: 
WebRtcVoiceEngine::Init
WebRtc VoiceEngine Version:
VoiceEngine 4.1.0
Build: Jun  6 2014 13:44:37 ?
Applying audio options: AudioOptions {aec: false, agc: false, ns: true, hf: true, swap: false, typing: false, conference: false, agc_delta: 0, experimental_agc: false, experimental_aec: false, experimental_ns: false, aec_dump: false, }
High pass filter enabled? 1
Stereo swapping enabled? 0
Typing detection is enabled? 0
Warning(webrtcvoiceengine.cc:846): SetTypingDetectionStatus(0) failed, err=8003
Error(webrtcvideoengine.cc:1545): webrtc: (voe_audio_processing_impl.cc:1001): SetTypingDetectionStatus: not supported
Adjust agc delta is 0
Adjusting AGC level from default -3dB to -3dB
Aec dump is enabled? 0
Experimental aec is 0
WebRtc VoiceEngine codecs:
opus/48000/2 (111)
ISAC/16000/1 (103)
G722/16000/1 (9)
ILBC/8000/1 (102)
PCMU/8000/1 (0)
PCMA/8000/1 (8)
CN/32000/1 (106)
CN/16000/1 (105)
CN/8000/1 (13)
red/8000/1 (127)
telephone-event/8000/1 (126)
WebRtcVoiceEngine::Init Done!
WebRtcVideoEngine::Init
WebRtcVideoEngine::InitVideoEngine
WebRtc VideoEngine Version:
VideoEngine 3.54.0
Build: Jun  6 2014 13:44:39 ?
webrtc: (vie_base_impl.cc:68): SetVoiceEngine: SetVoiceEngine
webrtc: (vie_render_impl.cc:64): RegisterVideoRenderModule: 
VideoEngine Init done
Applying audio options: AudioOptions {aec: false, agc: false, ns: true, hf: true, swap: false, typing: false, conference: false, agc_delta: 0, experimental_agc: false, experimental_aec: false, experimental_ns: false, aec_dump: false, }
High pass filter enabled? 1
Stereo swapping enabled? 0
Typing detection is enabled? 0
Warning(webrtcvoiceengine.cc:846): SetTypingDetectionStatus(0) failed, err=8003
Error(webrtcvideoengine.cc:1545): webrtc: (voe_audio_processing_impl.cc:1001): SetTypingDetectionStatus: not supported
Adjust agc delta is 0
Adjusting AGC level from default -3dB to -3dB
Aec dump is enabled? 0
Experimental aec is 0
Allowing SCTP data engine.
Generating identity.
2014-07-03 09:42:47.023 HelloCordova[429:722b] PCO onRenegotiationNeeded.
2014-07-03 09:42:47.033 HelloCordova[429:60b] THREAD WARNING: ['PhoneRTCPlugin'] took '1753.291748' ms. Plugin should use a background thread.
Ignored line: c=IN IP4 0.0.0.0
Created channel for audio
Setting voice channel options: AudioOptions {}
Set voice channel options.  Current options: AudioOptions {}
Session:1894311965860958199 Old state:STATE_INIT New state:STATE_SENTINITIATE Type:urn:xmpp:jingle:apps:rtp:1 Transport:http://www.google.com/transport/p2p
2014-07-03 09:42:47.093 HelloCordova[429:722b] PCO onSignalingStateChange: 1
Setting local voice description
Add send ssrc: 1989048592
Setting receive voice codecs:
ISAC/16000/1 (103)
opus/48000/2 (111)
G722/16000/1 (9)
ILBC/8000/1 (102)
PCMU/8000/1 (0)
PCMA/8000/1 (8)
CN/32000/1 (106)
CN/16000/1 (105)
CN/8000/1 (13)
red/8000/1 (127)
telephone-event/8000/1 (126)
Changing voice state, recv=0 send=0
Setting voice channel options: AudioOptions {}
Set voice channel options.  Current options: AudioOptions {}
Local and Remote descriptions must be applied to get SSL Role of the session.
Transport: audio, allocating candidates
2014-07-03 09:42:47.105 HelloCordova[429:60b] sendMessage 1
2014-07-03 09:42:47.106 HelloCordova[429:60b] SENDING MESSAGE: {"sdp":"v=0\r\no=- 1894311965860958199 2 IN IP4 127.0.0.1\r\ns=-\r\nt=0 0\r\na=group:BUNDLE audio\r\na=msid-semantic: WMS ARDAMS\r\nm=audio 1 RTP\/SAVPF 103 111 9 102 0 8 106 105 13 127 126\r\nc=IN IP4 0.0.0.0\r\na=rtcp:1 IN IP4 0.0.0.0\r\na=ice-ufrag:n1mhu0DCgJOBX3uU\r\na=ice-pwd:8ulsu744faeg3Ji9Z5zKSs5Z\r\na=ice-options:google-ice\r\na=fingerprint:sha-1 3B:55:56:CB:D2:27:80:28:2D:73:64:1F:61:64:91:A4:38:EF:AA:AB\r\na=setup:actpass\r\na=mid:audio\r\na=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level\r\na=extmap:3 http:\/\/www.webrtc.org\/experiments\/rtp-hdrext\/abs-send-time\r\na=sendrecv\r\na=rtcp-mux\r\na=rtpmap:111 opus\/48000\/2\r\na=fmtp:111 minptime=10\r\na=rtpmap:103 ISAC\/16000\r\na=rtpmap:9 G722\/16000\r\na=rtpmap:102 ILBC\/8000\r\na=rtpmap:0 PCMU\/8000\r\na=rtpmap:8 PCMA\/8000\r\na=rtpmap:106 CN\/32000\r\na=rtpmap:105 CN\/16000\r\na=rtpmap:13 CN\/8000\r\na=rtpmap:127 red\/8000\r\na=rtpmap:126 telephone-event\/8000\r\na=maxptime:60\r\na=ssrc:1989048592 cname:up9fzxATxUA1NBnx\r\na=ssrc:1989048592 msid:ARDAMS ARDAMSa0\r\na=ssrc:1989048592 mslabel:ARDAMS\r\na=ssrc:1989048592 label:ARDAMSa0\r\n","type":"offer"}
Jingle:Net[en0:192.168.1.0/24:Unknown]: Allocation Phase=Udp
Jingle:Port[:1:0::Net[en0:192.168.1.0/24:Unknown]]: Port created
AllocationSequence: UDPPort will be handling the STUN candidate generation.
Adding allocated port for audio
Jingle:Port[audio:1:0::Net[en0:192.168.1.0/24:Unknown]]: Added port to allocator
2014-07-03 09:42:47.104 HelloCordova[429:722b] PCO onIceGatheringChange. 1
Transport: audio, allocating candidates
2014-07-03 09:42:47.120 HelloCordova[429:722b] PCO onIceGatheringChange. 1
2014-07-03 09:42:47.122 HelloCordova[429:722b] PCO onICECandidate.
  Mid[audio] Index[0] Sdp[a=candidate:2530088836 1 udp 2122194687 192.168.1.106 60786 typ host generation 0

]
2014-07-03 09:42:47.123 HelloCordova[429:722b] gotICECandidate -- sending message
2014-07-03 09:42:47.124 HelloCordova[429:722b] sendMessage 1
2014-07-03 09:42:47.126 HelloCordova[429:722b] SENDING MESSAGE: {"type":"candidate","id":"audio","candidate":"a=candidate:2530088836 1 udp 2122194687 192.168.1.106 60786 typ host generation 0\r\n","label":0}
2014-07-03 09:42:47.128 HelloCordova[429:722b] PCO onICECandidate.
  Mid[audio] Index[0] Sdp[a=candidate:2530088836 2 udp 2122194687 192.168.1.106 60786 typ host generation 0

]
2014-07-03 09:42:47.130 HelloCordova[429:722b] gotICECandidate -- sending message
2014-07-03 09:42:47.132 HelloCordova[429:722b] sendMessage 1
2014-07-03 09:42:47.133 HelloCordova[429:722b] SENDING MESSAGE: {"type":"candidate","id":"audio","candidate":"a=candidate:2530088836 2 udp 2122194687 192.168.1.106 60786 typ host generation 0\r\n","label":0}
Jingle:Net[en0:192.168.1.0/24:Unknown]: Allocation Phase=Relay
Jingle:Port[:1:0::Net[en0:192.168.1.0/24:Unknown]]: Port created
Adding allocated port for audio
Jingle:Port[audio:1:0::Net[en0:192.168.1.0/24:Unknown]]: Added port to allocator
Warning(turnport.cc:462): Jingle:Port[audio:1:0::Net[en0:192.168.1.0/24:Unknown]]: TURN host lookup received error 8
2014-07-03 09:42:47.197 HelloCordova[429:722b] PCO onICECandidate.
  Mid[audio] Index[0] Sdp[a=candidate:394662192 1 udp 1685987071 70.113.42.156 60786 typ srflx raddr 192.168.1.106 rport 60786 generation 0

]
2014-07-03 09:42:47.200 HelloCordova[429:722b] gotICECandidate -- sending message
2014-07-03 09:42:47.201 HelloCordova[429:722b] sendMessage 1
2014-07-03 09:42:47.202 HelloCordova[429:722b] SENDING MESSAGE: {"type":"candidate","id":"audio","candidate":"a=candidate:394662192 1 udp 1685987071 70.113.42.156 60786 typ srflx raddr 192.168.1.106 rport 60786 generation 0\r\n","label":0}
2014-07-03 09:42:47.203 HelloCordova[429:722b] PCO onICECandidate.
  Mid[audio] Index[0] Sdp[a=candidate:394662192 2 udp 1685987071 70.113.42.156 60786 typ srflx raddr 192.168.1.106 rport 60786 generation 0

]
2014-07-03 09:42:47.204 HelloCordova[429:722b] gotICECandidate -- sending message
2014-07-03 09:42:47.205 HelloCordova[429:722b] sendMessage 1
2014-07-03 09:42:47.206 HelloCordova[429:722b] SENDING MESSAGE: {"type":"candidate","id":"audio","candidate":"a=candidate:394662192 2 udp 1685987071 70.113.42.156 60786 typ srflx raddr 192.168.1.106 rport 60786 generation 0\r\n","label":0}
Jingle:Net[en0:192.168.1.0/24:Unknown]: Allocation Phase=Tcp
Jingle:Port[:1:0:local:Net[en0:192.168.1.0/24:Unknown]]: Port created
Adding allocated port for audio
Jingle:Port[audio:1:0:local:Net[en0:192.168.1.0/24:Unknown]]: Added port to allocator
2014-07-03 09:42:47.229 HelloCordova[429:722b] PCO onICECandidate.
  Mid[audio] Index[0] Sdp[a=candidate:3628985204 1 tcp 1518214911 192.168.1.106 50712 typ host generation 0

]
2014-07-03 09:42:47.230 HelloCordova[429:722b] gotICECandidate -- sending message
2014-07-03 09:42:47.231 HelloCordova[429:722b] sendMessage 1
2014-07-03 09:42:47.232 HelloCordova[429:722b] SENDING MESSAGE: {"type":"candidate","id":"audio","candidate":"a=candidate:3628985204 1 tcp 1518214911 192.168.1.106 50712 typ host generation 0\r\n","label":0}
2014-07-03 09:42:47.234 HelloCordova[429:722b] PCO onICECandidate.
  Mid[audio] Index[0] Sdp[a=candidate:3628985204 2 tcp 1518214911 192.168.1.106 50712 typ host generation 0

]
2014-07-03 09:42:47.235 HelloCordova[429:722b] gotICECandidate -- sending message
2014-07-03 09:42:47.236 HelloCordova[429:722b] sendMessage 1
2014-07-03 09:42:47.237 HelloCordova[429:722b] SENDING MESSAGE: {"type":"candidate","id":"audio","candidate":"a=candidate:3628985204 2 tcp 1518214911 192.168.1.106 50712 typ host generation 0\r\n","label":0}
Jingle:Net[en0:192.168.1.0/24:Unknown]: Allocation Phase=SslTcp
All candidates gathered for audio:1:0
Transport: audio, component 1 allocation complete
Transport: audio, component 2 allocation complete
Transport: audio allocation complete
Candidate gathering is complete.
2014-07-03 09:42:47.281 HelloCordova[429:722b] PCO onIceGatheringChange. 2
2014-07-03 09:43:05.526 HelloCordova[429:1803] No ISAC/16000 line, so can't prefer iSAC
Destroying NSS identity
Jingle:Channel[audio|1|__]: DTLS setup complete.
Jingle:Channel[audio|2|__]: DTLS setup complete.
No BUNDLE information, not bundling.
Channel enabled
Starting playout for channel #0
Changing voice state, recv=1 send=0
Session:1894311965860958199 Old state:STATE_SENTINITIATE New state:STATE_RECEIVEDACCEPT Type:urn:xmpp:jingle:apps:rtp:1 Transport:http://www.google.com/transport/p2p
2014-07-03 09:43:06.302 HelloCordova[429:722b] PCO onSignalingStateChange: 0
Setting remote voice description
Send channel 0 selected voice codec PCMU/8000/1 (0), bitrate=64000
Enabling VAD
Recv stream 1426952649 reuse default channel
Starting playout for channel #0
Add remote ssrc: 1426952649
Destroying NSS identity
WebRtcVoiceMediaChanne::SetSendBandwidth.
WebRtcVoiceMediaChannel::SetSendBandwidthInternal.
Setting voice channel options: AudioOptions {}
Set voice channel options.  Current options: AudioOptions {}
Changing voice state, recv=1 send=0
Warning(webrtcvoiceengine.cc:2845): SetOutputVolumePan(0, 1, 1) failed, err=8040
SetOutputScaling to left=1 right=1 for channel 0 and ssrc 1426952649
2014-07-03 09:43:06.379 HelloCordova[429:722b] PCO onAddStream.
2014-07-03 09:43:06.381 HelloCordova[429:722b] sendMessage 1
2014-07-03 09:43:06.383 HelloCordova[429:722b] SENDING MESSAGE: {"type": "__answered"}
2014-07-03 09:43:06.389 HelloCordova[429:722b] PCO onIceConnectionChange. 1
Jingle:Conn[audio:kH9bFzxd:1:0:local:udp:192.168.1.106:60786->:1:0:local:udp:162.243.144.62:25294|C--W|2830971808005631|-]: Connection created
Jingle:Channel[audio|1|__]: Created connection with origin=2, (1 total)
Jingle:Channel[audio|1|__]: New best connection: Conn[audio:kH9bFzxd:1:0:local:udp:192.168.1.106:60786->:1:0:local:udp:162.243.144.62:25294|C--W|2830971808005631|-]
Session:1894311965860958199 Old state:STATE_RECEIVEDACCEPT New state:STATE_INPROGRESS Type:urn:xmpp:jingle:apps:rtp:1 Transport:http://www.google.com/transport/p2p
2014-07-03 09:43:06.407 HelloCordova[429:60b] SDP onSuccess - drain candidates
Jingle:Conn[audio:kH9bFzxd:1:0:local:udp:192.168.1.106:60786->:1:0:local:udp:162.243.144.62:25294|C--I|2830971808005631|-]: Timed out after 15007 ms without a response, rtt=3000
Jingle:Conn[audio:kH9bFzxd:1:0:local:udp:192.168.1.106:60786->:1:0:local:udp:162.243.144.62:25294|C-xI|2830971808005631|-]: Connection deleted
Jingle:Channel[audio|1|__]: Removed connection (0 remaining)
Jingle:Channel[audio|1|__]: No best connection
2014-07-03 09:43:21.411 HelloCordova[429:722b] PCO onIceConnectionChange. 4
2014-07-03 09:43:21.418 HelloCordova[429:722b] *** Assertion failure in -[PCObserver peerConnection:iceConnectionChanged:], /Users/lyle/Desktop/Ubuntu/sipjs-cordova/platforms/ios/HelloCordova/Plugins/com.dooble.phonertc/PhoneRTCDelegate.m:322
2014-07-03 09:43:21.430 HelloCordova[429:722b] *** Terminating app due to uncaught exception 'NSInternalInconsistencyException', reason: 'ICE Connection failed!'
*** First throw call stack:
(0x2f8cbfd3 0x3a142ccf 0x2f8cbead 0x30278d5b 0x52f83 0x456207 0x3add07 0x3add45 0x425f63 0x426275 0x2b85a3 0x2e1799 0x2e0529 0x16f177 0x1aa64d 0x1aa577 0x1aa46f 0x3a76e919 0x3a76e88b 0x3a76caa4)
libc++abi.dylib: terminating with uncaught exception of type NSException
josephfrazier commented 10 years ago

That looks like an iOS log. Do those include JS console logs? I know Android logs do, but I don't see any SIP.js-related messages in this one, so I'm guessing they don't.

lylepratt commented 10 years ago

Typically Cordova does log console.log calls to the XCode console. However, for some reason sip.js logs are not showing up. I have no idea why currently.

josephfrazier commented 10 years ago

Can you post your UA initialization code? It should look something like this:

    window.ua = new SIP.UA({
        // show SIP messages in console
        traceSip: true
    });
lylepratt commented 10 years ago

Normal console.log works and displays in the XCode console when I manually test it. However, no SIP.js logs are printed.

window.ua = new SIP.UA({
      traceSip: true,
      level: 'debug',
      displayName: "Lyle Pratt",
      uri: "lylepratt-1111@redacted.com",
      authorizationUser: "lylepratt-1111",
      password: "redacted",
      wsServers: "ws://redacted.com:5066",      
      mediaHandlerFactory: function defaultFactory (session, options) {
        return new PhoneRTCMediaHandler(session, options);
      }
    });
josephfrazier commented 10 years ago

Can you use your debugger to ensure console.log is actually being called by SIP.js? The relevant SIP.js function is LoggerFactory.prototype.print.

egreenmachine commented 10 years ago

I don't think that problem is in the signaling, because it works with identical signaling on Android. Try following this guide to get actual javascript logs for us to see the signaling.

alongubkin commented 10 years ago

@egreenmachine It's possible that when he tried in Android it didn't use the TURN server

egreenmachine commented 10 years ago

I don't think the TURN server should make a difference, TURN is not a requirement of WebRTC and if either the mobile device or FreeSWITCH box is accessible from the public internet it should not be used anyways (WebRTC negotiation should negotiate it out).

All of my testing thus far has been done without a TURN server, so there could be a problem with the way iOS is handling TURN servers, but we need to determine if that is actually the problem before we can address it.

lylepratt commented 10 years ago

Was able to get the logs from Safari via remote inspector:

[Log] Thu Jul 03 2014 12:14:11 GMT-0500 (CDT) | sip.ua | emitting event newTransaction (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:11 GMT-0500 (CDT) | sip.transaction.nict | adding event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:11 GMT-0500 (CDT) | sip.transaction.nict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:11 GMT-0500 (CDT) | sip.transport | sending WebSocket message: (sip.js, line 639)

REGISTER sip:redacted.com SIP/2.0
Via: SIP/2.0/WS i4dbigviujcd.invalid;branch=z9hG4bK6391840
Max-Forwards: 70
To: <sip:lylepratt-1111@redacted.com>
From: "Lyle Pratt" <sip:lylepratt-1111@redacted.com>;tag=46463oglop
Call-ID: v720aacvb3ovondurcf2qi
CSeq: 83 REGISTER
Authorization: Digest algorithm=MD5, username="lylepratt-1111", realm="redacted.com", nonce="62908100-02d5-11e4-aa9c-95208176e1b2", uri="sip:redacted.com", response="a3854dc2361cc08fa2a37d001a642834", qop=auth, cnonce="3tbf47s4g2fo", nc=00000001
Contact: <sip:lshcqspa@i4dbigviujcd.invalid;transport=ws>;reg-id=1;+sip.instance="<urn:uuid:e9ea7a0c-1c45-416f-afac-1bb63c648460>";expires=600
Allow: ACK,CANCEL,BYE,OPTIONS,INFO,NOTIFY
Supported: path,gruu,outbound
User-Agent: SIP.js/0.5.0-devel
Content-Length: 0

[Log] Thu Jul 03 2014 12:14:12 GMT-0500 (CDT) | sip.transport | received WebSocket text message: (sip.js, line 639)

SIP/2.0 401 Unauthorized
Via: SIP/2.0/WS i4dbigviujcd.invalid;branch=z9hG4bK6391840;received=67.78.97.126;rport=51219
From: "Lyle Pratt" <sip:lylepratt-1111@redacted.com>;tag=46463oglop
To: <sip:lylepratt-1111@redacted.com>;tag=apm7Z40Z5KZ3F
Call-ID: v720aacvb3ovondurcf2qi
CSeq: 83 REGISTER
User-Agent: FreeSWITCH-mod_sofia/1.5.11+git~20140702T185727Z~d1a96c546b~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
WWW-Authenticate: Digest realm="redacted.com", nonce="73b43fee-02d5-11e4-aa9e-95208176e1b2", stale=true, algorithm=MD5, qop="auth"
Content-Length: 0

[Log] Thu Jul 03 2014 12:14:12 GMT-0500 (CDT) | sip.transaction.nict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:12 GMT-0500 (CDT) | sip.ua | emitting event newTransaction (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:12 GMT-0500 (CDT) | sip.transaction.nict | adding event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:12 GMT-0500 (CDT) | sip.transaction.nict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:12 GMT-0500 (CDT) | sip.transport | sending WebSocket message: (sip.js, line 639)

REGISTER sip:redacted.com SIP/2.0
Via: SIP/2.0/WS i4dbigviujcd.invalid;branch=z9hG4bK4755318
Max-Forwards: 70
To: <sip:lylepratt-1111@redacted.com>
From: "Lyle Pratt" <sip:lylepratt-1111@redacted.com>;tag=46463oglop
Call-ID: v720aacvb3ovondurcf2qi
CSeq: 84 REGISTER
Authorization: Digest algorithm=MD5, username="lylepratt-1111", realm="redacted.com", nonce="73b43fee-02d5-11e4-aa9e-95208176e1b2", uri="sip:redacted.com", response="bea17bf8c0773e8b83337b00d66630bf", qop=auth, cnonce="khuee6gs2qrk", nc=00000001
Contact: <sip:lshcqspa@i4dbigviujcd.invalid;transport=ws>;reg-id=1;+sip.instance="<urn:uuid:e9ea7a0c-1c45-416f-afac-1bb63c648460>";expires=600
Allow: ACK,CANCEL,BYE,OPTIONS,INFO,NOTIFY
Supported: path,gruu,outbound
User-Agent: SIP.js/0.5.0-devel
Content-Length: 0

[Log] Thu Jul 03 2014 12:14:12 GMT-0500 (CDT) | sip.transaction.nict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:12 GMT-0500 (CDT) | sip.ua | emitting event transactionDestroyed (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:13 GMT-0500 (CDT) | sip.transport | received WebSocket text message: (sip.js, line 639)

SIP/2.0 200 OK
Via: SIP/2.0/WS i4dbigviujcd.invalid;branch=z9hG4bK4755318;received=67.78.97.126;rport=51219
From: "Lyle Pratt" <sip:lylepratt-1111@redacted.com>;tag=46463oglop
To: <sip:lylepratt-1111@redacted.com>;tag=BZD01ZH32vNpB
Call-ID: v720aacvb3ovondurcf2qi
CSeq: 84 REGISTER
Contact: <sip:lshcqspa@67.78.97.126:51219;transport=ws;received=67.78.97.126:51219>;expires=30
Date: Thu, 03 Jul 2014 17:14:13 GMT
User-Agent: FreeSWITCH-mod_sofia/1.5.11+git~20140702T185727Z~d1a96c546b~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Content-Length: 0

[Log] Thu Jul 03 2014 12:14:13 GMT-0500 (CDT) | sip.transaction.nict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:13 GMT-0500 (CDT) | sip.registercontext | emitting event accepted (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:13 GMT-0500 (CDT) | sip.registercontext | emitting event registered (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:13 GMT-0500 (CDT) | sip.ua | emitting event registered (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:13 GMT-0500 (CDT) | sip.transaction.nict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:13 GMT-0500 (CDT) | sip.ua | emitting event transactionDestroyed (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:40 GMT-0500 (CDT) | sip.ua | emitting event newTransaction (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:40 GMT-0500 (CDT) | sip.transaction.nict | adding event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:40 GMT-0500 (CDT) | sip.transaction.nict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:40 GMT-0500 (CDT) | sip.transport | sending WebSocket message: (sip.js, line 639)

REGISTER sip:redacted.com SIP/2.0
Via: SIP/2.0/WS i4dbigviujcd.invalid;branch=z9hG4bK801655
Max-Forwards: 70
To: <sip:lylepratt-1111@redacted.com>
From: "Lyle Pratt" <sip:lylepratt-1111@redacted.com>;tag=46463oglop
Call-ID: v720aacvb3ovondurcf2qi
CSeq: 85 REGISTER
Authorization: Digest algorithm=MD5, username="lylepratt-1111", realm="redacted.com", nonce="73b43fee-02d5-11e4-aa9e-95208176e1b2", uri="sip:redacted.com", response="bea17bf8c0773e8b83337b00d66630bf", qop=auth, cnonce="khuee6gs2qrk", nc=00000001
Contact: <sip:lshcqspa@i4dbigviujcd.invalid;transport=ws>;reg-id=1;+sip.instance="<urn:uuid:e9ea7a0c-1c45-416f-afac-1bb63c648460>";expires=600
Allow: ACK,CANCEL,BYE,OPTIONS,INFO,NOTIFY
Supported: path,gruu,outbound
User-Agent: SIP.js/0.5.0-devel
Content-Length: 0

[Log] Thu Jul 03 2014 12:14:40 GMT-0500 (CDT) | sip.transport | received WebSocket text message: (sip.js, line 639)

SIP/2.0 401 Unauthorized
Via: SIP/2.0/WS i4dbigviujcd.invalid;branch=z9hG4bK801655;received=67.78.97.126;rport=51219
From: "Lyle Pratt" <sip:lylepratt-1111@redacted.com>;tag=46463oglop
To: <sip:lylepratt-1111@redacted.com>;tag=c86r3t26Z5B9p
Call-ID: v720aacvb3ovondurcf2qi
CSeq: 85 REGISTER
User-Agent: FreeSWITCH-mod_sofia/1.5.11+git~20140702T185727Z~d1a96c546b~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
WWW-Authenticate: Digest realm="redacted.com", nonce="84c95df0-02d5-11e4-aaa0-95208176e1b2", stale=true, algorithm=MD5, qop="auth"
Content-Length: 0

[Log] Thu Jul 03 2014 12:14:41 GMT-0500 (CDT) | sip.transaction.nict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:41 GMT-0500 (CDT) | sip.ua | emitting event newTransaction (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:41 GMT-0500 (CDT) | sip.transaction.nict | adding event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:41 GMT-0500 (CDT) | sip.transaction.nict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:41 GMT-0500 (CDT) | sip.transport | sending WebSocket message: (sip.js, line 639)

REGISTER sip:redacted.com SIP/2.0
Via: SIP/2.0/WS i4dbigviujcd.invalid;branch=z9hG4bK7758687
Max-Forwards: 70
To: <sip:lylepratt-1111@redacted.com>
From: "Lyle Pratt" <sip:lylepratt-1111@redacted.com>;tag=46463oglop
Call-ID: v720aacvb3ovondurcf2qi
CSeq: 86 REGISTER
Authorization: Digest algorithm=MD5, username="lylepratt-1111", realm="redacted.com", nonce="84c95df0-02d5-11e4-aaa0-95208176e1b2", uri="sip:redacted.com", response="fd5c34a23cbfdc026b65bd8502de1b24", qop=auth, cnonce="e6ruaum8b710", nc=00000001
Contact: <sip:lshcqspa@i4dbigviujcd.invalid;transport=ws>;reg-id=1;+sip.instance="<urn:uuid:e9ea7a0c-1c45-416f-afac-1bb63c648460>";expires=600
Allow: ACK,CANCEL,BYE,OPTIONS,INFO,NOTIFY
Supported: path,gruu,outbound
User-Agent: SIP.js/0.5.0-devel
Content-Length: 0

[Log] Thu Jul 03 2014 12:14:41 GMT-0500 (CDT) | sip.transaction.nict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:41 GMT-0500 (CDT) | sip.ua | emitting event transactionDestroyed (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:41 GMT-0500 (CDT) | sip.transport | received WebSocket text message: (sip.js, line 639)

SIP/2.0 200 OK
Via: SIP/2.0/WS i4dbigviujcd.invalid;branch=z9hG4bK7758687;received=67.78.97.126;rport=51219
From: "Lyle Pratt" <sip:lylepratt-1111@redacted.com>;tag=46463oglop
To: <sip:lylepratt-1111@redacted.com>;tag=DH0H5NKaXe2Uj
Call-ID: v720aacvb3ovondurcf2qi
CSeq: 86 REGISTER
Contact: <sip:lshcqspa@67.78.97.126:51219;transport=ws;received=67.78.97.126:51219>;expires=30
Date: Thu, 03 Jul 2014 17:14:41 GMT
User-Agent: FreeSWITCH-mod_sofia/1.5.11+git~20140702T185727Z~d1a96c546b~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Content-Length: 0

[Log] Thu Jul 03 2014 12:14:42 GMT-0500 (CDT) | sip.transaction.nict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:42 GMT-0500 (CDT) | sip.registercontext | emitting event accepted (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:42 GMT-0500 (CDT) | sip.registercontext | emitting event registered (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:42 GMT-0500 (CDT) | sip.ua | emitting event registered (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:42 GMT-0500 (CDT) | sip.transaction.nict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:42 GMT-0500 (CDT) | sip.ua | emitting event transactionDestroyed (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:56 GMT-0500 (CDT) | sip.clientcontext | adding event progress (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:56 GMT-0500 (CDT) | sip.clientcontext | adding event accepted (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:56 GMT-0500 (CDT) | sip.clientcontext | adding event rejected (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:56 GMT-0500 (CDT) | sip.clientcontext | adding event failed (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:56 GMT-0500 (CDT) | sip.clientcontext | adding event cancel (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:56 GMT-0500 (CDT) | sip.clientcontext | adding event connecting (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:56 GMT-0500 (CDT) | sip.clientcontext | adding event terminated (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:56 GMT-0500 (CDT) | sip.clientcontext | adding event dtmf (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:56 GMT-0500 (CDT) | sip.clientcontext | adding event invite (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:56 GMT-0500 (CDT) | sip.clientcontext | skipping event cancel - Event exists (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:56 GMT-0500 (CDT) | sip.clientcontext | adding event refer (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:56 GMT-0500 (CDT) | sip.clientcontext | adding event bye (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:56 GMT-0500 (CDT) | sip.clientcontext | adding event hold (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:56 GMT-0500 (CDT) | sip.clientcontext | adding event unhold (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:56 GMT-0500 (CDT) | sip.clientcontext | adding event muted (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:56 GMT-0500 (CDT) | sip.clientcontext | adding event unmuted (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:56 GMT-0500 (CDT) | sip.invitecontext.mediahandler | XXX phonertcCall: caller (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:56 GMT-0500 (CDT) | sip.inviteclientcontext | new listener added to event terminated (sip.js, line 639)
[Log] Thu Jul 03 2014 12:14:58 GMT-0500 (CDT) | sip.invitecontext.mediahandler | XXX phonertcSendMessageCallback: { (sip.js, line 639)
  "sdp": "v=0\r\no=- 2849603402717568182 2 IN IP4 127.0.0.1\r\ns=-\r\nt=0 0\r\na=group:BUNDLE audio\r\na=msid-semantic: WMS ARDAMS\r\nm=audio 1 RTP/SAVPF 103 111 9 102 0 8 106 105 13 127 126\r\nc=IN IP4 0.0.0.0\r\na=rtcp:1 IN IP4 0.0.0.0\r\na=ice-ufrag:7SD9HAwddeV4DB/G\r\na=ice-pwd:apbsbkMFNPcKP5t2wfFf12tJ\r\na=ice-options:google-ice\r\na=fingerprint:sha-1 FC:AB:C7:EC:B2:48:93:4D:E4:C1:C4:74:68:F3:D3:F6:ED:3D:31:CF\r\na=setup:actpass\r\na=mid:audio\r\na=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level\r\na=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time\r\na=sendrecv\r\na=rtcp-mux\r\na=rtpmap:111 opus/48000/2\r\na=fmtp:111 minptime=10\r\na=rtpmap:103 ISAC/16000\r\na=rtpmap:9 G722/16000\r\na=rtpmap:102 ILBC/8000\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:8 PCMA/8000\r\na=rtpmap:106 CN/32000\r\na=rtpmap:105 CN/16000\r\na=rtpmap:13 CN/8000\r\na=rtpmap:127 red/8000\r\na=rtpmap:126 telephone-event/8000\r\na=maxptime:60\r\na=ssrc:193161721 cname:jnw/NgnOxPaF9a39\r\na=ssrc:193161721 msid:ARDAMS ARDAMSa0\r\na=ssrc:193161721 mslabel:ARDAMS\r\na=ssrc:193161721 label:ARDAMSa0\r\n",
  "type": "offer"
}
[Log] Thu Jul 03 2014 12:14:58 GMT-0500 (CDT) | sip.invitecontext.mediahandler | XXX phonertcSendMessageCallback: { (sip.js, line 639)
  "type": "candidate",
  "id": "audio",
  "candidate": "a=candidate:449597170 1 udp 2122194687 192.168.32.110 62006 typ host generation 0\r\n",
  "label": 0
}
[Log] Thu Jul 03 2014 12:14:58 GMT-0500 (CDT) | sip.invitecontext.mediahandler | XXX phonertcSendMessageCallback: { (sip.js, line 639)
  "type": "candidate",
  "id": "audio",
  "candidate": "a=candidate:449597170 2 udp 2122194687 192.168.32.110 62006 typ host generation 0\r\n",
  "label": 0
}
[Log] Thu Jul 03 2014 12:14:58 GMT-0500 (CDT) | sip.invitecontext.mediahandler | XXX phonertcSendMessageCallback: { (sip.js, line 639)
  "type": "candidate",
  "id": "audio",
  "candidate": "a=candidate:3594613089 1 udp 1685987071 67.78.97.126 62006 typ srflx raddr 192.168.32.110 rport 62006 generation 0\r\n",
  "label": 0
}
[Log] Thu Jul 03 2014 12:14:58 GMT-0500 (CDT) | sip.invitecontext.mediahandler | XXX phonertcSendMessageCallback: { (sip.js, line 639)
  "type": "candidate",
  "id": "audio",
  "candidate": "a=candidate:3594613089 2 udp 1685987071 67.78.97.126 62006 typ srflx raddr 192.168.32.110 rport 62006 generation 0\r\n",
  "label": 0
}
[Log] Thu Jul 03 2014 12:14:58 GMT-0500 (CDT) | sip.invitecontext.mediahandler | XXX phonertcSendMessageCallback: { (sip.js, line 639)
  "type": "candidate",
  "id": "audio",
  "candidate": "a=candidate:1414509058 1 tcp 1518214911 192.168.32.110 51221 typ host generation 0\r\n",
  "label": 0
}
[Log] Thu Jul 03 2014 12:14:58 GMT-0500 (CDT) | sip.invitecontext.mediahandler | XXX phonertcSendMessageCallback: { (sip.js, line 639)
  "type": "candidate",
  "id": "audio",
  "candidate": "a=candidate:1414509058 2 tcp 1518214911 192.168.32.110 51221 typ host generation 0\r\n",
  "label": 0
}
[Log] Thu Jul 03 2014 12:15:01 GMT-0500 (CDT) | sip.ua | emitting event newTransaction (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:01 GMT-0500 (CDT) | sip.transaction.ict | adding event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:01 GMT-0500 (CDT) | sip.transaction.ict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:01 GMT-0500 (CDT) | sip.transport | sending WebSocket message: (sip.js, line 639)

INVITE sip:user-lylepratt-1234@redacted.com SIP/2.0
Via: SIP/2.0/WS i4dbigviujcd.invalid;branch=z9hG4bK1503521
Max-Forwards: 70
To: <sip:user-lylepratt-1234@redacted.com>
From: "Lyle Pratt" <sip:lylepratt-1111@redacted.com>;tag=6fq8nutlmu
Call-ID: ncoc77ckqtafuhmoovpe
CSeq: 2095 INVITE
Contact: <sip:lshcqspa@i4dbigviujcd.invalid;transport=ws;ob>
Allow: ACK,CANCEL,BYE,OPTIONS,INFO,NOTIFY
Content-Type: application/sdp
Supported: outbound
User-Agent: SIP.js/0.5.0-devel
Content-Length: 1610

v=0
o=- 2849603402717568182 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE audio
a=msid-semantic: WMS ARDAMS
m=audio 1 RTP/SAVPF 103 111 9 102 0 8 106 105 13 127 126
c=IN IP4 0.0.0.0
a=rtcp:1 IN IP4 0.0.0.0
a=ice-ufrag:7SD9HAwddeV4DB/G
a=ice-pwd:apbsbkMFNPcKP5t2wfFf12tJ
a=ice-options:google-ice
a=fingerprint:sha-1 FC:AB:C7:EC:B2:48:93:4D:E4:C1:C4:74:68:F3:D3:F6:ED:3D:31:CF
a=setup:actpass
a=mid:audio
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=sendrecv
a=rtcp-mux
a=rtpmap:111 opus/48000/2
a=fmtp:111 minptime=10
a=rtpmap:103 ISAC/16000
a=rtpmap:9 G722/16000
a=rtpmap:102 ILBC/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:106 CN/32000
a=rtpmap:105 CN/16000
a=rtpmap:13 CN/8000
a=rtpmap:127 red/8000
a=rtpmap:126 telephone-event/8000
a=maxptime:60
a=ssrc:193161721 cname:jnw/NgnOxPaF9a39
a=ssrc:193161721 msid:ARDAMS ARDAMSa0
a=ssrc:193161721 mslabel:ARDAMS
a=ssrc:193161721 label:ARDAMSa0
a=a=candidate:449597170 1 udp 2122194687 192.168.32.110 62006 typ host generation 0

a=a=candidate:449597170 2 udp 2122194687 192.168.32.110 62006 typ host generation 0

a=a=candidate:3594613089 1 udp 1685987071 67.78.97.126 62006 typ srflx raddr 192.168.32.110 rport 62006 generation 0

a=a=candidate:3594613089 2 udp 1685987071 67.78.97.126 62006 typ srflx raddr 192.168.32.110 rport 62006 generation 0

a=a=candidate:1414509058 1 tcp 1518214911 192.168.32.110 51221 typ host generation 0

a=a=candidate:1414509058 2 tcp 1518214911 192.168.32.110 51221 typ host generation 0

[Log] Thu Jul 03 2014 12:15:01 GMT-0500 (CDT) | sip.transport | received WebSocket text message: (sip.js, line 639)

SIP/2.0 100 Trying
Via: SIP/2.0/WS i4dbigviujcd.invalid;branch=z9hG4bK1503521;received=67.78.97.126;rport=51219
From: "Lyle Pratt" <sip:lylepratt-1111@redacted.com>;tag=6fq8nutlmu
To: <sip:user-lylepratt-1234@redacted.com>
Call-ID: ncoc77ckqtafuhmoovpe
CSeq: 2095 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.5.11+git~20140702T185727Z~d1a96c546b~64bit
Content-Length: 0

[Log] Thu Jul 03 2014 12:15:02 GMT-0500 (CDT) | sip.transaction.ict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:02 GMT-0500 (CDT) | sip.transport | received WebSocket text message: (sip.js, line 639)

SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/WS i4dbigviujcd.invalid;branch=z9hG4bK1503521;received=67.78.97.126;rport=51219
From: "Lyle Pratt" <sip:lylepratt-1111@redacted.com>;tag=6fq8nutlmu
To: <sip:user-lylepratt-1234@redacted.com>;tag=gccva75mm94KN
Call-ID: ncoc77ckqtafuhmoovpe
CSeq: 2095 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.5.11+git~20140702T185727Z~d1a96c546b~64bit
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Proxy-Authenticate: Digest realm="redacted.com", nonce="91478af2-02d5-11e4-aaa5-95208176e1b2", algorithm=MD5, qop="auth"
Content-Length: 0

[Log] Thu Jul 03 2014 12:15:02 GMT-0500 (CDT) | sip.transaction.ict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:02 GMT-0500 (CDT) | sip.transport | sending WebSocket message: (sip.js, line 639)

ACK sip:user-lylepratt-1234@redacted.com SIP/2.0
Via: SIP/2.0/WS i4dbigviujcd.invalid;branch=z9hG4bK1503521
To: <sip:user-lylepratt-1234@redacted.com>;tag=gccva75mm94KN
From: "Lyle Pratt" <sip:lylepratt-1111@redacted.com>;tag=6fq8nutlmu
Call-ID: ncoc77ckqtafuhmoovpe
CSeq: 2095 ACK

[Log] Thu Jul 03 2014 12:15:02 GMT-0500 (CDT) | sip.ua | emitting event newTransaction (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:02 GMT-0500 (CDT) | sip.transaction.ict | adding event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:02 GMT-0500 (CDT) | sip.transaction.ict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:02 GMT-0500 (CDT) | sip.transport | sending WebSocket message: (sip.js, line 639)

INVITE sip:user-lylepratt-1234@redacted.com SIP/2.0
Via: SIP/2.0/WS i4dbigviujcd.invalid;branch=z9hG4bK1432058
Max-Forwards: 70
To: <sip:user-lylepratt-1234@redacted.com>
From: "Lyle Pratt" <sip:lylepratt-1111@redacted.com>;tag=6fq8nutlmu
Call-ID: ncoc77ckqtafuhmoovpe
CSeq: 2096 INVITE
Proxy-Authorization: Digest algorithm=MD5, username="lylepratt-1111", realm="redacted.com", nonce="91478af2-02d5-11e4-aaa5-95208176e1b2", uri="sip:user-lylepratt-1234@redacted.com", response="53841c10ac3103d8242e8b397dbd019a", qop=auth, cnonce="2094lnubpti7", nc=00000001
Contact: <sip:lshcqspa@i4dbigviujcd.invalid;transport=ws;ob>
Allow: ACK,CANCEL,BYE,OPTIONS,INFO,NOTIFY
Content-Type: application/sdp
Supported: outbound
User-Agent: SIP.js/0.5.0-devel
Content-Length: 1610

v=0
o=- 2849603402717568182 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE audio
a=msid-semantic: WMS ARDAMS
m=audio 1 RTP/SAVPF 103 111 9 102 0 8 106 105 13 127 126
c=IN IP4 0.0.0.0
a=rtcp:1 IN IP4 0.0.0.0
a=ice-ufrag:7SD9HAwddeV4DB/G
a=ice-pwd:apbsbkMFNPcKP5t2wfFf12tJ
a=ice-options:google-ice
a=fingerprint:sha-1 FC:AB:C7:EC:B2:48:93:4D:E4:C1:C4:74:68:F3:D3:F6:ED:3D:31:CF
a=setup:actpass
a=mid:audio
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=sendrecv
a=rtcp-mux
a=rtpmap:111 opus/48000/2
a=fmtp:111 minptime=10
a=rtpmap:103 ISAC/16000
a=rtpmap:9 G722/16000
a=rtpmap:102 ILBC/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:106 CN/32000
a=rtpmap:105 CN/16000
a=rtpmap:13 CN/8000
a=rtpmap:127 red/8000
a=rtpmap:126 telephone-event/8000
a=maxptime:60
a=ssrc:193161721 cname:jnw/NgnOxPaF9a39
a=ssrc:193161721 msid:ARDAMS ARDAMSa0
a=ssrc:193161721 mslabel:ARDAMS
a=ssrc:193161721 label:ARDAMSa0
a=a=candidate:449597170 1 udp 2122194687 192.168.32.110 62006 typ host generation 0

a=a=candidate:449597170 2 udp 2122194687 192.168.32.110 62006 typ host generation 0

a=a=candidate:3594613089 1 udp 1685987071 67.78.97.126 62006 typ srflx raddr 192.168.32.110 rport 62006 generation 0

a=a=candidate:3594613089 2 udp 1685987071 67.78.97.126 62006 typ srflx raddr 192.168.32.110 rport 62006 generation 0

a=a=candidate:1414509058 1 tcp 1518214911 192.168.32.110 51221 typ host generation 0

a=a=candidate:1414509058 2 tcp 1518214911 192.168.32.110 51221 typ host generation 0

[Log] Thu Jul 03 2014 12:15:02 GMT-0500 (CDT) | sip.transaction.ict | Timer D expired for INVITE client transaction z9hG4bK1503521 (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:02 GMT-0500 (CDT) | sip.transaction.ict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:02 GMT-0500 (CDT) | sip.ua | emitting event transactionDestroyed (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:02 GMT-0500 (CDT) | sip.transport | received WebSocket text message: (sip.js, line 639)

SIP/2.0 100 Trying
Via: SIP/2.0/WS i4dbigviujcd.invalid;branch=z9hG4bK1432058;received=67.78.97.126;rport=51219
From: "Lyle Pratt" <sip:lylepratt-1111@redacted.com>;tag=6fq8nutlmu
To: <sip:user-lylepratt-1234@redacted.com>
Call-ID: ncoc77ckqtafuhmoovpe
CSeq: 2096 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.5.11+git~20140702T185727Z~d1a96c546b~64bit
Content-Length: 0

[Log] Thu Jul 03 2014 12:15:03 GMT-0500 (CDT) | sip.transaction.ict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:03 GMT-0500 (CDT) | sip.transport | received WebSocket text message: (sip.js, line 639)

SIP/2.0 180 Ringing
Via: SIP/2.0/WS i4dbigviujcd.invalid;branch=z9hG4bK1432058;received=67.78.97.126;rport=51219
From: "Lyle Pratt" <sip:lylepratt-1111@redacted.com>;tag=6fq8nutlmu
To: <sip:user-lylepratt-1234@redacted.com>;tag=HN5mc2prHjU6g
Call-ID: ncoc77ckqtafuhmoovpe
CSeq: 2096 INVITE
Contact: <sip:user-lylepratt-1234@162.243.144.62:5060;transport=udp>
User-Agent: FreeSWITCH-mod_sofia/1.5.11+git~20140702T185727Z~d1a96c546b~64bit
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Length: 0
Remote-Party-ID: "Outbound Call" <sip:coeqk220@redacted.com>;party=calling;privacy=off;screen=no

[Log] Thu Jul 03 2014 12:15:04 GMT-0500 (CDT) | sip.dialog | new UAC dialog created with status EARLY (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:04 GMT-0500 (CDT) | sip.inviteclientcontext | emitting event progress (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:09 GMT-0500 (CDT) | sip.ua | emitting event newTransaction (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:09 GMT-0500 (CDT) | sip.transaction.nict | adding event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:09 GMT-0500 (CDT) | sip.transaction.nict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:09 GMT-0500 (CDT) | sip.transport | sending WebSocket message: (sip.js, line 639)

REGISTER sip:redacted.com SIP/2.0
Via: SIP/2.0/WS i4dbigviujcd.invalid;branch=z9hG4bK6859312
Max-Forwards: 70
To: <sip:lylepratt-1111@redacted.com>
From: "Lyle Pratt" <sip:lylepratt-1111@redacted.com>;tag=46463oglop
Call-ID: v720aacvb3ovondurcf2qi
CSeq: 87 REGISTER
Authorization: Digest algorithm=MD5, username="lylepratt-1111", realm="redacted.com", nonce="84c95df0-02d5-11e4-aaa0-95208176e1b2", uri="sip:redacted.com", response="fd5c34a23cbfdc026b65bd8502de1b24", qop=auth, cnonce="e6ruaum8b710", nc=00000001
Contact: <sip:lshcqspa@i4dbigviujcd.invalid;transport=ws>;reg-id=1;+sip.instance="<urn:uuid:e9ea7a0c-1c45-416f-afac-1bb63c648460>";expires=600
Allow: ACK,CANCEL,BYE,OPTIONS,INFO,NOTIFY
Supported: path,gruu,outbound
User-Agent: SIP.js/0.5.0-devel
Content-Length: 0

[Log] Thu Jul 03 2014 12:15:09 GMT-0500 (CDT) | sip.transport | received WebSocket text message: (sip.js, line 639)

SIP/2.0 401 Unauthorized
Via: SIP/2.0/WS i4dbigviujcd.invalid;branch=z9hG4bK6859312;received=67.78.97.126;rport=51219
From: "Lyle Pratt" <sip:lylepratt-1111@redacted.com>;tag=46463oglop
To: <sip:lylepratt-1111@redacted.com>;tag=K7Q6FrrZB47Br
Call-ID: v720aacvb3ovondurcf2qi
CSeq: 87 REGISTER
User-Agent: FreeSWITCH-mod_sofia/1.5.11+git~20140702T185727Z~d1a96c546b~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
WWW-Authenticate: Digest realm="redacted.com", nonce="95d8a75e-02d5-11e4-aab1-95208176e1b2", stale=true, algorithm=MD5, qop="auth"
Content-Length: 0

[Log] Thu Jul 03 2014 12:15:09 GMT-0500 (CDT) | sip.transaction.nict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:09 GMT-0500 (CDT) | sip.ua | emitting event newTransaction (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:09 GMT-0500 (CDT) | sip.transaction.nict | adding event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:09 GMT-0500 (CDT) | sip.transaction.nict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:09 GMT-0500 (CDT) | sip.transport | sending WebSocket message: (sip.js, line 639)

REGISTER sip:redacted.com SIP/2.0
Via: SIP/2.0/WS i4dbigviujcd.invalid;branch=z9hG4bK8386511
Max-Forwards: 70
To: <sip:lylepratt-1111@redacted.com>
From: "Lyle Pratt" <sip:lylepratt-1111@redacted.com>;tag=46463oglop
Call-ID: v720aacvb3ovondurcf2qi
CSeq: 88 REGISTER
Authorization: Digest algorithm=MD5, username="lylepratt-1111", realm="redacted.com", nonce="95d8a75e-02d5-11e4-aab1-95208176e1b2", uri="sip:redacted.com", response="1de9f7083a35d7a4520d7080f25a7ede", qop=auth, cnonce="dipb7rrmo097", nc=00000001
Contact: <sip:lshcqspa@i4dbigviujcd.invalid;transport=ws>;reg-id=1;+sip.instance="<urn:uuid:e9ea7a0c-1c45-416f-afac-1bb63c648460>";expires=600
Allow: ACK,CANCEL,BYE,OPTIONS,INFO,NOTIFY
Supported: path,gruu,outbound
User-Agent: SIP.js/0.5.0-devel
Content-Length: 0

[Log] Thu Jul 03 2014 12:15:09 GMT-0500 (CDT) | sip.transaction.nict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:09 GMT-0500 (CDT) | sip.ua | emitting event transactionDestroyed (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:10 GMT-0500 (CDT) | sip.transport | received WebSocket text message: (sip.js, line 639)

SIP/2.0 200 OK
Via: SIP/2.0/WS i4dbigviujcd.invalid;branch=z9hG4bK8386511;received=67.78.97.126;rport=51219
From: "Lyle Pratt" <sip:lylepratt-1111@redacted.com>;tag=46463oglop
To: <sip:lylepratt-1111@redacted.com>;tag=mgHZHK928cyyK
Call-ID: v720aacvb3ovondurcf2qi
CSeq: 88 REGISTER
Contact: <sip:lshcqspa@67.78.97.126:51219;transport=ws;received=67.78.97.126:51219>;expires=30
Date: Thu, 03 Jul 2014 17:15:10 GMT
User-Agent: FreeSWITCH-mod_sofia/1.5.11+git~20140702T185727Z~d1a96c546b~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Content-Length: 0

[Log] Thu Jul 03 2014 12:15:11 GMT-0500 (CDT) | sip.transaction.nict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:11 GMT-0500 (CDT) | sip.registercontext | emitting event accepted (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:11 GMT-0500 (CDT) | sip.registercontext | emitting event registered (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:11 GMT-0500 (CDT) | sip.ua | emitting event registered (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:11 GMT-0500 (CDT) | sip.transaction.nict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:11 GMT-0500 (CDT) | sip.ua | emitting event transactionDestroyed (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:21 GMT-0500 (CDT) | sip.transport | received WebSocket text message: (sip.js, line 639)

SIP/2.0 200 OK
Via: SIP/2.0/WS i4dbigviujcd.invalid;branch=z9hG4bK1432058;received=67.78.97.126;rport=51219
From: "Lyle Pratt" <sip:lylepratt-1111@redacted.com>;tag=6fq8nutlmu
To: <sip:user-lylepratt-1234@redacted.com>;tag=HN5mc2prHjU6g
Call-ID: ncoc77ckqtafuhmoovpe
CSeq: 2096 INVITE
Contact: <sip:user-lylepratt-1234@162.243.144.62:5060;transport=udp>
User-Agent: FreeSWITCH-mod_sofia/1.5.11+git~20140702T185727Z~d1a96c546b~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Session-Expires: 120;refresher=uas
Min-SE: 120
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 799
Remote-Party-ID: "Outbound Call" <sip:coeqk220@redacted.com>;party=calling;privacy=off;screen=no

v=0
o=FreeSWITCH 1404379711 1404379712 IN IP4 162.243.144.62
s=FreeSWITCH
c=IN IP4 162.243.144.62
t=0 0
a=msid-semantic: WMS Iw5PZ4P9TMfhAkrKMZnUUVrXt8r7AjK8
m=audio 28010 RTP/SAVPF 0 126 106
a=rtpmap:0 PCMU/8000
a=rtpmap:126 telephone-event/8000
a=rtpmap:106 CN/8000
a=recvonly
a=ptime:20
a=fingerprint:sha-1 49:62:23:6D:B7:42:82:92:44:82:5C:94:BC:44:FE:0E:93:0A:F9:F2
a=rtcp-mux
a=rtcp:28010 IN IP4 162.243.144.62
a=ssrc:1418223765 cname:GFOvAtvj5BrvLJ6n
a=ssrc:1418223765 msid:Iw5PZ4P9TMfhAkrKMZnUUVrXt8r7AjK8 a0
a=ssrc:1418223765 mslabel:Iw5PZ4P9TMfhAkrKMZnUUVrXt8r7AjK8
a=ssrc:1418223765 label:Iw5PZ4P9TMfhAkrKMZnUUVrXt8r7AjK8a0
a=ice-ufrag:yj8j5p6onnmOxWN3
a=ice-pwd:srpSKL2Gcj2NSY1h8Zq3fnis
a=candidate:1450951828 1 udp 659136 162.243.144.62 28010 typ host generation 0

[Log] Thu Jul 03 2014 12:15:22 GMT-0500 (CDT) | sip.transaction.ict | emitting event stateChanged (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:22 GMT-0500 (CDT) | sip.dialog | dialog ncoc77ckqtafuhmoovpe6fq8nutlmuHN5mc2prHjU6g  changed to CONFIRMED state (sip.js, line 639)
[Log] Thu Jul 03 2014 12:15:22 GMT-0500 (CDT) | sip.invitecontext.mediahandler | XXX setRemoteDescription: answer (sip.js, line 639)
v=0
o=FreeSWITCH 1404379711 1404379712 IN IP4 162.243.144.62
s=FreeSWITCH
c=IN IP4 162.243.144.62
t=0 0
a=msid-semantic: WMS Iw5PZ4P9TMfhAkrKMZnUUVrXt8r7AjK8
m=audio 28010 RTP/SAVPF 0 126 106
a=rtpmap:0 PCMU/8000
a=rtpmap:126 telephone-event/8000
a=rtpmap:106 CN/8000
a=recvonly
a=ptime:20
a=fingerprint:sha-1 49:62:23:6D:B7:42:82:92:44:82:5C:94:BC:44:FE:0E:93:0A:F9:F2
a=rtcp-mux
a=rtcp:28010 IN IP4 162.243.144.62
a=ssrc:1418223765 cname:GFOvAtvj5BrvLJ6n
a=ssrc:1418223765 msid:Iw5PZ4P9TMfhAkrKMZnUUVrXt8r7AjK8 a0
a=ssrc:1418223765 mslabel:Iw5PZ4P9TMfhAkrKMZnUUVrXt8r7AjK8
a=ssrc:1418223765 label:Iw5PZ4P9TMfhAkrKMZnUUVrXt8r7AjK8a0
a=ice-ufrag:yj8j5p6onnmOxWN3
a=ice-pwd:srpSKL2Gcj2NSY1h8Zq3fnis
a=candidate:1450951828 1 udp 659136 162.243.144.62 28010 typ host generation 0

[Log] Thu Jul 03 2014 12:15:22 GMT-0500 (CDT) | sip.transport | sending WebSocket message: (sip.js, line 639)

ACK sip:user-lylepratt-1234@162.243.144.62:5060;transport=udp SIP/2.0
Via: SIP/2.0/WS i4dbigviujcd.invalid;branch=z9hG4bK787089
Max-Forwards: 70
To: <sip:user-lylepratt-1234@redacted.com>;tag=HN5mc2prHjU6g
From: "Lyle Pratt" <sip:lylepratt-1111@redacted.com>;tag=6fq8nutlmu
Call-ID: ncoc77ckqtafuhmoovpe
CSeq: 2096 ACK
Supported: outbound
User-Agent: SIP.js/0.5.0-devel
Content-Length: 0

[Log] Thu Jul 03 2014 12:15:22 GMT-0500 (CDT) | sip.inviteclientcontext | emitting event accepted (sip.js, line 639)
[Log] Callee answered! (console-via-logger.js, line 173)
[Log] Thu Jul 03 2014 12:15:23 GMT-0500 (CDT) | sip.transport | received WebSocket text message: (sip.js, line 639)

SIP/2.0 200 OK
Via: SIP/2.0/WS i4dbigviujcd.invalid;branch=z9hG4bK1432058;received=67.78.97.126;rport=51219
From: "Lyle Pratt" <sip:lylepratt-1111@redacted.com>;tag=6fq8nutlmu
To: <sip:user-lylepratt-1234@redacted.com>;tag=HN5mc2prHjU6g
Call-ID: ncoc77ckqtafuhmoovpe
CSeq: 2096 INVITE
Contact: <sip:user-lylepratt-1234@162.243.144.62:5060;transport=udp>
User-Agent: FreeSWITCH-mod_sofia/1.5.11+git~20140702T185727Z~d1a96c546b~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Session-Expires: 120;refresher=uas
Min-SE: 120
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 799
Remote-Party-ID: "Outbound Call" <sip:coeqk220@redacted.com>;party=calling;privacy=off;screen=no

v=0
o=FreeSWITCH 1404379711 1404379712 IN IP4 162.243.144.62
s=FreeSWITCH
c=IN IP4 162.243.144.62
t=0 0
a=msid-semantic: WMS Iw5PZ4P9TMfhAkrKMZnUUVrXt8r7AjK8
m=audio 28010 RTP/SAVPF 0 126 106
a=rtpmap:0 PCMU/8000
a=rtpmap:126 telephone-event/8000
a=rtpmap:106 CN/8000
a=recvonly
a=ptime:20
a=fingerprint:sha-1 49:62:23:6D:B7:42:82:92:44:82:5C:94:BC:44:FE:0E:93:0A:F9:F2
a=rtcp-mux
a=rtcp:28010 IN IP4 162.243.144.62
a=ssrc:1418223765 cname:GFOvAtvj5BrvLJ6n
a=ssrc:1418223765 msid:Iw5PZ4P9TMfhAkrKMZnUUVrXt8r7AjK8 a0
a=ssrc:1418223765 mslabel:Iw5PZ4P9TMfhAkrKMZnUUVrXt8r7AjK8
a=ssrc:1418223765 label:Iw5PZ4P9TMfhAkrKMZnUUVrXt8r7AjK8a0
a=ice-ufrag:yj8j5p6onnmOxWN3
a=ice-pwd:srpSKL2Gcj2NSY1h8Zq3fnis
a=candidate:1450951828 1 udp 659136 162.243.144.62 28010 typ host generation 0

[Log] Thu Jul 03 2014 12:15:23 GMT-0500 (CDT) | sip.transport | sending WebSocket message: (sip.js, line 639)

ACK sip:user-lylepratt-1234@162.243.144.62:5060;transport=udp SIP/2.0
Via: SIP/2.0/WS i4dbigviujcd.invalid;branch=z9hG4bK5885739
Max-Forwards: 70
To: <sip:user-lylepratt-1234@redacted.com>;tag=HN5mc2prHjU6g
From: "Lyle Pratt" <sip:lylepratt-1111@redacted.com>;tag=6fq8nutlmu
Call-ID: ncoc77ckqtafuhmoovpe
CSeq: 2096 ACK
Supported: outbound
User-Agent: SIP.js/0.5.0-devel
Content-Length: 0

[Log] Thu Jul 03 2014 12:15:34 GMT-0500 (CDT) | sip.transaction.ict | Timer B expired for INVITE client transaction z9hG4bK1432058 (sip.js, line 639)
egreenmachine commented 10 years ago

Very clearly an SDP problem. Note the a=a= on the candidates.

josephfrazier commented 10 years ago

Oh, the WebRTC libraries for iOS probably need to be updated. See https://github.com/joseph-onsip/sipjs-cordova/commit/4151eb92fe30edcbd1dd5c58355273b0743f9961

alongubkin commented 10 years ago

But @egreenmachine just updated them, didn't he?

lylepratt commented 10 years ago

I'll git pull and try again shortly.

lylepratt commented 10 years ago

Same issue on fresh git pull from cordova-sipjs repo.

lylepratt commented 10 years ago

I just got Media on iOS by changing line 89 in PhoneRTCMediaHandler.js to:

var candidate = data.candidate + "\r\n"; //Removed the `"a=" +`

I can push a pull request for that if you want, but I'm not sure if it will break other things.

josephfrazier commented 10 years ago

But @egreenmachine just updated them, didn't he?

It looks like they're currently behind the Android WebRTC libraries by about 200 commits: https://github.com/alongubkin/phonertc/tree/6ad3dd5090342bc7fa366632f386f22ed58186b8/libs

I just got it to work by changing line 89 in PhoneRTCMediaHandler.js to:

var candidate = data.candidate + "\r\n"; //Removed the `"a=" +`

Yes, the newer WebRTC libraries report candidates without the leading "a=", so I had to add it back in.

lylepratt commented 10 years ago

So solution is to update the WebRTC libraries in PhoneRTC and it will work correctly as-is without my change above?

josephfrazier commented 10 years ago

It should, assuming the WebRTC API is kept consistent across platforms for each commit.

lylepratt commented 10 years ago

Makes sense, and explains why it works on Android, but not on iOS. Older library on iOS. Let me know if there is something I can do to help in that.

josephfrazier commented 10 years ago

Well, you could recompile WebRTC for iOS. Or just wait for @alongubkin or @egreenmachine to do it.

lylepratt commented 10 years ago

I'll give it a go and report back!

lylepratt commented 10 years ago

Success! And it fixed this issue. Creating Pull Request now.

josephfrazier commented 10 years ago

Glad to hear it :smiley:

noahxinhao commented 8 years ago

does it work now?