[Dec 16 21:54:40] VERBOSE[27911] config.c: == Parsing '/etc/asterisk/logger.conf': [Dec 16 21:54:40] DEBUG[27911] config.c: Parsing /etc/asterisk/logger.conf [Dec 16 21:54:40] VERBOSE[27911] config.c: == Found [Dec 16 21:54:40] VERBOSE[27911] logger.c: Asterisk Queue Logger restarted [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Auto destroying SIP dialog '2114317149' [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Destroying SIP dialog 2114317149 [Dec 16 21:55:02] VERBOSE[27769] chan_sip.c: Really destroying SIP dialog '2114317149' Method: OPTIONS [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Auto destroying SIP dialog '924064418' [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Destroying SIP dialog 924064418 [Dec 16 21:55:02] VERBOSE[27769] chan_sip.c: Really destroying SIP dialog '924064418' Method: ACK [Dec 16 21:55:02] DEBUG[27769] rtp_engine.c: Destroyed RTP instance '0x8ad9cf0' [Dec 16 21:55:02] DEBUG[27769] rtp_engine.c: Destroyed RTP instance '0x8add3f8' [Dec 16 21:55:02] VERBOSE[27769] chan_sip.c: <--- SIP read from UDP:192.168.100.6:5060 ---> OPTIONS sip:211@192.168.100.29 SIP/2.0 Via: SIP/2.0/UDP 192.168.100.6:5060;rport;branch=z9hG4bK1856643648 From: "clau" ;tag=1928631702 To: Call-ID: 193245645 CSeq: 20 OPTIONS Accept: application/sdp Max-Forwards: 70 User-Agent: Linphone/3.3.99.8 (eXosip2/3.3.0) Expires: 120 Content-Length: 0 <-------------> [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 0 [ 38]: OPTIONS sip:211@192.168.100.29 SIP/2.0 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 1 [ 66]: Via: SIP/2.0/UDP 192.168.100.6:5060;rport;branch=z9hG4bK1856643648 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 2 [ 52]: From: "clau" ;tag=1928631702 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 3 [ 28]: To: [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 4 [ 18]: Call-ID: 193245645 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 5 [ 16]: CSeq: 20 OPTIONS [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 6 [ 23]: Accept: application/sdp [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 8 [ 45]: User-Agent: Linphone/3.3.99.8 (eXosip2/3.3.0) [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 9 [ 12]: Expires: 120 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Dec 16 21:55:02] VERBOSE[27769] chan_sip.c: --- (11 headers 0 lines) --- [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: = Looking for Call ID: 193245645 (Checking From) --From tag 1928631702 --To-tag [Dec 16 21:55:02] DEBUG[27769] acl.c: For destination '192.168.100.6', our source address is '192.168.100.29'. [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.100.29:5060 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Allocating new SIP dialog for 193245645 - OPTIONS (No RTP) [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Dec 16 21:55:02] VERBOSE[27769] chan_sip.c: Looking for 211 in default (domain 192.168.100.29) [Dec 16 21:55:02] VERBOSE[27769] chan_sip.c: <--- Transmitting (no NAT) to 192.168.100.6:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.100.6:5060;rport;branch=z9hG4bK1856643648;received=192.168.100.6 From: "clau" ;tag=1928631702 To: ;tag=as7e237e61 Call-ID: 193245645 CSeq: 20 OPTIONS Server: Asterisk PBX SVN-trunk-r298686 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Accept: application/sdp Content-Length: 0 <------------> [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.100.6:5060 [Dec 16 21:55:02] VERBOSE[27769] chan_sip.c: Scheduling destruction of SIP dialog '193245645' in 32000 ms (Method: OPTIONS) [Dec 16 21:55:02] VERBOSE[27769] chan_sip.c: <--- SIP read from UDP:192.168.100.6:5060 ---> INVITE sip:211@192.168.100.29 SIP/2.0 Via: SIP/2.0/UDP 192.168.100.6:5060;rport;branch=z9hG4bK1286411818 From: "clau" ;tag=764665301 To: Call-ID: 993614872 CSeq: 20 INVITE Contact: "clau" Content-Type: application/sdp Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Max-Forwards: 70 User-Agent: Linphone/3.3.99.8 (eXosip2/3.3.0) Subject: Phone call Content-Length: 305 v=0 o=clau 123456 654321 IN IP4 192.168.100.6 s=A conversation c=IN IP4 192.168.100.6 b=AS:512 t=0 0 m=audio 7078 RTP/AVP 0 101 b=AS:80 a=rtpmap:0 PCMU/8000/1 a=rtpmap:101 telephone-event/8000/1 a=fmtp:101 0-11 a=sendrecv m=video 9078 RTP/AVP 34 b=AS:422 a=rtpmap:34 H263/90000 a=sendrecv <-------------> [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 0 [ 37]: INVITE sip:211@192.168.100.29 SIP/2.0 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 1 [ 66]: Via: SIP/2.0/UDP 192.168.100.6:5060;rport;branch=z9hG4bK1286411818 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 2 [ 51]: From: "clau" ;tag=764665301 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 3 [ 28]: To: [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 4 [ 18]: Call-ID: 993614872 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 5 [ 15]: CSeq: 20 INVITE [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 6 [ 40]: Contact: "clau" [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 7 [ 29]: Content-Type: application/sdp [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 8 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 9 [ 16]: Max-Forwards: 70 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 10 [ 45]: User-Agent: Linphone/3.3.99.8 (eXosip2/3.3.0) [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 11 [ 19]: Subject: Phone call [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 12 [ 19]: Content-Length: 305 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Header 13 [ 0]: [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Body 0 [ 3]: v=0 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Body 1 [ 41]: o=clau 123456 654321 IN IP4 192.168.100.6 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Body 2 [ 16]: s=A conversation [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Body 3 [ 22]: c=IN IP4 192.168.100.6 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Body 4 [ 8]: b=AS:512 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Body 5 [ 5]: t=0 0 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Body 6 [ 26]: m=audio 7078 RTP/AVP 0 101 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Body 7 [ 7]: b=AS:80 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Body 8 [ 22]: a=rtpmap:0 PCMU/8000/1 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Body 9 [ 35]: a=rtpmap:101 telephone-event/8000/1 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Body 10 [ 15]: a=fmtp:101 0-11 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Body 11 [ 10]: a=sendrecv [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Body 12 [ 23]: m=video 9078 RTP/AVP 34 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Body 13 [ 8]: b=AS:422 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Body 14 [ 22]: a=rtpmap:34 H263/90000 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Body 15 [ 10]: a=sendrecv [Dec 16 21:55:02] VERBOSE[27769] chan_sip.c: --- (13 headers 16 lines) --- [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: = Looking for Call ID: 993614872 (Checking From) --From tag 764665301 --To-tag [Dec 16 21:55:02] DEBUG[27769] acl.c: For destination '192.168.100.6', our source address is '192.168.100.29'. [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.100.29:5060 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Allocating new SIP dialog for 993614872 - INVITE (No RTP) [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Dec 16 21:55:02] DEBUG[27769] netsock2.c: Splitting '192.168.100.6:5060' gives... [Dec 16 21:55:02] DEBUG[27769] netsock2.c: ...host '192.168.100.6' and port '5060'. [Dec 16 21:55:02] VERBOSE[27769] chan_sip.c: Sending to 192.168.100.6:5060 (no NAT) [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Initializing initreq for method INVITE - callid 993614872 [Dec 16 21:55:02] VERBOSE[27769] chan_sip.c: Using INVITE request as basis request - 993614872 [Dec 16 21:55:02] VERBOSE[27769] chan_sip.c: No matching peer for 'clau' from '192.168.100.6:5060' [Dec 16 21:55:02] DEBUG[27769] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x8ad9cf0' [Dec 16 21:55:02] DEBUG[27769] res_rtp_asterisk.c: Allocated port 15652 for RTP instance '0x8ad9cf0' [Dec 16 21:55:02] DEBUG[27769] rtp_engine.c: RTP instance '0x8ad9cf0' is setup and ready to go [Dec 16 21:55:02] DEBUG[27769] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x8add3f8' [Dec 16 21:55:02] DEBUG[27769] res_rtp_asterisk.c: Allocated port 14194 for RTP instance '0x8add3f8' [Dec 16 21:55:02] DEBUG[27769] rtp_engine.c: RTP instance '0x8add3f8' is setup and ready to go [Dec 16 21:55:02] DEBUG[27769] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x8add3f8' [Dec 16 21:55:02] DEBUG[27769] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x8ad9cf0' [Dec 16 21:55:02] VERBOSE[27769] netsock2.c: == Using SIP RTP CoS mark 5 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Setting NAT on RTP to Off [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Setting NAT on VRTP to Off [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Processing session-level SDP o=clau 123456 654321 IN IP4 192.168.100.6... UNSUPPORTED. [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Processing session-level SDP s=A conversation... UNSUPPORTED. [Dec 16 21:55:02] DEBUG[27769] netsock2.c: Splitting '192.168.100.6' gives... [Dec 16 21:55:02] DEBUG[27769] netsock2.c: ...host '192.168.100.6' and port '(null)'. [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.100.6... OK. [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Processing session-level SDP b=AS:512... UNSUPPORTED. [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Dec 16 21:55:02] VERBOSE[27769] chan_sip.c: Found RTP audio format 0 [Dec 16 21:55:02] DEBUG[27769] rtp_engine.c: Setting payload 0 based on m type on 0xb7425954 [Dec 16 21:55:02] VERBOSE[27769] chan_sip.c: Found RTP audio format 101 [Dec 16 21:55:02] DEBUG[27769] rtp_engine.c: Setting payload 101 based on m type on 0xb7425954 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Processing media-level (audio) SDP b=AS:80... UNSUPPORTED. [Dec 16 21:55:02] VERBOSE[27769] chan_sip.c: Found audio description format PCMU for ID 0 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000/1... OK. [Dec 16 21:55:02] VERBOSE[27769] chan_sip.c: Found audio description format telephone-event for ID 101 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000/1... OK. [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-11... UNSUPPORTED. [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Dec 16 21:55:02] VERBOSE[27769] chan_sip.c: Found RTP video format 34 [Dec 16 21:55:02] DEBUG[27769] rtp_engine.c: Setting payload 34 based on m type on 0xb7424cd4 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Processing media-level (video) SDP b=AS:422... UNSUPPORTED. [Dec 16 21:55:02] VERBOSE[27769] chan_sip.c: Found video description format H263 for ID 34 [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Processing media-level (video) SDP a=rtpmap:34 H263/90000... OK. [Dec 16 21:55:02] DEBUG[27769] chan_sip.c: Processing media-level (video) SDP a=sendrecv... OK. [Dec 16 21:55:02] DEBUG[27769] rtp_engine.c: Incorporating payload 0 on 0xb7425954 [Dec 16 21:55:02] DEBUG[27769] rtp_engine.c: Incorporating payload 101 on 0xb7425954 [Dec 16 21:55:02] DEBUG[27769] rtp_engine.c: Incorporating payload 34 on 0xb7424cd4 [Dec 16 21:55:02] VERBOSE[27769] chan_sip.c: Capabilities: us - 0x180004 (ulaw|h263|h263p), peer - audio=0x4 (ulaw)/video=0x80000 (h263)/text=0x0 (nothing), combined - 0x80004 (ulaw|h263) [Dec 16 21:55:02] VERBOSE[27769] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Dec 16 21:55:02] DEBUG[27769] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x8ad9cf0' [Dec 16 21:55:02] VERBOSE[27769] chan_sip.c: Peer audio RTP is at port 192.168.100.6:7078 [Dec 16 21:55:02] DEBUG[27769] rtp_engine.c: Copying payload 0 from 0xb7425954 to 0x8ad9e9c [Dec 16 21:55:03] DEBUG[27769] rtp_engine.c: Copying payload 101 from 0xb7425954 to 0x8ad9e9c [Dec 16 21:55:03] DEBUG[27769] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x8add3f8' [Dec 16 21:55:03] VERBOSE[27769] chan_sip.c: Peer video RTP is at port 192.168.100.6:9078 [Dec 16 21:55:03] DEBUG[27769] rtp_engine.c: Copying payload 34 from 0xb7424cd4 to 0x8add5a4 [Dec 16 21:55:03] DEBUG[27769] chan_sip.c: We're settling with these formats: 0x80004 (ulaw|h263) [Dec 16 21:55:03] DEBUG[27769] chan_sip.c: Checking SIP call limits for device [Dec 16 21:55:03] DEBUG[27769] chan_sip.c: Updating call counter for incoming call [Dec 16 21:55:03] VERBOSE[27769] chan_sip.c: Looking for 211 in default (domain 192.168.100.29) [Dec 16 21:55:03] DEBUG[27769] chan_sip.c: *** Our native formats are 0x80004 (ulaw|h263) [Dec 16 21:55:03] DEBUG[27769] chan_sip.c: *** Joint capabilities are 0x80004 (ulaw|h263) [Dec 16 21:55:03] DEBUG[27769] chan_sip.c: *** Our capabilities are 0x180004 (ulaw|h263|h263p) [Dec 16 21:55:03] DEBUG[27769] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Dec 16 21:55:03] DEBUG[27769] chan_sip.c: This channel can handle video! HOLLYWOOD next! [Dec 16 21:55:03] DEBUG[27769] chan_sip.c: build_route: Contact hop: "clau" [Dec 16 21:55:03] VERBOSE[27769] chan_sip.c: list_route: hop: [Dec 16 21:55:03] DEBUG[27769] chan_sip.c: SIP/192.168.100.6-00000005: New call is still down.... Trying... [Dec 16 21:55:03] VERBOSE[27769] chan_sip.c: <--- Transmitting (no NAT) to 192.168.100.6:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.100.6:5060;branch=z9hG4bK1286411818;received=192.168.100.6;rport=5060 From: "clau" ;tag=764665301 To: Call-ID: 993614872 CSeq: 20 INVITE Server: Asterisk PBX SVN-trunk-r298686 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [Dec 16 21:55:03] DEBUG[27769] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.100.6:5060 [Dec 16 21:55:03] DEBUG[27762] devicestate.c: No provider found, checking channel drivers for SIP - 192.168.100.6 [Dec 16 21:55:03] DEBUG[27762] chan_sip.c: Checking device state for peer 192.168.100.6 [Dec 16 21:55:03] DEBUG[27762] devicestate.c: Changing state for SIP/192.168.100.6 - state 2 (In use) [Dec 16 21:55:03] DEBUG[27762] devicestate.c: device 'SIP/192.168.100.6' state '2' [Dec 16 21:55:03] DEBUG[27914] pbx.c: Launching 'AGI' [Dec 16 21:55:03] VERBOSE[27914] pbx.c: -- Executing [211@default:1] AGI("SIP/192.168.100.6-00000005", "agi://192.168.100.6") in new stack [Dec 16 21:55:03] VERBOSE[27914] res_agi.c: AGI Tx >> agi_network: yes [Dec 16 21:55:03] DEBUG[27914] res_agi.c: Wow, connected! [Dec 16 21:55:03] VERBOSE[27914] res_agi.c: AGI Tx >> agi_request: agi://192.168.100.6 [Dec 16 21:55:03] VERBOSE[27914] res_agi.c: AGI Tx >> agi_channel: SIP/192.168.100.6-00000005 [Dec 16 21:55:03] VERBOSE[27914] res_agi.c: AGI Tx >> agi_language: en [Dec 16 21:55:03] VERBOSE[27914] res_agi.c: AGI Tx >> agi_type: SIP [Dec 16 21:55:03] VERBOSE[27914] res_agi.c: AGI Tx >> agi_uniqueid: 1292554503.5 [Dec 16 21:55:03] VERBOSE[27914] res_agi.c: AGI Tx >> agi_version: SVN-trunk-r298686 [Dec 16 21:55:03] VERBOSE[27914] res_agi.c: AGI Tx >> agi_callerid: clau [Dec 16 21:55:03] VERBOSE[27914] res_agi.c: AGI Tx >> agi_calleridname: clau [Dec 16 21:55:03] VERBOSE[27914] res_agi.c: AGI Tx >> agi_callingpres: 0 [Dec 16 21:55:03] VERBOSE[27914] res_agi.c: AGI Tx >> agi_callingani2: 0 [Dec 16 21:55:03] VERBOSE[27914] res_agi.c: AGI Tx >> agi_callington: 0 [Dec 16 21:55:03] VERBOSE[27914] res_agi.c: AGI Tx >> agi_callingtns: 0 [Dec 16 21:55:03] VERBOSE[27914] res_agi.c: AGI Tx >> agi_dnid: 211 [Dec 16 21:55:03] VERBOSE[27914] res_agi.c: AGI Tx >> agi_rdnis: unknown [Dec 16 21:55:03] VERBOSE[27914] res_agi.c: AGI Tx >> agi_context: default [Dec 16 21:55:03] VERBOSE[27914] res_agi.c: AGI Tx >> agi_extension: 211 [Dec 16 21:55:03] VERBOSE[27914] res_agi.c: AGI Tx >> agi_priority: 1 [Dec 16 21:55:03] VERBOSE[27914] res_agi.c: AGI Tx >> agi_enhanced: 0.0 [Dec 16 21:55:03] VERBOSE[27914] res_agi.c: AGI Tx >> agi_accountcode: [Dec 16 21:55:03] VERBOSE[27914] res_agi.c: AGI Tx >> agi_threadid: -1221358736 [Dec 16 21:55:03] VERBOSE[27914] res_agi.c: AGI Tx >> [Dec 16 21:55:13] VERBOSE[27914] res_agi.c: AGI Rx << ANSWER [Dec 16 21:55:13] DEBUG[27762] devicestate.c: No provider found, checking channel drivers for SIP - 192.168.100.6 [Dec 16 21:55:13] DEBUG[27762] chan_sip.c: Checking device state for peer 192.168.100.6 [Dec 16 21:55:13] DEBUG[27914] chan_sip.c: SIP answering channel: SIP/192.168.100.6-00000005 [Dec 16 21:55:13] DEBUG[27914] res_rtp_asterisk.c: Setting the marker bit due to a source update [Dec 16 21:55:13] DEBUG[27914] chan_sip.c: Setting framing from config on incoming call [Dec 16 21:55:13] DEBUG[27914] chan_sip.c: This call needs video offers! [Dec 16 21:55:13] DEBUG[27914] chan_sip.c: ** Our capability: 0x80004 (ulaw|h263) Video flag: False Text flag: True [Dec 16 21:55:13] DEBUG[27914] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Dec 16 21:55:13] VERBOSE[27914] chan_sip.c: Audio is at 5060 [Dec 16 21:55:13] VERBOSE[27914] chan_sip.c: Video is at 192.168.100.29:5060 [Dec 16 21:55:13] VERBOSE[27914] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [Dec 16 21:55:13] VERBOSE[27914] chan_sip.c: Adding video codec 0x80000 (h263) to SDP [Dec 16 21:55:13] VERBOSE[27914] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Dec 16 21:55:13] DEBUG[27914] chan_sip.c: -- Done with adding codecs to SDP [Dec 16 21:55:13] DEBUG[27914] chan_sip.c: Done building SDP. Settling with this capability: 0x80004 (ulaw|h263) [Dec 16 21:55:13] VERBOSE[27914] chan_sip.c: <--- Reliably Transmitting (no NAT) to 192.168.100.6:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.100.6:5060;branch=z9hG4bK1286411818;received=192.168.100.6;rport=5060 From: "clau" ;tag=764665301 To: ;tag=as6b8f2fe2 Call-ID: 993614872 CSeq: 20 INVITE Server: Asterisk PBX SVN-trunk-r298686 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 349 v=0 o=root 1764185867 1764185867 IN IP4 192.168.100.29 s=Asterisk PBX SVN-trunk-r298686 c=IN IP4 192.168.100.29 b=CT:384 t=0 0 m=audio 15652 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv m=video 14194 RTP/AVP 34 a=rtpmap:34 H263/90000 a=sendrecv <------------> [Dec 16 21:55:13] DEBUG[27914] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #47 [Dec 16 21:55:13] DEBUG[27914] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.100.6:5060 [Dec 16 21:55:13] DEBUG[27762] devicestate.c: Changing state for SIP/192.168.100.6 - state 2 (In use) [Dec 16 21:55:13] DEBUG[27762] devicestate.c: device 'SIP/192.168.100.6' state '2' [Dec 16 21:55:13] VERBOSE[27769] chan_sip.c: <--- SIP read from UDP:192.168.100.6:5060 ---> ACK sip:211@192.168.100.29:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.100.6:5060;rport;branch=z9hG4bK2138976552 From: "clau" ;tag=764665301 To: ;tag=as6b8f2fe2 Call-ID: 993614872 CSeq: 20 ACK Contact: "clau" Max-Forwards: 70 User-Agent: Linphone/3.3.99.8 (eXosip2/3.3.0) Content-Length: 0 <-------------> [Dec 16 21:55:13] DEBUG[27769] chan_sip.c: Header 0 [ 39]: ACK sip:211@192.168.100.29:5060 SIP/2.0 [Dec 16 21:55:13] DEBUG[27769] chan_sip.c: Header 1 [ 66]: Via: SIP/2.0/UDP 192.168.100.6:5060;rport;branch=z9hG4bK2138976552 [Dec 16 21:55:13] DEBUG[27769] chan_sip.c: Header 2 [ 51]: From: "clau" ;tag=764665301 [Dec 16 21:55:13] DEBUG[27769] chan_sip.c: Header 3 [ 43]: To: ;tag=as6b8f2fe2 [Dec 16 21:55:13] DEBUG[27769] chan_sip.c: Header 4 [ 18]: Call-ID: 993614872 [Dec 16 21:55:13] DEBUG[27769] chan_sip.c: Header 5 [ 12]: CSeq: 20 ACK [Dec 16 21:55:13] DEBUG[27769] chan_sip.c: Header 6 [ 40]: Contact: "clau" [Dec 16 21:55:13] DEBUG[27769] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [Dec 16 21:55:13] DEBUG[27769] chan_sip.c: Header 8 [ 45]: User-Agent: Linphone/3.3.99.8 (eXosip2/3.3.0) [Dec 16 21:55:13] DEBUG[27769] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Dec 16 21:55:13] VERBOSE[27769] chan_sip.c: --- (10 headers 0 lines) --- [Dec 16 21:55:13] DEBUG[27769] chan_sip.c: = Looking for Call ID: 993614872 (Checking From) --From tag 764665301 --To-tag as6b8f2fe2 [Dec 16 21:55:13] DEBUG[27769] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Dec 16 21:55:13] DEBUG[27769] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #47 [Dec 16 21:55:13] DEBUG[27769] chan_sip.c: Stopping retransmission on '993614872' of Response 20: Match Found [Dec 16 21:55:13] DEBUG[27914] channel.c: Didn't receive a media frame from SIP/192.168.100.6-00000005 within 500 ms of answering. Continuing anyway [Dec 16 21:55:13] VERBOSE[27914] res_agi.c: AGI Tx >> 200 result=0 [Dec 16 21:55:13] VERBOSE[27914] res_agi.c: AGI Rx << ANSWER [Dec 16 21:55:13] VERBOSE[27914] res_agi.c: AGI Tx >> 200 result=0 [Dec 16 21:55:13] VERBOSE[27914] res_agi.c: AGI Rx << EXEC Wait "5" [Dec 16 21:55:13] VERBOSE[27914] res_agi.c: -- AGI Script Executing Application: (Wait) Options: (5) [Dec 16 21:55:18] VERBOSE[27914] res_agi.c: AGI Tx >> 200 result=0 [Dec 16 21:55:18] VERBOSE[27914] res_agi.c: AGI Rx << EXEC Wait "5" [Dec 16 21:55:18] VERBOSE[27914] res_agi.c: -- AGI Script Executing Application: (Wait) Options: (5) [Dec 16 21:55:23] VERBOSE[27914] res_agi.c: AGI Tx >> 200 result=0 [Dec 16 21:55:23] VERBOSE[27914] res_agi.c: AGI Rx << EXEC Wait "5" [Dec 16 21:55:23] VERBOSE[27914] res_agi.c: -- AGI Script Executing Application: (Wait) Options: (5) [Dec 16 21:55:28] VERBOSE[27914] res_agi.c: AGI Tx >> 200 result=0 [Dec 16 21:55:28] VERBOSE[27914] res_agi.c: AGI Rx << EXEC Wait "5" [Dec 16 21:55:28] VERBOSE[27914] res_agi.c: -- AGI Script Executing Application: (Wait) Options: (5) [Dec 16 21:55:32] VERBOSE[27769] chan_sip.c: <--- SIP read from UDP:192.168.100.6:5060 ---> BYE sip:211@192.168.100.29:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.100.6:5060;rport;branch=z9hG4bK294575461 From: "clau" ;tag=764665301 To: ;tag=as6b8f2fe2 Call-ID: 993614872 CSeq: 21 BYE Contact: Max-Forwards: 70 User-Agent: Linphone/3.3.99.8 (eXosip2/3.3.0) Content-Length: 0 <-------------> [Dec 16 21:55:32] DEBUG[27769] chan_sip.c: Header 0 [ 39]: BYE sip:211@192.168.100.29:5060 SIP/2.0 [Dec 16 21:55:32] DEBUG[27769] chan_sip.c: Header 1 [ 65]: Via: SIP/2.0/UDP 192.168.100.6:5060;rport;branch=z9hG4bK294575461 [Dec 16 21:55:32] DEBUG[27769] chan_sip.c: Header 2 [ 51]: From: "clau" ;tag=764665301 [Dec 16 21:55:32] DEBUG[27769] chan_sip.c: Header 3 [ 43]: To: ;tag=as6b8f2fe2 [Dec 16 21:55:32] DEBUG[27769] chan_sip.c: Header 4 [ 18]: Call-ID: 993614872 [Dec 16 21:55:32] DEBUG[27769] chan_sip.c: Header 5 [ 12]: CSeq: 21 BYE [Dec 16 21:55:32] DEBUG[27769] chan_sip.c: Header 6 [ 38]: Contact: [Dec 16 21:55:32] DEBUG[27769] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [Dec 16 21:55:32] DEBUG[27769] chan_sip.c: Header 8 [ 45]: User-Agent: Linphone/3.3.99.8 (eXosip2/3.3.0) [Dec 16 21:55:32] DEBUG[27769] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Dec 16 21:55:32] VERBOSE[27769] chan_sip.c: --- (10 headers 0 lines) --- [Dec 16 21:55:32] DEBUG[27769] chan_sip.c: = Looking for Call ID: 993614872 (Checking From) --From tag 764665301 --To-tag as6b8f2fe2 [Dec 16 21:55:32] DEBUG[27769] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Dec 16 21:55:32] DEBUG[27769] chan_sip.c: Initializing initreq for method BYE - callid 993614872 [Dec 16 21:55:32] DEBUG[27769] netsock2.c: Splitting '192.168.100.6:5060' gives... [Dec 16 21:55:32] DEBUG[27769] netsock2.c: ...host '192.168.100.6' and port '5060'. [Dec 16 21:55:32] VERBOSE[27769] chan_sip.c: Sending to 192.168.100.6:5060 (no NAT) [Dec 16 21:55:32] DEBUG[27769] chan_sip.c: Setting SIP_ALREADYGONE on dialog 993614872 [Dec 16 21:55:32] DEBUG[27769] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x8ad9cf0' [Dec 16 21:55:32] DEBUG[27769] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x8add3f8' [Dec 16 21:55:32] VERBOSE[27769] chan_sip.c: Scheduling destruction of SIP dialog '993614872' in 32000 ms (Method: BYE) [Dec 16 21:55:32] DEBUG[27769] chan_sip.c: Received bye, issuing owner hangup [Dec 16 21:55:32] VERBOSE[27769] chan_sip.c: <--- Transmitting (no NAT) to 192.168.100.6:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.100.6:5060;branch=z9hG4bK294575461;received=192.168.100.6;rport=5060 From: "clau" ;tag=764665301 To: ;tag=as6b8f2fe2 Call-ID: 993614872 CSeq: 21 BYE Server: Asterisk PBX SVN-trunk-r298686 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [Dec 16 21:55:32] DEBUG[27769] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.100.6:5060 [Dec 16 21:55:32] VERBOSE[27914] res_agi.c: AGI Tx >> 200 result=-1 [Dec 16 21:55:32] VERBOSE[27914] res_agi.c: AGI Rx << EXEC Wait "5" [Dec 16 21:55:32] VERBOSE[27914] res_agi.c: -- AGI Script Executing Application: (Wait) Options: (5) [Dec 16 21:55:34] DEBUG[27769] chan_sip.c: Auto destroying SIP dialog '193245645' [Dec 16 21:55:34] DEBUG[27769] chan_sip.c: Destroying SIP dialog 193245645 [Dec 16 21:55:34] VERBOSE[27769] chan_sip.c: Really destroying SIP dialog '193245645' Method: OPTIONS [Dec 16 21:55:37] VERBOSE[27914] res_agi.c: AGI Tx >> 200 result=0 [Dec 16 21:55:37] VERBOSE[27914] res_agi.c: AGI Rx << EXEC Wait "5" [Dec 16 21:55:37] VERBOSE[27914] res_agi.c: -- AGI Script Executing Application: (Wait) Options: (5) [Dec 16 21:55:42] VERBOSE[27914] res_agi.c: AGI Tx >> 200 result=0 [Dec 16 21:55:42] VERBOSE[27914] res_agi.c: AGI Rx << EXEC Wait "5" [Dec 16 21:55:42] VERBOSE[27914] res_agi.c: -- AGI Script Executing Application: (Wait) Options: (5) [Dec 16 21:55:47] VERBOSE[27914] res_agi.c: AGI Tx >> 200 result=0 [Dec 16 21:55:47] VERBOSE[27914] res_agi.c: -- AGI Script agi://192.168.100.6 completed, returning 0 [Dec 16 21:55:47] DEBUG[27914] pbx.c: Extension 211, priority 1 returned normally even though call was hung up [Dec 16 21:55:47] DEBUG[27914] channel.c: Soft-Hanging up channel 'SIP/192.168.100.6-00000005' [Dec 16 21:55:47] DEBUG[27914] pbx.c: Launching 'AGI' [Dec 16 21:55:47] VERBOSE[27914] pbx.c: -- Executing [h@default:1] AGI("SIP/192.168.100.6-00000005", "agi://192.168.100.6") in new stack [Dec 16 21:55:47] DEBUG[27914] res_agi.c: Hungup channel detected, running agi in dead mode. [Dec 16 21:55:47] VERBOSE[27914] res_agi.c: AGI Tx >> agi_network: yes [Dec 16 21:55:47] ERROR[27914] utils.c: write() returned error: Connection refused [Dec 16 21:55:47] WARNING[27914] res_agi.c: Connect to 'agi://192.168.100.6' failed: Connection refused [Dec 16 21:55:47] DEBUG[27914] pbx.c: Launching 'Hangup' [Dec 16 21:55:47] VERBOSE[27914] pbx.c: -- Executing [h@default:2] Hangup("SIP/192.168.100.6-00000005", "") in new stack [Dec 16 21:55:47] DEBUG[27914] pbx.c: Spawn extension (default,h,2) exited non-zero on 'SIP/192.168.100.6-00000005' [Dec 16 21:55:47] VERBOSE[27914] pbx.c: == Spawn extension (default, h, 2) exited non-zero on 'SIP/192.168.100.6-00000005' [Dec 16 21:55:47] DEBUG[27914] channel.c: Hanging up channel 'SIP/192.168.100.6-00000005' [Dec 16 21:55:47] DEBUG[27914] chan_sip.c: Hangup call SIP/192.168.100.6-00000005, SIP callid 993614872 [Dec 16 21:55:47] DEBUG[27914] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x8ad9cf0' [Dec 16 21:55:47] DEBUG[27914] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x8add3f8' [Dec 16 21:55:47] DEBUG[27762] devicestate.c: No provider found, checking channel drivers for SIP - 192.168.100.6 [Dec 16 21:55:47] DEBUG[27762] chan_sip.c: Checking device state for peer 192.168.100.6 [Dec 16 21:55:47] DEBUG[27762] devicestate.c: Changing state for SIP/192.168.100.6 - state 0 (Unknown) [Dec 16 21:55:47] DEBUG[27762] devicestate.c: device 'SIP/192.168.100.6' state '0' [Dec 16 21:56:04] DEBUG[27769] chan_sip.c: Auto destroying SIP dialog '993614872' [Dec 16 21:56:04] DEBUG[27769] chan_sip.c: Destroying SIP dialog 993614872 [Dec 16 21:56:04] VERBOSE[27769] chan_sip.c: Really destroying SIP dialog '993614872' Method: BYE [Dec 16 21:56:04] DEBUG[27769] rtp_engine.c: Destroyed RTP instance '0x8ad9cf0' [Dec 16 21:56:04] DEBUG[27769] rtp_engine.c: Destroyed RTP instance '0x8add3f8' [Dec 16 21:56:10] VERBOSE[27911] asterisk.c: -- Remote UNIX connection disconnected