root@shirley:~# cat /var/log/asterisk/myDebugLog [Apr 8 12:58:45] VERBOSE[15248] config.c: == Parsing '/etc/asterisk/logger.conf': [Apr 8 12:58:45] DEBUG[15248] config.c: Parsing /etc/asterisk/logger.conf [Apr 8 12:58:45] VERBOSE[15248] config.c: == Found [Apr 8 12:58:45] VERBOSE[15248] logger.c: Asterisk Queue Logger restarted [Apr 8 12:58:45] DEBUG[13920] chan_sip.c: Allocating new SIP dialog for 667517a36e405aea1650fd8c42166171@172.30.1.47:5060 - OPTIONS (No RTP) [Apr 8 12:58:45] DEBUG[13920] acl.c: For destination '172.30.245.71', our source address is '172.30.1.47'. [Apr 8 12:58:45] DEBUG[13920] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 172.30.1.47:5060 [Apr 8 12:58:45] DEBUG[13920] chan_sip.c: Initializing initreq for method OPTIONS - callid 12537b541a35e16a0a0731d82f30e203@172.30.1.47:5060 [Apr 8 12:58:45] DEBUG[13920] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 172.30.245.71:5060 [Apr 8 12:58:45] DEBUG[13920] chan_sip.c: = Looking for Call ID: 12537b541a35e16a0a0731d82f30e203@172.30.1.47:5060 (Checking To) --From tag as03dc0943 --To-tag 4AAB6B21-5778653A [Apr 8 12:58:45] DEBUG[13920] chan_sip.c: Stopping retransmission on '12537b541a35e16a0a0731d82f30e203@172.30.1.47:5060' of Request 102: Match Found [Apr 8 12:58:45] DEBUG[13920] chan_sip.c: Destroying SIP dialog 12537b541a35e16a0a0731d82f30e203@172.30.1.47:5060 [Apr 8 12:58:59] DEBUG[13915] chan_iax2.c: Allocate call number [Apr 8 12:58:59] DEBUG[13915] chan_iax2.c: ip callno count incremented to 2 for 172.30.245.208 [Apr 8 12:58:59] DEBUG[13915] chan_iax2.c: Registration created on call 715 [Apr 8 12:58:59] DEBUG[13914] chan_iax2.c: schedule decrement of callno used for 172.30.245.208 in 60 seconds [Apr 8 12:59:09] DEBUG[13908] chan_iax2.c: ip callno count decremented to 1 for 172.30.245.208 [Apr 8 12:59:23] VERBOSE[13920] chan_sip.c: <--- SIP read from UDP:172.30.254.48:5060 ---> INVITE sip:7624@172.30.1.47:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 172.30.254.48;branch=z9hG4bK2f2634f4C8756E5D From: "Cambridge Guest" ;tag=DA87FFEE-A33412B9 To: CSeq: 1 INVITE Call-ID: 47e59e82-4cf00900-7c1efcf3@172.30.254.48 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 Supported: 100rel,replaces Allow-Events: talk,hold,conference Max-Forwards: 70 Content-Type: application/sdp Content-Length: 251 v=0 o=- 1302282025 1302282025 IN IP4 172.30.254.48 s=Polycom IP Phone c=IN IP4 172.30.254.48 t=0 0 a=sendrecv m=audio 2230 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 <-------------> [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Header 0 [ 51]: INVITE sip:7624@172.30.1.47:5060;user=phone SIP/2.0 [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Header 1 [ 61]: Via: SIP/2.0/UDP 172.30.254.48;branch=z9hG4bK2f2634f4C8756E5D [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Header 2 [ 68]: From: "Cambridge Guest" ;tag=DA87FFEE-A33412B9 [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Header 3 [ 37]: To: [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Header 4 [ 14]: CSeq: 1 INVITE [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Header 5 [ 49]: Call-ID: 47e59e82-4cf00900-7c1efcf3@172.30.254.48 [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Header 6 [ 33]: Contact: [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Header 7 [ 96]: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Header 8 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Header 9 [ 26]: Supported: 100rel,replaces [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Header 10 [ 34]: Allow-Events: talk,hold,conference [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Header 11 [ 16]: Max-Forwards: 70 [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Header 13 [ 19]: Content-Length: 251 [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Header 14 [ 0]: [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Body 0 [ 3]: v=0 [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Body 1 [ 46]: o=- 1302282025 1302282025 IN IP4 172.30.254.48 [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Body 2 [ 18]: s=Polycom IP Phone [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Body 3 [ 22]: c=IN IP4 172.30.254.48 [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Body 4 [ 5]: t=0 0 [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Body 5 [ 10]: a=sendrecv [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Body 6 [ 31]: m=audio 2230 RTP/AVP 0 8 18 101 [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Body 8 [ 20]: a=rtpmap:8 PCMA/8000 [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Body 9 [ 21]: a=rtpmap:18 G729/8000 [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Body 10 [ 33]: a=rtpmap:101 telephone-event/8000 [Apr 8 12:59:23] VERBOSE[13920] chan_sip.c: --- (14 headers 11 lines) --- [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: = Looking for Call ID: 47e59e82-4cf00900-7c1efcf3@172.30.254.48 (Checking From) --From tag DA87FFEE-A33412B9 --To-tag [Apr 8 12:59:23] DEBUG[13920] acl.c: For destination '172.30.254.48', our source address is '172.30.1.47'. [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 172.30.1.47:5060 [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Allocating new SIP dialog for 47e59e82-4cf00900-7c1efcf3@172.30.254.48 - INVITE (No RTP) [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Apr 8 12:59:23] DEBUG[13920] sip/reqresp_parser.c: Begin: parsing SIP "Supported: 100rel,replaces" [Apr 8 12:59:23] DEBUG[13920] sip/reqresp_parser.c: Found SIP option: -100rel- [Apr 8 12:59:23] DEBUG[13920] sip/reqresp_parser.c: Matched SIP option: 100rel [Apr 8 12:59:23] DEBUG[13920] sip/reqresp_parser.c: Found SIP option: -replaces- [Apr 8 12:59:23] DEBUG[13920] sip/reqresp_parser.c: Matched SIP option: replaces [Apr 8 12:59:23] DEBUG[13920] netsock2.c: Splitting '172.30.254.48' gives... [Apr 8 12:59:23] DEBUG[13920] netsock2.c: ...host '172.30.254.48' and port '(null)'. [Apr 8 12:59:23] VERBOSE[13920] chan_sip.c: Sending to 172.30.254.48:5060 (no NAT) [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Initializing initreq for method INVITE - callid 47e59e82-4cf00900-7c1efcf3@172.30.254.48 [Apr 8 12:59:23] VERBOSE[13920] chan_sip.c: Using INVITE request as basis request - 47e59e82-4cf00900-7c1efcf3@172.30.254.48 [Apr 8 12:59:23] VERBOSE[13920] chan_sip.c: Found peer '7527' for '7527' from 172.30.254.48:5060 [Apr 8 12:59:23] DEBUG[13920] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x2815898' [Apr 8 12:59:23] DEBUG[13920] res_rtp_asterisk.c: Allocated port 19680 for RTP instance '0x2815898' [Apr 8 12:59:23] DEBUG[13920] rtp_engine.c: RTP instance '0x2815898' is setup and ready to go [Apr 8 12:59:23] DEBUG[13920] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x2815898' [Apr 8 12:59:23] VERBOSE[13920] netsock2.c: == Using SIP RTP CoS mark 5 [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Setting NAT on RTP to Off [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Processing session-level SDP o=- 1302282025 1302282025 IN IP4 172.30.254.48... UNSUPPORTED. [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Processing session-level SDP s=Polycom IP Phone... UNSUPPORTED. [Apr 8 12:59:23] DEBUG[13920] netsock2.c: Splitting '172.30.254.48' gives... [Apr 8 12:59:23] DEBUG[13920] netsock2.c: ...host '172.30.254.48' and port '(null)'. [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Processing session-level SDP c=IN IP4 172.30.254.48... OK. [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Processing session-level SDP a=sendrecv... OK. [Apr 8 12:59:23] VERBOSE[13920] chan_sip.c: Found RTP audio format 0 [Apr 8 12:59:23] DEBUG[13920] rtp_engine.c: Setting payload 0 based on m type on 0x7fd0925f1f80 [Apr 8 12:59:23] VERBOSE[13920] chan_sip.c: Found RTP audio format 8 [Apr 8 12:59:23] DEBUG[13920] rtp_engine.c: Setting payload 8 based on m type on 0x7fd0925f1f80 [Apr 8 12:59:23] VERBOSE[13920] chan_sip.c: Found RTP audio format 18 [Apr 8 12:59:23] DEBUG[13920] rtp_engine.c: Setting payload 18 based on m type on 0x7fd0925f1f80 [Apr 8 12:59:23] VERBOSE[13920] chan_sip.c: Found RTP audio format 101 [Apr 8 12:59:23] DEBUG[13920] rtp_engine.c: Setting payload 101 based on m type on 0x7fd0925f1f80 [Apr 8 12:59:23] VERBOSE[13920] chan_sip.c: Found audio description format PCMU for ID 0 [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Apr 8 12:59:23] VERBOSE[13920] chan_sip.c: Found audio description format PCMA for ID 8 [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Apr 8 12:59:23] VERBOSE[13920] chan_sip.c: Found audio description format G729 for ID 18 [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Apr 8 12:59:23] VERBOSE[13920] chan_sip.c: Found audio description format telephone-event for ID 101 [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Apr 8 12:59:23] DEBUG[13920] rtp_engine.c: Incorporating payload 0 on 0x7fd0925f1f80 [Apr 8 12:59:23] DEBUG[13920] rtp_engine.c: Incorporating payload 8 on 0x7fd0925f1f80 [Apr 8 12:59:23] DEBUG[13920] rtp_engine.c: Incorporating payload 18 on 0x7fd0925f1f80 [Apr 8 12:59:23] DEBUG[13920] rtp_engine.c: Incorporating payload 101 on 0x7fd0925f1f80 [Apr 8 12:59:23] VERBOSE[13920] chan_sip.c: Capabilities: us - 0x6 (gsm|ulaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) [Apr 8 12:59:23] VERBOSE[13920] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Apr 8 12:59:23] DEBUG[13920] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2815898' [Apr 8 12:59:23] VERBOSE[13920] chan_sip.c: Peer audio RTP is at port 172.30.254.48:2230 [Apr 8 12:59:23] DEBUG[13920] rtp_engine.c: Copying payload 0 from 0x7fd0925f1f80 to 0x2815a60 [Apr 8 12:59:23] DEBUG[13920] rtp_engine.c: Copying payload 8 from 0x7fd0925f1f80 to 0x2815a60 [Apr 8 12:59:23] DEBUG[13920] rtp_engine.c: Copying payload 18 from 0x7fd0925f1f80 to 0x2815a60 [Apr 8 12:59:23] DEBUG[13920] rtp_engine.c: Copying payload 101 from 0x7fd0925f1f80 to 0x2815a60 [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Checking SIP call limits for device 7527 [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Updating call counter for incoming call [Apr 8 12:59:23] VERBOSE[13920] chan_sip.c: Looking for 7624 in from-sip (domain 172.30.1.47:5060) [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: *** Our capabilities are 0x6 (gsm|ulaw) [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: This channel will not be able to handle video. [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: build_route: Contact hop: [Apr 8 12:59:23] VERBOSE[13920] chan_sip.c: list_route: hop: [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: SIP/7527-000000d8: New call is still down.... Trying... [Apr 8 12:59:23] VERBOSE[13920] chan_sip.c: <--- Transmitting (no NAT) to 172.30.254.48:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 172.30.254.48;branch=z9hG4bK2f2634f4C8756E5D;received=172.30.254.48 From: "Cambridge Guest" ;tag=DA87FFEE-A33412B9 To: Call-ID: 47e59e82-4cf00900-7c1efcf3@172.30.254.48 CSeq: 1 INVITE Server: Asterisk PBX 1.8.3.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [Apr 8 12:59:23] DEBUG[13920] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 172.30.254.48:5060 [Apr 8 12:59:23] DEBUG[13900] devicestate.c: No provider found, checking channel drivers for SIP - 7527 [Apr 8 12:59:23] DEBUG[13900] chan_sip.c: Checking device state for peer 7527 [Apr 8 12:59:23] DEBUG[13900] devicestate.c: Changing state for SIP/7527 - state 1 (Not in use) [Apr 8 12:59:23] DEBUG[13900] devicestate.c: device 'SIP/7527' state '1' [Apr 8 12:59:23] DEBUG[15249] pbx.c: Result of 'EXTEN' is '7624' [Apr 8 12:59:23] DEBUG[15249] pbx.c: Result of 'EXTEN' is '7624' [Apr 8 12:59:23] DEBUG[15249] pbx.c: Launching 'Macro' [Apr 8 12:59:23] VERBOSE[15249] pbx.c: -- Executing [7624@from-sip:1] Macro("SIP/7527-000000d8", "stdexten,7624,SIP/7624") in new stack [Apr 8 12:59:23] DEBUG[15249] pbx.c: Result of 'ARG2' is 'SIP/7624' [Apr 8 12:59:23] DEBUG[15249] pbx.c: Result of 'ARG1' is '7624' [Apr 8 12:59:23] DEBUG[15249] pbx.c: Launching 'Dial' [Apr 8 12:59:23] VERBOSE[15249] pbx.c: -- Executing [s@macro-stdexten:1] Dial("SIP/7527-000000d8", "SIP/7624&IAX2/7624,20,t") in new stack [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: Allocating new SIP dialog for 7f2406893c0f8bf10e0e27486b311e5a@172.30.1.47:5060 - INVITE (No RTP) [Apr 8 12:59:23] DEBUG[15249] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fd084007178' [Apr 8 12:59:23] DEBUG[15249] res_rtp_asterisk.c: Allocated port 12384 for RTP instance '0x7fd084007178' [Apr 8 12:59:23] DEBUG[15249] rtp_engine.c: RTP instance '0x7fd084007178' is setup and ready to go [Apr 8 12:59:23] DEBUG[15249] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fd084007178' [Apr 8 12:59:23] VERBOSE[15249] netsock2.c: == Using SIP RTP CoS mark 5 [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: Setting NAT on RTP to Off [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: OBPROXY: Not applying OBproxy to this call [Apr 8 12:59:23] DEBUG[13927] app_queue.c: Device 'SIP/7527' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 8 12:59:23] DEBUG[15249] netsock2.c: Splitting '7624' gives... [Apr 8 12:59:23] DEBUG[15249] netsock2.c: ...host '7624' and port '(null)'. [Apr 8 12:59:23] WARNING[15249] acl.c: Cannot connect [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 172.30.1.47:5060 [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: *** Our capabilities are 0x6 (gsm|ulaw) [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: This channel will not be able to handle video. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable DIALEDTIME. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable ANSWEREDTIME. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable DIALEDPEERNAME. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable DIALEDPEERNUMBER. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable DIALSTATUS. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable MACRO_DEPTH. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable ARG2. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable ARG1. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable MACRO_PRIORITY. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable MACRO_CONTEXT. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable MACRO_EXTEN. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable SIPCALLID. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable SIPDOMAIN. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable SIPURI. [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: Outgoing Call for [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: Updating call counter for outgoing call [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: ** Our capability: 0x6 (gsm|ulaw) Video flag: False Text flag: False [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Apr 8 12:59:23] VERBOSE[15249] chan_sip.c: Audio is at 5060 [Apr 8 12:59:23] VERBOSE[15249] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [Apr 8 12:59:23] VERBOSE[15249] chan_sip.c: Adding codec 0x2 (gsm) to SDP [Apr 8 12:59:23] VERBOSE[15249] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: -- Done with adding codecs to SDP [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: Done building SDP. Settling with this capability: 0x6 (gsm|ulaw) [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: Initializing initreq for method INVITE - callid 6d8be7981c3219884243c61b4a4de639@172.30.1.47:5060 [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: Header 0 [ 23]: INVITE sip:7624 SIP/2.0 [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: Header 1 [ 56]: Via: SIP/2.0/UDP 172.30.1.47:5060;branch=z9hG4bK1789e45d [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: Header 3 [ 61]: From: "Cambridge Guest" ;tag=as1f3e09eb [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: Header 4 [ 14]: To: [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: Header 5 [ 36]: Contact: [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: Header 6 [ 58]: Call-ID: 6d8be7981c3219884243c61b4a4de639@172.30.1.47:5060 [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: Header 8 [ 32]: User-Agent: Asterisk PBX 1.8.3.2 [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: Header 9 [ 35]: Date: Fri, 08 Apr 2011 19:59:23 GMT [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [Apr 8 12:59:23] VERBOSE[15249] chan_sip.c: Reliably Transmitting (no NAT) to 0.0.29.200:5060: INVITE sip:7624 SIP/2.0 Via: SIP/2.0/UDP 172.30.1.47:5060;branch=z9hG4bK1789e45d Max-Forwards: 70 From: "Cambridge Guest" ;tag=as1f3e09eb To: Contact: Call-ID: 6d8be7981c3219884243c61b4a4de639@172.30.1.47:5060 CSeq: 102 INVITE User-Agent: Asterisk PBX 1.8.3.2 Date: Fri, 08 Apr 2011 19:59:23 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Type: application/sdp Content-Length: 257 v=0 o=root 1103328122 1103328122 IN IP4 172.30.1.47 s=Asterisk PBX 1.8.3.2 c=IN IP4 172.30.1.47 t=0 0 m=audio 12384 RTP/AVP 0 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #9245 [Apr 8 12:59:23] DEBUG[15249] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 0.0.29.200:5060 [Apr 8 12:59:23] WARNING[15249] chan_sip.c: sip_xmit of 0x2f32e00 (len 789) to 0.0.29.200:5060 returned -1: Invalid argument [Apr 8 12:59:23] VERBOSE[15249] app_dial.c: -- Called 7624 [Apr 8 12:59:23] DEBUG[15249] netsock2.c: Splitting '7624' gives... [Apr 8 12:59:23] DEBUG[15249] netsock2.c: ...host '7624' and port '(null)'. [Apr 8 12:59:23] DEBUG[15249] chan_iax2.c: ip callno count incremented to 1 for 0.0.29.200 [Apr 8 12:59:23] DEBUG[15249] chan_iax2.c: New max nontrunk callno is 4966 [Apr 8 12:59:23] DEBUG[15249] chan_iax2.c: Creating new call structure 4965 [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable DIALEDTIME. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable ANSWEREDTIME. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable DIALEDPEERNAME. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable DIALEDPEERNUMBER. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable DIALSTATUS. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable MACRO_DEPTH. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable ARG2. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable ARG1. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable MACRO_PRIORITY. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable MACRO_CONTEXT. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable MACRO_EXTEN. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable SIPCALLID. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable SIPDOMAIN. [Apr 8 12:59:23] DEBUG[15249] channel.c: Not copying variable SIPURI. [Apr 8 12:59:23] DEBUG[15249] netsock2.c: Splitting '7624' gives... [Apr 8 12:59:23] DEBUG[15249] netsock2.c: ...host '7624' and port '(null)'. [Apr 8 12:59:23] DEBUG[15249] chan_iax2.c: OSP token is undefined [Apr 8 12:59:23] DEBUG[13907] chan_iax2.c: Sending 5 on 4965/0 to 0.0.29.200:4569 [Apr 8 12:59:23] VERBOSE[13907] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW [Apr 8 12:59:23] VERBOSE[13907] chan_iax2.c: Timestamp: 00005ms SCall: 04965 DCall: 00000 [0.0.29.200:4569] [Apr 8 12:59:23] VERBOSE[13907] chan_iax2.c: VERSION : 2 [Apr 8 12:59:23] VERBOSE[13907] chan_iax2.c: CALLED NUMBER : s [Apr 8 12:59:23] VERBOSE[13907] chan_iax2.c: CODEC_PREFS : () [Apr 8 12:59:23] VERBOSE[13907] chan_iax2.c: CALLING NUMBER : 7527 [Apr 8 12:59:23] VERBOSE[13907] chan_iax2.c: CALLING PRESNTN : 0 [Apr 8 12:59:23] VERBOSE[13907] chan_iax2.c: CALLING TYPEOFN : 0 [Apr 8 12:59:23] VERBOSE[13907] chan_iax2.c: CALLING TRANSIT : 0 [Apr 8 12:59:23] VERBOSE[13907] chan_iax2.c: CALLING NAME : Cambridge Guest [Apr 8 12:59:23] VERBOSE[13907] chan_iax2.c: LANGUAGE : en [Apr 8 12:59:23] VERBOSE[13907] chan_iax2.c: FORMAT : 2 [Apr 8 12:59:23] VERBOSE[13907] chan_iax2.c: FORMAT2 : gsm [Apr 8 12:59:23] VERBOSE[13907] chan_iax2.c: CAPABILITY : 1795 [Apr 8 12:59:23] VERBOSE[13907] chan_iax2.c: CAPABILITY2 : unknown [Apr 8 12:59:23] VERBOSE[13907] chan_iax2.c: ADSICPE : 2 [Apr 8 12:59:23] VERBOSE[13907] chan_iax2.c: DATE TIME : 2011-04-08 12:59:22 [Apr 8 12:59:23] VERBOSE[13907] chan_iax2.c: [Apr 8 12:59:23] DEBUG[13907] chan_iax2.c: Received error: Invalid argument [Apr 8 12:59:23] VERBOSE[15249] app_dial.c: -- Called 7624 [Apr 8 12:59:23] DEBUG[13900] devicestate.c: No provider found, checking channel drivers for IAX2 - 0.0.29.200:4569 [Apr 8 12:59:23] DEBUG[13900] chan_iax2.c: Checking device state for device 0.0.29.200 [Apr 8 12:59:23] DEBUG[13900] devicestate.c: Changing state for IAX2/0.0.29.200:4569 - state 4 (Invalid) [Apr 8 12:59:23] DEBUG[13900] devicestate.c: device 'IAX2/0.0.29.200:4569' state '4' [Apr 8 12:59:23] DEBUG[13927] app_queue.c: Device 'IAX2/0.0.29.200:4569' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 8 12:59:24] DEBUG[13920] chan_sip.c: SIP TIMER: Rescheduling retransmission #9245 (1) INVITE - 5 [Apr 8 12:59:24] DEBUG[13920] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #9245)) [Apr 8 12:59:24] VERBOSE[13920] chan_sip.c: Retransmitting #1 (no NAT) to 0.0.29.200:5060: INVITE sip:7624 SIP/2.0 Via: SIP/2.0/UDP 172.30.1.47:5060;branch=z9hG4bK1789e45d Max-Forwards: 70 From: "Cambridge Guest" ;tag=as1f3e09eb To: Contact: Call-ID: 6d8be7981c3219884243c61b4a4de639@172.30.1.47:5060 CSeq: 102 INVITE User-Agent: Asterisk PBX 1.8.3.2 Date: Fri, 08 Apr 2011 19:59:23 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Type: application/sdp Content-Length: 257 v=0 o=root 1103328122 1103328122 IN IP4 172.30.1.47 s=Asterisk PBX 1.8.3.2 c=IN IP4 172.30.1.47 t=0 0 m=audio 12384 RTP/AVP 0 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- [Apr 8 12:59:24] DEBUG[13920] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 0.0.29.200:5060 [Apr 8 12:59:24] WARNING[13920] chan_sip.c: sip_xmit of 0x2f32e00 (len 789) to 0.0.29.200:5060 returned -1: Invalid argument [Apr 8 12:59:25] DEBUG[13920] chan_sip.c: SIP TIMER: Rescheduling retransmission #9245 (2) INVITE - 5 [Apr 8 12:59:25] DEBUG[13920] chan_sip.c: ** SIP timers: Rescheduling retransmission 3 to 2000 ms (t1 500 ms (Retrans id #9245)) [Apr 8 12:59:25] VERBOSE[13920] chan_sip.c: Retransmitting #2 (no NAT) to 0.0.29.200:5060: INVITE sip:7624 SIP/2.0 Via: SIP/2.0/UDP 172.30.1.47:5060;branch=z9hG4bK1789e45d Max-Forwards: 70 From: "Cambridge Guest" ;tag=as1f3e09eb To: Contact: Call-ID: 6d8be7981c3219884243c61b4a4de639@172.30.1.47:5060 CSeq: 102 INVITE User-Agent: Asterisk PBX 1.8.3.2 Date: Fri, 08 Apr 2011 19:59:23 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Type: application/sdp Content-Length: 257 v=0 o=root 1103328122 1103328122 IN IP4 172.30.1.47 s=Asterisk PBX 1.8.3.2 c=IN IP4 172.30.1.47 t=0 0 m=audio 12384 RTP/AVP 0 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- [Apr 8 12:59:25] DEBUG[13920] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 0.0.29.200:5060 [Apr 8 12:59:25] WARNING[13920] chan_sip.c: sip_xmit of 0x2f32e00 (len 789) to 0.0.29.200:5060 returned -1: Invalid argument [Apr 8 12:59:25] DEBUG[13910] chan_iax2.c: Sending 5 on 4965/0 to 0.0.29.200:4569 [Apr 8 12:59:25] VERBOSE[13910] chan_iax2.c: Tx-Frame Retry[001] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW [Apr 8 12:59:25] VERBOSE[13910] chan_iax2.c: Timestamp: 00005ms SCall: 04965 DCall: 00000 [0.0.29.200:4569] [Apr 8 12:59:25] VERBOSE[13910] chan_iax2.c: VERSION : 2 [Apr 8 12:59:25] VERBOSE[13910] chan_iax2.c: CALLED NUMBER : s [Apr 8 12:59:25] VERBOSE[13910] chan_iax2.c: CODEC_PREFS : () [Apr 8 12:59:25] VERBOSE[13910] chan_iax2.c: CALLING NUMBER : 7527 [Apr 8 12:59:25] VERBOSE[13910] chan_iax2.c: CALLING PRESNTN : 0 [Apr 8 12:59:25] VERBOSE[13910] chan_iax2.c: CALLING TYPEOFN : 0 [Apr 8 12:59:25] VERBOSE[13910] chan_iax2.c: CALLING TRANSIT : 0 [Apr 8 12:59:25] VERBOSE[13910] chan_iax2.c: CALLING NAME : Cambridge Guest [Apr 8 12:59:25] VERBOSE[13910] chan_iax2.c: LANGUAGE : en [Apr 8 12:59:25] VERBOSE[13910] chan_iax2.c: FORMAT : 2 [Apr 8 12:59:25] VERBOSE[13910] chan_iax2.c: FORMAT2 : gsm [Apr 8 12:59:25] VERBOSE[13910] chan_iax2.c: CAPABILITY : 1795 [Apr 8 12:59:25] VERBOSE[13910] chan_iax2.c: CAPABILITY2 : unknown [Apr 8 12:59:25] VERBOSE[13910] chan_iax2.c: ADSICPE : 2 [Apr 8 12:59:25] VERBOSE[13910] chan_iax2.c: DATE TIME : 2011-04-08 12:59:22 [Apr 8 12:59:25] VERBOSE[13910] chan_iax2.c: [Apr 8 12:59:25] DEBUG[13910] chan_iax2.c: Received error: Invalid argument [Apr 8 12:59:27] DEBUG[13920] chan_sip.c: SIP TIMER: Rescheduling retransmission #9245 (3) INVITE - 5 [Apr 8 12:59:27] DEBUG[13920] chan_sip.c: ** SIP timers: Rescheduling retransmission 4 to 4000 ms (t1 500 ms (Retrans id #9245)) [Apr 8 12:59:27] VERBOSE[13920] chan_sip.c: Retransmitting #3 (no NAT) to 0.0.29.200:5060: INVITE sip:7624 SIP/2.0 Via: SIP/2.0/UDP 172.30.1.47:5060;branch=z9hG4bK1789e45d Max-Forwards: 70 From: "Cambridge Guest" ;tag=as1f3e09eb To: Contact: Call-ID: 6d8be7981c3219884243c61b4a4de639@172.30.1.47:5060 CSeq: 102 INVITE User-Agent: Asterisk PBX 1.8.3.2 Date: Fri, 08 Apr 2011 19:59:23 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Type: application/sdp Content-Length: 257 v=0 o=root 1103328122 1103328122 IN IP4 172.30.1.47 s=Asterisk PBX 1.8.3.2 c=IN IP4 172.30.1.47 t=0 0 m=audio 12384 RTP/AVP 0 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- [Apr 8 12:59:27] DEBUG[13920] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 0.0.29.200:5060 [Apr 8 12:59:27] WARNING[13920] chan_sip.c: sip_xmit of 0x2f32e00 (len 789) to 0.0.29.200:5060 returned -1: Invalid argument [Apr 8 12:59:27] NOTICE[13917] chan_iax2.c: Auto-congesting call due to slow response [Apr 8 12:59:27] VERBOSE[15249] app_dial.c: -- IAX2/0.0.29.200:4569-4965 is circuit-busy [Apr 8 12:59:27] DEBUG[15249] channel.c: Hanging up channel 'IAX2/0.0.29.200:4569-4965' [Apr 8 12:59:27] DEBUG[15249] chan_iax2.c: We're hanging up IAX2/0.0.29.200:4569-4965 now... [Apr 8 12:59:27] VERBOSE[15249] chan_iax2.c: -- Hungup 'IAX2/0.0.29.200:4569-4965' [Apr 8 12:59:27] DEBUG[13907] chan_iax2.c: Sending 4005 on 4965/0 to 0.0.29.200:4569 [Apr 8 12:59:27] VERBOSE[13907] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: HANGUP [Apr 8 12:59:27] VERBOSE[13907] chan_iax2.c: Timestamp: 04005ms SCall: 04965 DCall: 00000 [0.0.29.200:4569] [Apr 8 12:59:27] VERBOSE[13907] chan_iax2.c: CAUSE CODE : 0 [Apr 8 12:59:27] VERBOSE[13907] chan_iax2.c: [Apr 8 12:59:27] DEBUG[13907] chan_iax2.c: Received error: Invalid argument [Apr 8 12:59:27] DEBUG[13900] devicestate.c: No provider found, checking channel drivers for IAX2 - 0.0.29.200:4569 [Apr 8 12:59:27] DEBUG[13900] chan_iax2.c: Checking device state for device 0.0.29.200 [Apr 8 12:59:27] DEBUG[13900] devicestate.c: Changing state for IAX2/0.0.29.200:4569 - state 4 (Invalid) [Apr 8 12:59:27] DEBUG[13900] devicestate.c: device 'IAX2/0.0.29.200:4569' state '4' [Apr 8 12:59:27] DEBUG[13927] app_queue.c: Device 'IAX2/0.0.29.200:4569' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 8 12:59:29] DEBUG[13911] chan_iax2.c: Sending 4005 on 4965/0 to 0.0.29.200:4569 [Apr 8 12:59:29] VERBOSE[13911] chan_iax2.c: Tx-Frame Retry[001] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: HANGUP [Apr 8 12:59:29] VERBOSE[13911] chan_iax2.c: Timestamp: 04005ms SCall: 04965 DCall: 00000 [0.0.29.200:4569] [Apr 8 12:59:29] VERBOSE[13911] chan_iax2.c: CAUSE CODE : 0 [Apr 8 12:59:29] VERBOSE[13911] chan_iax2.c: [Apr 8 12:59:29] DEBUG[13911] chan_iax2.c: Received error: Invalid argument [Apr 8 12:59:31] DEBUG[13920] chan_sip.c: SIP TIMER: Rescheduling retransmission #9245 (4) INVITE - 5 [Apr 8 12:59:31] DEBUG[13920] chan_sip.c: ** SIP timers: Rescheduling retransmission 5 to 8000 ms (t1 500 ms (Retrans id #9245)) [Apr 8 12:59:31] VERBOSE[13920] chan_sip.c: Retransmitting #4 (no NAT) to 0.0.29.200:5060: INVITE sip:7624 SIP/2.0 Via: SIP/2.0/UDP 172.30.1.47:5060;branch=z9hG4bK1789e45d Max-Forwards: 70 From: "Cambridge Guest" ;tag=as1f3e09eb To: Contact: Call-ID: 6d8be7981c3219884243c61b4a4de639@172.30.1.47:5060 CSeq: 102 INVITE User-Agent: Asterisk PBX 1.8.3.2 Date: Fri, 08 Apr 2011 19:59:23 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Type: application/sdp Content-Length: 257 v=0 o=root 1103328122 1103328122 IN IP4 172.30.1.47 s=Asterisk PBX 1.8.3.2 c=IN IP4 172.30.1.47 t=0 0 m=audio 12384 RTP/AVP 0 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- [Apr 8 12:59:31] DEBUG[13920] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 0.0.29.200:5060 [Apr 8 12:59:31] WARNING[13920] chan_sip.c: sip_xmit of 0x2f32e00 (len 789) to 0.0.29.200:5060 returned -1: Invalid argument [Apr 8 12:59:35] DEBUG[13909] chan_iax2.c: Sending 5 on 4965/0 to 0.0.29.200:4569 [Apr 8 12:59:35] VERBOSE[13909] chan_iax2.c: Tx-Frame Retry[002] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW [Apr 8 12:59:35] VERBOSE[13909] chan_iax2.c: Timestamp: 00005ms SCall: 04965 DCall: 00000 [0.0.29.200:4569] [Apr 8 12:59:35] VERBOSE[13909] chan_iax2.c: VERSION : 2 [Apr 8 12:59:35] VERBOSE[13909] chan_iax2.c: CALLED NUMBER : s [Apr 8 12:59:35] VERBOSE[13909] chan_iax2.c: CODEC_PREFS : () [Apr 8 12:59:35] VERBOSE[13909] chan_iax2.c: CALLING NUMBER : 7527 [Apr 8 12:59:35] VERBOSE[13909] chan_iax2.c: CALLING PRESNTN : 0 [Apr 8 12:59:35] VERBOSE[13909] chan_iax2.c: CALLING TYPEOFN : 0 [Apr 8 12:59:35] VERBOSE[13909] chan_iax2.c: CALLING TRANSIT : 0 [Apr 8 12:59:35] VERBOSE[13909] chan_iax2.c: CALLING NAME : Cambridge Guest [Apr 8 12:59:35] VERBOSE[13909] chan_iax2.c: LANGUAGE : en [Apr 8 12:59:35] VERBOSE[13909] chan_iax2.c: FORMAT : 2 [Apr 8 12:59:35] VERBOSE[13909] chan_iax2.c: FORMAT2 : gsm [Apr 8 12:59:35] VERBOSE[13909] chan_iax2.c: CAPABILITY : 1795 [Apr 8 12:59:35] VERBOSE[13909] chan_iax2.c: CAPABILITY2 : unknown [Apr 8 12:59:35] VERBOSE[13909] chan_iax2.c: ADSICPE : 2 [Apr 8 12:59:35] VERBOSE[13909] chan_iax2.c: DATE TIME : 2011-04-08 12:59:22 [Apr 8 12:59:35] VERBOSE[13909] chan_iax2.c: [Apr 8 12:59:35] DEBUG[13909] chan_iax2.c: Received error: Invalid argument [Apr 8 12:59:37] DEBUG[13908] chan_iax2.c: Really destroying 4965 now... [Apr 8 12:59:37] DEBUG[13908] chan_iax2.c: schedule decrement of callno used for 0.0.29.200 in 60 seconds [Apr 8 12:59:39] DEBUG[13920] chan_sip.c: SIP TIMER: Rescheduling retransmission #9245 (5) INVITE - 5 [Apr 8 12:59:39] DEBUG[13920] chan_sip.c: ** SIP timers: Rescheduling retransmission 6 to 16000 ms (t1 500 ms (Retrans id #9245)) [Apr 8 12:59:39] VERBOSE[13920] chan_sip.c: Retransmitting #5 (no NAT) to 0.0.29.200:5060: INVITE sip:7624 SIP/2.0 Via: SIP/2.0/UDP 172.30.1.47:5060;branch=z9hG4bK1789e45d Max-Forwards: 70 From: "Cambridge Guest" ;tag=as1f3e09eb To: Contact: Call-ID: 6d8be7981c3219884243c61b4a4de639@172.30.1.47:5060 CSeq: 102 INVITE User-Agent: Asterisk PBX 1.8.3.2 Date: Fri, 08 Apr 2011 19:59:23 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Type: application/sdp Content-Length: 257 v=0 o=root 1103328122 1103328122 IN IP4 172.30.1.47 s=Asterisk PBX 1.8.3.2 c=IN IP4 172.30.1.47 t=0 0 m=audio 12384 RTP/AVP 0 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- [Apr 8 12:59:39] DEBUG[13920] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 0.0.29.200:5060 [Apr 8 12:59:39] WARNING[13920] chan_sip.c: sip_xmit of 0x2f32e00 (len 789) to 0.0.29.200:5060 returned -1: Invalid argument [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Allocating new SIP dialog for 3e06e51f1660a6623f5f6c734a7964d5@172.30.1.47:5060 - OPTIONS (No RTP) [Apr 8 12:59:43] DEBUG[13920] acl.c: For destination '172.30.254.48', our source address is '172.30.1.47'. [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 172.30.1.47:5060 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Initializing initreq for method OPTIONS - callid 77506e220482eae05f3dbdbd0b9dcb7c@172.30.1.47:5060 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 0 [ 38]: OPTIONS sip:7527@172.30.254.48 SIP/2.0 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 1 [ 56]: Via: SIP/2.0/UDP 172.30.1.47:5060;branch=z9hG4bK7dc3ffd7 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 3 [ 58]: From: "asterisk" ;tag=as57dfe083 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 4 [ 28]: To: [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 5 [ 40]: Contact: [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 6 [ 58]: Call-ID: 77506e220482eae05f3dbdbd0b9dcb7c@172.30.1.47:5060 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 8 [ 32]: User-Agent: Asterisk PBX 1.8.3.2 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 9 [ 35]: Date: Fri, 08 Apr 2011 19:59:43 GMT [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Apr 8 12:59:43] VERBOSE[13920] chan_sip.c: Reliably Transmitting (no NAT) to 172.30.254.48:5060: OPTIONS sip:7527@172.30.254.48 SIP/2.0 Via: SIP/2.0/UDP 172.30.1.47:5060;branch=z9hG4bK7dc3ffd7 Max-Forwards: 70 From: "asterisk" ;tag=as57dfe083 To: Contact: Call-ID: 77506e220482eae05f3dbdbd0b9dcb7c@172.30.1.47:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.3.2 Date: Fri, 08 Apr 2011 19:59:43 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #9247 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 172.30.254.48:5060 [Apr 8 12:59:43] VERBOSE[13920] chan_sip.c: <--- SIP read from UDP:172.30.254.48:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.30.1.47:5060;branch=z9hG4bK7dc3ffd7 From: "asterisk" ;tag=as57dfe083 To: ;tag=BE6D0D1A-BD7D95D5 CSeq: 102 OPTIONS Call-ID: 77506e220482eae05f3dbdbd0b9dcb7c@172.30.1.47:5060 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 Content-Length: 0 <-------------> [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 1 [ 56]: Via: SIP/2.0/UDP 172.30.1.47:5060;branch=z9hG4bK7dc3ffd7 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 2 [ 58]: From: "asterisk" ;tag=as57dfe083 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 3 [ 50]: To: ;tag=BE6D0D1A-BD7D95D5 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 4 [ 17]: CSeq: 102 OPTIONS [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 5 [ 58]: Call-ID: 77506e220482eae05f3dbdbd0b9dcb7c@172.30.1.47:5060 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 6 [ 33]: Contact: [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 7 [ 96]: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 8 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Apr 8 12:59:43] VERBOSE[13920] chan_sip.c: --- (10 headers 0 lines) --- [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: = Looking for Call ID: 77506e220482eae05f3dbdbd0b9dcb7c@172.30.1.47:5060 (Checking To) --From tag as57dfe083 --To-tag BE6D0D1A-BD7D95D5 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #9247 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Stopping retransmission on '77506e220482eae05f3dbdbd0b9dcb7c@172.30.1.47:5060' of Request 102: Match Found [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Destroying SIP dialog 77506e220482eae05f3dbdbd0b9dcb7c@172.30.1.47:5060 [Apr 8 12:59:43] VERBOSE[13920] chan_sip.c: Really destroying SIP dialog '77506e220482eae05f3dbdbd0b9dcb7c@172.30.1.47:5060' Method: OPTIONS [Apr 8 12:59:43] VERBOSE[15249] app_dial.c: -- Nobody picked up in 20000 ms [Apr 8 12:59:43] DEBUG[15249] channel.c: Hanging up channel 'SIP/7624-000000d9' [Apr 8 12:59:43] DEBUG[15249] chan_sip.c: Hangup call SIP/7624-000000d9, SIP callid 6d8be7981c3219884243c61b4a4de639@172.30.1.47:5060 [Apr 8 12:59:43] DEBUG[15249] chan_sip.c: Hanging up channel in state Down (not UP) [Apr 8 12:59:43] DEBUG[15249] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fd084007178' [Apr 8 12:59:43] VERBOSE[15249] chan_sip.c: Scheduling destruction of SIP dialog '6d8be7981c3219884243c61b4a4de639@172.30.1.47:5060' in 32000 ms (Method: INVITE) [Apr 8 12:59:43] DEBUG[15249] app_dial.c: Exiting with DIALSTATUS=NOANSWER. [Apr 8 12:59:43] DEBUG[15249] app_macro.c: Executed application: Dial [Apr 8 12:59:43] DEBUG[15249] pbx.c: Result of 'DIALSTATUS' is 'NOANSWER' [Apr 8 12:59:43] DEBUG[15249] pbx.c: Launching 'Goto' [Apr 8 12:59:43] VERBOSE[15249] pbx.c: -- Executing [s@macro-stdexten:2] Goto("SIP/7527-000000d8", "s-NOANSWER,1") in new stack [Apr 8 12:59:43] VERBOSE[15249] pbx.c: -- Goto (macro-stdexten,s-NOANSWER,1) [Apr 8 12:59:43] DEBUG[15249] app_macro.c: Executed application: Goto [Apr 8 12:59:43] DEBUG[15249] pbx.c: Result of 'ARG1' is '7624' [Apr 8 12:59:43] DEBUG[15249] pbx.c: Launching 'VoiceMail' [Apr 8 12:59:43] VERBOSE[15249] pbx.c: -- Executing [s-NOANSWER@macro-stdexten:1] VoiceMail("SIP/7527-000000d8", "7624,u") in new stack [Apr 8 12:59:43] DEBUG[15249] chan_sip.c: SIP answering channel: SIP/7527-000000d8 [Apr 8 12:59:43] DEBUG[15249] res_rtp_asterisk.c: Setting the marker bit due to a source update [Apr 8 12:59:43] DEBUG[15249] chan_sip.c: Setting framing from config on incoming call [Apr 8 12:59:43] DEBUG[15249] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Apr 8 12:59:43] DEBUG[15249] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Apr 8 12:59:43] VERBOSE[15249] chan_sip.c: Audio is at 5060 [Apr 8 12:59:43] VERBOSE[15249] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [Apr 8 12:59:43] VERBOSE[15249] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Apr 8 12:59:43] DEBUG[15249] chan_sip.c: -- Done with adding codecs to SDP [Apr 8 12:59:43] DEBUG[15249] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 8 12:59:43] VERBOSE[15249] chan_sip.c: <--- Reliably Transmitting (no NAT) to 172.30.254.48:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.30.254.48;branch=z9hG4bK2f2634f4C8756E5D;received=172.30.254.48 From: "Cambridge Guest" ;tag=DA87FFEE-A33412B9 To: ;tag=as6819eff0 Call-ID: 47e59e82-4cf00900-7c1efcf3@172.30.254.48 CSeq: 1 INVITE Server: Asterisk PBX 1.8.3.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 234 v=0 o=root 1513891678 1513891678 IN IP4 172.30.1.47 s=Asterisk PBX 1.8.3.2 c=IN IP4 172.30.1.47 t=0 0 m=audio 19680 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> [Apr 8 12:59:43] DEBUG[15249] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #9251 [Apr 8 12:59:43] DEBUG[15249] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 172.30.254.48:5060 [Apr 8 12:59:43] DEBUG[13900] devicestate.c: No provider found, checking channel drivers for SIP - 7624 [Apr 8 12:59:43] DEBUG[13900] chan_sip.c: Checking device state for peer 7624 [Apr 8 12:59:43] DEBUG[13900] devicestate.c: Changing state for SIP/7624 - state 0 (Unknown) [Apr 8 12:59:43] DEBUG[13900] devicestate.c: device 'SIP/7624' state '0' [Apr 8 12:59:43] DEBUG[13900] devicestate.c: No provider found, checking channel drivers for SIP - 7527 [Apr 8 12:59:43] DEBUG[13900] chan_sip.c: Checking device state for peer 7527 [Apr 8 12:59:43] DEBUG[13900] devicestate.c: Changing state for SIP/7527 - state 1 (Not in use) [Apr 8 12:59:43] DEBUG[13900] devicestate.c: device 'SIP/7527' state '1' [Apr 8 12:59:43] DEBUG[13927] app_queue.c: Device 'SIP/7624' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Apr 8 12:59:43] DEBUG[13927] app_queue.c: Device 'SIP/7527' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 8 12:59:43] VERBOSE[13920] chan_sip.c: <--- SIP read from UDP:172.30.254.48:5060 ---> ACK sip:7624@172.30.1.47:5060 SIP/2.0 Via: SIP/2.0/UDP 172.30.254.48;branch=z9hG4bKd83fe22bD9972658 From: "Cambridge Guest" ;tag=DA87FFEE-A33412B9 To: ;tag=as6819eff0 CSeq: 1 ACK Call-ID: 47e59e82-4cf00900-7c1efcf3@172.30.254.48 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 Max-Forwards: 70 Content-Length: 0 <-------------> [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 0 [ 37]: ACK sip:7624@172.30.1.47:5060 SIP/2.0 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 1 [ 61]: Via: SIP/2.0/UDP 172.30.254.48;branch=z9hG4bKd83fe22bD9972658 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 2 [ 68]: From: "Cambridge Guest" ;tag=DA87FFEE-A33412B9 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 3 [ 52]: To: ;tag=as6819eff0 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 4 [ 11]: CSeq: 1 ACK [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 5 [ 49]: Call-ID: 47e59e82-4cf00900-7c1efcf3@172.30.254.48 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 6 [ 33]: Contact: [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 7 [ 96]: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 8 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 9 [ 16]: Max-Forwards: 70 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Apr 8 12:59:43] VERBOSE[13920] chan_sip.c: --- (11 headers 0 lines) --- [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: = Looking for Call ID: 47e59e82-4cf00900-7c1efcf3@172.30.254.48 (Checking From) --From tag DA87FFEE-A33412B9 --To-tag as6819eff0 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #9251 [Apr 8 12:59:43] DEBUG[13920] chan_sip.c: Stopping retransmission on '47e59e82-4cf00900-7c1efcf3@172.30.254.48' of Response 1: Match Found [Apr 8 12:59:44] DEBUG[15249] app_voicemail.c: Before find_user [Apr 8 12:59:44] WARNING[15249] app_voicemail.c: No entry in voicemail config file for '7624' [Apr 8 12:59:44] DEBUG[15249] app_macro.c: Executed application: Voicemail [Apr 8 12:59:44] DEBUG[15249] pbx.c: Launching 'Goto' [Apr 8 12:59:44] VERBOSE[15249] pbx.c: -- Executing [s-NOANSWER@macro-stdexten:2] Goto("SIP/7527-000000d8", "default,s,1") in new stack [Apr 8 12:59:44] VERBOSE[15249] pbx.c: -- Goto (default,s,1) [Apr 8 12:59:44] DEBUG[15249] app_macro.c: Executed application: Goto [Apr 8 12:59:44] VERBOSE[15249] app_macro.c: == Channel 'SIP/7527-000000d8' jumping out of macro 'stdexten' [Apr 8 12:59:44] VERBOSE[15249] pbx.c: -- Sent into invalid extension 's' in context 'default' on SIP/7527-000000d8 [Apr 8 12:59:44] DEBUG[15249] pbx.c: Launching 'Playback' [Apr 8 12:59:44] VERBOSE[15249] pbx.c: -- Executing [i@default:1] Playback("SIP/7527-000000d8", "invalid") in new stack [Apr 8 12:59:44] DEBUG[15249] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [Apr 8 12:59:44] DEBUG[15249] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [Apr 8 12:59:44] DEBUG[15249] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Apr 8 12:59:44] VERBOSE[15249] file.c: -- Playing 'invalid.ulaw' (language 'en') [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Allocating new SIP dialog for 07dfc610136a384f24aaf8b12f895896@172.30.1.47:5060 - OPTIONS (No RTP) [Apr 8 12:59:45] DEBUG[13920] acl.c: For destination '172.30.245.71', our source address is '172.30.1.47'. [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 172.30.1.47:5060 [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Initializing initreq for method OPTIONS - callid 1dea34bf10da195977eb50966571b306@172.30.1.47:5060 [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Header 0 [ 38]: OPTIONS sip:7516@172.30.245.71 SIP/2.0 [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Header 1 [ 56]: Via: SIP/2.0/UDP 172.30.1.47:5060;branch=z9hG4bK2a3d392b [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Header 3 [ 58]: From: "asterisk" ;tag=as2a39f1f5 [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Header 4 [ 28]: To: [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Header 5 [ 40]: Contact: [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Header 6 [ 58]: Call-ID: 1dea34bf10da195977eb50966571b306@172.30.1.47:5060 [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Header 8 [ 32]: User-Agent: Asterisk PBX 1.8.3.2 [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Header 9 [ 35]: Date: Fri, 08 Apr 2011 19:59:45 GMT [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Apr 8 12:59:45] VERBOSE[13920] chan_sip.c: Reliably Transmitting (no NAT) to 172.30.245.71:5060: OPTIONS sip:7516@172.30.245.71 SIP/2.0 Via: SIP/2.0/UDP 172.30.1.47:5060;branch=z9hG4bK2a3d392b Max-Forwards: 70 From: "asterisk" ;tag=as2a39f1f5 To: Contact: Call-ID: 1dea34bf10da195977eb50966571b306@172.30.1.47:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.3.2 Date: Fri, 08 Apr 2011 19:59:45 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 --- [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #9253 [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 172.30.245.71:5060 [Apr 8 12:59:45] VERBOSE[13920] chan_sip.c: <--- SIP read from UDP:172.30.245.71:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.30.1.47:5060;branch=z9hG4bK2a3d392b From: "asterisk" ;tag=as2a39f1f5 To: ;tag=3AE1872E-EE021A8B CSeq: 102 OPTIONS Call-ID: 1dea34bf10da195977eb50966571b306@172.30.1.47:5060 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 Content-Length: 0 <-------------> [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Header 1 [ 56]: Via: SIP/2.0/UDP 172.30.1.47:5060;branch=z9hG4bK2a3d392b [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Header 2 [ 58]: From: "asterisk" ;tag=as2a39f1f5 [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Header 3 [ 50]: To: ;tag=3AE1872E-EE021A8B [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Header 4 [ 17]: CSeq: 102 OPTIONS [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Header 5 [ 58]: Call-ID: 1dea34bf10da195977eb50966571b306@172.30.1.47:5060 [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Header 6 [ 33]: Contact: [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Header 7 [ 96]: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Header 8 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Apr 8 12:59:45] VERBOSE[13920] chan_sip.c: --- (10 headers 0 lines) --- [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: = Looking for Call ID: 1dea34bf10da195977eb50966571b306@172.30.1.47:5060 (Checking To) --From tag as2a39f1f5 --To-tag 3AE1872E-EE021A8B [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #9253 [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Stopping retransmission on '1dea34bf10da195977eb50966571b306@172.30.1.47:5060' of Request 102: Match Found [Apr 8 12:59:45] DEBUG[13920] chan_sip.c: Destroying SIP dialog 1dea34bf10da195977eb50966571b306@172.30.1.47:5060 [Apr 8 12:59:45] VERBOSE[13920] chan_sip.c: Really destroying SIP dialog '1dea34bf10da195977eb50966571b306@172.30.1.47:5060' Method: OPTIONS [Apr 8 12:59:46] DEBUG[15249] res_rtp_asterisk.c: Got RTCP report of 92 bytes [Apr 8 12:59:48] DEBUG[15249] channel.c: Scheduling timer at (74 requested / 74 actual) timer ticks per second [Apr 8 12:59:48] DEBUG[15249] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 8 12:59:48] DEBUG[15249] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 8 12:59:48] DEBUG[15249] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 8 12:59:48] DEBUG[15249] pbx.c: Launching 'Hangup' [Apr 8 12:59:48] VERBOSE[15249] pbx.c: -- Executing [i@default:2] Hangup("SIP/7527-000000d8", "") in new stack [Apr 8 12:59:48] DEBUG[15249] pbx.c: Spawn extension (default,i,2) exited non-zero on 'SIP/7527-000000d8' [Apr 8 12:59:48] VERBOSE[15249] pbx.c: == Spawn extension (default, i, 2) exited non-zero on 'SIP/7527-000000d8' [Apr 8 12:59:48] DEBUG[15249] channel.c: Soft-Hanging up channel 'SIP/7527-000000d8' [Apr 8 12:59:48] DEBUG[15249] channel.c: Hanging up channel 'SIP/7527-000000d8' [Apr 8 12:59:48] DEBUG[15249] chan_sip.c: Hangup call SIP/7527-000000d8, SIP callid 47e59e82-4cf00900-7c1efcf3@172.30.254.48 [Apr 8 12:59:48] DEBUG[15249] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2815898' [Apr 8 12:59:48] VERBOSE[15249] chan_sip.c: Scheduling destruction of SIP dialog '47e59e82-4cf00900-7c1efcf3@172.30.254.48' in 6400 ms (Method: ACK) [Apr 8 12:59:48] DEBUG[15249] chan_sip.c: Strict routing enforced for session 47e59e82-4cf00900-7c1efcf3@172.30.254.48 [Apr 8 12:59:48] VERBOSE[15249] chan_sip.c: set_destination: Parsing for address/port to send to [Apr 8 12:59:48] DEBUG[15249] netsock2.c: Splitting '172.30.254.48' gives... [Apr 8 12:59:48] DEBUG[15249] netsock2.c: ...host '172.30.254.48' and port '(null)'. [Apr 8 12:59:48] VERBOSE[15249] chan_sip.c: set_destination: set destination to 172.30.254.48:5060 [Apr 8 12:59:48] VERBOSE[15249] chan_sip.c: Reliably Transmitting (no NAT) to 172.30.254.48:5060: BYE sip:7527@172.30.254.48 SIP/2.0 Via: SIP/2.0/UDP 172.30.1.47:5060;branch=z9hG4bK1672f8f9 Max-Forwards: 70 From: ;tag=as6819eff0 To: "Cambridge Guest" ;tag=DA87FFEE-A33412B9 Call-ID: 47e59e82-4cf00900-7c1efcf3@172.30.254.48 CSeq: 102 BYE User-Agent: Asterisk PBX 1.8.3.2 X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- [Apr 8 12:59:48] DEBUG[15249] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #9257 [Apr 8 12:59:48] DEBUG[15249] chan_sip.c: Trying to put 'BYE sip:752' onto UDP socket destined for 172.30.254.48:5060 [Apr 8 12:59:48] DEBUG[15249] cdr_mysql.c: Inserting a CDR record. [Apr 8 12:59:48] DEBUG[15249] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (calldate,src,dst,dcontext,channel,dstchannel,lastapp,duration,billsec,disposition,amaflags,uniqueid) VALUES ('2011-04-08 12:59:23','7527','i','default','SIP/7527-000000d8','IAX2/0.0.29.200:4569-4965','Hangup','25','5','ANSWERED','3','1302292763.300') [Apr 8 12:59:48] DEBUG[13900] devicestate.c: No provider found, checking channel drivers for SIP - 7527 [Apr 8 12:59:48] DEBUG[13900] chan_sip.c: Checking device state for peer 7527 [Apr 8 12:59:48] DEBUG[13900] devicestate.c: Changing state for SIP/7527 - state 1 (Not in use) [Apr 8 12:59:48] DEBUG[13900] devicestate.c: device 'SIP/7527' state '1' [Apr 8 12:59:48] DEBUG[13927] app_queue.c: Device 'SIP/7527' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 8 12:59:48] VERBOSE[13920] chan_sip.c: <--- SIP read from UDP:172.30.254.48:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.30.1.47:5060;branch=z9hG4bK1672f8f9 From: ;tag=as6819eff0 To: "Cambridge Guest" ;tag=DA87FFEE-A33412B9 CSeq: 102 BYE Call-ID: 47e59e82-4cf00900-7c1efcf3@172.30.254.48 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 Content-Length: 0 <-------------> [Apr 8 12:59:48] DEBUG[13920] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Apr 8 12:59:48] DEBUG[13920] chan_sip.c: Header 1 [ 56]: Via: SIP/2.0/UDP 172.30.1.47:5060;branch=z9hG4bK1672f8f9 [Apr 8 12:59:48] DEBUG[13920] chan_sip.c: Header 2 [ 54]: From: ;tag=as6819eff0 [Apr 8 12:59:48] DEBUG[13920] chan_sip.c: Header 3 [ 66]: To: "Cambridge Guest" ;tag=DA87FFEE-A33412B9 [Apr 8 12:59:48] DEBUG[13920] chan_sip.c: Header 4 [ 13]: CSeq: 102 BYE [Apr 8 12:59:48] DEBUG[13920] chan_sip.c: Header 5 [ 49]: Call-ID: 47e59e82-4cf00900-7c1efcf3@172.30.254.48 [Apr 8 12:59:48] DEBUG[13920] chan_sip.c: Header 6 [ 33]: Contact: [Apr 8 12:59:48] DEBUG[13920] chan_sip.c: Header 7 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 [Apr 8 12:59:48] DEBUG[13920] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Apr 8 12:59:48] VERBOSE[13920] chan_sip.c: --- (9 headers 0 lines) --- [Apr 8 12:59:48] DEBUG[13920] chan_sip.c: = Looking for Call ID: 47e59e82-4cf00900-7c1efcf3@172.30.254.48 (Checking To) --From tag as6819eff0 --To-tag DA87FFEE-A33412B9 [Apr 8 12:59:48] DEBUG[13920] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #9257 [Apr 8 12:59:48] DEBUG[13920] chan_sip.c: Stopping retransmission on '47e59e82-4cf00900-7c1efcf3@172.30.254.48' of Request 102: Match Found [Apr 8 12:59:48] VERBOSE[13920] chan_sip.c: SIP Response message for INCOMING dialog BYE arrived [Apr 8 12:59:48] DEBUG[13920] chan_sip.c: Destroying SIP dialog 47e59e82-4cf00900-7c1efcf3@172.30.254.48 [Apr 8 12:59:48] VERBOSE[13920] chan_sip.c: Really destroying SIP dialog '47e59e82-4cf00900-7c1efcf3@172.30.254.48' Method: ACK [Apr 8 12:59:48] DEBUG[13920] rtp_engine.c: Destroyed RTP instance '0x2815898' [Apr 8 12:59:49] DEBUG[13916] chan_iax2.c: Sending registration request for 'orasebcam' [Apr 8 12:59:49] DEBUG[13916] chan_iax2.c: Allocate call number [Apr 8 12:59:49] DEBUG[13916] chan_iax2.c: ip callno count incremented to 2 for 172.30.245.208 [Apr 8 12:59:49] DEBUG[13916] chan_iax2.c: New max nontrunk callno is 2094 [Apr 8 12:59:49] DEBUG[13916] chan_iax2.c: Creating new call structure 2093 [Apr 8 12:59:49] DEBUG[13916] chan_iax2.c: Registration created on call 2093 [Apr 8 12:59:49] DEBUG[13907] chan_iax2.c: Sending 6 on 2093/0 to 172.30.245.208:4569 [Apr 8 12:59:49] VERBOSE[13907] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Apr 8 12:59:49] VERBOSE[13907] chan_iax2.c: Timestamp: 00006ms SCall: 02093 DCall: 00000 [172.30.245.208:4569] [Apr 8 12:59:49] VERBOSE[13907] chan_iax2.c: USERNAME : orasebcam [Apr 8 12:59:49] VERBOSE[13907] chan_iax2.c: REFRESH : 60 [Apr 8 12:59:49] VERBOSE[13907] chan_iax2.c: [Apr 8 12:59:49] VERBOSE[13914] chan_iax2.c: Rx-Frame Retry[Yes] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: CTOKEN [Apr 8 12:59:49] VERBOSE[13914] chan_iax2.c: Timestamp: 00006ms SCall: 00001 DCall: 02093 [172.30.245.208:4569] [Apr 8 12:59:49] VERBOSE[13914] chan_iax2.c: CALLTOKEN : 51 bytes [Apr 8 12:59:49] VERBOSE[13914] chan_iax2.c: [Apr 8 12:59:49] DEBUG[13914] chan_iax2.c: Received packet 0, (6, 40) [Apr 8 12:59:49] DEBUG[13914] chan_iax2.c: Cancelling transmission of packet 0 [Apr 8 12:59:49] DEBUG[13914] chan_iax2.c: IAX subclass 40 received [Apr 8 12:59:49] DEBUG[13914] chan_iax2.c: For call=2093, set last=6 [Apr 8 12:59:49] DEBUG[13907] chan_iax2.c: Sending 9 on 2093/0 to 172.30.245.208:4569 [Apr 8 12:59:49] VERBOSE[13907] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Apr 8 12:59:49] VERBOSE[13907] chan_iax2.c: Timestamp: 00009ms SCall: 02093 DCall: 00000 [172.30.245.208:4569] [Apr 8 12:59:49] VERBOSE[13907] chan_iax2.c: USERNAME : orasebcam [Apr 8 12:59:49] VERBOSE[13907] chan_iax2.c: REFRESH : 60 [Apr 8 12:59:49] VERBOSE[13907] chan_iax2.c: CALLTOKEN : 51 bytes [Apr 8 12:59:49] VERBOSE[13907] chan_iax2.c: [Apr 8 12:59:49] VERBOSE[13912] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH [Apr 8 12:59:49] VERBOSE[13912] chan_iax2.c: Timestamp: 00019ms SCall: 15741 DCall: 02093 [172.30.245.208:4569] [Apr 8 12:59:49] VERBOSE[13912] chan_iax2.c: AUTHMETHODS : 2 [Apr 8 12:59:49] VERBOSE[13912] chan_iax2.c: CHALLENGE : \x31\x30\x35\x39\x34\x30\x37\x38\x37 [Apr 8 12:59:49] VERBOSE[13912] chan_iax2.c: USERNAME : orasebcam [Apr 8 12:59:49] VERBOSE[13912] chan_iax2.c: [Apr 8 12:59:49] DEBUG[13912] chan_iax2.c: Received packet 0, (6, 14) [Apr 8 12:59:49] DEBUG[13912] chan_iax2.c: Cancelling transmission of packet 0 [Apr 8 12:59:49] DEBUG[13912] chan_iax2.c: IAX subclass 14 received [Apr 8 12:59:49] DEBUG[13912] chan_iax2.c: For call=2093, set last=19 [Apr 8 12:59:49] DEBUG[13907] chan_iax2.c: Sending 12 on 2093/15741 to 172.30.245.208:4569 [Apr 8 12:59:49] VERBOSE[13907] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ [Apr 8 12:59:49] VERBOSE[13907] chan_iax2.c: Timestamp: 00012ms SCall: 02093 DCall: 15741 [172.30.245.208:4569] [Apr 8 12:59:49] VERBOSE[13907] chan_iax2.c: USERNAME : orasebcam [Apr 8 12:59:49] VERBOSE[13907] chan_iax2.c: REFRESH : 60 [Apr 8 12:59:49] VERBOSE[13907] chan_iax2.c: MD5 RESULT : 63d3cf33db5fcc7a3bc2d6153fd16953 [Apr 8 12:59:49] VERBOSE[13907] chan_iax2.c: [Apr 8 12:59:49] VERBOSE[13918] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK [Apr 8 12:59:49] VERBOSE[13918] chan_iax2.c: Timestamp: 00020ms SCall: 15741 DCall: 02093 [172.30.245.208:4569] [Apr 8 12:59:49] VERBOSE[13918] chan_iax2.c: USERNAME : orasebcam [Apr 8 12:59:49] VERBOSE[13918] chan_iax2.c: DATE TIME : 2011-04-08 13:01:34 [Apr 8 12:59:49] VERBOSE[13918] chan_iax2.c: REFRESH : 60 [Apr 8 12:59:49] VERBOSE[13918] chan_iax2.c: APPARENT ADDRES : IPV4 172.30.1.47:4569 [Apr 8 12:59:49] VERBOSE[13918] chan_iax2.c: [Apr 8 12:59:49] DEBUG[13918] chan_iax2.c: Received packet 1, (6, 15) [Apr 8 12:59:49] DEBUG[13918] chan_iax2.c: Cancelling transmission of packet 1 [Apr 8 12:59:49] DEBUG[13918] chan_iax2.c: IAX subclass 15 received [Apr 8 12:59:49] DEBUG[13918] chan_iax2.c: For call=2093, set last=20 [Apr 8 12:59:49] DEBUG[13918] chan_iax2.c: Sending 20 on 2093/15741 to 172.30.245.208:4569 [Apr 8 12:59:49] VERBOSE[13918] chan_iax2.c: Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK [Apr 8 12:59:49] VERBOSE[13918] chan_iax2.c: Timestamp: 00020ms SCall: 02093 DCall: 15741 [172.30.245.208:4569] [Apr 8 12:59:49] DEBUG[13918] chan_iax2.c: schedule decrement of callno used for 172.30.245.208 in 60 seconds [Apr 8 12:59:55] DEBUG[13920] chan_sip.c: SIP TIMER: Rescheduling retransmission #9245 (6) INVITE - 5 [Apr 8 12:59:55] DEBUG[13920] chan_sip.c: ** SIP timers: Rescheduling retransmission 7 to 32000 ms (t1 500 ms (Retrans id #9245)) [Apr 8 12:59:55] VERBOSE[13920] chan_sip.c: Retransmitting #6 (no NAT) to 0.0.29.200:5060: INVITE sip:7624 SIP/2.0 Via: SIP/2.0/UDP 172.30.1.47:5060;branch=z9hG4bK1789e45d Max-Forwards: 70 From: "Cambridge Guest" ;tag=as1f3e09eb To: Contact: Call-ID: 6d8be7981c3219884243c61b4a4de639@172.30.1.47:5060 CSeq: 102 INVITE User-Agent: Asterisk PBX 1.8.3.2 Date: Fri, 08 Apr 2011 19:59:23 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Type: application/sdp Content-Length: 257 v=0 o=root 1103328122 1103328122 IN IP4 172.30.1.47 s=Asterisk PBX 1.8.3.2 c=IN IP4 172.30.1.47 t=0 0 m=audio 12384 RTP/AVP 0 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- [Apr 8 12:59:55] DEBUG[13920] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 0.0.29.200:5060 [Apr 8 12:59:55] WARNING[13920] chan_sip.c: sip_xmit of 0x2f32e00 (len 789) to 0.0.29.200:5060 returned -1: Invalid argument [Apr 8 12:59:55] WARNING[13920] chan_sip.c: Retransmission timeout reached on transmission 6d8be7981c3219884243c61b4a4de639@172.30.1.47:5060 for seqno 102 (Critical Request) -- See doc/sip-retransmit.txt. Packet timed out after 32000ms with no response [Apr 8 12:59:55] DEBUG[13920] chan_sip.c: Setting SIP_ALREADYGONE on dialog 6d8be7981c3219884243c61b4a4de639@172.30.1.47:5060 [Apr 8 12:59:55] DEBUG[13920] chan_sip.c: Destroying SIP dialog 6d8be7981c3219884243c61b4a4de639@172.30.1.47:5060 [Apr 8 12:59:55] VERBOSE[13920] chan_sip.c: Really destroying SIP dialog '6d8be7981c3219884243c61b4a4de639@172.30.1.47:5060' Method: INVITE [Apr 8 12:59:55] DEBUG[13920] rtp_engine.c: Destroyed RTP instance '0x7fd084007178' [Apr 8 12:59:59] VERBOSE[15248] asterisk.c: -- Remote UNIX connection disconnected [Apr 8 12:59:59] DEBUG[13908] chan_iax2.c: ip callno count decremented to 1 for 172.30.245.208 [Apr 8 13:00:11] VERBOSE[13896] asterisk.c: -- Remote UNIX connection