************************* 226683 Playback with answer - OK ************************* [Nov 9 18:22:59] DEBUG[12653]: pbx.c:4009 pbx_extension_helper: Launching 'Playback' [Nov 9 18:22:59] -- Executing [_ZXXX@from-cucm:39] Playback("SIP/cucm-0a75f188", "vlastni/nedostupny") in new stack [Nov 9 18:22:59] DEBUG[12553]: devicestate.c:338 _ast_device_state: No provider found, checking channel drivers for SIP - cucm [Nov 9 18:22:59] DEBUG[12553]: chan_sip.c:23829 sip_devicestate: Checking device state for peer cucm [Nov 9 18:22:59] DEBUG[12553]: devicestate.c:456 do_state_change: Changing state for SIP/cucm - state 5 (Unavailable) [Nov 9 18:22:59] DEBUG[12553]: devicestate.c:436 devstate_event: device 'SIP/cucm' state '5' [Nov 9 18:22:59] DEBUG[12653]: chan_sip.c:6506 sip_answer: SIP answering channel: SIP/cucm-0a75f188 [Nov 9 18:22:59] DEBUG[12653]: chan_sip.c:10779 transmit_response_with_sdp: Setting framing from config on incoming call [Nov 9 18:22:59] DEBUG[12653]: chan_sip.c:10454 add_sdp: ** Our capability: 0x100 (g729) Video flag: True Text flag: True [Nov 9 18:22:59] DEBUG[12653]: chan_sip.c:10455 add_sdp: ** Our prefcodec: 0x0 (nothing) [Nov 9 18:22:59] Audio is at 78.31.26.174 port 17086 [Nov 9 18:22:59] Adding codec 0x100 (g729) to SDP [Nov 9 18:22:59] Adding non-codec 0x1 (telephone-event) to SDP [Nov 9 18:22:59] DEBUG[12653]: chan_sip.c:10571 add_sdp: -- Done with adding codecs to SDP [Nov 9 18:22:59] DEBUG[12653]: channel.c:3537 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=1048576 chan->timingfd=-1) [Nov 9 18:22:59] DEBUG[12653]: chan_sip.c:10713 add_sdp: Done building SDP. Settling with this capability: 0x100 (g729) [Nov 9 18:22:59] <--- Reliably Transmitting (no NAT) to 10.0.156.33:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.156.33:5060;branch=z9hG4bK100e71717b3e;received=10.0.156.33 From: "Michal Gust" ;tag=0635268a-0640-41a8-aac3-9f9685a0ff80-44433263 To: ;tag=as3e70443d Call-ID: 832f4700-af814fef-f91-219c000a@10.0.156.33 CSeq: 102 INVITE Server: SIP PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Require: timer Session-Expires: 1800;refresher=uas Contact: Remote-Party-ID: "Michal Gust" ;party=called;privacy=off;screen=no Content-Type: application/sdp Content-Length: 274 v=0 o=ipbx 1438377557 1438377557 IN IP4 78.31.26.174 s=SIP Call c=IN IP4 78.31.26.174 t=0 0 m=audio 17086 RTP/AVP 18 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Nov 9 18:22:59] DEBUG[12653]: chan_sip.c:4069 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id 0002360 [Nov 9 18:22:59] DEBUG[12653]: chan_sip.c:3704 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.0.156.33:5060 [Nov 9 18:22:59] <--- SIP read from UDP:10.0.156.33:5060 ---> ACK sip:1322@78.31.26.174:5060 SIP/2.0 Date: Mon, 09 Nov 2009 17:22:55 GMT Authorization: Digest username="cucm",realm="ipbx.i.cz",uri="sip:1322@78.31.26.174:5060",response="f88ec72ee7a8f0439c6a5e5da03772e0",nonce="66b317ca",algorithm=MD5 From: "Michal Gust" ;tag=0635268a-0640-41a8-aac3-9f9685a0ff80-44433263 Allow-Events: presence, kpml Content-Length: 0 To: ;tag=as3e70443d Call-ID: 832f4700-af814fef-f91-219c000a@10.0.156.33 Via: SIP/2.0/UDP 10.0.156.33:5060;branch=z9hG4bK100f2cd67f50 CSeq: 102 ACK Max-Forwards: 70 <-------------> [Nov 9 18:22:59] DEBUG[12563]: chan_sip.c:8129 parse_request: Header 0 [ 38]: ACK sip:1322@78.31.26.174:5060 SIP/2.0 [Nov 9 18:22:59] DEBUG[12563]: chan_sip.c:8129 parse_request: Header 1 [ 35]: Date: Mon, 09 Nov 2009 17:22:55 GMT [Nov 9 18:22:59] DEBUG[12563]: chan_sip.c:8129 parse_request: Header 2 [163]: Authorization: Digest username="cucm",realm="ipbx.i.cz",uri="sip:1322@78.31.26.174:5060",response="f88ec72ee7a8f0439c6a5e5da03772e0",nonce="66b317ca",algorithm=MD5 [Nov 9 18:22:59] DEBUG[12563]: chan_sip.c:8129 parse_request: Header 3 [ 92]: From: "Michal Gust" ;tag=0635268a-0640-41a8-aac3-9f9685a0ff80-44433263 [Nov 9 18:22:59] DEBUG[12563]: chan_sip.c:8129 parse_request: Header 4 [ 28]: Allow-Events: presence, kpml [Nov 9 18:22:59] DEBUG[12563]: chan_sip.c:8129 parse_request: Header 5 [ 17]: Content-Length: 0 [Nov 9 18:22:59] DEBUG[12563]: chan_sip.c:8129 parse_request: Header 6 [ 42]: To: ;tag=as3e70443d [Nov 9 18:22:59] DEBUG[12563]: chan_sip.c:8129 parse_request: Header 7 [ 51]: Call-ID: 832f4700-af814fef-f91-219c000a@10.0.156.33 [Nov 9 18:22:59] DEBUG[12563]: chan_sip.c:8129 parse_request: Header 8 [ 60]: Via: SIP/2.0/UDP 10.0.156.33:5060;branch=z9hG4bK100f2cd67f50 [Nov 9 18:22:59] DEBUG[12563]: chan_sip.c:8129 parse_request: Header 9 [ 13]: CSeq: 102 ACK [Nov 9 18:22:59] DEBUG[12563]: chan_sip.c:8129 parse_request: Header 10 [ 16]: Max-Forwards: 70 [Nov 9 18:22:59] DEBUG[12563]: chan_sip.c:8129 parse_request: Header 11 [ 0]: [Nov 9 18:22:59] --- (11 headers 0 lines) --- [Nov 9 18:22:59] DEBUG[12563]: chan_sip.c:22483 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Nov 9 18:22:59] DEBUG[12563]: chan_sip.c:4223 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid 0002360 [Nov 9 18:22:59] DEBUG[12563]: chan_sip.c:4255 __sip_ack: Stopping retransmission on '832f4700-af814fef-f91-219c000a@10.0.156.33' of Response 102: Match Found [Nov 9 18:22:59] DEBUG[12653]: res_rtp_asterisk.c:1572 ast_rtcp_read: Got RTCP report of 44 bytes [Nov 9 18:22:59] DEBUG[12653]: channel.c:2346 __ast_answer: Didn't receive a media frame from SIP/cucm-0a75f188 within 500 ms of answering. Continuing anyway [Nov 9 18:22:59] DEBUG[12653]: channel.c:4214 set_format: Set channel SIP/cucm-0a75f188 to write format slin [Nov 9 18:22:59] DEBUG[12653]: res_rtp_asterisk.c:1149 ast_rtp_write: Ooh, format changed from unknown to g729 [Nov 9 18:22:59] DEBUG[12653]: res_rtp_asterisk.c:1178 ast_rtp_write: Created smoother: format: 256 ms: 20 len: 20 [Nov 9 18:22:59] DEBUG[12653]: res_rtp_asterisk.c:1051 ast_rtp_raw_write: Starting RTCP transmission on RTP instance '0xa65ce50' [Nov 9 18:22:59] -- Playing 'vlastni/nedostupny.slin' (language 'cz') [Nov 9 18:23:06] DEBUG[12653]: channel.c:4214 set_format: Set channel SIP/cucm-0a75f188 to write format g729 [Nov 9 18:23:06] DEBUG[12653]: pbx.c:4009 pbx_extension_helper: Launching 'NoOp' [Nov 9 18:23:06] -- Executing [_ZXXX@from-cucm:40] NoOp("SIP/cucm-0a75f188", "Finish if-if-if-from-cucm-82-88-89") in new stack