[Dec 22 11:38:04] Found RTP audio format 0 [Dec 22 11:38:04] Found RTP audio format 101 [Dec 22 11:38:04] Peer audio RTP is at port 192.168.1.201:2262 [Dec 22 11:38:04] Found description format PCMU for ID 0 [Dec 22 11:38:04] Found description format telephone-event for ID 101 [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:5066 process_sdp: T38 state changed to 0 on channel SIP/808-081f6440 [Dec 22 11:38:04] Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Dec 22 11:38:04] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Dec 22 11:38:04] Peer audio RTP is at port 192.168.1.201:2262 [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:5143 process_sdp: We're settling with these formats: 0x4 (ulaw) [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:5150 process_sdp: We have an owner, now see if we need to change this call [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:13284 handle_request_invite: Got a SIP re-invite for call 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:13379 handle_request_invite: SIP/808-081f6440: This call is UP.... [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:6352 transmit_response_with_sdp: Setting framing from config on incoming call [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:6120 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:6121 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Dec 22 11:38:04] Audio is at 192.168.1.12 port 15086 [Dec 22 11:38:04] Adding codec 0x4 (ulaw) to SDP [Dec 22 11:38:04] Adding non-codec 0x1 (telephone-event) to SDP [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:6252 add_sdp: -- Done with adding codecs to SDP [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:6297 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Dec 22 11:38:04] <--- Reliably Transmitting (no NAT) to 192.168.1.201:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bKe15ae7646033E3BD;received=192.168.1.201 From: ;tag=E3B396A7-86EA13F6 To: "ITRANSACT" ;tag=as798faed5 Call-ID: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 240 v=0 o=root 29436 29437 IN IP4 192.168.1.12 s=session c=IN IP4 192.168.1.12 t=0 0 m=audio 15086 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=recvonly <------------> [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:1957 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #101 [Dec 22 11:38:04] DEBUG[29469]: chan_zap.c:5008 zt_indicate: Requested indication 16 on channel Zap/2-1 [Dec 22 11:38:04] DEBUG[29469]: channel.c:2731 set_format: Set channel Zap/2-1 to write format slin [Dec 22 11:38:04] -- Started music on hold, class 'default', on channel 'Zap/2-1' [Dec 22 11:38:04] DEBUG[29469]: channel.c:1908 ast_settimeout: Scheduling timer at 160 sample intervals [Dec 22 11:38:04] DEBUG[29469]: channel.c:2225 __ast_read: Generator got voice, switching to phase locked mode [Dec 22 11:38:04] DEBUG[29469]: channel.c:1908 ast_settimeout: Scheduling timer at 0 sample intervals [Dec 22 11:38:04] <--- SIP read from 192.168.1.201:5060 ---> ACK sip:8019518134@192.168.1.12 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bK69600802EDB1B043 From: ;tag=E3B396A7-86EA13F6 To: "ITRANSACT" ;tag=as798faed5 CSeq: 1 ACK Call-ID: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 Max-Forwards: 70 Content-Length: 0 <-------------> [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 0: ACK sip:8019518134@192.168.1.12 SIP/2.0 (39) [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bK69600802EDB1B043 (61) [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 2: From: ;tag=E3B396A7-86EA13F6 (51) [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 3: To: "ITRANSACT" ;tag=as798faed5 (60) [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 4: CSeq: 1 ACK (11) [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 5: Call-ID: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 (54) [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 6: Contact: (32) [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 (54) [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 9: Max-Forwards: 70 (16) [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 10: Content-Length: 0 (17) [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 11: (0) [Dec 22 11:38:04] --- (11 headers 0 lines) --- [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:14449 handle_request: **** Received ACK (6) - Command in SIP ACK [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:2061 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #101 [Dec 22 11:38:04] DEBUG[29461]: chan_sip.c:2071 __sip_ack: Stopping retransmission on '03c67e11087c3d9a794972a72bdcde46@192.168.1.12' of Response 1: Match Not Found [Dec 22 11:38:06] <--- SIP read from 192.168.1.201:5060 ---> INVITE sip:700@192.168.1.12:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bKcf602550B55B05B9 From: "Cashier Station 3" ;tag=624FD85A-E3143D75 To: CSeq: 1 INVITE Call-ID: 15b65ace-c94b0ffc-b824699f@192.168.1.201 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 Supported: 100rel,replaces Allow-Events: talk,hold,conference Max-Forwards: 70 Content-Type: application/sdp Content-Length: 251 v=0 o=- 1166766328 1166766328 IN IP4 192.168.1.201 s=Polycom IP Phone c=IN IP4 192.168.1.201 t=0 0 a=sendrecv m=audio 2260 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 <-------------> [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 0: INVITE sip:700@192.168.1.12:5060;user=phone SIP/2.0 (51) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bKcf602550B55B05B9 (61) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 2: From: "Cashier Station 3" ;tag=624FD85A-E3143D75 (70) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 3: To: (37) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 4: CSeq: 1 INVITE (14) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 5: Call-ID: 15b65ace-c94b0ffc-b824699f@192.168.1.201 (49) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 6: Contact: (32) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 (54) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 9: Supported: 100rel,replaces (26) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 10: Allow-Events: talk,hold,conference (34) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 11: Max-Forwards: 70 (16) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 12: Content-Type: application/sdp (29) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 13: Content-Length: 251 (19) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 14: (0) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: v=0 (3) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: o=- 1166766328 1166766328 IN IP4 192.168.1.201 (46) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: s=Polycom IP Phone (18) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: c=IN IP4 192.168.1.201 (22) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: t=0 0 (5) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: a=sendrecv (10) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: m=audio 2260 RTP/AVP 0 8 18 101 (31) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Dec 22 11:38:06] --- (14 headers 11 lines) --- [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:2559 do_setnat: Setting NAT on RTP to Off [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4262 sip_alloc: Allocating new SIP dialog for 15b65ace-c94b0ffc-b824699f@192.168.1.201 - INVITE (With RTP) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:14449 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:1662 parse_sip_options: Begin: parsing SIP "Supported: 100rel,replaces" [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:1670 parse_sip_options: Found SIP option: -100rel- [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:1676 parse_sip_options: Matched SIP option: 100rel [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:1670 parse_sip_options: Found SIP option: -replaces- [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:1676 parse_sip_options: Matched SIP option: replaces [Dec 22 11:38:06] Sending to 192.168.1.201 : 5060 (no NAT) [Dec 22 11:38:06] Using INVITE request as basis request - 15b65ace-c94b0ffc-b824699f@192.168.1.201 [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:2559 do_setnat: Setting NAT on RTP to Off [Dec 22 11:38:06] <--- Reliably Transmitting (no NAT) to 192.168.1.201:5060 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bKcf602550B55B05B9;received=192.168.1.201 From: "Cashier Station 3" ;tag=624FD85A-E3143D75 To: ;tag=as1be781ab Call-ID: 15b65ace-c94b0ffc-b824699f@192.168.1.201 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="7a0f9faa" Content-Length: 0 <------------> [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:1957 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #102 [Dec 22 11:38:06] Scheduling destruction of SIP dialog '15b65ace-c94b0ffc-b824699f@192.168.1.201' in 32000 ms (Method: INVITE) [Dec 22 11:38:06] Found user '808' [Dec 22 11:38:06] <--- SIP read from 192.168.1.201:5060 ---> ACK sip:700@192.168.1.12:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bKcf602550B55B05B9 From: "Cashier Station 3" ;tag=624FD85A-E3143D75 To: ;tag=as1be781ab CSeq: 1 ACK Call-ID: 15b65ace-c94b0ffc-b824699f@192.168.1.201 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 Max-Forwards: 70 Content-Length: 0 <-------------> [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 0: ACK sip:700@192.168.1.12:5060 SIP/2.0 (37) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bKcf602550B55B05B9 (61) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 2: From: "Cashier Station 3" ;tag=624FD85A-E3143D75 (70) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 3: To: ;tag=as1be781ab (52) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 4: CSeq: 1 ACK (11) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 5: Call-ID: 15b65ace-c94b0ffc-b824699f@192.168.1.201 (49) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 6: Contact: (32) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 (54) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 9: Max-Forwards: 70 (16) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 10: Content-Length: 0 (17) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 11: (0) [Dec 22 11:38:06] --- (11 headers 0 lines) --- [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:14449 handle_request: **** Received ACK (6) - Command in SIP ACK [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:2061 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #102 [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:2071 __sip_ack: Stopping retransmission on '15b65ace-c94b0ffc-b824699f@192.168.1.201' of Response 1: Match Not Found [Dec 22 11:38:06] <--- SIP read from 192.168.1.201:5060 ---> INVITE sip:700@192.168.1.12:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bKd2951ebb1C965368 From: "Cashier Station 3" ;tag=624FD85A-E3143D75 To: CSeq: 2 INVITE Call-ID: 15b65ace-c94b0ffc-b824699f@192.168.1.201 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 Supported: 100rel,replaces Allow-Events: talk,hold,conference Proxy-Authorization: Digest username="808", realm="asterisk", nonce="7a0f9faa", uri="sip:700@192.168.1.12:5060;user=phone", response="5c28f0ca4e0e3fc6fc84a7139f01c7c1", algorithm=MD5 Max-Forwards: 70 Content-Type: application/sdp Content-Length: 251 v=0 o=- 1166766328 1166766328 IN IP4 192.168.1.201 s=Polycom IP Phone c=IN IP4 192.168.1.201 t=0 0 a=sendrecv m=audio 2260 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 <-------------> [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 0: INVITE sip:700@192.168.1.12:5060;user=phone SIP/2.0 (51) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bKd2951ebb1C965368 (61) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 2: From: "Cashier Station 3" ;tag=624FD85A-E3143D75 (70) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 3: To: (37) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 4: CSeq: 2 INVITE (14) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 5: Call-ID: 15b65ace-c94b0ffc-b824699f@192.168.1.201 (49) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 6: Contact: (32) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 (54) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 9: Supported: 100rel,replaces (26) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 10: Allow-Events: talk,hold,conference (34) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 11: Proxy-Authorization: Digest username="808", realm="asterisk", nonce="7a0f9faa", uri="sip:700@192.168.1.12:5060;user=phone", response="5c28f0ca4e0e3fc6fc84a7139f01c7c1", algorithm=MD5 (182) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 12: Max-Forwards: 70 (16) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 13: Content-Type: application/sdp (29) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 14: Content-Length: 251 (19) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 15: (0) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: v=0 (3) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: o=- 1166766328 1166766328 IN IP4 192.168.1.201 (46) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: s=Polycom IP Phone (18) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: c=IN IP4 192.168.1.201 (22) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: t=0 0 (5) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: a=sendrecv (10) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: m=audio 2260 RTP/AVP 0 8 18 101 (31) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Dec 22 11:38:06] --- (15 headers 11 lines) --- [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:14449 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Dec 22 11:38:06] Sending to 192.168.1.201 : 5060 (no NAT) [Dec 22 11:38:06] Using INVITE request as basis request - 15b65ace-c94b0ffc-b824699f@192.168.1.201 [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:2559 do_setnat: Setting NAT on RTP to Off [Dec 22 11:38:06] Found user '808' [Dec 22 11:38:06] Found RTP audio format 0 [Dec 22 11:38:06] Found RTP audio format 8 [Dec 22 11:38:06] Found RTP audio format 18 [Dec 22 11:38:06] Found RTP audio format 101 [Dec 22 11:38:06] Peer audio RTP is at port 192.168.1.201:2260 [Dec 22 11:38:06] Found description format PCMU for ID 0 [Dec 22 11:38:06] Found description format PCMA for ID 8 [Dec 22 11:38:06] Found description format G729 for ID 18 [Dec 22 11:38:06] Found description format telephone-event for ID 101 [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:5066 process_sdp: T38 state changed to 0 on channel [Dec 22 11:38:06] Capabilities: us - 0x4 (ulaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw) [Dec 22 11:38:06] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Dec 22 11:38:06] Peer audio RTP is at port 192.168.1.201:2260 [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:5143 process_sdp: We're settling with these formats: 0x4 (ulaw) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:13233 handle_request_invite: Checking SIP call limits for device 808 [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:2978 update_call_counter: Updating call counter for incoming call [Dec 22 11:38:06] Looking for 700 in internal (domain 192.168.1.12) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:3766 sip_new: *** Our native formats are 0x4 (ulaw) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:3767 sip_new: *** Joint capabilities are 0x4 (ulaw) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:3768 sip_new: *** Our capabilities are 0x4 (ulaw) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:3769 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:3792 sip_new: This channel will not be able to handle video. [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:7889 build_route: build_route: Contact hop: [Dec 22 11:38:06] list_route: hop: [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:13306 handle_request_invite: SIP/808-40f12500: New call is still down.... Trying... [Dec 22 11:38:06] <--- Transmitting (no NAT) to 192.168.1.201:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bKd2951ebb1C965368;received=192.168.1.201 From: "Cashier Station 3" ;tag=624FD85A-E3143D75 To: Call-ID: 15b65ace-c94b0ffc-b824699f@192.168.1.201 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Dec 22 11:38:06] DEBUG[29461]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/808-40f12500 [Dec 22 11:38:06] DEBUG[29486]: pbx.c:1767 pbx_extension_helper: Launching 'Park' [Dec 22 11:38:06] -- Executing [700@internal:1] Park("SIP/808-40f12500", "") in new stack [Dec 22 11:38:06] DEBUG[29440]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 808 [Dec 22 11:38:06] DEBUG[29440]: chan_sip.c:15044 sip_devicestate: Checking device state for peer 808 [Dec 22 11:38:06] DEBUG[29440]: devicestate.c:287 do_state_change: Changing state for SIP/808 - state 1 (Not in use) [Dec 22 11:38:06] DEBUG[29487]: app_queue.c:546 changethread: Device 'SIP/808' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 22 11:38:06] DEBUG[29486]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/808-40f12500 [Dec 22 11:38:06] DEBUG[29486]: chan_sip.c:3428 sip_answer: SIP answering channel: SIP/808-40f12500 [Dec 22 11:38:06] DEBUG[29486]: chan_sip.c:6352 transmit_response_with_sdp: Setting framing from config on incoming call [Dec 22 11:38:06] DEBUG[29486]: chan_sip.c:6120 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Dec 22 11:38:06] DEBUG[29486]: chan_sip.c:6121 add_sdp: ** Our prefcodec: 0x0 (nothing) [Dec 22 11:38:06] Audio is at 192.168.1.12 port 14882 [Dec 22 11:38:06] Adding codec 0x4 (ulaw) to SDP [Dec 22 11:38:06] Adding non-codec 0x1 (telephone-event) to SDP [Dec 22 11:38:06] DEBUG[29486]: chan_sip.c:6252 add_sdp: -- Done with adding codecs to SDP [Dec 22 11:38:06] DEBUG[29486]: chan_sip.c:6297 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Dec 22 11:38:06] <--- Reliably Transmitting (no NAT) to 192.168.1.201:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bKd2951ebb1C965368;received=192.168.1.201 From: "Cashier Station 3" ;tag=624FD85A-E3143D75 To: ;tag=as3fefa148 Call-ID: 15b65ace-c94b0ffc-b824699f@192.168.1.201 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 240 v=0 o=root 29436 29436 IN IP4 192.168.1.12 s=session c=IN IP4 192.168.1.12 t=0 0 m=audio 14882 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 <------------> [Dec 22 11:38:06] DEBUG[29486]: chan_sip.c:1957 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #104 [Dec 22 11:38:06] DEBUG[29440]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 808 [Dec 22 11:38:06] DEBUG[29440]: chan_sip.c:15044 sip_devicestate: Checking device state for peer 808 [Dec 22 11:38:06] DEBUG[29440]: devicestate.c:287 do_state_change: Changing state for SIP/808 - state 1 (Not in use) [Dec 22 11:38:06] DEBUG[29488]: app_queue.c:546 changethread: Device 'SIP/808' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 22 11:38:06] <--- SIP read from 192.168.1.201:5060 ---> ACK sip:700@192.168.1.12 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bK8155b94D92D9E2D From: "Cashier Station 3" ;tag=624FD85A-E3143D75 To: ;tag=as3fefa148 CSeq: 2 ACK Call-ID: 15b65ace-c94b0ffc-b824699f@192.168.1.201 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 Proxy-Authorization: Digest username="808", realm="asterisk", nonce="7a0f9faa", uri="sip:700@192.168.1.12:5060;user=phone", response="5c28f0ca4e0e3fc6fc84a7139f01c7c1", algorithm=MD5 Max-Forwards: 70 Content-Length: 0 <-------------> [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 0: ACK sip:700@192.168.1.12 SIP/2.0 (32) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bK8155b94D92D9E2D (60) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 2: From: "Cashier Station 3" ;tag=624FD85A-E3143D75 (70) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 3: To: ;tag=as3fefa148 (52) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 4: CSeq: 2 ACK (11) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 5: Call-ID: 15b65ace-c94b0ffc-b824699f@192.168.1.201 (49) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 6: Contact: (32) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 (54) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 9: Proxy-Authorization: Digest username="808", realm="asterisk", nonce="7a0f9faa", uri="sip:700@192.168.1.12:5060;user=phone", response="5c28f0ca4e0e3fc6fc84a7139f01c7c1", algorithm=MD5 (182) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 10: Max-Forwards: 70 (16) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 11: Content-Length: 0 (17) [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 12: (0) [Dec 22 11:38:06] --- (12 headers 0 lines) --- [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:14449 handle_request: **** Received ACK (6) - Command in SIP ACK [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:2061 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #104 [Dec 22 11:38:06] DEBUG[29461]: chan_sip.c:2071 __sip_ack: Stopping retransmission on '15b65ace-c94b0ffc-b824699f@192.168.1.201' of Response 2: Match Not Found [Dec 22 11:38:07] == Parked SIP/808-40f12500 on 701@parkedcalls. Will timeout back to extension [internal] s, 1 in 45 seconds [Dec 22 11:38:07] DEBUG[29486]: pbx.c:4794 ast_add_extension2: Added extension '701' priority 1 to parkedcalls [Dec 22 11:38:07] -- Added extension '701' priority 1 to parkedcalls [Dec 22 11:38:07] DEBUG[29486]: res_features.c:277 notify_metermaids: Notification of state change to metermaids 701@parkedcalls [Dec 22 11:38:07] DEBUG[29486]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel park:701@parkedcalls [Dec 22 11:38:07] DEBUG[29486]: channel.c:2731 set_format: Set channel SIP/808-40f12500 to write format gsm [Dec 22 11:38:07] DEBUG[29486]: rtp.c:2621 ast_rtp_write: Ooh, format changed from unknown to ulaw [Dec 22 11:38:07] DEBUG[29486]: rtp.c:2638 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Dec 22 11:38:07] DEBUG[29486]: channel.c:1908 ast_settimeout: Scheduling timer at 160 sample intervals [Dec 22 11:38:07] -- Playing 'digits/7' (language 'en') [Dec 22 11:38:07] DEBUG[29440]: devicestate.c:157 ast_device_state: Checking if I can find provider for "park" - number: 701@parkedcalls [Dec 22 11:38:07] DEBUG[29440]: res_features.c:296 metermaidstate: Checking state of exten 701 in context parkedcalls [Dec 22 11:38:07] DEBUG[29440]: devicestate.c:287 do_state_change: Changing state for park:701@parkedcalls - state 2 (In use) [Dec 22 11:38:08] DEBUG[29486]: channel.c:1908 ast_settimeout: Scheduling timer at 0 sample intervals [Dec 22 11:38:08] DEBUG[29486]: channel.c:1908 ast_settimeout: Scheduling timer at 0 sample intervals [Dec 22 11:38:08] DEBUG[29486]: channel.c:2731 set_format: Set channel SIP/808-40f12500 to write format ulaw [Dec 22 11:38:08] DEBUG[29486]: channel.c:2731 set_format: Set channel SIP/808-40f12500 to write format gsm [Dec 22 11:38:08] DEBUG[29486]: channel.c:1908 ast_settimeout: Scheduling timer at 160 sample intervals [Dec 22 11:38:08] -- Playing 'digits/0' (language 'en') [Dec 22 11:38:08] DEBUG[29486]: channel.c:1908 ast_settimeout: Scheduling timer at 0 sample intervals [Dec 22 11:38:08] DEBUG[29486]: channel.c:1908 ast_settimeout: Scheduling timer at 0 sample intervals [Dec 22 11:38:08] DEBUG[29486]: channel.c:2731 set_format: Set channel SIP/808-40f12500 to write format ulaw [Dec 22 11:38:08] DEBUG[29486]: channel.c:2731 set_format: Set channel SIP/808-40f12500 to write format gsm [Dec 22 11:38:08] DEBUG[29486]: channel.c:1908 ast_settimeout: Scheduling timer at 160 sample intervals [Dec 22 11:38:08] -- Playing 'digits/1' (language 'en') [Dec 22 11:38:09] DEBUG[29486]: channel.c:1908 ast_settimeout: Scheduling timer at 0 sample intervals [Dec 22 11:38:09] DEBUG[29486]: channel.c:1908 ast_settimeout: Scheduling timer at 0 sample intervals [Dec 22 11:38:09] DEBUG[29486]: channel.c:2731 set_format: Set channel SIP/808-40f12500 to write format ulaw [Dec 22 11:38:09] DEBUG[29486]: channel.c:2731 set_format: Set channel SIP/808-40f12500 to write format slin [Dec 22 11:38:09] -- Started music on hold, class 'default', on channel 'SIP/808-40f12500' [Dec 22 11:38:09] DEBUG[29486]: channel.c:1908 ast_settimeout: Scheduling timer at 160 sample intervals [Dec 22 11:38:09] DEBUG[29486]: pbx.c:2356 __ast_pbx_run: Spawn extension (internal,s,1) exited KEEPALIVE on 'SIP/808-40f12500' [Dec 22 11:38:09] == Spawn extension (internal, s, 1) exited KEEPALIVE on 'SIP/808-40f12500' [Dec 22 11:38:09] DEBUG[29443]: channel.c:2225 __ast_read: Generator got voice, switching to phase locked mode [Dec 22 11:38:09] DEBUG[29443]: channel.c:1908 ast_settimeout: Scheduling timer at 0 sample intervals [Dec 22 11:38:10] <--- SIP read from 192.168.1.201:5060 ---> REFER sip:8019518134@192.168.1.12 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bKf03943b2A99CAC33 From: ;tag=E3B396A7-86EA13F6 To: "ITRANSACT" ;tag=as798faed5 CSeq: 2 REFER Call-ID: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 Contact: User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 Refer-To: Referred-By: Max-Forwards: 70 Content-Length: 0 <-------------> [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 0: REFER sip:8019518134@192.168.1.12 SIP/2.0 (41) [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bKf03943b2A99CAC33 (61) [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 2: From: ;tag=E3B396A7-86EA13F6 (51) [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 3: To: "ITRANSACT" ;tag=as798faed5 (60) [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 4: CSeq: 2 REFER (13) [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 5: Call-ID: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 (54) [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 6: Contact: (32) [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 (54) [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 8: Refer-To: (148) [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 9: Referred-By: (35) [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 10: Max-Forwards: 70 (16) [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 11: Content-Length: 0 (17) [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 12: (0) [Dec 22 11:38:10] --- (12 headers 0 lines) --- [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:14449 handle_request: **** Received REFER (9) - Command in SIP REFER [Dec 22 11:38:10] Call 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 got a SIP call transfer from caller: (REFER)! [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:8621 get_refer_info: Attended transfer: Will use Replace-Call-ID : 15b65ace-c94b0ffc-b824699f@192.168.1.201 (No check of from/to tags) [Dec 22 11:38:10] SIP transfer to extension 700@internal by 808@192.168.1.12 [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:13790 handle_request_refer: SIP attended transfer: Transferer channel SIP/808-081f6440, transferee channel Zap/2-1 [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:13806 handle_request_refer: Got SIP transfer, applying to bridged peer 'Zap/2-1' [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:8475 get_sip_pvt_byid_locked: Looking for callid 15b65ace-c94b0ffc-b824699f@192.168.1.201 (fromtag 624FD85A-E3143D75 totag as3fefa148) [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:8499 get_sip_pvt_byid_locked: Matched INCOMING call - their tag is 624FD85A-E3143D75 Our tag is as3fefa148 [Dec 22 11:38:10] <--- Transmitting (no NAT) to 192.168.1.201:5060 ---> SIP/2.0 202 Accepted Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bKf03943b2A99CAC33;received=192.168.1.201 From: ;tag=E3B396A7-86EA13F6 To: "ITRANSACT" ;tag=as798faed5 Call-ID: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 CSeq: 2 REFER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:13539 local_attended_transfer: SIP attended transfer: Error: No target channel [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:5574 reqprep: Strict routing enforced for session 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 [Dec 22 11:38:10] set_destination: Parsing for address/port to send to [Dec 22 11:38:10] set_destination: set destination to 192.168.1.201, port 5060 [Dec 22 11:38:10] Reliably Transmitting (no NAT) to 192.168.1.201:5060: NOTIFY sip:808@192.168.1.201 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.12:5060;branch=z9hG4bK6f67af51;rport From: "ITRANSACT" ;tag=as798faed5 To: ;tag=E3B396A7-86EA13F6 Contact: Call-ID: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 CSeq: 103 NOTIFY User-Agent: Asterisk PBX Max-Forwards: 70 Event: refer;id=2 Subscription-state: terminated;reason=noresource Content-Type: message/sipfrag;version=2.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 33 SIP/2.0 503 Service Unavailable --- [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:1957 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #106 [Dec 22 11:38:10] DEBUG[29469]: chan_zap.c:5008 zt_indicate: Requested indication 17 on channel Zap/2-1 [Dec 22 11:38:10] DEBUG[29469]: channel.c:2731 set_format: Set channel Zap/2-1 to write format ulaw [Dec 22 11:38:10] -- Stopped music on hold on Zap/2-1 [Dec 22 11:38:10] DEBUG[29469]: channel.c:1908 ast_settimeout: Scheduling timer at 0 sample intervals [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:14660 sipsock_read: SIP message could not be handled, bad request: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 [Dec 22 11:38:10] <--- SIP read from 192.168.1.201:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.12:5060;branch=z9hG4bK6f67af51;rport From: "ITRANSACT" ;tag=as798faed5 To: ;tag=E3B396A7-86EA13F6 CSeq: 103 NOTIFY Call-ID: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 Contact: Event: refer;id=2 User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 Content-Length: 0 <-------------> [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 0: SIP/2.0 200 OK (14) [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.12:5060;branch=z9hG4bK6f67af51;rport (63) [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 2: From: "ITRANSACT" ;tag=as798faed5 (62) [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 3: To: ;tag=E3B396A7-86EA13F6 (49) [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 4: CSeq: 103 NOTIFY (16) [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 5: Call-ID: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 (54) [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 6: Contact: (32) [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 7: Event: refer;id=2 (17) [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 (54) [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 9: Content-Length: 0 (17) [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 10: (0) [Dec 22 11:38:10] --- (10 headers 0 lines) --- [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:2061 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #106 [Dec 22 11:38:10] DEBUG[29461]: chan_sip.c:2071 __sip_ack: Stopping retransmission on '03c67e11087c3d9a794972a72bdcde46@192.168.1.12' of Request 103: Match Not Found [Dec 22 11:38:10] SIP Response message for INCOMING dialog NOTIFY arrived [Dec 22 11:38:10] WARNING[29461]: chan_sip.c:12307 handle_response: Notify answer on an owned channel? [Dec 22 11:38:12] <--- SIP read from 192.168.1.201:5060 ---> REFER sip:8019518134@192.168.1.12 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bK1f6054805C8E7F29 From: ;tag=E3B396A7-86EA13F6 To: "ITRANSACT" ;tag=as798faed5 CSeq: 3 REFER Call-ID: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 Contact: User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 Refer-To: Referred-By: Max-Forwards: 70 Content-Length: 0 <-------------> [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 0: REFER sip:8019518134@192.168.1.12 SIP/2.0 (41) [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bK1f6054805C8E7F29 (61) [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 2: From: ;tag=E3B396A7-86EA13F6 (51) [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 3: To: "ITRANSACT" ;tag=as798faed5 (60) [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 4: CSeq: 3 REFER (13) [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 5: Call-ID: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 (54) [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 6: Contact: (32) [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 (54) [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 8: Refer-To: (148) [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 9: Referred-By: (35) [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 10: Max-Forwards: 70 (16) [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 11: Content-Length: 0 (17) [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 12: (0) [Dec 22 11:38:12] --- (12 headers 0 lines) --- [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:14449 handle_request: **** Received REFER (9) - Command in SIP REFER [Dec 22 11:38:12] Call 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 got a SIP call transfer from caller: (REFER)! [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:8621 get_refer_info: Attended transfer: Will use Replace-Call-ID : 15b65ace-c94b0ffc-b824699f@192.168.1.201 (No check of from/to tags) [Dec 22 11:38:12] SIP transfer to extension 700@internal by 808@192.168.1.12 [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:13790 handle_request_refer: SIP attended transfer: Transferer channel SIP/808-081f6440, transferee channel Zap/2-1 [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:13806 handle_request_refer: Got SIP transfer, applying to bridged peer 'Zap/2-1' [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:8475 get_sip_pvt_byid_locked: Looking for callid 15b65ace-c94b0ffc-b824699f@192.168.1.201 (fromtag 624FD85A-E3143D75 totag as3fefa148) [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:8499 get_sip_pvt_byid_locked: Matched INCOMING call - their tag is 624FD85A-E3143D75 Our tag is as3fefa148 [Dec 22 11:38:12] <--- Transmitting (no NAT) to 192.168.1.201:5060 ---> SIP/2.0 202 Accepted Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bK1f6054805C8E7F29;received=192.168.1.201 From: ;tag=E3B396A7-86EA13F6 To: "ITRANSACT" ;tag=as798faed5 Call-ID: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 CSeq: 3 REFER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:13539 local_attended_transfer: SIP attended transfer: Error: No target channel [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:5574 reqprep: Strict routing enforced for session 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 [Dec 22 11:38:12] set_destination: Parsing for address/port to send to [Dec 22 11:38:12] set_destination: set destination to 192.168.1.201, port 5060 [Dec 22 11:38:12] Reliably Transmitting (no NAT) to 192.168.1.201:5060: NOTIFY sip:808@192.168.1.201 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.12:5060;branch=z9hG4bK73a88b72;rport From: "ITRANSACT" ;tag=as798faed5 To: ;tag=E3B396A7-86EA13F6 Contact: Call-ID: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 CSeq: 104 NOTIFY User-Agent: Asterisk PBX Max-Forwards: 70 Event: refer;id=3 Subscription-state: terminated;reason=noresource Content-Type: message/sipfrag;version=2.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 33 SIP/2.0 503 Service Unavailable --- [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:1957 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #107 [Dec 22 11:38:12] DEBUG[29469]: chan_zap.c:5008 zt_indicate: Requested indication 17 on channel Zap/2-1 [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:14660 sipsock_read: SIP message could not be handled, bad request: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 [Dec 22 11:38:12] <--- SIP read from 192.168.1.201:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.12:5060;branch=z9hG4bK73a88b72;rport From: "ITRANSACT" ;tag=as798faed5 To: ;tag=E3B396A7-86EA13F6 CSeq: 104 NOTIFY Call-ID: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 Contact: Event: refer;id=3 User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 Content-Length: 0 <-------------> [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 0: SIP/2.0 200 OK (14) [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.12:5060;branch=z9hG4bK73a88b72;rport (63) [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 2: From: "ITRANSACT" ;tag=as798faed5 (62) [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 3: To: ;tag=E3B396A7-86EA13F6 (49) [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 4: CSeq: 104 NOTIFY (16) [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 5: Call-ID: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 (54) [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 6: Contact: (32) [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 7: Event: refer;id=3 (17) [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 (54) [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 9: Content-Length: 0 (17) [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 10: (0) [Dec 22 11:38:12] --- (10 headers 0 lines) --- [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:2061 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #107 [Dec 22 11:38:12] DEBUG[29461]: chan_sip.c:2071 __sip_ack: Stopping retransmission on '03c67e11087c3d9a794972a72bdcde46@192.168.1.12' of Request 104: Match Not Found [Dec 22 11:38:12] SIP Response message for INCOMING dialog NOTIFY arrived [Dec 22 11:38:12] WARNING[29461]: chan_sip.c:12307 handle_response: Notify answer on an owned channel? [Dec 22 11:38:15] <--- SIP read from 192.168.1.201:5060 ---> BYE sip:700@192.168.1.12 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bK2814897e1060FC8F From: "Cashier Station 3" ;tag=624FD85A-E3143D75 To: ;tag=as3fefa148 CSeq: 3 BYE Call-ID: 15b65ace-c94b0ffc-b824699f@192.168.1.201 Contact: User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 Proxy-Authorization: Digest username="808", realm="asterisk", nonce="7a0f9faa", uri="sip:700@192.168.1.12:5060;user=phone", response="4db0c1149de1c2a7f9d87578ec3ba735", algorithm=MD5 Max-Forwards: 70 Content-Length: 0 <-------------> [Dec 22 11:38:15] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 0: BYE sip:700@192.168.1.12 SIP/2.0 (32) [Dec 22 11:38:15] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bK2814897e1060FC8F (61) [Dec 22 11:38:15] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 2: From: "Cashier Station 3" ;tag=624FD85A-E3143D75 (70) [Dec 22 11:38:15] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 3: To: ;tag=as3fefa148 (52) [Dec 22 11:38:15] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 4: CSeq: 3 BYE (11) [Dec 22 11:38:15] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 5: Call-ID: 15b65ace-c94b0ffc-b824699f@192.168.1.201 (49) [Dec 22 11:38:15] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 6: Contact: (32) [Dec 22 11:38:15] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 (54) [Dec 22 11:38:15] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 8: Proxy-Authorization: Digest username="808", realm="asterisk", nonce="7a0f9faa", uri="sip:700@192.168.1.12:5060;user=phone", response="4db0c1149de1c2a7f9d87578ec3ba735", algorithm=MD5 (182) [Dec 22 11:38:15] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 9: Max-Forwards: 70 (16) [Dec 22 11:38:15] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 10: Content-Length: 0 (17) [Dec 22 11:38:15] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 11: (0) [Dec 22 11:38:15] --- (11 headers 0 lines) --- [Dec 22 11:38:15] DEBUG[29461]: chan_sip.c:14449 handle_request: **** Received BYE (8) - Command in SIP BYE [Dec 22 11:38:15] Sending to 192.168.1.201 : 5060 (no NAT) [Dec 22 11:38:15] DEBUG[29461]: chan_sip.c:1615 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 15b65ace-c94b0ffc-b824699f@192.168.1.201 [Dec 22 11:38:15] DEBUG[29461]: chan_sip.c:14026 handle_request_bye: Received bye, issuing owner hangup .[Dec 22 11:38:15] <--- Transmitting (no NAT) to 192.168.1.201:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bK2814897e1060FC8F;received=192.168.1.201 From: "Cashier Station 3" ;tag=624FD85A-E3143D75 To: ;tag=as3fefa148 Call-ID: 15b65ace-c94b0ffc-b824699f@192.168.1.201 CSeq: 3 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Dec 22 11:38:15] DEBUG[29443]: channel.c:2731 set_format: Set channel SIP/808-40f12500 to write format ulaw [Dec 22 11:38:15] -- Stopped music on hold on SIP/808-40f12500 [Dec 22 11:38:15] DEBUG[29443]: channel.c:1908 ast_settimeout: Scheduling timer at 0 sample intervals [Dec 22 11:38:15] == SIP/808-40f12500 got tired of being parked [Dec 22 11:38:15] DEBUG[29443]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '"Cashier Station 3" <808>' [Dec 22 11:38:15] DEBUG[29443]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '808' [Dec 22 11:38:15] DEBUG[29443]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '700' [Dec 22 11:38:15] DEBUG[29443]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'internal' [Dec 22 11:38:15] DEBUG[29443]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/808-40f12500' [Dec 22 11:38:15] DEBUG[29443]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Dec 22 11:38:15] DEBUG[29443]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'Park' [Dec 22 11:38:15] DEBUG[29443]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Dec 22 11:38:15] DEBUG[29443]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-12-22 11:38:06' [Dec 22 11:38:15] DEBUG[29443]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-12-22 11:38:06' [Dec 22 11:38:15] DEBUG[29443]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-12-22 11:38:15' [Dec 22 11:38:15] DEBUG[29443]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '9' [Dec 22 11:38:15] DEBUG[29443]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '9' [Dec 22 11:38:15] DEBUG[29443]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Dec 22 11:38:15] DEBUG[29443]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Dec 22 11:38:15] DEBUG[29443]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Dec 22 11:38:15] DEBUG[29443]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1166816286.8' [Dec 22 11:38:15] DEBUG[29443]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Dec 22 11:38:15] DEBUG[29443]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/808-40f12500' [Dec 22 11:38:15] DEBUG[29443]: chan_sip.c:3278 sip_hangup: Hangup call SIP/808-40f12500, SIP callid 15b65ace-c94b0ffc-b824699f@192.168.1.201) [Dec 22 11:38:15] DEBUG[29443]: chan_sip.c:3286 sip_hangup: update_call_counter(808) - decrement call limit counter on hangup [Dec 22 11:38:15] DEBUG[29443]: chan_sip.c:2978 update_call_counter: Updating call counter for incoming call [Dec 22 11:38:15] DEBUG[29443]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/808-40f12500 [Dec 22 11:38:15] DEBUG[29443]: res_features.c:277 notify_metermaids: Notification of state change to metermaids 701@parkedcalls [Dec 22 11:38:15] DEBUG[29443]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel park:701@parkedcalls [Dec 22 11:38:15] DEBUG[29440]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 808 [Dec 22 11:38:15] DEBUG[29440]: chan_sip.c:15044 sip_devicestate: Checking device state for peer 808 [Dec 22 11:38:15] DEBUG[29440]: devicestate.c:287 do_state_change: Changing state for SIP/808 - state 1 (Not in use) [Dec 22 11:38:15] DEBUG[29490]: app_queue.c:546 changethread: Device 'SIP/808' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 22 11:38:15] DEBUG[29440]: devicestate.c:157 ast_device_state: Checking if I can find provider for "park" - number: 701@parkedcalls [Dec 22 11:38:15] DEBUG[29440]: res_features.c:296 metermaidstate: Checking state of exten 701 in context parkedcalls [Dec 22 11:38:15] DEBUG[29440]: devicestate.c:287 do_state_change: Changing state for park:701@parkedcalls - state 1 (Not in use) [Dec 22 11:38:16] Really destroying SIP dialog '15b65ace-c94b0ffc-b824699f@192.168.1.201' Method: BYE [Dec 22 11:38:17] <--- SIP read from 192.168.1.201:5060 ---> INVITE sip:8019518134@192.168.1.12 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bK73002a2cCF3AE5E5 From: ;tag=E3B396A7-86EA13F6 To: "ITRANSACT" ;tag=as798faed5 CSeq: 4 INVITE Call-ID: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 Supported: 100rel,replaces Allow-Events: talk,hold,conference Max-Forwards: 70 Content-Type: application/sdp Content-Length: 251 v=0 o=- 1166766294 1166766296 IN IP4 192.168.1.201 s=Polycom IP Phone c=IN IP4 192.168.1.201 t=0 0 a=sendrecv m=audio 2262 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 <-------------> [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 0: INVITE sip:8019518134@192.168.1.12 SIP/2.0 (42) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bK73002a2cCF3AE5E5 (61) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 2: From: ;tag=E3B396A7-86EA13F6 (51) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 3: To: "ITRANSACT" ;tag=as798faed5 (60) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 4: CSeq: 4 INVITE (14) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 5: Call-ID: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 (54) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 6: Contact: (32) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 (54) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 9: Supported: 100rel,replaces (26) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 10: Allow-Events: talk,hold,conference (34) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 11: Max-Forwards: 70 (16) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 12: Content-Type: application/sdp (29) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 13: Content-Length: 251 (19) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 14: (0) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: v=0 (3) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: o=- 1166766294 1166766296 IN IP4 192.168.1.201 (46) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: s=Polycom IP Phone (18) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: c=IN IP4 192.168.1.201 (22) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: t=0 0 (5) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: a=sendrecv (10) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: m=audio 2262 RTP/AVP 0 8 18 101 (31) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4557 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Dec 22 11:38:17] --- (14 headers 11 lines) --- [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:14449 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Dec 22 11:38:17] Sending to 192.168.1.201 : 5060 (no NAT) [Dec 22 11:38:17] Found RTP audio format 0 [Dec 22 11:38:17] Found RTP audio format 8 [Dec 22 11:38:17] Found RTP audio format 18 [Dec 22 11:38:17] Found RTP audio format 101 [Dec 22 11:38:17] Peer audio RTP is at port 192.168.1.201:2262 [Dec 22 11:38:17] Found description format PCMU for ID 0 [Dec 22 11:38:17] Found description format PCMA for ID 8 [Dec 22 11:38:17] Found description format G729 for ID 18 [Dec 22 11:38:17] Found description format telephone-event for ID 101 [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:5066 process_sdp: T38 state changed to 0 on channel SIP/808-081f6440 [Dec 22 11:38:17] Capabilities: us - 0x4 (ulaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw) [Dec 22 11:38:17] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Dec 22 11:38:17] Peer audio RTP is at port 192.168.1.201:2262 [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:5143 process_sdp: We're settling with these formats: 0x4 (ulaw) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:5150 process_sdp: We have an owner, now see if we need to change this call [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:13284 handle_request_invite: Got a SIP re-invite for call 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:13379 handle_request_invite: SIP/808-081f6440: This call is UP.... [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:6352 transmit_response_with_sdp: Setting framing from config on incoming call [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:6120 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:6121 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Dec 22 11:38:17] Audio is at 192.168.1.12 port 15086 [Dec 22 11:38:17] Adding codec 0x4 (ulaw) to SDP [Dec 22 11:38:17] Adding non-codec 0x1 (telephone-event) to SDP [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:6252 add_sdp: -- Done with adding codecs to SDP [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:6297 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Dec 22 11:38:17] <--- Reliably Transmitting (no NAT) to 192.168.1.201:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bK73002a2cCF3AE5E5;received=192.168.1.201 From: ;tag=E3B396A7-86EA13F6 To: "ITRANSACT" ;tag=as798faed5 Call-ID: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 CSeq: 4 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 240 v=0 o=root 29436 29438 IN IP4 192.168.1.12 s=session c=IN IP4 192.168.1.12 t=0 0 m=audio 15086 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 <------------> [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:1957 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #108 [Dec 22 11:38:17] DEBUG[29469]: chan_zap.c:5008 zt_indicate: Requested indication 17 on channel Zap/2-1 [Dec 22 11:38:17] DEBUG[29469]: rtp.c:2638 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Dec 22 11:38:17] DEBUG[29469]: rtp.c:2491 ast_rtp_raw_write: Difference is 104320, ms is 13060 [Dec 22 11:38:17] <--- SIP read from 192.168.1.201:5060 ---> ACK sip:8019518134@192.168.1.12 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bK98a1aa0aE8F638AB From: ;tag=E3B396A7-86EA13F6 To: "ITRANSACT" ;tag=as798faed5 CSeq: 4 ACK Call-ID: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 Max-Forwards: 70 Content-Length: 0 <-------------> [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 0: ACK sip:8019518134@192.168.1.12 SIP/2.0 (39) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bK98a1aa0aE8F638AB (61) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 2: From: ;tag=E3B396A7-86EA13F6 (51) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 3: To: "ITRANSACT" ;tag=as798faed5 (60) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 4: CSeq: 4 ACK (11) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 5: Call-ID: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 (54) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 6: Contact: (32) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 (54) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 9: Max-Forwards: 70 (16) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 10: Content-Length: 0 (17) [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 11: (0) [Dec 22 11:38:17] --- (11 headers 0 lines) --- [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:14449 handle_request: **** Received ACK (6) - Command in SIP ACK [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:2061 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #108 [Dec 22 11:38:17] DEBUG[29461]: chan_sip.c:2071 __sip_ack: Stopping retransmission on '03c67e11087c3d9a794972a72bdcde46@192.168.1.12' of Response 4: Match Not Found [Dec 22 11:38:18] DEBUG[29469]: rtp.c:866 ast_rtcp_read: Got RTCP report of 100 bytes [Dec 22 11:38:22] DEBUG[29451]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/800-iax [Dec 22 11:38:22] DEBUG[29440]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 800 [Dec 22 11:38:22] DEBUG[29440]: chan_iax2.c:9570 iax2_devicestate: Checking device state for device 800 [Dec 22 11:38:22] DEBUG[29440]: devicestate.c:287 do_state_change: Changing state for IAX2/800 - state 4 (Invalid) [Dec 22 11:38:22] DEBUG[29492]: app_queue.c:546 changethread: Device 'IAX2/800' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Dec 22 11:38:23] <--- SIP read from 192.168.1.201:5060 ---> BYE sip:8019518134@192.168.1.12 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bKa95a88982EE98E61 From: ;tag=E3B396A7-86EA13F6 To: "ITRANSACT" ;tag=as798faed5 CSeq: 5 BYE Call-ID: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 Contact: User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 Max-Forwards: 70 Content-Length: 0 <-------------> [Dec 22 11:38:23] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 0: BYE sip:8019518134@192.168.1.12 SIP/2.0 (39) [Dec 22 11:38:23] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bKa95a88982EE98E61 (61) [Dec 22 11:38:23] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 2: From: ;tag=E3B396A7-86EA13F6 (51) [Dec 22 11:38:23] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 3: To: "ITRANSACT" ;tag=as798faed5 (60) [Dec 22 11:38:23] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 4: CSeq: 5 BYE (11) [Dec 22 11:38:23] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 5: Call-ID: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 (54) [Dec 22 11:38:23] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 6: Contact: (32) [Dec 22 11:38:23] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_600-UA/1.6.7.0098 (54) [Dec 22 11:38:23] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 8: Max-Forwards: 70 (16) [Dec 22 11:38:23] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 9: Content-Length: 0 (17) [Dec 22 11:38:23] DEBUG[29461]: chan_sip.c:4525 parse_request: Header 10: (0) [Dec 22 11:38:23] --- (10 headers 0 lines) --- [Dec 22 11:38:23] DEBUG[29461]: chan_sip.c:14449 handle_request: **** Received BYE (8) - Command in SIP BYE [Dec 22 11:38:23] Sending to 192.168.1.201 : 5060 (no NAT) [Dec 22 11:38:23] DEBUG[29461]: chan_sip.c:1615 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 [Dec 22 11:38:23] DEBUG[29461]: chan_sip.c:14026 handle_request_bye: Received bye, issuing owner hangup .[Dec 22 11:38:23] <--- Transmitting (no NAT) to 192.168.1.201:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.201;branch=z9hG4bKa95a88982EE98E61;received=192.168.1.201 From: ;tag=E3B396A7-86EA13F6 To: "ITRANSACT" ;tag=as798faed5 Call-ID: 03c67e11087c3d9a794972a72bdcde46@192.168.1.12 CSeq: 5 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Dec 22 11:38:23] DEBUG[29469]: channel.c:3682 ast_generic_bridge: Didn't get a frame from channel: SIP/808-081f6440 [Dec 22 11:38:23] DEBUG[29469]: channel.c:3990 ast_channel_bridge: Bridge stops bridging channels Zap/2-1 and SIP/808-081f6440 [Dec 22 11:38:23] DEBUG[29469]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/808-081f6440' [Dec 22 11:38:23] DEBUG[29469]: chan_sip.c:3278 sip_hangup: Hangup call SIP/808-081f6440, SIP callid 03c67e11087c3d9a794972a72bdcde46@192.168.1.12) [Dec 22 11:38:23] DEBUG[29469]: chan_sip.c:3286 sip_hangup: update_call_counter(808) - decrement call limit counter on hangup [Dec 22 11:38:23] DEBUG[29469]: chan_sip.c:2978 update_call_counter: Updating call counter for incoming call [Dec 22 11:38:23] DEBUG[29469]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/808-081f6440 [Dec 22 11:38:23] DEBUG[29469]: rtp.c:1469 ast_rtp_early_bridge: Channel 'Zap/2-1' has no RTP, not doing anything [Dec 22 11:38:23] DEBUG[29469]: app_dial.c:1640 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Dec 22 11:38:23] DEBUG[29469]: pbx.c:2363 __ast_pbx_run: Spawn extension (default,s,8) exited non-zero on 'Zap/2-1' [Dec 22 11:38:23] == Spawn extension (default, s, 8) exited non-zero on 'Zap/2-1' [Dec 22 11:38:23] DEBUG[29440]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 808 [Dec 22 11:38:23] DEBUG[29440]: chan_sip.c:15044 sip_devicestate: Checking device state for peer 808 [Dec 22 11:38:23] DEBUG[29440]: devicestate.c:287 do_state_change: Changing state for SIP/808 - state 1 (Not in use) [Dec 22 11:38:23] DEBUG[29493]: app_queue.c:546 changethread: Device 'SIP/808' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 22 11:38:23] Really destroying SIP dialog '03c67e11087c3d9a794972a72bdcde46@192.168.1.12' Method: BYE [Dec 22 11:38:23] DEBUG[29469]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '"ITRANSACT " <8019518134>' [Dec 22 11:38:23] DEBUG[29469]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '8019518134' [Dec 22 11:38:23] DEBUG[29469]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 's' [Dec 22 11:38:23] DEBUG[29469]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'default' [Dec 22 11:38:23] DEBUG[29469]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'Zap/2-1' [Dec 22 11:38:23] DEBUG[29469]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/808-081f6440' [Dec 22 11:38:23] DEBUG[29469]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'Dial' [Dec 22 11:38:23] DEBUG[29469]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/806&SIP/807&SIP/808&SIP/810&SIP/820&SIP/830&SIP/840|20|r' [Dec 22 11:38:23] DEBUG[29469]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-12-22 11:37:25' [Dec 22 11:38:23] DEBUG[29469]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-12-22 11:37:25' [Dec 22 11:38:23] DEBUG[29469]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-12-22 11:38:23' [Dec 22 11:38:23] DEBUG[29469]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '58' [Dec 22 11:38:23] DEBUG[29469]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '58' [Dec 22 11:38:23] DEBUG[29469]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Dec 22 11:38:23] DEBUG[29469]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Dec 22 11:38:23] DEBUG[29469]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Dec 22 11:38:23] DEBUG[29469]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1166816244.0' [Dec 22 11:38:23] DEBUG[29469]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Dec 22 11:38:23] DEBUG[29469]: channel.c:1606 ast_hangup: Hanging up channel 'Zap/2-1' [Dec 22 11:38:23] DEBUG[29469]: chan_zap.c:2438 zt_hangup: zt_hangup(Zap/2-1) [Dec 22 11:38:23] DEBUG[29469]: chan_zap.c:2471 zt_hangup: Hangup: channel: 2 index = 0, normal = 20, callwait = -1, thirdcall = -1 [Dec 22 11:38:23] DEBUG[29469]: chan_zap.c:1493 zt_disable_ec: disabled echo cancellation on channel 2 [Dec 22 11:38:23] DEBUG[29469]: chan_zap.c:2899 zt_setoption: Set option TDD MODE, value: OFF(0) on Zap/2-1 [Dec 22 11:38:23] DEBUG[29469]: chan_zap.c:1430 update_conf: Updated conferencing on 2, with 0 conference users [Dec 22 11:38:23] -- Hungup 'Zap/2-1' [Dec 22 11:38:23] DEBUG[29469]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/2-1 [Dec 22 11:38:23] DEBUG[29440]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 2 [Dec 22 11:38:23] DEBUG[29440]: devicestate.c:287 do_state_change: Changing state for Zap/2 - state 0 (Unknown) [Dec 22 11:38:23] DEBUG[29494]: app_queue.c:546 changethread: Device 'Zap/2' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. *CLI> stop now [Dec 22 11:38:27] Beginning asterisk shutdown.... [Dec 22 11:38:27] Executing last minute cleanups [Dec 22 11:38:27] == Destroying musiconhold processes [Dec 22 11:38:27] DEBUG[29436]: res_musiconhold.c:1118 ast_moh_destroy: killing 29442! [Dec 22 11:38:27] DEBUG[29436]: res_musiconhold.c:1132 ast_moh_destroy: mpg123 pid 29442 and child died after 21248 bytes read [Dec 22 11:38:27] Asterisk cleanly ending (0). [Dec 22 11:38:27] DEBUG[29436]: asterisk.c:1193 quit_handler: Asterisk ending (0). vs1:/etc/asterisk#