[Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: <--- SIP read from UDP:86.59.13.51:1198 ---> INVITE sip:200@voip-dev-01-01-1002.sil.at SIP/2.0 Via: SIP/2.0/UDP 86.59.13.51:1254;branch=z9hG4bK-c4c2b39 From: ;tag=7d6902f4e3ed4993o1 To: Call-ID: b733f348-f76cf54f@192.168.2.170 CSeq: 101 INVITE Max-Forwards: 70 Contact: Expires: 240 User-Agent: Cisco/SPA525G-7.4.3 Content-Length: 333 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE Supported: replaces Content-Type: application/sdp v=0 o=- 23928 23928 IN IP4 192.168.2.170 s=- c=IN IP4 86.59.13.51 t=0 0 m=audio 6968 RTP/AVP 8 0 2 9 104 18 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:9 G722/8000 a=rtpmap:104 L16/16000 a=rtpmap:18 G729a/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv <-------------> [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 0 [ 49]: INVITE sip:200@voip-dev-01-01-1002.sil.at SIP/2.0 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 1 [ 56]: Via: SIP/2.0/UDP 86.59.13.51:1254;branch=z9hG4bK-c4c2b39 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 2 [ 65]: From: ;tag=7d6902f4e3ed4993o1 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 3 [ 40]: To: [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 4 [ 40]: Call-ID: b733f348-f76cf54f@192.168.2.170 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 5 [ 16]: CSeq: 101 INVITE [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 7 [ 35]: Contact: [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 8 [ 12]: Expires: 240 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 9 [ 31]: User-Agent: Cisco/SPA525G-7.4.3 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 10 [ 19]: Content-Length: 333 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 11 [ 69]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 12 [ 19]: Supported: replaces [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 13 [ 29]: Content-Type: application/sdp [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 14 [ 0]: [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 0 [ 3]: v=0 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 1 [ 36]: o=- 23928 23928 IN IP4 192.168.2.170 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 2 [ 3]: s=- [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 3 [ 20]: c=IN IP4 86.59.13.51 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 4 [ 5]: t=0 0 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 5 [ 39]: m=audio 6968 RTP/AVP 8 0 2 9 104 18 101 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 8 [ 23]: a=rtpmap:2 G726-32/8000 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 9 [ 20]: a=rtpmap:9 G722/8000 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 10 [ 22]: a=rtpmap:104 L16/16000 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 11 [ 22]: a=rtpmap:18 G729a/8000 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 12 [ 33]: a=rtpmap:101 telephone-event/8000 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 13 [ 15]: a=fmtp:101 0-15 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 14 [ 10]: a=ptime:20 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 15 [ 10]: a=sendrecv [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: --- (14 headers 16 lines) --- [Jun 16 13:18:51] DEBUG[21576] acl.c: Found IP address for this socket [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 86.59.114.69:5060 [Jun 16 13:18:51] VERBOSE[21576] netsock.c: == Using SIP RTP CoS mark 5 [Jun 16 13:18:51] VERBOSE[21576] netsock.c: == Using UDPTL CoS mark 5 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Setting NAT on RTP to On [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Setting NAT on UDPTL to On [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Allocating new SIP dialog for b733f348-f76cf54f@192.168.2.170 - INVITE (With RTP) [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Begin: parsing SIP "Supported: replaces" [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Found SIP option: -replaces- [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Matched SIP option: replaces [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Sending to 86.59.13.51 : 1198 (NAT) [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Initializing initreq for method INVITE - callid b733f348-f76cf54f@192.168.2.170 [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Using INVITE request as basis request - b733f348-f76cf54f@192.168.2.170 [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Found peer '100' for '100' from 86.59.13.51:1198 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Setting NAT on RTP to On [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Setting NAT on UDPTL to On [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: <--- Reliably Transmitting (NAT) to 86.59.13.51:1198 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 86.59.13.51:1254;branch=z9hG4bK-c4c2b39;received=86.59.13.51 From: ;tag=7d6902f4e3ed4993o1 To: ;tag=as274a81e3 Call-ID: b733f348-f76cf54f@192.168.2.170 CSeq: 101 INVITE Server: PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="pbx.sil.at", nonce="43e788cb" Content-Length: 0 <------------> [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #205 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 86.59.13.51:1198 [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Scheduling destruction of SIP dialog 'b733f348-f76cf54f@192.168.2.170' in 32000 ms (Method: INVITE) [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: <--- SIP read from UDP:86.59.13.51:1198 ---> ACK sip:200@voip-dev-01-01-1002.sil.at SIP/2.0 Via: SIP/2.0/UDP 86.59.13.51:1254;branch=z9hG4bK-c4c2b39 From: ;tag=7d6902f4e3ed4993o1 To: ;tag=as274a81e3 Call-ID: b733f348-f76cf54f@192.168.2.170 CSeq: 101 ACK Max-Forwards: 70 Contact: User-Agent: Cisco/SPA525G-7.4.3 Content-Length: 0 <-------------> [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 0 [ 46]: ACK sip:200@voip-dev-01-01-1002.sil.at SIP/2.0 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 1 [ 56]: Via: SIP/2.0/UDP 86.59.13.51:1254;branch=z9hG4bK-c4c2b39 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 2 [ 65]: From: ;tag=7d6902f4e3ed4993o1 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 3 [ 55]: To: ;tag=as274a81e3 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 4 [ 40]: Call-ID: b733f348-f76cf54f@192.168.2.170 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 5 [ 13]: CSeq: 101 ACK [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 7 [ 35]: Contact: [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 8 [ 31]: User-Agent: Cisco/SPA525G-7.4.3 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 10 [ 0]: [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: --- (10 headers 0 lines) --- [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #205 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Stopping retransmission on 'b733f348-f76cf54f@192.168.2.170' of Response 101: Match Found [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: <--- SIP read from UDP:86.59.13.51:1198 ---> INVITE sip:200@voip-dev-01-01-1002.sil.at SIP/2.0 Via: SIP/2.0/UDP 86.59.13.51:1254;branch=z9hG4bK-a63de0dd From: ;tag=7d6902f4e3ed4993o1 To: Call-ID: b733f348-f76cf54f@192.168.2.170 CSeq: 102 INVITE Max-Forwards: 70 Authorization: Digest username="100",realm="pbx.sil.at",nonce="43e788cb",uri="sip:200@voip-dev-01-01-1002.sil.at",algorithm=MD5,response="8d045d4883936eaa3be4b66f710573ee" Contact: Expires: 240 User-Agent: Cisco/SPA525G-7.4.3 Content-Length: 333 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE Supported: replaces Content-Type: application/sdp v=0 o=- 23928 23928 IN IP4 192.168.2.170 s=- c=IN IP4 86.59.13.51 t=0 0 m=audio 6968 RTP/AVP 8 0 2 9 104 18 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:9 G722/8000 a=rtpmap:104 L16/16000 a=rtpmap:18 G729a/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv <-------------> [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 0 [ 49]: INVITE sip:200@voip-dev-01-01-1002.sil.at SIP/2.0 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 86.59.13.51:1254;branch=z9hG4bK-a63de0dd [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 2 [ 65]: From: ;tag=7d6902f4e3ed4993o1 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 3 [ 40]: To: [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 4 [ 40]: Call-ID: b733f348-f76cf54f@192.168.2.170 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 5 [ 16]: CSeq: 102 INVITE [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 7 [171]: Authorization: Digest username="100",realm="pbx.sil.at",nonce="43e788cb",uri="sip:200@voip-dev-01-01-1002.sil.at",algorithm=MD5,response="8d045d4883936eaa3be4b66f710573ee" [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 8 [ 35]: Contact: [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 9 [ 12]: Expires: 240 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 10 [ 31]: User-Agent: Cisco/SPA525G-7.4.3 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 11 [ 19]: Content-Length: 333 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 12 [ 69]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 13 [ 19]: Supported: replaces [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 14 [ 29]: Content-Type: application/sdp [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 15 [ 0]: [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 0 [ 3]: v=0 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 1 [ 36]: o=- 23928 23928 IN IP4 192.168.2.170 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 2 [ 3]: s=- [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 3 [ 20]: c=IN IP4 86.59.13.51 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 4 [ 5]: t=0 0 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 5 [ 39]: m=audio 6968 RTP/AVP 8 0 2 9 104 18 101 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 8 [ 23]: a=rtpmap:2 G726-32/8000 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 9 [ 20]: a=rtpmap:9 G722/8000 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 10 [ 22]: a=rtpmap:104 L16/16000 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 11 [ 22]: a=rtpmap:18 G729a/8000 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 12 [ 33]: a=rtpmap:101 telephone-event/8000 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 13 [ 15]: a=fmtp:101 0-15 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 14 [ 10]: a=ptime:20 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Body 15 [ 10]: a=sendrecv [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: --- (15 headers 16 lines) --- [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Sending to 86.59.13.51 : 1198 (NAT) [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Initializing initreq for method INVITE - callid b733f348-f76cf54f@192.168.2.170 [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Using INVITE request as basis request - b733f348-f76cf54f@192.168.2.170 [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Found peer '100' for '100' from 86.59.13.51:1198 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Setting NAT on RTP to On [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Setting NAT on UDPTL to On [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Processing session-level SDP o=- 23928 23928 IN IP4 192.168.2.170... UNSUPPORTED. [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Processing session-level SDP c=IN IP4 86.59.13.51... OK. [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Found RTP audio format 8 [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Found RTP audio format 0 [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Found RTP audio format 2 [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Found RTP audio format 9 [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Found RTP audio format 104 [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Found RTP audio format 18 [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Found RTP audio format 101 [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Found audio description format PCMA for ID 8 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Found audio description format PCMU for ID 0 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Found audio description format G726-32 for ID 2 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:2 G726-32/8000... OK. [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Found audio description format G722 for ID 9 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Found audio description format L16 for ID 104 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:104 L16/16000... OK. [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Found audio description format G729a for ID 18 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729a/8000... OK. [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Found audio description format telephone-event for ID 101 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Capabilities: us - 0x8 (alaw), peer - audio=0x40190c (ulaw|alaw|g726|g729|g722|mpeg4)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x8 (alaw) [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Peer audio RTP is at port 86.59.13.51:6968 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Peer doesn't provide T.38 UDPTL [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: We're settling with these formats: 0x8 (alaw) [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Checking SIP call limits for device 100 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Updating call counter for incoming call [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Call from peer '100' is 1 out of 100 [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: Looking for 200 in outcust (domain voip-dev-01-01-1002.sil.at) [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: *** Our native formats are 0x8 (alaw) [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: *** Joint capabilities are 0x8 (alaw) [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: *** Our capabilities are 0x8 (alaw) [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: This channel will not be able to handle video. [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: build_route: Contact hop: [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: list_route: hop: [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: SIP/100-00000000: New call is still down.... Trying... [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: <--- Transmitting (NAT) to 86.59.13.51:1198 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 86.59.13.51:1254;branch=z9hG4bK-a63de0dd;received=86.59.13.51 From: ;tag=7d6902f4e3ed4993o1 To: Call-ID: b733f348-f76cf54f@192.168.2.170 CSeq: 102 INVITE Server: PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Length: 0 <------------> [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 86.59.13.51:1198 [Jun 16 13:18:51] DEBUG[21563] devicestate.c: No provider found, checking channel drivers for SIP - 100 [Jun 16 13:18:51] DEBUG[21563] chan_sip.c: Checking device state for peer 100 [Jun 16 13:18:51] DEBUG[21563] devicestate.c: Changing state for SIP/100 - state 2 (In use) [Jun 16 13:18:51] DEBUG[21563] devicestate.c: device 'SIP/100' state '2' [Jun 16 13:18:51] DEBUG[31834] pbx.c: Launching 'Answer' [Jun 16 13:18:51] VERBOSE[31834] pbx.c: -- Executing [200@outcust:1] Answer("SIP/100-00000000", "") in new stack [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: SIP answering channel: SIP/100-00000000 [Jun 16 13:18:51] DEBUG[31834] rtp.c: Setting the marker bit due to a source update [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Setting framing from config on incoming call [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: True Text flag: True [Jun 16 13:18:51] DEBUG[21568] app_queue.c: Device 'SIP/100' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Jun 16 13:18:51] VERBOSE[31834] chan_sip.c: Audio is at 86.59.114.69 port 12138 [Jun 16 13:18:51] VERBOSE[31834] chan_sip.c: Adding codec 0x8 (alaw) to SDP [Jun 16 13:18:51] VERBOSE[31834] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: -- Done with adding codecs to SDP [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw) [Jun 16 13:18:51] VERBOSE[31834] chan_sip.c: <--- Reliably Transmitting (NAT) to 86.59.13.51:1198 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 86.59.13.51:1254;branch=z9hG4bK-a63de0dd;received=86.59.13.51 From: ;tag=7d6902f4e3ed4993o1 To: ;tag=as33c727d0 Call-ID: b733f348-f76cf54f@192.168.2.170 CSeq: 102 INVITE Server: PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 263 v=0 o=root 1874631378 1874631378 IN IP4 86.59.114.69 s=Asterisk PBX 1.6.2.7 c=IN IP4 86.59.114.69 t=0 0 m=audio 12138 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #208 [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 86.59.13.51:1198 [Jun 16 13:18:51] DEBUG[21563] devicestate.c: No provider found, checking channel drivers for SIP - 100 [Jun 16 13:18:51] DEBUG[21563] chan_sip.c: Checking device state for peer 100 [Jun 16 13:18:51] DEBUG[21563] devicestate.c: Changing state for SIP/100 - state 2 (In use) [Jun 16 13:18:51] DEBUG[21563] devicestate.c: device 'SIP/100' state '2' [Jun 16 13:18:51] DEBUG[21563] devicestate.c: No provider found, checking channel drivers for SIP - 100 [Jun 16 13:18:51] DEBUG[21563] chan_sip.c: Checking device state for peer 100 [Jun 16 13:18:51] DEBUG[21563] devicestate.c: Changing state for SIP/100 - state 2 (In use) [Jun 16 13:18:51] DEBUG[21563] devicestate.c: device 'SIP/100' state '2' [Jun 16 13:18:51] DEBUG[21568] app_queue.c: Device 'SIP/100' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 16 13:18:51] DEBUG[21568] app_queue.c: Device 'SIP/100' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: <--- SIP read from UDP:86.59.13.51:1198 ---> ACK sip:200@86.59.114.69 SIP/2.0 Via: SIP/2.0/UDP 86.59.13.51:1254;branch=z9hG4bK-aa835cc8 From: ;tag=7d6902f4e3ed4993o1 To: ;tag=as33c727d0 Call-ID: b733f348-f76cf54f@192.168.2.170 CSeq: 102 ACK Max-Forwards: 70 Authorization: Digest username="100",realm="pbx.sil.at",nonce="43e788cb",uri="sip:200@voip-dev-01-01-1002.sil.at",algorithm=MD5,response="8d045d4883936eaa3be4b66f710573ee" Contact: User-Agent: Cisco/SPA525G-7.4.3 Content-Length: 0 <-------------> [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 0 [ 32]: ACK sip:200@86.59.114.69 SIP/2.0 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 86.59.13.51:1254;branch=z9hG4bK-aa835cc8 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 2 [ 65]: From: ;tag=7d6902f4e3ed4993o1 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 3 [ 55]: To: ;tag=as33c727d0 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 4 [ 40]: Call-ID: b733f348-f76cf54f@192.168.2.170 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 5 [ 13]: CSeq: 102 ACK [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 7 [171]: Authorization: Digest username="100",realm="pbx.sil.at",nonce="43e788cb",uri="sip:200@voip-dev-01-01-1002.sil.at",algorithm=MD5,response="8d045d4883936eaa3be4b66f710573ee" [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 8 [ 35]: Contact: [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 9 [ 31]: User-Agent: Cisco/SPA525G-7.4.3 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 11 [ 0]: [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: --- (11 headers 0 lines) --- [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #208 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Stopping retransmission on 'b733f348-f76cf54f@192.168.2.170' of Response 102: Match Found [Jun 16 13:18:51] DEBUG[31834] rtp.c: RTP NAT: Got audio from other end. Now sending to address 86.59.13.51:3473 [Jun 16 13:18:51] DEBUG[31834] pbx.c: Launching 'Dial' [Jun 16 13:18:51] VERBOSE[31834] pbx.c: -- Executing [200@outcust:2] Dial("SIP/100-00000000", "SIP/200,20") in new stack [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Asked to create a SIP channel with formats: 0x8 (alaw) [Jun 16 13:18:51] VERBOSE[31834] netsock.c: == Using SIP RTP CoS mark 5 [Jun 16 13:18:51] VERBOSE[31834] netsock.c: == Using UDPTL CoS mark 5 [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Allocating new SIP dialog for 394b4979330ead8e0c7b040321b9b6ea@86.59.114.69 - INVITE (With RTP) [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Setting NAT on RTP to On [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Setting NAT on UDPTL to On [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: OBPROXY: Not applying OBproxy to this call [Jun 16 13:18:51] DEBUG[31834] acl.c: Found IP address for this socket [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 86.59.114.69:5060 [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: *** Our native formats are 0x8 (alaw) [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: *** Joint capabilities are 0x8 (alaw) [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: *** Our capabilities are 0x8 (alaw) [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: *** Our preferred formats from the incoming channel are 0x8 (alaw) [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: This channel will not be able to handle video. [Jun 16 13:18:51] DEBUG[31834] channel.c: Not copying variable DIALEDTIME. [Jun 16 13:18:51] DEBUG[31834] channel.c: Not copying variable ANSWEREDTIME. [Jun 16 13:18:51] DEBUG[31834] channel.c: Not copying variable DIALEDPEERNAME. [Jun 16 13:18:51] DEBUG[31834] channel.c: Not copying variable DIALEDPEERNUMBER. [Jun 16 13:18:51] DEBUG[31834] channel.c: Not copying variable DIALSTATUS. [Jun 16 13:18:51] DEBUG[31834] channel.c: Not copying variable SIPCALLID. [Jun 16 13:18:51] DEBUG[31834] channel.c: Not copying variable SIPDOMAIN. [Jun 16 13:18:51] DEBUG[31834] channel.c: Not copying variable SIPURI. [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Outgoing Call for 200 [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Updating call counter for outgoing call [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Call to peer '200' is 1 out of 100 [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: False Text flag: False [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: ** Our prefcodec: 0x8 (alaw) [Jun 16 13:18:51] VERBOSE[31834] chan_sip.c: Audio is at 86.59.114.69 port 18400 [Jun 16 13:18:51] VERBOSE[31834] chan_sip.c: Adding codec 0x8 (alaw) to SDP [Jun 16 13:18:51] VERBOSE[31834] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: -- Done with adding codecs to SDP [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw) [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Initializing initreq for method INVITE - callid 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Header 0 [ 39]: INVITE sip:200@86.59.13.51:6206 SIP/2.0 [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK11166dec;rport [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Header 3 [ 53]: From: "Phone A" ;tag=as377e020c [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Header 4 [ 30]: To: [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Header 5 [ 31]: Contact: [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Header 6 [ 54]: Call-ID: 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Header 8 [ 15]: User-Agent: PBX [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Header 9 [ 71]: Remote-Party-ID: "Phone A" ;privacy=off;screen=no [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Header 10 [ 35]: Date: Wed, 16 Jun 2010 11:18:51 GMT [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Header 11 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Header 12 [ 26]: Supported: replaces, timer [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Header 13 [ 29]: Content-Type: application/sdp [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Header 14 [ 19]: Content-Length: 263 [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Header 15 [ 0]: [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Body 0 [ 3]: v=0 [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Body 1 [ 48]: o=root 1527560327 1527560327 IN IP4 86.59.114.69 [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Body 2 [ 22]: s=Asterisk PBX 1.6.2.7 [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Body 3 [ 21]: c=IN IP4 86.59.114.69 [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Body 4 [ 5]: t=0 0 [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Body 5 [ 27]: m=audio 18400 RTP/AVP 8 101 [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-16 [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Body 9 [ 25]: a=silenceSupp:off - - - - [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Body 10 [ 10]: a=ptime:20 [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Body 11 [ 10]: a=sendrecv [Jun 16 13:18:51] VERBOSE[31834] chan_sip.c: Reliably Transmitting (NAT) to 86.59.13.51:4927: INVITE sip:200@86.59.13.51:6206 SIP/2.0 Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK11166dec;rport Max-Forwards: 70 From: "Phone A" ;tag=as377e020c To: Contact: Call-ID: 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 CSeq: 102 INVITE User-Agent: PBX Remote-Party-ID: "Phone A" ;privacy=off;screen=no Date: Wed, 16 Jun 2010 11:18:51 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Type: application/sdp Content-Length: 263 v=0 o=root 1527560327 1527560327 IN IP4 86.59.114.69 s=Asterisk PBX 1.6.2.7 c=IN IP4 86.59.114.69 t=0 0 m=audio 18400 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #210 [Jun 16 13:18:51] DEBUG[31834] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 86.59.13.51:4927 [Jun 16 13:18:51] VERBOSE[31834] app_dial.c: -- Called 200 [Jun 16 13:18:51] DEBUG[21563] devicestate.c: No provider found, checking channel drivers for SIP - 200 [Jun 16 13:18:51] DEBUG[21563] chan_sip.c: Checking device state for peer 200 [Jun 16 13:18:51] DEBUG[21563] devicestate.c: Changing state for SIP/200 - state 6 (Ringing) [Jun 16 13:18:51] DEBUG[21563] devicestate.c: device 'SIP/200' state '6' [Jun 16 13:18:51] DEBUG[21568] app_queue.c: Device 'SIP/200' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: <--- SIP read from UDP:86.59.13.51:4927 ---> SIP/2.0 100 Trying To: From: "Phone A" ;tag=as377e020c Call-ID: 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 CSeq: 102 INVITE Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK11166dec Server: Cisco/SPA525G-7.4.4 Content-Length: 0 <-------------> [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 0 [ 18]: SIP/2.0 100 Trying [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 1 [ 30]: To: [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 2 [ 53]: From: "Phone A" ;tag=as377e020c [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 3 [ 54]: Call-ID: 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 4 [ 16]: CSeq: 102 INVITE [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 5 [ 57]: Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK11166dec [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 6 [ 27]: Server: Cisco/SPA525G-7.4.4 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 8 [ 0]: [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: --- (8 headers 0 lines) --- [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: *** SIP TIMER: Cancelling retransmission #210 - INVITE (got response) [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '641fe9110adc7f6c0ba085e861064c7c@86.59.114.69' Request 102: Found [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: SIP response 100 to standard invite [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: <--- SIP read from UDP:86.59.13.51:4927 ---> SIP/2.0 180 Ringing To: ;tag=777c78c2d97c931ai2 From: "Phone A" ;tag=as377e020c Call-ID: 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 CSeq: 102 INVITE Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK11166dec Contact: Server: Cisco/SPA525G-7.4.4 Content-Length: 0 <-------------> [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 0 [ 19]: SIP/2.0 180 Ringing [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 1 [ 53]: To: ;tag=777c78c2d97c931ai2 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 2 [ 53]: From: "Phone A" ;tag=as377e020c [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 3 [ 54]: Call-ID: 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 4 [ 16]: CSeq: 102 INVITE [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 5 [ 57]: Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK11166dec [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 6 [ 35]: Contact: [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 7 [ 27]: Server: Cisco/SPA525G-7.4.4 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: Header 9 [ 0]: [Jun 16 13:18:51] VERBOSE[21576] chan_sip.c: --- (9 headers 0 lines) --- [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '641fe9110adc7f6c0ba085e861064c7c@86.59.114.69' Request 102: Found [Jun 16 13:18:51] DEBUG[21576] chan_sip.c: SIP response 180 to standard invite [Jun 16 13:18:51] DEBUG[21563] devicestate.c: No provider found, checking channel drivers for SIP - 200 [Jun 16 13:18:51] DEBUG[21563] chan_sip.c: Checking device state for peer 200 [Jun 16 13:18:51] DEBUG[21563] devicestate.c: Changing state for SIP/200 - state 6 (Ringing) [Jun 16 13:18:51] DEBUG[21563] devicestate.c: device 'SIP/200' state '6' [Jun 16 13:18:51] VERBOSE[31834] app_dial.c: -- SIP/200-00000001 is ringing [Jun 16 13:18:51] DEBUG[31834] channel.c: Driver for channel 'SIP/100-00000000' does not support indication 3, emulating it [Jun 16 13:18:51] DEBUG[31834] channel.c: Set channel SIP/100-00000000 to write format slin [Jun 16 13:18:51] DEBUG[31834] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 16 13:18:51] DEBUG[21568] app_queue.c: Device 'SIP/200' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jun 16 13:18:51] DEBUG[31834] channel.c: Generator got voice, switching to phase locked mode [Jun 16 13:18:51] DEBUG[31834] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 16 13:18:51] DEBUG[31834] rtp.c: Ooh, format changed from unknown to alaw [Jun 16 13:18:51] DEBUG[31834] rtp.c: Created smoother: format: 8 ms: 20 len: 160 [Jun 16 13:18:54] VERBOSE[21576] chan_sip.c: <--- SIP read from UDP:86.59.13.51:4927 ---> SIP/2.0 200 OK To: ;tag=777c78c2d97c931ai2 From: "Phone A" ;tag=as377e020c Call-ID: 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 CSeq: 102 INVITE Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK11166dec Contact: Server: Cisco/SPA525G-7.4.4 Content-Length: 202 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE Supported: replaces Content-Type: application/sdp v=0 o=- 21109 21109 IN IP4 192.168.2.77 s=- c=IN IP4 86.59.13.51 t=0 0 m=audio 6750 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv <-------------> [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Header 1 [ 53]: To: ;tag=777c78c2d97c931ai2 [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Header 2 [ 53]: From: "Phone A" ;tag=as377e020c [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Header 3 [ 54]: Call-ID: 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Header 4 [ 16]: CSeq: 102 INVITE [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Header 5 [ 57]: Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK11166dec [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Header 6 [ 35]: Contact: [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Header 7 [ 27]: Server: Cisco/SPA525G-7.4.4 [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Header 8 [ 19]: Content-Length: 202 [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Header 9 [ 69]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Header 10 [ 19]: Supported: replaces [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Header 11 [ 29]: Content-Type: application/sdp [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Header 12 [ 0]: [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Body 0 [ 3]: v=0 [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Body 1 [ 35]: o=- 21109 21109 IN IP4 192.168.2.77 [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Body 2 [ 3]: s=- [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Body 3 [ 20]: c=IN IP4 86.59.13.51 [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Body 4 [ 5]: t=0 0 [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Body 5 [ 26]: m=audio 6750 RTP/AVP 8 101 [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-15 [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Body 9 [ 10]: a=ptime:20 [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Body 10 [ 10]: a=sendrecv [Jun 16 13:18:54] VERBOSE[21576] chan_sip.c: --- (12 headers 11 lines) --- [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Acked pending invite 102 [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Stopping retransmission on '641fe9110adc7f6c0ba085e861064c7c@86.59.114.69' of Request 102: Match Found [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: SIP response 200 to standard invite [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Processing session-level SDP o=- 21109 21109 IN IP4 192.168.2.77... UNSUPPORTED. [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Processing session-level SDP c=IN IP4 86.59.13.51... OK. [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Jun 16 13:18:54] VERBOSE[21576] chan_sip.c: Found RTP audio format 8 [Jun 16 13:18:54] VERBOSE[21576] chan_sip.c: Found RTP audio format 101 [Jun 16 13:18:54] VERBOSE[21576] chan_sip.c: Found audio description format PCMA for ID 8 [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Jun 16 13:18:54] VERBOSE[21576] chan_sip.c: Found audio description format telephone-event for ID 101 [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jun 16 13:18:54] VERBOSE[21576] chan_sip.c: Capabilities: us - 0x8 (alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x8 (alaw) [Jun 16 13:18:54] VERBOSE[21576] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jun 16 13:18:54] VERBOSE[21576] chan_sip.c: Peer audio RTP is at port 86.59.13.51:6750 [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Peer doesn't provide T.38 UDPTL [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: We're settling with these formats: 0x8 (alaw) [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: We have an owner, now see if we need to change this call [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Updating call counter for outgoing call [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: build_route: Contact hop: [Jun 16 13:18:54] VERBOSE[21576] chan_sip.c: list_route: hop: [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Strict routing enforced for session 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 [Jun 16 13:18:54] DEBUG[21563] devicestate.c: No provider found, checking channel drivers for SIP - 200 [Jun 16 13:18:54] DEBUG[21563] chan_sip.c: Checking device state for peer 200 [Jun 16 13:18:54] DEBUG[21563] devicestate.c: Changing state for SIP/200 - state 2 (In use) [Jun 16 13:18:54] DEBUG[21563] devicestate.c: device 'SIP/200' state '2' [Jun 16 13:18:54] VERBOSE[21576] chan_sip.c: set_destination: Parsing for address/port to send to [Jun 16 13:18:54] VERBOSE[21576] chan_sip.c: set_destination: set destination to 86.59.13.51, port 6206 [Jun 16 13:18:54] DEBUG[21568] app_queue.c: Device 'SIP/200' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 16 13:18:54] VERBOSE[21576] chan_sip.c: Transmitting (NAT) to 86.59.13.51:4927: ACK sip:200@86.59.13.51:6206 SIP/2.0 Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK4eb63595;rport Max-Forwards: 70 From: "Phone A" ;tag=as377e020c To: ;tag=777c78c2d97c931ai2 Contact: Call-ID: 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 CSeq: 102 ACK User-Agent: PBX Remote-Party-ID: "Phone A" ;privacy=off;screen=no Content-Length: 0 --- [Jun 16 13:18:54] DEBUG[21576] chan_sip.c: Trying to put 'ACK sip:200' onto UDP socket destined for 86.59.13.51:4927 [Jun 16 13:18:54] DEBUG[31834] rtp.c: Ooh, format changed from unknown to alaw [Jun 16 13:18:54] DEBUG[31834] rtp.c: Created smoother: format: 8 ms: 20 len: 160 [Jun 16 13:18:54] VERBOSE[31834] app_dial.c: -- SIP/200-00000001 answered SIP/100-00000000 [Jun 16 13:18:54] DEBUG[31834] channel.c: Set channel SIP/100-00000000 to write format alaw [Jun 16 13:18:54] DEBUG[31834] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 16 13:18:54] DEBUG[31834] features.c: bridge answer set, chan answer set [Jun 16 13:18:54] DEBUG[31834] rtp.c: Setting the marker bit due to a source update [Jun 16 13:18:54] DEBUG[31834] rtp.c: Setting the marker bit due to a source update [Jun 16 13:18:54] VERBOSE[31834] rtp.c: -- Packet2Packet bridging SIP/100-00000000 and SIP/200-00000001 [Jun 16 13:18:54] DEBUG[21563] devicestate.c: No provider found, checking channel drivers for SIP - 200 [Jun 16 13:18:54] DEBUG[21563] chan_sip.c: Checking device state for peer 200 [Jun 16 13:18:54] DEBUG[21563] devicestate.c: Changing state for SIP/200 - state 2 (In use) [Jun 16 13:18:54] DEBUG[21563] devicestate.c: device 'SIP/200' state '2' [Jun 16 13:18:54] DEBUG[21568] app_queue.c: Device 'SIP/200' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 16 13:18:56] VERBOSE[21576] chan_sip.c: <--- SIP read from UDP:86.59.13.51:4927 ---> INVITE sip:100@86.59.114.69 SIP/2.0 Via: SIP/2.0/UDP 86.59.13.51:6206;branch=z9hG4bK-12025f22 From: ;tag=777c78c2d97c931ai2 To: "Phone A" ;tag=as377e020c Call-ID: 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 CSeq: 101 INVITE Max-Forwards: 70 Contact: Expires: 30 User-Agent: Cisco/SPA525G-7.4.4 Content-Length: 223 Content-Type: application/sdp v=0 o=- 21109 21110 IN IP4 192.168.2.77 s=- c=IN IP4 0.0.0.0 t=0 0 m=audio 16478 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendonly <-------------> [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 0 [ 35]: INVITE sip:100@86.59.114.69 SIP/2.0 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 86.59.13.51:6206;branch=z9hG4bK-12025f22 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 2 [ 55]: From: ;tag=777c78c2d97c931ai2 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 3 [ 51]: To: "Phone A" ;tag=as377e020c [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 4 [ 54]: Call-ID: 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 5 [ 16]: CSeq: 101 INVITE [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 7 [ 35]: Contact: [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 8 [ 11]: Expires: 30 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 9 [ 31]: User-Agent: Cisco/SPA525G-7.4.4 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 10 [ 19]: Content-Length: 223 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 11 [ 29]: Content-Type: application/sdp [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 12 [ 0]: [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Body 0 [ 3]: v=0 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Body 1 [ 35]: o=- 21109 21110 IN IP4 192.168.2.77 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Body 2 [ 3]: s=- [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Body 3 [ 16]: c=IN IP4 0.0.0.0 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Body 4 [ 5]: t=0 0 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Body 5 [ 29]: m=audio 16478 RTP/AVP 8 0 101 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Body 9 [ 15]: a=fmtp:101 0-15 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Body 10 [ 10]: a=ptime:20 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Body 11 [ 10]: a=sendonly [Jun 16 13:18:56] VERBOSE[21576] chan_sip.c: --- (12 headers 12 lines) --- [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 16 13:18:56] VERBOSE[21576] chan_sip.c: Sending to 86.59.13.51 : 4927 (NAT) [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Initializing initreq for method INVITE - callid 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Processing session-level SDP o=- 21109 21110 IN IP4 192.168.2.77... UNSUPPORTED. [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Processing session-level SDP c=IN IP4 0.0.0.0... OK. [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Jun 16 13:18:56] VERBOSE[21576] chan_sip.c: Found RTP audio format 8 [Jun 16 13:18:56] VERBOSE[21576] chan_sip.c: Found RTP audio format 0 [Jun 16 13:18:56] VERBOSE[21576] chan_sip.c: Found RTP audio format 101 [Jun 16 13:18:56] VERBOSE[21576] chan_sip.c: Found audio description format PCMA for ID 8 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Jun 16 13:18:56] VERBOSE[21576] chan_sip.c: Found audio description format PCMU for ID 0 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jun 16 13:18:56] VERBOSE[21576] chan_sip.c: Found audio description format telephone-event for ID 101 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=sendonly... OK. [Jun 16 13:18:56] VERBOSE[21576] chan_sip.c: Capabilities: us - 0x8 (alaw), peer - audio=0xc (ulaw|alaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x8 (alaw) [Jun 16 13:18:56] VERBOSE[21576] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jun 16 13:18:56] VERBOSE[21576] chan_sip.c: Peer audio RTP is at port 0.0.0.0:16478 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Peer doesn't provide T.38 UDPTL [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: We're settling with these formats: 0x8 (alaw) [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: We have an owner, now see if we need to change this call [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Got a SIP re-invite for call 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: SIP/200-00000001: This call is UP.... [Jun 16 13:18:56] VERBOSE[21576] chan_sip.c: <--- Transmitting (NAT) to 86.59.13.51:4927 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 86.59.13.51:6206;branch=z9hG4bK-12025f22;received=86.59.13.51 From: ;tag=777c78c2d97c931ai2 To: "Phone A" ;tag=as377e020c Call-ID: 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 CSeq: 101 INVITE Server: PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Length: 0 <------------> [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 86.59.13.51:4927 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Setting framing from config on incoming call [Jun 16 13:18:56] DEBUG[21563] devicestate.c: No provider found, checking channel drivers for SIP - 200 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: True Text flag: True [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: ** Our prefcodec: 0x8 (alaw) [Jun 16 13:18:56] VERBOSE[21576] chan_sip.c: Audio is at 86.59.114.69 port 18400 [Jun 16 13:18:56] VERBOSE[21576] chan_sip.c: Adding codec 0x8 (alaw) to SDP [Jun 16 13:18:56] VERBOSE[21576] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: -- Done with adding codecs to SDP [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw) [Jun 16 13:18:56] VERBOSE[21576] chan_sip.c: <--- Reliably Transmitting (NAT) to 86.59.13.51:4927 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 86.59.13.51:6206;branch=z9hG4bK-12025f22;received=86.59.13.51 From: ;tag=777c78c2d97c931ai2 To: "Phone A" ;tag=as377e020c Call-ID: 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 CSeq: 101 INVITE Server: PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 263 v=0 o=root 1527560327 1527560328 IN IP4 86.59.114.69 s=Asterisk PBX 1.6.2.7 c=IN IP4 86.59.114.69 t=0 0 m=audio 18400 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=recvonly <------------> [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #213 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 86.59.13.51:4927 [Jun 16 13:18:56] DEBUG[21563] chan_sip.c: Checking device state for peer 200 [Jun 16 13:18:56] DEBUG[21563] devicestate.c: Changing state for SIP/200 - state 8 (On Hold) [Jun 16 13:18:56] DEBUG[21563] devicestate.c: device 'SIP/200' state '8' [Jun 16 13:18:56] DEBUG[21568] app_queue.c: Device 'SIP/200' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Jun 16 13:18:56] DEBUG[31834] rtp.c: Setting the marker bit due to a source update [Jun 16 13:18:56] VERBOSE[31834] res_musiconhold.c: -- Started music on hold, class 'default', on SIP/100-00000000 [Jun 16 13:18:56] DEBUG[31834] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 16 13:18:56] DEBUG[31834] rtp.c: Setting the marker bit due to a source update [Jun 16 13:18:56] DEBUG[31834] channel.c: Generator got voice, switching to phase locked mode [Jun 16 13:18:56] DEBUG[31834] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 16 13:18:56] DEBUG[31834] channel.c: Set channel SIP/100-00000000 to write format slin [Jun 16 13:18:56] DEBUG[31834] res_musiconhold.c: SIP/100-00000000 Opened file 0 '/var/lib/asterisk/moh-files/default/plswait' [Jun 16 13:18:56] DEBUG[31834] rtp.c: Difference is 14072, ms is 1779 [Jun 16 13:18:56] VERBOSE[21576] chan_sip.c: <--- SIP read from UDP:86.59.13.51:4927 ---> ACK sip:100@86.59.114.69 SIP/2.0 Via: SIP/2.0/UDP 86.59.13.51:6206;branch=z9hG4bK-8398e200 From: ;tag=777c78c2d97c931ai2 To: "Phone A" ;tag=as377e020c Call-ID: 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 CSeq: 101 ACK Max-Forwards: 70 Contact: User-Agent: Cisco/SPA525G-7.4.4 Content-Length: 0 <-------------> [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 0 [ 32]: ACK sip:100@86.59.114.69 SIP/2.0 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 86.59.13.51:6206;branch=z9hG4bK-8398e200 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 2 [ 55]: From: ;tag=777c78c2d97c931ai2 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 3 [ 51]: To: "Phone A" ;tag=as377e020c [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 4 [ 54]: Call-ID: 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 5 [ 13]: CSeq: 101 ACK [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 7 [ 35]: Contact: [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 8 [ 31]: User-Agent: Cisco/SPA525G-7.4.4 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 10 [ 0]: [Jun 16 13:18:56] VERBOSE[21576] chan_sip.c: --- (10 headers 0 lines) --- [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #213 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Stopping retransmission on '641fe9110adc7f6c0ba085e861064c7c@86.59.114.69' of Response 101: Match Found [Jun 16 13:18:56] VERBOSE[21576] chan_sip.c: <--- SIP read from UDP:86.59.13.51:3044 ---> NOTIFY sip:voip-dev-01-01-1002.sil.at SIP/2.0 Via: SIP/2.0/UDP 86.59.13.51:1306;branch=z9hG4bK-4b6fbdb4 From: ;tag=67be832166bf24f8o3 To: Call-ID: 44826011-e04b6cc8@192.168.2.70 CSeq: 6171 NOTIFY Max-Forwards: 70 Event: keep-alive User-Agent: Linksys/SPA941-5.1.8 Content-Length: 0 <-------------> [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 0 [ 45]: NOTIFY sip:voip-dev-01-01-1002.sil.at SIP/2.0 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 86.59.13.51:1306;branch=z9hG4bK-4b6fbdb4 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 2 [ 69]: From: ;tag=67be832166bf24f8o3 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 3 [ 36]: To: [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 4 [ 39]: Call-ID: 44826011-e04b6cc8@192.168.2.70 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 5 [ 17]: CSeq: 6171 NOTIFY [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 7 [ 17]: Event: keep-alive [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 8 [ 32]: User-Agent: Linksys/SPA941-5.1.8 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Header 10 [ 0]: [Jun 16 13:18:56] VERBOSE[21576] chan_sip.c: --- (10 headers 0 lines) --- [Jun 16 13:18:56] DEBUG[21576] acl.c: Found IP address for this socket [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 86.59.114.69:5060 [Jun 16 13:18:56] VERBOSE[21576] chan_sip.c: <--- Transmitting (NAT) to 86.59.13.51:3044 ---> SIP/2.0 489 Bad event Via: SIP/2.0/UDP 86.59.13.51:1306;branch=z9hG4bK-4b6fbdb4;received=86.59.13.51 From: ;tag=67be832166bf24f8o3 To: ;tag=as57cf2421 Call-ID: 44826011-e04b6cc8@192.168.2.70 CSeq: 6171 NOTIFY Server: PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Length: 0 <------------> [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Trying to put 'SIP/2.0 489' onto UDP socket destined for 86.59.13.51:3044 [Jun 16 13:18:56] DEBUG[21576] chan_sip.c: Invalid SIP message - rejected , no callid, len 367 [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: <--- SIP read from UDP:86.59.13.51:4927 ---> INVITE sip:300@voip-dev-01-01-1002.sil.at SIP/2.0 Via: SIP/2.0/UDP 86.59.13.51:6206;branch=z9hG4bK-c02adff9 From: ;tag=6c047c6892a0f678o2 To: Call-ID: 6ae8a728-e8accab8@192.168.2.77 CSeq: 101 INVITE Max-Forwards: 70 Contact: Expires: 240 User-Agent: Cisco/SPA525G-7.4.4 Content-Length: 332 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE Supported: replaces Content-Type: application/sdp v=0 o=- 21825 21825 IN IP4 192.168.2.77 s=- c=IN IP4 86.59.13.51 t=0 0 m=audio 6618 RTP/AVP 8 0 2 9 104 18 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:9 G722/8000 a=rtpmap:104 L16/16000 a=rtpmap:18 G729a/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv <-------------> [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 0 [ 49]: INVITE sip:300@voip-dev-01-01-1002.sil.at SIP/2.0 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 86.59.13.51:6206;branch=z9hG4bK-c02adff9 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 2 [ 65]: From: ;tag=6c047c6892a0f678o2 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 3 [ 40]: To: [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 4 [ 39]: Call-ID: 6ae8a728-e8accab8@192.168.2.77 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 5 [ 16]: CSeq: 101 INVITE [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 7 [ 35]: Contact: [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 8 [ 12]: Expires: 240 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 9 [ 31]: User-Agent: Cisco/SPA525G-7.4.4 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 10 [ 19]: Content-Length: 332 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 11 [ 69]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 12 [ 19]: Supported: replaces [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 13 [ 29]: Content-Type: application/sdp [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 14 [ 0]: [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 0 [ 3]: v=0 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 1 [ 35]: o=- 21825 21825 IN IP4 192.168.2.77 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 2 [ 3]: s=- [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 3 [ 20]: c=IN IP4 86.59.13.51 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 4 [ 5]: t=0 0 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 5 [ 39]: m=audio 6618 RTP/AVP 8 0 2 9 104 18 101 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 8 [ 23]: a=rtpmap:2 G726-32/8000 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 9 [ 20]: a=rtpmap:9 G722/8000 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 10 [ 22]: a=rtpmap:104 L16/16000 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 11 [ 22]: a=rtpmap:18 G729a/8000 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 12 [ 33]: a=rtpmap:101 telephone-event/8000 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 13 [ 15]: a=fmtp:101 0-15 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 14 [ 10]: a=ptime:20 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 15 [ 10]: a=sendrecv [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: --- (14 headers 16 lines) --- [Jun 16 13:18:58] DEBUG[21576] acl.c: Found IP address for this socket [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 86.59.114.69:5060 [Jun 16 13:18:58] VERBOSE[21576] netsock.c: == Using SIP RTP CoS mark 5 [Jun 16 13:18:58] VERBOSE[21576] netsock.c: == Using UDPTL CoS mark 5 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Setting NAT on RTP to On [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Setting NAT on UDPTL to On [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Allocating new SIP dialog for 6ae8a728-e8accab8@192.168.2.77 - INVITE (With RTP) [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Begin: parsing SIP "Supported: replaces" [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Found SIP option: -replaces- [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Matched SIP option: replaces [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Sending to 86.59.13.51 : 4927 (NAT) [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Initializing initreq for method INVITE - callid 6ae8a728-e8accab8@192.168.2.77 [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Using INVITE request as basis request - 6ae8a728-e8accab8@192.168.2.77 [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Found peer '200' for '200' from 86.59.13.51:4927 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Setting NAT on RTP to On [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Setting NAT on UDPTL to On [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: <--- Reliably Transmitting (NAT) to 86.59.13.51:4927 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 86.59.13.51:6206;branch=z9hG4bK-c02adff9;received=86.59.13.51 From: ;tag=6c047c6892a0f678o2 To: ;tag=as13cb8a38 Call-ID: 6ae8a728-e8accab8@192.168.2.77 CSeq: 101 INVITE Server: PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="pbx.sil.at", nonce="0d18bbcb" Content-Length: 0 <------------> [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #214 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 86.59.13.51:4927 [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Scheduling destruction of SIP dialog '6ae8a728-e8accab8@192.168.2.77' in 32000 ms (Method: INVITE) [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: <--- SIP read from UDP:86.59.13.51:4927 ---> ACK sip:300@voip-dev-01-01-1002.sil.at SIP/2.0 Via: SIP/2.0/UDP 86.59.13.51:6206;branch=z9hG4bK-c02adff9 From: ;tag=6c047c6892a0f678o2 To: ;tag=as13cb8a38 Call-ID: 6ae8a728-e8accab8@192.168.2.77 CSeq: 101 ACK Max-Forwards: 70 Contact: User-Agent: Cisco/SPA525G-7.4.4 Content-Length: 0 <-------------> [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 0 [ 46]: ACK sip:300@voip-dev-01-01-1002.sil.at SIP/2.0 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 86.59.13.51:6206;branch=z9hG4bK-c02adff9 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 2 [ 65]: From: ;tag=6c047c6892a0f678o2 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 3 [ 55]: To: ;tag=as13cb8a38 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 4 [ 39]: Call-ID: 6ae8a728-e8accab8@192.168.2.77 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 5 [ 13]: CSeq: 101 ACK [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 7 [ 35]: Contact: [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 8 [ 31]: User-Agent: Cisco/SPA525G-7.4.4 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 10 [ 0]: [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: --- (10 headers 0 lines) --- [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #214 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Stopping retransmission on '6ae8a728-e8accab8@192.168.2.77' of Response 101: Match Found [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: <--- SIP read from UDP:86.59.13.51:4927 ---> INVITE sip:300@voip-dev-01-01-1002.sil.at SIP/2.0 Via: SIP/2.0/UDP 86.59.13.51:6206;branch=z9hG4bK-4c7d8625 From: ;tag=6c047c6892a0f678o2 To: Call-ID: 6ae8a728-e8accab8@192.168.2.77 CSeq: 102 INVITE Max-Forwards: 70 Authorization: Digest username="200",realm="pbx.sil.at",nonce="0d18bbcb",uri="sip:300@voip-dev-01-01-1002.sil.at",algorithm=MD5,response="fab7fb00d57559c585d3965610bec488" Contact: Expires: 240 User-Agent: Cisco/SPA525G-7.4.4 Content-Length: 332 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE Supported: replaces Content-Type: application/sdp v=0 o=- 21825 21825 IN IP4 192.168.2.77 s=- c=IN IP4 86.59.13.51 t=0 0 m=audio 6618 RTP/AVP 8 0 2 9 104 18 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:9 G722/8000 a=rtpmap:104 L16/16000 a=rtpmap:18 G729a/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv <-------------> [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 0 [ 49]: INVITE sip:300@voip-dev-01-01-1002.sil.at SIP/2.0 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 86.59.13.51:6206;branch=z9hG4bK-4c7d8625 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 2 [ 65]: From: ;tag=6c047c6892a0f678o2 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 3 [ 40]: To: [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 4 [ 39]: Call-ID: 6ae8a728-e8accab8@192.168.2.77 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 5 [ 16]: CSeq: 102 INVITE [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 7 [171]: Authorization: Digest username="200",realm="pbx.sil.at",nonce="0d18bbcb",uri="sip:300@voip-dev-01-01-1002.sil.at",algorithm=MD5,response="fab7fb00d57559c585d3965610bec488" [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 8 [ 35]: Contact: [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 9 [ 12]: Expires: 240 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 10 [ 31]: User-Agent: Cisco/SPA525G-7.4.4 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 11 [ 19]: Content-Length: 332 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 12 [ 69]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER, UPDATE [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 13 [ 19]: Supported: replaces [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 14 [ 29]: Content-Type: application/sdp [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 15 [ 0]: [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 0 [ 3]: v=0 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 1 [ 35]: o=- 21825 21825 IN IP4 192.168.2.77 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 2 [ 3]: s=- [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 3 [ 20]: c=IN IP4 86.59.13.51 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 4 [ 5]: t=0 0 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 5 [ 39]: m=audio 6618 RTP/AVP 8 0 2 9 104 18 101 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 8 [ 23]: a=rtpmap:2 G726-32/8000 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 9 [ 20]: a=rtpmap:9 G722/8000 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 10 [ 22]: a=rtpmap:104 L16/16000 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 11 [ 22]: a=rtpmap:18 G729a/8000 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 12 [ 33]: a=rtpmap:101 telephone-event/8000 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 13 [ 15]: a=fmtp:101 0-15 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 14 [ 10]: a=ptime:20 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Body 15 [ 10]: a=sendrecv [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: --- (15 headers 16 lines) --- [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Sending to 86.59.13.51 : 4927 (NAT) [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Initializing initreq for method INVITE - callid 6ae8a728-e8accab8@192.168.2.77 [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Using INVITE request as basis request - 6ae8a728-e8accab8@192.168.2.77 [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Found peer '200' for '200' from 86.59.13.51:4927 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Setting NAT on RTP to On [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Setting NAT on UDPTL to On [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Processing session-level SDP o=- 21825 21825 IN IP4 192.168.2.77... UNSUPPORTED. [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Processing session-level SDP c=IN IP4 86.59.13.51... OK. [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Found RTP audio format 8 [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Found RTP audio format 0 [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Found RTP audio format 2 [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Found RTP audio format 9 [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Found RTP audio format 104 [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Found RTP audio format 18 [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Found RTP audio format 101 [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Found audio description format PCMA for ID 8 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Found audio description format PCMU for ID 0 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Found audio description format G726-32 for ID 2 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:2 G726-32/8000... OK. [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Found audio description format G722 for ID 9 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Found audio description format L16 for ID 104 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:104 L16/16000... OK. [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Found audio description format G729a for ID 18 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729a/8000... OK. [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Found audio description format telephone-event for ID 101 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Capabilities: us - 0x8 (alaw), peer - audio=0x40190c (ulaw|alaw|g726|g729|g722|mpeg4)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x8 (alaw) [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Peer audio RTP is at port 86.59.13.51:6618 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Peer doesn't provide T.38 UDPTL [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: We're settling with these formats: 0x8 (alaw) [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Checking SIP call limits for device 200 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Updating call counter for incoming call [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Call from peer '200' is 2 out of 100 [Jun 16 13:18:58] DEBUG[21563] devicestate.c: No provider found, checking channel drivers for SIP - 200 [Jun 16 13:18:58] DEBUG[21563] chan_sip.c: Checking device state for peer 200 [Jun 16 13:18:58] DEBUG[21563] devicestate.c: Changing state for SIP/200 - state 8 (On Hold) [Jun 16 13:18:58] DEBUG[21563] devicestate.c: device 'SIP/200' state '8' [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: Looking for 300 in outcust (domain voip-dev-01-01-1002.sil.at) [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: *** Our native formats are 0x8 (alaw) [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: *** Joint capabilities are 0x8 (alaw) [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: *** Our capabilities are 0x8 (alaw) [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Jun 16 13:18:58] DEBUG[21568] app_queue.c: Device 'SIP/200' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: This channel will not be able to handle video. [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: build_route: Contact hop: [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: list_route: hop: [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: SIP/200-00000002: New call is still down.... Trying... [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: <--- Transmitting (NAT) to 86.59.13.51:4927 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 86.59.13.51:6206;branch=z9hG4bK-4c7d8625;received=86.59.13.51 From: ;tag=6c047c6892a0f678o2 To: Call-ID: 6ae8a728-e8accab8@192.168.2.77 CSeq: 102 INVITE Server: PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Length: 0 <------------> [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 86.59.13.51:4927 [Jun 16 13:18:58] DEBUG[21563] devicestate.c: No provider found, checking channel drivers for SIP - 200 [Jun 16 13:18:58] DEBUG[21563] chan_sip.c: Checking device state for peer 200 [Jun 16 13:18:58] DEBUG[21563] devicestate.c: Changing state for SIP/200 - state 8 (On Hold) [Jun 16 13:18:58] DEBUG[21563] devicestate.c: device 'SIP/200' state '8' [Jun 16 13:18:58] DEBUG[21568] app_queue.c: Device 'SIP/200' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Jun 16 13:18:58] DEBUG[31838] pbx.c: Launching 'Answer' [Jun 16 13:18:58] VERBOSE[31838] pbx.c: -- Executing [300@outcust:1] Answer("SIP/200-00000002", "") in new stack [Jun 16 13:18:58] DEBUG[21563] devicestate.c: No provider found, checking channel drivers for SIP - 200 [Jun 16 13:18:58] DEBUG[21563] chan_sip.c: Checking device state for peer 200 [Jun 16 13:18:58] DEBUG[21563] devicestate.c: Changing state for SIP/200 - state 8 (On Hold) [Jun 16 13:18:58] DEBUG[21563] devicestate.c: device 'SIP/200' state '8' [Jun 16 13:18:58] DEBUG[21568] app_queue.c: Device 'SIP/200' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: SIP answering channel: SIP/200-00000002 [Jun 16 13:18:58] DEBUG[31838] rtp.c: Setting the marker bit due to a source update [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Setting framing from config on incoming call [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: True Text flag: True [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Jun 16 13:18:58] VERBOSE[31838] chan_sip.c: Audio is at 86.59.114.69 port 11088 [Jun 16 13:18:58] VERBOSE[31838] chan_sip.c: Adding codec 0x8 (alaw) to SDP [Jun 16 13:18:58] VERBOSE[31838] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: -- Done with adding codecs to SDP [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw) [Jun 16 13:18:58] VERBOSE[31838] chan_sip.c: <--- Reliably Transmitting (NAT) to 86.59.13.51:4927 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 86.59.13.51:6206;branch=z9hG4bK-4c7d8625;received=86.59.13.51 From: ;tag=6c047c6892a0f678o2 To: ;tag=as222d00c8 Call-ID: 6ae8a728-e8accab8@192.168.2.77 CSeq: 102 INVITE Server: PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 263 v=0 o=root 1830012406 1830012406 IN IP4 86.59.114.69 s=Asterisk PBX 1.6.2.7 c=IN IP4 86.59.114.69 t=0 0 m=audio 11088 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #217 [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 86.59.13.51:4927 [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: <--- SIP read from UDP:86.59.13.51:4927 ---> ACK sip:300@86.59.114.69 SIP/2.0 Via: SIP/2.0/UDP 86.59.13.51:6206;branch=z9hG4bK-4282afeb From: ;tag=6c047c6892a0f678o2 To: ;tag=as222d00c8 Call-ID: 6ae8a728-e8accab8@192.168.2.77 CSeq: 102 ACK Max-Forwards: 70 Authorization: Digest username="200",realm="pbx.sil.at",nonce="0d18bbcb",uri="sip:300@voip-dev-01-01-1002.sil.at",algorithm=MD5,response="fab7fb00d57559c585d3965610bec488" Contact: User-Agent: Cisco/SPA525G-7.4.4 Content-Length: 0 <-------------> [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 0 [ 32]: ACK sip:300@86.59.114.69 SIP/2.0 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 86.59.13.51:6206;branch=z9hG4bK-4282afeb [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 2 [ 65]: From: ;tag=6c047c6892a0f678o2 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 3 [ 55]: To: ;tag=as222d00c8 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 4 [ 39]: Call-ID: 6ae8a728-e8accab8@192.168.2.77 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 5 [ 13]: CSeq: 102 ACK [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 7 [171]: Authorization: Digest username="200",realm="pbx.sil.at",nonce="0d18bbcb",uri="sip:300@voip-dev-01-01-1002.sil.at",algorithm=MD5,response="fab7fb00d57559c585d3965610bec488" [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 8 [ 35]: Contact: [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 9 [ 31]: User-Agent: Cisco/SPA525G-7.4.4 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Header 11 [ 0]: [Jun 16 13:18:58] VERBOSE[21576] chan_sip.c: --- (11 headers 0 lines) --- [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #217 [Jun 16 13:18:58] DEBUG[21576] chan_sip.c: Stopping retransmission on '6ae8a728-e8accab8@192.168.2.77' of Response 102: Match Found [Jun 16 13:18:58] DEBUG[31838] rtp.c: RTP NAT: Got audio from other end. Now sending to address 86.59.13.51:5960 [Jun 16 13:18:58] DEBUG[31838] pbx.c: Launching 'Dial' [Jun 16 13:18:58] VERBOSE[31838] pbx.c: -- Executing [300@outcust:2] Dial("SIP/200-00000002", "SIP/300,20") in new stack [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Asked to create a SIP channel with formats: 0x8 (alaw) [Jun 16 13:18:58] VERBOSE[31838] netsock.c: == Using SIP RTP CoS mark 5 [Jun 16 13:18:58] VERBOSE[31838] netsock.c: == Using UDPTL CoS mark 5 [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Allocating new SIP dialog for 53b068ab4ee4431876adf2283cdea08d@86.59.114.69 - INVITE (With RTP) [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Setting NAT on RTP to On [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Setting NAT on UDPTL to On [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: OBPROXY: Not applying OBproxy to this call [Jun 16 13:18:58] DEBUG[31838] acl.c: Found IP address for this socket [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 86.59.114.69:5060 [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: *** Our native formats are 0x8 (alaw) [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: *** Joint capabilities are 0x8 (alaw) [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: *** Our capabilities are 0x8 (alaw) [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: *** Our preferred formats from the incoming channel are 0x8 (alaw) [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: This channel will not be able to handle video. [Jun 16 13:18:58] DEBUG[31838] channel.c: Not copying variable DIALEDTIME. [Jun 16 13:18:58] DEBUG[31838] channel.c: Not copying variable ANSWEREDTIME. [Jun 16 13:18:58] DEBUG[31838] channel.c: Not copying variable DIALEDPEERNAME. [Jun 16 13:18:58] DEBUG[31838] channel.c: Not copying variable DIALEDPEERNUMBER. [Jun 16 13:18:58] DEBUG[31838] channel.c: Not copying variable DIALSTATUS. [Jun 16 13:18:58] DEBUG[31838] channel.c: Not copying variable SIPCALLID. [Jun 16 13:18:58] DEBUG[31838] channel.c: Not copying variable SIPDOMAIN. [Jun 16 13:18:58] DEBUG[31838] channel.c: Not copying variable SIPURI. [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Outgoing Call for 300 [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Updating call counter for outgoing call [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Call to peer '300' is 1 out of 100 [Jun 16 13:18:58] DEBUG[21563] devicestate.c: No provider found, checking channel drivers for SIP - 300 [Jun 16 13:18:58] DEBUG[21563] chan_sip.c: Checking device state for peer 300 [Jun 16 13:18:58] DEBUG[21563] devicestate.c: Changing state for SIP/300 - state 6 (Ringing) [Jun 16 13:18:58] DEBUG[21563] devicestate.c: device 'SIP/300' state '6' [Jun 16 13:18:58] DEBUG[21568] app_queue.c: Device 'SIP/300' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: False Text flag: False [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: ** Our prefcodec: 0x8 (alaw) [Jun 16 13:18:58] VERBOSE[31838] chan_sip.c: Audio is at 86.59.114.69 port 17212 [Jun 16 13:18:58] VERBOSE[31838] chan_sip.c: Adding codec 0x8 (alaw) to SDP [Jun 16 13:18:58] VERBOSE[31838] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: -- Done with adding codecs to SDP [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw) [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Initializing initreq for method INVITE - callid 59a5edf26ceca76d4d41ad4e2a0f0e25@86.59.114.69 [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Header 0 [ 43]: INVITE sip:300@213.235.212.193:5061 SIP/2.0 [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK1ecb6ba5;rport [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Header 3 [ 53]: From: "Phone B" ;tag=as14a144f4 [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Header 4 [ 34]: To: [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Header 5 [ 31]: Contact: [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Header 6 [ 54]: Call-ID: 59a5edf26ceca76d4d41ad4e2a0f0e25@86.59.114.69 [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Header 8 [ 15]: User-Agent: PBX [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Header 9 [ 71]: Remote-Party-ID: "Phone B" ;privacy=off;screen=no [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Header 10 [ 35]: Date: Wed, 16 Jun 2010 11:18:58 GMT [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Header 11 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Header 12 [ 26]: Supported: replaces, timer [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Header 13 [ 29]: Content-Type: application/sdp [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Header 14 [ 19]: Content-Length: 263 [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Header 15 [ 0]: [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Body 0 [ 3]: v=0 [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Body 1 [ 48]: o=root 1044658925 1044658925 IN IP4 86.59.114.69 [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Body 2 [ 22]: s=Asterisk PBX 1.6.2.7 [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Body 3 [ 21]: c=IN IP4 86.59.114.69 [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Body 4 [ 5]: t=0 0 [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Body 5 [ 27]: m=audio 17212 RTP/AVP 8 101 [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-16 [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Body 9 [ 25]: a=silenceSupp:off - - - - [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Body 10 [ 10]: a=ptime:20 [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Body 11 [ 10]: a=sendrecv [Jun 16 13:18:58] VERBOSE[31838] chan_sip.c: Reliably Transmitting (NAT) to 213.235.212.193:5061: INVITE sip:300@213.235.212.193:5061 SIP/2.0 Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK1ecb6ba5;rport Max-Forwards: 70 From: "Phone B" ;tag=as14a144f4 To: Contact: Call-ID: 59a5edf26ceca76d4d41ad4e2a0f0e25@86.59.114.69 CSeq: 102 INVITE User-Agent: PBX Remote-Party-ID: "Phone B" ;privacy=off;screen=no Date: Wed, 16 Jun 2010 11:18:58 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Type: application/sdp Content-Length: 263 v=0 o=root 1044658925 1044658925 IN IP4 86.59.114.69 s=Asterisk PBX 1.6.2.7 c=IN IP4 86.59.114.69 t=0 0 m=audio 17212 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #219 [Jun 16 13:18:58] DEBUG[31838] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 213.235.212.193:5061 [Jun 16 13:18:58] VERBOSE[31838] app_dial.c: -- Called 300 [Jun 16 13:18:59] VERBOSE[21576] chan_sip.c: <--- SIP read from UDP:213.235.212.193:5061 ---> SIP/2.0 100 Trying To: From: "Phone B" ;tag=as14a144f4 Call-ID: 59a5edf26ceca76d4d41ad4e2a0f0e25@86.59.114.69 CSeq: 102 INVITE Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK1ecb6ba5 Server: Linksys/SPA941-5.1.8 Content-Length: 0 <-------------> [Jun 16 13:18:59] DEBUG[21576] chan_sip.c: Header 0 [ 18]: SIP/2.0 100 Trying [Jun 16 13:18:59] DEBUG[21576] chan_sip.c: Header 1 [ 34]: To: [Jun 16 13:18:59] DEBUG[21576] chan_sip.c: Header 2 [ 53]: From: "Phone B" ;tag=as14a144f4 [Jun 16 13:18:59] DEBUG[21576] chan_sip.c: Header 3 [ 54]: Call-ID: 59a5edf26ceca76d4d41ad4e2a0f0e25@86.59.114.69 [Jun 16 13:18:59] DEBUG[21576] chan_sip.c: Header 4 [ 16]: CSeq: 102 INVITE [Jun 16 13:18:59] DEBUG[21576] chan_sip.c: Header 5 [ 57]: Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK1ecb6ba5 [Jun 16 13:18:59] DEBUG[21576] chan_sip.c: Header 6 [ 28]: Server: Linksys/SPA941-5.1.8 [Jun 16 13:18:59] DEBUG[21576] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jun 16 13:18:59] DEBUG[21576] chan_sip.c: Header 8 [ 0]: [Jun 16 13:18:59] VERBOSE[21576] chan_sip.c: --- (8 headers 0 lines) --- [Jun 16 13:18:59] DEBUG[21576] chan_sip.c: *** SIP TIMER: Cancelling retransmission #219 - INVITE (got response) [Jun 16 13:18:59] DEBUG[21576] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '59a5edf26ceca76d4d41ad4e2a0f0e25@86.59.114.69' Request 102: Found [Jun 16 13:18:59] DEBUG[21576] chan_sip.c: SIP response 100 to standard invite [Jun 16 13:18:59] VERBOSE[21576] chan_sip.c: <--- SIP read from UDP:213.235.212.193:5061 ---> SIP/2.0 180 Ringing To: ;tag=5b06c4d1e3a4a8f0i1 From: "Phone B" ;tag=as14a144f4 Call-ID: 59a5edf26ceca76d4d41ad4e2a0f0e25@86.59.114.69 CSeq: 102 INVITE Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK1ecb6ba5 Server: Linksys/SPA941-5.1.8 Content-Length: 0 <-------------> [Jun 16 13:18:59] DEBUG[21576] chan_sip.c: Header 0 [ 19]: SIP/2.0 180 Ringing [Jun 16 13:18:59] DEBUG[21576] chan_sip.c: Header 1 [ 57]: To: ;tag=5b06c4d1e3a4a8f0i1 [Jun 16 13:18:59] DEBUG[21576] chan_sip.c: Header 2 [ 53]: From: "Phone B" ;tag=as14a144f4 [Jun 16 13:18:59] DEBUG[21576] chan_sip.c: Header 3 [ 54]: Call-ID: 59a5edf26ceca76d4d41ad4e2a0f0e25@86.59.114.69 [Jun 16 13:18:59] DEBUG[21576] chan_sip.c: Header 4 [ 16]: CSeq: 102 INVITE [Jun 16 13:18:59] DEBUG[21576] chan_sip.c: Header 5 [ 57]: Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK1ecb6ba5 [Jun 16 13:18:59] DEBUG[21576] chan_sip.c: Header 6 [ 28]: Server: Linksys/SPA941-5.1.8 [Jun 16 13:18:59] DEBUG[21576] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jun 16 13:18:59] DEBUG[21576] chan_sip.c: Header 8 [ 0]: [Jun 16 13:18:59] VERBOSE[21576] chan_sip.c: --- (8 headers 0 lines) --- [Jun 16 13:18:59] DEBUG[21576] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '59a5edf26ceca76d4d41ad4e2a0f0e25@86.59.114.69' Request 102: Found [Jun 16 13:18:59] DEBUG[21576] chan_sip.c: SIP response 180 to standard invite [Jun 16 13:18:59] DEBUG[21563] devicestate.c: No provider found, checking channel drivers for SIP - 300 [Jun 16 13:18:59] DEBUG[21563] chan_sip.c: Checking device state for peer 300 [Jun 16 13:18:59] DEBUG[21563] devicestate.c: Changing state for SIP/300 - state 6 (Ringing) [Jun 16 13:18:59] DEBUG[21563] devicestate.c: device 'SIP/300' state '6' [Jun 16 13:18:59] DEBUG[21568] app_queue.c: Device 'SIP/300' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jun 16 13:18:59] VERBOSE[31838] app_dial.c: -- SIP/300-00000003 is ringing [Jun 16 13:18:59] DEBUG[31838] channel.c: Driver for channel 'SIP/200-00000002' does not support indication 3, emulating it [Jun 16 13:18:59] DEBUG[31838] channel.c: Set channel SIP/200-00000002 to write format slin [Jun 16 13:18:59] DEBUG[31838] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 16 13:18:59] DEBUG[31838] channel.c: Generator got voice, switching to phase locked mode [Jun 16 13:18:59] DEBUG[31838] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 16 13:18:59] DEBUG[31838] rtp.c: Ooh, format changed from unknown to alaw [Jun 16 13:18:59] DEBUG[31838] rtp.c: Created smoother: format: 8 ms: 20 len: 160 [Jun 16 13:19:00] VERBOSE[21576] chan_sip.c: <--- SIP read from UDP:213.235.212.193:5061 ---> SIP/2.0 200 OK To: ;tag=5b06c4d1e3a4a8f0i1 From: "Phone B" ;tag=as14a144f4 Call-ID: 59a5edf26ceca76d4d41ad4e2a0f0e25@86.59.114.69 CSeq: 102 INVITE Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK1ecb6ba5 Contact: Server: Linksys/SPA941-5.1.8 Content-Length: 207 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces Content-Type: application/sdp v=0 o=- 23822 23822 IN IP4 192.168.1.113 s=- c=IN IP4 213.235.212.193 t=0 0 m=audio 1210 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv <-------------> [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Header 1 [ 57]: To: ;tag=5b06c4d1e3a4a8f0i1 [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Header 2 [ 53]: From: "Phone B" ;tag=as14a144f4 [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Header 3 [ 54]: Call-ID: 59a5edf26ceca76d4d41ad4e2a0f0e25@86.59.114.69 [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Header 4 [ 16]: CSeq: 102 INVITE [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Header 5 [ 57]: Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK1ecb6ba5 [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Header 6 [ 39]: Contact: [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Header 7 [ 28]: Server: Linksys/SPA941-5.1.8 [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Header 8 [ 19]: Content-Length: 207 [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Header 9 [ 61]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Header 10 [ 19]: Supported: replaces [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Header 11 [ 29]: Content-Type: application/sdp [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Header 12 [ 0]: [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Body 0 [ 3]: v=0 [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Body 1 [ 36]: o=- 23822 23822 IN IP4 192.168.1.113 [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Body 2 [ 3]: s=- [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Body 3 [ 24]: c=IN IP4 213.235.212.193 [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Body 4 [ 5]: t=0 0 [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Body 5 [ 26]: m=audio 1210 RTP/AVP 8 101 [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-15 [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Body 9 [ 10]: a=ptime:20 [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Body 10 [ 10]: a=sendrecv [Jun 16 13:19:00] VERBOSE[21576] chan_sip.c: --- (12 headers 11 lines) --- [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Acked pending invite 102 [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Stopping retransmission on '59a5edf26ceca76d4d41ad4e2a0f0e25@86.59.114.69' of Request 102: Match Found [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: SIP response 200 to standard invite [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Processing session-level SDP o=- 23822 23822 IN IP4 192.168.1.113... UNSUPPORTED. [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Processing session-level SDP c=IN IP4 213.235.212.193... OK. [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Jun 16 13:19:00] VERBOSE[21576] chan_sip.c: Found RTP audio format 8 [Jun 16 13:19:00] VERBOSE[21576] chan_sip.c: Found RTP audio format 101 [Jun 16 13:19:00] VERBOSE[21576] chan_sip.c: Found audio description format PCMA for ID 8 [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Jun 16 13:19:00] VERBOSE[21576] chan_sip.c: Found audio description format telephone-event for ID 101 [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jun 16 13:19:00] VERBOSE[21576] chan_sip.c: Capabilities: us - 0x8 (alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x8 (alaw) [Jun 16 13:19:00] VERBOSE[21576] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jun 16 13:19:00] VERBOSE[21576] chan_sip.c: Peer audio RTP is at port 213.235.212.193:1210 [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Peer doesn't provide T.38 UDPTL [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: We're settling with these formats: 0x8 (alaw) [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: We have an owner, now see if we need to change this call [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Updating call counter for outgoing call [Jun 16 13:19:00] DEBUG[21563] devicestate.c: No provider found, checking channel drivers for SIP - 300 [Jun 16 13:19:00] DEBUG[21563] chan_sip.c: Checking device state for peer 300 [Jun 16 13:19:00] DEBUG[21563] devicestate.c: Changing state for SIP/300 - state 2 (In use) [Jun 16 13:19:00] DEBUG[21563] devicestate.c: device 'SIP/300' state '2' [Jun 16 13:19:00] DEBUG[21568] app_queue.c: Device 'SIP/300' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: build_route: Contact hop: [Jun 16 13:19:00] VERBOSE[21576] chan_sip.c: list_route: hop: [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Strict routing enforced for session 59a5edf26ceca76d4d41ad4e2a0f0e25@86.59.114.69 [Jun 16 13:19:00] VERBOSE[21576] chan_sip.c: set_destination: Parsing for address/port to send to [Jun 16 13:19:00] VERBOSE[21576] chan_sip.c: set_destination: set destination to 213.235.212.193, port 5061 [Jun 16 13:19:00] VERBOSE[21576] chan_sip.c: Transmitting (NAT) to 213.235.212.193:5061: ACK sip:300@213.235.212.193:5061 SIP/2.0 Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK180d844a;rport Max-Forwards: 70 From: "Phone B" ;tag=as14a144f4 To: ;tag=5b06c4d1e3a4a8f0i1 Contact: Call-ID: 59a5edf26ceca76d4d41ad4e2a0f0e25@86.59.114.69 CSeq: 102 ACK User-Agent: PBX Remote-Party-ID: "Phone B" ;privacy=off;screen=no Content-Length: 0 --- [Jun 16 13:19:00] DEBUG[21576] chan_sip.c: Trying to put 'ACK sip:300' onto UDP socket destined for 213.235.212.193:5061 [Jun 16 13:19:00] VERBOSE[31838] app_dial.c: -- SIP/300-00000003 answered SIP/200-00000002 [Jun 16 13:19:00] DEBUG[31838] channel.c: Set channel SIP/200-00000002 to write format alaw [Jun 16 13:19:00] DEBUG[31838] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 16 13:19:00] DEBUG[31838] features.c: bridge answer set, chan answer set [Jun 16 13:19:00] DEBUG[31838] rtp.c: Setting the marker bit due to a source update [Jun 16 13:19:00] DEBUG[31838] rtp.c: Setting the marker bit due to a source update [Jun 16 13:19:00] VERBOSE[31838] rtp.c: -- Packet2Packet bridging SIP/200-00000002 and SIP/300-00000003 [Jun 16 13:19:00] DEBUG[21563] devicestate.c: No provider found, checking channel drivers for SIP - 300 [Jun 16 13:19:00] DEBUG[21563] chan_sip.c: Checking device state for peer 300 [Jun 16 13:19:00] DEBUG[21563] devicestate.c: Changing state for SIP/300 - state 2 (In use) [Jun 16 13:19:00] DEBUG[21563] devicestate.c: device 'SIP/300' state '2' [Jun 16 13:19:00] DEBUG[21568] app_queue.c: Device 'SIP/300' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 16 13:19:02] VERBOSE[21576] chan_sip.c: <--- SIP read from UDP:86.59.13.51:4927 ---> REFER sip:100@86.59.114.69 SIP/2.0 Via: SIP/2.0/UDP 86.59.13.51:6206;branch=z9hG4bK-e4f2245 From: ;tag=777c78c2d97c931ai2 To: "Phone A" ;tag=as377e020c Referred-By: Call-ID: 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 CSeq: 102 REFER Max-Forwards: 70 Contact: Refer-To: User-Agent: Cisco/SPA525G-7.4.4 Content-Length: 0 <-------------> [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 0 [ 34]: REFER sip:100@86.59.114.69 SIP/2.0 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 1 [ 56]: Via: SIP/2.0/UDP 86.59.13.51:6206;branch=z9hG4bK-e4f2245 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 2 [ 55]: From: ;tag=777c78c2d97c931ai2 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 3 [ 51]: To: "Phone A" ;tag=as377e020c [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 4 [ 49]: Referred-By: [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 5 [ 54]: Call-ID: 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 6 [ 15]: CSeq: 102 REFER [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 8 [ 35]: Contact: [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 9 [142]: Refer-To: [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 10 [ 31]: User-Agent: Cisco/SPA525G-7.4.4 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 12 [ 0]: [Jun 16 13:19:02] VERBOSE[21576] chan_sip.c: --- (12 headers 0 lines) --- [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: **** Received REFER (9) - Command in SIP REFER [Jun 16 13:19:02] VERBOSE[21576] chan_sip.c: Call 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 got a SIP call transfer from caller: (REFER)! [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Attended transfer: Will use Replace-Call-ID : 6ae8a728-e8accab8@192.168.2.77 (No check of from/to tags) [Jun 16 13:19:02] VERBOSE[21576] chan_sip.c: SIP transfer to extension 300@outcust by 200@voip-dev-01-01-1002.sil.at [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: SIP attended transfer: Transferer channel SIP/200-00000001, transferee channel SIP/100-00000000 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Got SIP transfer, applying to bridged peer 'SIP/100-00000000' [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Looking for callid 6ae8a728-e8accab8@192.168.2.77 (fromtag 6c047c6892a0f678o2 totag as222d00c8) [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Matched INCOMING call - their tag is 6c047c6892a0f678o2 Our tag is as222d00c8 [Jun 16 13:19:02] VERBOSE[21576] chan_sip.c: <--- Transmitting (NAT) to 86.59.13.51:4927 ---> SIP/2.0 202 Accepted Via: SIP/2.0/UDP 86.59.13.51:6206;branch=z9hG4bK-e4f2245;received=86.59.13.51 From: ;tag=777c78c2d97c931ai2 To: "Phone A" ;tag=as377e020c Call-ID: 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 CSeq: 102 REFER Server: PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Length: 0 <------------> [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Trying to put 'SIP/2.0 202' onto UDP socket destined for 86.59.13.51:4927 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: SIP attended transfer: trying to bridge SIP/200-00000002 and SIP/100-00000000 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Sip transfer:-------------------- [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: -- Transferer to PBX channel: SIP/200-00000001 State Up [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: -- Transferer to PBX second channel (target): SIP/200-00000002 State Up [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: -- Bridged call to transferee: SIP/100-00000000 State Up [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: -- Bridged call to transfer target: SIP/300-00000003 State Up [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: -- END Sip transfer:-------------------- [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: SIP transfer: Four channels to handle [Jun 16 13:19:02] VERBOSE[21576] res_musiconhold.c: -- Stopped music on hold on SIP/100-00000000 [Jun 16 13:19:02] DEBUG[21576] channel.c: Set channel SIP/100-00000000 to write format alaw [Jun 16 13:19:02] DEBUG[21576] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: SIP transfer: trying to masquerade SIP/100-00000000 into SIP/200-00000002 [Jun 16 13:19:02] DEBUG[21576] channel.c: Planning to masquerade channel SIP/100-00000000 into the structure of SIP/200-00000002 [Jun 16 13:19:02] DEBUG[21576] channel.c: Done planning to masquerade channel SIP/100-00000000 into the structure of SIP/200-00000002 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: SIP transfer: Succeeded to masquerade channels. [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Strict routing enforced for session 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 [Jun 16 13:19:02] VERBOSE[21576] chan_sip.c: set_destination: Parsing for address/port to send to [Jun 16 13:19:02] VERBOSE[21576] chan_sip.c: set_destination: set destination to 86.59.13.51, port 6206 [Jun 16 13:19:02] VERBOSE[21576] chan_sip.c: Reliably Transmitting (NAT) to 86.59.13.51:4927: NOTIFY sip:200@86.59.13.51:6206 SIP/2.0 Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK7cb84c71;rport Max-Forwards: 70 From: "Phone A" ;tag=as377e020c To: ;tag=777c78c2d97c931ai2 Contact: Call-ID: 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 CSeq: 103 NOTIFY User-Agent: PBX Remote-Party-ID: "Phone A" ;privacy=off;screen=no Event: refer;id=102 Subscription-state: terminated;reason=noresource Content-Type: message/sipfrag;version=2.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Length: 16 SIP/2.0 200 OK --- [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #221 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 86.59.13.51:4927 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: SIP attended transfer: Unlocking channel SIP/200-00000002 [Jun 16 13:19:02] DEBUG[31838] channel.c: Actually Masquerading SIP/100-00000000(6) into the structure of SIP/200-00000002(6) [Jun 16 13:19:02] DEBUG[31838] channel.c: Got clone lock for masquerade on 'SIP/100-00000000' at 0x8630d98 [Jun 16 13:19:02] DEBUG[31838] chan_sip.c: SIP Fixup: New owner for dialogue 6ae8a728-e8accab8@192.168.2.77: SIP/100-00000000 (Old parent: SIP/100-00000000) [Jun 16 13:19:02] DEBUG[31838] chan_sip.c: Hangup call SIP/100-00000000, SIP callid 6ae8a728-e8accab8@192.168.2.77 [Jun 16 13:19:02] DEBUG[31838] chan_sip.c: update_call_counter(200) - decrement call limit counter on hangup [Jun 16 13:19:02] DEBUG[31838] chan_sip.c: Updating call counter for incoming call [Jun 16 13:19:02] DEBUG[31838] chan_sip.c: Call from peer '200' removed from call limit 100 [Jun 16 13:19:02] VERBOSE[31838] chan_sip.c: Scheduling destruction of SIP dialog '6ae8a728-e8accab8@192.168.2.77' in 32000 ms (Method: ACK) [Jun 16 13:19:02] DEBUG[31838] chan_sip.c: Strict routing enforced for session 6ae8a728-e8accab8@192.168.2.77 [Jun 16 13:19:02] VERBOSE[31838] chan_sip.c: set_destination: Parsing for address/port to send to [Jun 16 13:19:02] VERBOSE[31838] chan_sip.c: set_destination: set destination to 86.59.13.51, port 6206 [Jun 16 13:19:02] VERBOSE[31838] chan_sip.c: Reliably Transmitting (NAT) to 86.59.13.51:4927: BYE sip:200@86.59.13.51:6206 SIP/2.0 Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK22f67615;rport Max-Forwards: 70 From: ;tag=as222d00c8 To: ;tag=6c047c6892a0f678o2 Call-ID: 6ae8a728-e8accab8@192.168.2.77 CSeq: 102 BYE User-Agent: PBX X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- [Jun 16 13:19:02] DEBUG[31838] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #223 [Jun 16 13:19:02] DEBUG[31838] chan_sip.c: Trying to put 'BYE sip:200' onto UDP socket destined for 86.59.13.51:4927 [Jun 16 13:19:02] DEBUG[31838] channel.c: Putting channel SIP/100-00000000 in 8/8 formats [Jun 16 13:19:02] DEBUG[31838] chan_sip.c: SIP Fixup: New owner for dialogue b733f348-f76cf54f@192.168.2.170: SIP/100-00000000 (Old parent: SIP/200-00000002) [Jun 16 13:19:02] DEBUG[31838] channel.c: Driver for channel 'SIP/100-00000000' does not support indication 3, emulating it [Jun 16 13:19:02] DEBUG[31838] channel.c: Set channel SIP/100-00000000 to write format slin [Jun 16 13:19:02] DEBUG[31838] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 16 13:19:02] DEBUG[31838] channel.c: Released clone lock on 'SIP/200-00000002' [Jun 16 13:19:02] DEBUG[31838] channel.c: Done Masquerading SIP/100-00000000 (6) [Jun 16 13:19:02] DEBUG[31838] rtp.c: p2p-rtp-bridge: Oooh, something is weird, backing out [Jun 16 13:19:02] VERBOSE[31838] rtp.c: -- Packet2Packet bridging SIP/100-00000000 and SIP/300-00000003 [Jun 16 13:19:02] DEBUG[21563] devicestate.c: No provider found, checking channel drivers for SIP - 200 [Jun 16 13:19:02] DEBUG[21563] chan_sip.c: Checking device state for peer 200 [Jun 16 13:19:02] DEBUG[21563] devicestate.c: Changing state for SIP/200 - state 8 (On Hold) [Jun 16 13:19:02] DEBUG[21563] devicestate.c: device 'SIP/200' state '8' [Jun 16 13:19:02] DEBUG[31834] rtp.c: p2p-rtp-bridge: Oooh, something is weird, backing out [Jun 16 13:19:02] DEBUG[31834] channel.c: Bridge stops because we're zombie or need a soft hangup: c0=SIP/200-00000002, c1=SIP/200-00000001, flags: Yes,Yes,No,No [Jun 16 13:19:02] DEBUG[31834] rtp.c: Setting the marker bit due to a source update [Jun 16 13:19:02] DEBUG[31834] channel.c: Bridge stops bridging channels SIP/200-00000002 and SIP/200-00000001 [Jun 16 13:19:02] DEBUG[31834] cdr_addon_mysql.c: Inserting a CDR record. [Jun 16 13:19:02] DEBUG[31834] cdr_addon_mysql.c: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES ('2010-06-16 13:18:51','\"Phone A\" <100>','100','200','outcust','SIP/100-00000000','SIP/200-00000001','Dial','SIP/200,20','11','8','ANSWERED','3','100','1276687131.0') [Jun 16 13:19:02] DEBUG[21568] app_queue.c: Device 'SIP/200' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Jun 16 13:19:02] DEBUG[31838] channel.c: Generator got voice, switching to phase locked mode [Jun 16 13:19:02] DEBUG[31838] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 16 13:19:02] DEBUG[31838] rtp.c: Ooh, format changed from unknown to alaw [Jun 16 13:19:02] DEBUG[31838] rtp.c: Created smoother: format: 8 ms: 20 len: 160 [Jun 16 13:19:02] DEBUG[31834] pbx.c: Function result is '"Phone A" <100>' [Jun 16 13:19:02] DEBUG[31834] pbx.c: Function result is '100' [Jun 16 13:19:02] DEBUG[31834] pbx.c: Function result is '200' [Jun 16 13:19:02] DEBUG[31834] pbx.c: Function result is 'outcust' [Jun 16 13:19:02] DEBUG[31834] pbx.c: Function result is 'SIP/100-00000000' [Jun 16 13:19:02] DEBUG[31834] pbx.c: Function result is 'SIP/200-00000001' [Jun 16 13:19:02] DEBUG[31834] pbx.c: Function result is 'Dial' [Jun 16 13:19:02] DEBUG[31834] pbx.c: Function result is 'SIP/200,20' [Jun 16 13:19:02] DEBUG[31834] pbx.c: Function result is '2010-06-16 13:18:51' [Jun 16 13:19:02] DEBUG[31834] pbx.c: Function result is '2010-06-16 13:18:54' [Jun 16 13:19:02] DEBUG[31834] pbx.c: Function result is '2010-06-16 13:19:02' [Jun 16 13:19:02] DEBUG[31834] pbx.c: Function result is '11' [Jun 16 13:19:02] DEBUG[31834] pbx.c: Function result is '8' [Jun 16 13:19:02] DEBUG[31834] pbx.c: Function result is 'ANSWERED' [Jun 16 13:19:02] DEBUG[31834] pbx.c: Function result is 'DOCUMENTATION' [Jun 16 13:19:02] DEBUG[31834] pbx.c: Function result is '100' [Jun 16 13:19:02] DEBUG[31834] pbx.c: Function result is '1276687131.0' [Jun 16 13:19:02] DEBUG[31834] pbx.c: Function result is '(null)' [Jun 16 13:19:02] DEBUG[31834] channel.c: Hanging up channel 'SIP/200-00000001' [Jun 16 13:19:02] DEBUG[31834] chan_sip.c: update_call_counter(200) - decrement call limit counter on hangup [Jun 16 13:19:02] DEBUG[31834] chan_sip.c: Updating call counter for outgoing call [Jun 16 13:19:02] DEBUG[31834] chan_sip.c: Call to peer '200' removed from call limit 100 [Jun 16 13:19:02] DEBUG[31834] chan_sip.c: SIP Transfer: Not hanging up right now... Rescheduling hangup for 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69. [Jun 16 13:19:02] VERBOSE[31834] chan_sip.c: Scheduling destruction of SIP dialog '641fe9110adc7f6c0ba085e861064c7c@86.59.114.69' in 32000 ms (Method: REFER) [Jun 16 13:19:02] DEBUG[31834] rtp.c: Channel '' has no RTP, not doing anything [Jun 16 13:19:02] DEBUG[31834] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Jun 16 13:19:02] DEBUG[31834] pbx.c: Spawn extension (outcust,200,2) exited non-zero on 'SIP/200-00000002' [Jun 16 13:19:02] VERBOSE[31834] pbx.c: == Spawn extension (outcust, 200, 2) exited non-zero on 'SIP/200-00000002' [Jun 16 13:19:02] DEBUG[31834] channel.c: Soft-Hanging up channel 'SIP/200-00000002' [Jun 16 13:19:02] DEBUG[31834] channel.c: Hanging up zombie 'SIP/200-00000002' [Jun 16 13:19:02] DEBUG[21563] devicestate.c: No provider found, checking channel drivers for SIP - 200 [Jun 16 13:19:02] DEBUG[21563] chan_sip.c: Checking device state for peer 200 [Jun 16 13:19:02] DEBUG[21563] devicestate.c: Changing state for SIP/200 - state 1 (Not in use) [Jun 16 13:19:02] DEBUG[21563] devicestate.c: device 'SIP/200' state '1' [Jun 16 13:19:02] DEBUG[21563] devicestate.c: No provider found, checking channel drivers for SIP - 200 [Jun 16 13:19:02] DEBUG[21563] chan_sip.c: Checking device state for peer 200 [Jun 16 13:19:02] DEBUG[21568] app_queue.c: Device 'SIP/200' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 16 13:19:02] DEBUG[21563] devicestate.c: Changing state for SIP/200 - state 1 (Not in use) [Jun 16 13:19:02] DEBUG[21563] devicestate.c: device 'SIP/200' state '1' [Jun 16 13:19:02] DEBUG[21568] app_queue.c: Device 'SIP/200' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 16 13:19:02] DEBUG[21563] devicestate.c: No provider found, checking channel drivers for SIP - 200 [Jun 16 13:19:02] DEBUG[21563] chan_sip.c: Checking device state for peer 200 [Jun 16 13:19:02] DEBUG[21563] devicestate.c: Changing state for SIP/200 - state 1 (Not in use) [Jun 16 13:19:02] DEBUG[21563] devicestate.c: device 'SIP/200' state '1' [Jun 16 13:19:02] DEBUG[21568] app_queue.c: Device 'SIP/200' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 16 13:19:02] DEBUG[21563] devicestate.c: No provider found, checking channel drivers for SIP - 200 [Jun 16 13:19:02] DEBUG[21563] chan_sip.c: Checking device state for peer 200 [Jun 16 13:19:02] DEBUG[21563] devicestate.c: Changing state for SIP/200 - state 1 (Not in use) [Jun 16 13:19:02] DEBUG[21563] devicestate.c: device 'SIP/200' state '1' [Jun 16 13:19:02] DEBUG[21568] app_queue.c: Device 'SIP/200' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 16 13:19:02] VERBOSE[21576] chan_sip.c: <--- SIP read from UDP:86.59.13.51:4927 ---> SIP/2.0 200 OK To: ;tag=6c047c6892a0f678o2 From: ;tag=as222d00c8 Call-ID: 6ae8a728-e8accab8@192.168.2.77 CSeq: 102 BYE Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK22f67615 Server: Cisco/SPA525G-7.4.4 Content-Length: 0 <-------------> [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 1 [ 63]: To: ;tag=6c047c6892a0f678o2 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 2 [ 57]: From: ;tag=as222d00c8 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 3 [ 39]: Call-ID: 6ae8a728-e8accab8@192.168.2.77 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 4 [ 13]: CSeq: 102 BYE [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 5 [ 57]: Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK22f67615 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 6 [ 27]: Server: Cisco/SPA525G-7.4.4 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 8 [ 0]: [Jun 16 13:19:02] VERBOSE[21576] chan_sip.c: --- (8 headers 0 lines) --- [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #223 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Stopping retransmission on '6ae8a728-e8accab8@192.168.2.77' of Request 102: Match Found [Jun 16 13:19:02] VERBOSE[21576] chan_sip.c: SIP Response message for INCOMING dialog BYE arrived [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Destroying SIP dialog 6ae8a728-e8accab8@192.168.2.77 [Jun 16 13:19:02] VERBOSE[21576] chan_sip.c: Really destroying SIP dialog '6ae8a728-e8accab8@192.168.2.77' Method: ACK [Jun 16 13:19:02] VERBOSE[21576] chan_sip.c: <--- SIP read from UDP:86.59.13.51:4927 ---> SIP/2.0 200 OK To: ;tag=777c78c2d97c931ai2 From: "Phone A" ;tag=as377e020c Call-ID: 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 CSeq: 103 NOTIFY Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK7cb84c71 Server: Cisco/SPA525G-7.4.4 Content-Length: 0 <-------------> [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 1 [ 53]: To: ;tag=777c78c2d97c931ai2 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 2 [ 53]: From: "Phone A" ;tag=as377e020c [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 3 [ 54]: Call-ID: 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 4 [ 16]: CSeq: 103 NOTIFY [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 5 [ 57]: Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK7cb84c71 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 6 [ 27]: Server: Cisco/SPA525G-7.4.4 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Header 8 [ 0]: [Jun 16 13:19:02] VERBOSE[21576] chan_sip.c: --- (8 headers 0 lines) --- [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #221 [Jun 16 13:19:02] DEBUG[21576] chan_sip.c: Stopping retransmission on '641fe9110adc7f6c0ba085e861064c7c@86.59.114.69' of Request 103: Match Found [Jun 16 13:19:02] VERBOSE[21576] chan_sip.c: SIP Response message for INCOMING dialog NOTIFY arrived [Jun 16 13:19:06] VERBOSE[21576] chan_sip.c: <--- SIP read from UDP:86.59.13.51:4927 ---> BYE sip:100@86.59.114.69 SIP/2.0 Via: SIP/2.0/UDP 86.59.13.51:6206;branch=z9hG4bK-88f0c549 From: ;tag=777c78c2d97c931ai2 To: "Phone A" ;tag=as377e020c Call-ID: 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 CSeq: 103 BYE Max-Forwards: 70 User-Agent: Cisco/SPA525G-7.4.4 Content-Length: 0 <-------------> [Jun 16 13:19:06] DEBUG[21576] chan_sip.c: Header 0 [ 32]: BYE sip:100@86.59.114.69 SIP/2.0 [Jun 16 13:19:06] DEBUG[21576] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 86.59.13.51:6206;branch=z9hG4bK-88f0c549 [Jun 16 13:19:06] DEBUG[21576] chan_sip.c: Header 2 [ 55]: From: ;tag=777c78c2d97c931ai2 [Jun 16 13:19:06] DEBUG[21576] chan_sip.c: Header 3 [ 51]: To: "Phone A" ;tag=as377e020c [Jun 16 13:19:06] DEBUG[21576] chan_sip.c: Header 4 [ 54]: Call-ID: 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 [Jun 16 13:19:06] DEBUG[21576] chan_sip.c: Header 5 [ 13]: CSeq: 103 BYE [Jun 16 13:19:06] DEBUG[21576] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Jun 16 13:19:06] DEBUG[21576] chan_sip.c: Header 7 [ 31]: User-Agent: Cisco/SPA525G-7.4.4 [Jun 16 13:19:06] DEBUG[21576] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Jun 16 13:19:06] DEBUG[21576] chan_sip.c: Header 9 [ 0]: [Jun 16 13:19:06] VERBOSE[21576] chan_sip.c: --- (9 headers 0 lines) --- [Jun 16 13:19:06] DEBUG[21576] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Jun 16 13:19:06] DEBUG[21576] chan_sip.c: Initializing initreq for method BYE - callid 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 [Jun 16 13:19:06] VERBOSE[21576] chan_sip.c: Sending to 86.59.13.51 : 4927 (NAT) [Jun 16 13:19:06] DEBUG[21576] chan_sip.c: Setting SIP_ALREADYGONE on dialog 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 [Jun 16 13:19:06] VERBOSE[21576] chan_sip.c: Scheduling destruction of SIP dialog '641fe9110adc7f6c0ba085e861064c7c@86.59.114.69' in 32000 ms (Method: BYE) [Jun 16 13:19:06] DEBUG[21576] chan_sip.c: Received bye, no owner, selfdestruct soon. [Jun 16 13:19:06] VERBOSE[21576] chan_sip.c: <--- Transmitting (NAT) to 86.59.13.51:4927 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 86.59.13.51:6206;branch=z9hG4bK-88f0c549;received=86.59.13.51 From: ;tag=777c78c2d97c931ai2 To: "Phone A" ;tag=as377e020c Call-ID: 641fe9110adc7f6c0ba085e861064c7c@86.59.114.69 CSeq: 103 BYE Server: PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Length: 0 <------------> [Jun 16 13:19:06] DEBUG[21576] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 86.59.13.51:4927 [Jun 16 13:19:12] VERBOSE[21576] chan_sip.c: <--- SIP read from UDP:86.59.13.51:1198 ---> BYE sip:200@86.59.114.69 SIP/2.0 Via: SIP/2.0/UDP 86.59.13.51:1254;branch=z9hG4bK-25d90a51 From: ;tag=7d6902f4e3ed4993o1 To: ;tag=as33c727d0 Call-ID: b733f348-f76cf54f@192.168.2.170 CSeq: 103 BYE Max-Forwards: 70 Authorization: Digest username="100",realm="pbx.sil.at",nonce="43e788cb",uri="sip:200@86.59.114.69",algorithm=MD5,response="919689c3eabe6288c95e3309c50d6e3d" User-Agent: Cisco/SPA525G-7.4.3 Content-Length: 0 <-------------> [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Header 0 [ 32]: BYE sip:200@86.59.114.69 SIP/2.0 [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 86.59.13.51:1254;branch=z9hG4bK-25d90a51 [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Header 2 [ 65]: From: ;tag=7d6902f4e3ed4993o1 [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Header 3 [ 55]: To: ;tag=as33c727d0 [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Header 4 [ 40]: Call-ID: b733f348-f76cf54f@192.168.2.170 [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Header 5 [ 13]: CSeq: 103 BYE [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Header 7 [157]: Authorization: Digest username="100",realm="pbx.sil.at",nonce="43e788cb",uri="sip:200@86.59.114.69",algorithm=MD5,response="919689c3eabe6288c95e3309c50d6e3d" [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Header 8 [ 31]: User-Agent: Cisco/SPA525G-7.4.3 [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Header 10 [ 0]: [Jun 16 13:19:12] VERBOSE[21576] chan_sip.c: --- (10 headers 0 lines) --- [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Initializing initreq for method BYE - callid b733f348-f76cf54f@192.168.2.170 [Jun 16 13:19:12] VERBOSE[21576] chan_sip.c: Sending to 86.59.13.51 : 1198 (NAT) [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Setting SIP_ALREADYGONE on dialog b733f348-f76cf54f@192.168.2.170 [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Received bye, issuing owner hangup [Jun 16 13:19:12] VERBOSE[21576] chan_sip.c: <--- Transmitting (NAT) to 86.59.13.51:1198 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 86.59.13.51:1254;branch=z9hG4bK-25d90a51;received=86.59.13.51 From: ;tag=7d6902f4e3ed4993o1 To: ;tag=as33c727d0 Call-ID: b733f348-f76cf54f@192.168.2.170 CSeq: 103 BYE Server: PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Length: 0 <------------> [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 86.59.13.51:1198 [Jun 16 13:19:12] DEBUG[31838] channel.c: Set channel SIP/100-00000000 to write format alaw [Jun 16 13:19:12] DEBUG[31838] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 16 13:19:12] DEBUG[31838] rtp.c: p2p-rtp-bridge: Ooh, got a hangup [Jun 16 13:19:12] DEBUG[31838] channel.c: Returning from native bridge, channels: SIP/100-00000000, SIP/300-00000003 [Jun 16 13:19:12] DEBUG[31838] cdr_addon_mysql.c: Inserting a CDR record. [Jun 16 13:19:12] DEBUG[31838] cdr_addon_mysql.c: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES ('2010-06-16 13:18:58','\"Phone B\" <200>','200','300','outcust','SIP/200-00000002','SIP/300-00000003','Dial','SIP/300,20','14','12','ANSWERED','3','200','1276687138.2') [Jun 16 13:19:12] DEBUG[31838] pbx.c: Function result is '"Phone B" <200>' [Jun 16 13:19:12] DEBUG[31838] pbx.c: Function result is '200' [Jun 16 13:19:12] DEBUG[31838] pbx.c: Function result is '300' [Jun 16 13:19:12] DEBUG[31838] pbx.c: Function result is 'outcust' [Jun 16 13:19:12] DEBUG[31838] pbx.c: Function result is 'SIP/200-00000002' [Jun 16 13:19:12] DEBUG[31838] pbx.c: Function result is 'SIP/300-00000003' [Jun 16 13:19:12] DEBUG[31838] pbx.c: Function result is 'Dial' [Jun 16 13:19:12] DEBUG[31838] pbx.c: Function result is 'SIP/300,20' [Jun 16 13:19:12] DEBUG[31838] pbx.c: Function result is '2010-06-16 13:18:58' [Jun 16 13:19:12] DEBUG[31838] pbx.c: Function result is '2010-06-16 13:19:00' [Jun 16 13:19:12] DEBUG[31838] pbx.c: Function result is '2010-06-16 13:19:12' [Jun 16 13:19:12] DEBUG[31838] pbx.c: Function result is '14' [Jun 16 13:19:12] DEBUG[31838] pbx.c: Function result is '12' [Jun 16 13:19:12] DEBUG[31838] pbx.c: Function result is 'ANSWERED' [Jun 16 13:19:12] DEBUG[31838] pbx.c: Function result is 'DOCUMENTATION' [Jun 16 13:19:12] DEBUG[31838] pbx.c: Function result is '200' [Jun 16 13:19:12] DEBUG[31838] pbx.c: Function result is '1276687138.2' [Jun 16 13:19:12] DEBUG[31838] pbx.c: Function result is '(null)' [Jun 16 13:19:12] DEBUG[31838] channel.c: Hanging up channel 'SIP/300-00000003' [Jun 16 13:19:12] DEBUG[31838] chan_sip.c: Hangup call SIP/300-00000003, SIP callid 59a5edf26ceca76d4d41ad4e2a0f0e25@86.59.114.69 [Jun 16 13:19:12] DEBUG[31838] chan_sip.c: update_call_counter(300) - decrement call limit counter on hangup [Jun 16 13:19:12] DEBUG[31838] chan_sip.c: Updating call counter for outgoing call [Jun 16 13:19:12] DEBUG[31838] chan_sip.c: Call to peer '300' removed from call limit 100 [Jun 16 13:19:12] DEBUG[21563] devicestate.c: No provider found, checking channel drivers for SIP - 300 [Jun 16 13:19:12] DEBUG[21563] chan_sip.c: Checking device state for peer 300 [Jun 16 13:19:12] DEBUG[21563] devicestate.c: Changing state for SIP/300 - state 1 (Not in use) [Jun 16 13:19:12] DEBUG[21563] devicestate.c: device 'SIP/300' state '1' [Jun 16 13:19:12] VERBOSE[31838] chan_sip.c: Scheduling destruction of SIP dialog '59a5edf26ceca76d4d41ad4e2a0f0e25@86.59.114.69' in 32000 ms (Method: INVITE) [Jun 16 13:19:12] DEBUG[21568] app_queue.c: Device 'SIP/300' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 16 13:19:12] DEBUG[31838] chan_sip.c: Strict routing enforced for session 59a5edf26ceca76d4d41ad4e2a0f0e25@86.59.114.69 [Jun 16 13:19:12] VERBOSE[31838] chan_sip.c: set_destination: Parsing for address/port to send to [Jun 16 13:19:12] VERBOSE[31838] chan_sip.c: set_destination: set destination to 213.235.212.193, port 5061 [Jun 16 13:19:12] VERBOSE[31838] chan_sip.c: Reliably Transmitting (NAT) to 213.235.212.193:5061: BYE sip:300@213.235.212.193:5061 SIP/2.0 Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK4042bb1f;rport Max-Forwards: 70 From: "Phone B" ;tag=as14a144f4 To: ;tag=5b06c4d1e3a4a8f0i1 Call-ID: 59a5edf26ceca76d4d41ad4e2a0f0e25@86.59.114.69 CSeq: 103 BYE User-Agent: PBX Remote-Party-ID: "Phone B" ;privacy=off;screen=no X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- [Jun 16 13:19:12] DEBUG[31838] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #230 [Jun 16 13:19:12] DEBUG[31838] chan_sip.c: Trying to put 'BYE sip:300' onto UDP socket destined for 213.235.212.193:5061 [Jun 16 13:19:12] DEBUG[21563] devicestate.c: No provider found, checking channel drivers for SIP - 300 [Jun 16 13:19:12] DEBUG[21563] chan_sip.c: Checking device state for peer 300 [Jun 16 13:19:12] DEBUG[21563] devicestate.c: Changing state for SIP/300 - state 1 (Not in use) [Jun 16 13:19:12] DEBUG[21563] devicestate.c: device 'SIP/300' state '1' [Jun 16 13:19:12] DEBUG[21568] app_queue.c: Device 'SIP/300' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 16 13:19:12] DEBUG[31838] rtp.c: Channel '' has no RTP, not doing anything [Jun 16 13:19:12] DEBUG[31838] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Jun 16 13:19:12] DEBUG[31838] pbx.c: Spawn extension (outcust,300,2) exited non-zero on 'SIP/100-00000000' [Jun 16 13:19:12] VERBOSE[31838] pbx.c: == Spawn extension (outcust, 300, 2) exited non-zero on 'SIP/100-00000000' [Jun 16 13:19:12] DEBUG[31838] channel.c: Soft-Hanging up channel 'SIP/100-00000000' [Jun 16 13:19:12] DEBUG[31838] channel.c: Hanging up channel 'SIP/100-00000000' [Jun 16 13:19:12] DEBUG[31838] chan_sip.c: Hangup call SIP/100-00000000, SIP callid b733f348-f76cf54f@192.168.2.170 [Jun 16 13:19:12] DEBUG[31838] chan_sip.c: update_call_counter(100) - decrement call limit counter on hangup [Jun 16 13:19:12] DEBUG[31838] chan_sip.c: Updating call counter for incoming call [Jun 16 13:19:12] DEBUG[31838] chan_sip.c: Call from peer '100' removed from call limit 100 [Jun 16 13:19:12] DEBUG[21563] devicestate.c: No provider found, checking channel drivers for SIP - 100 [Jun 16 13:19:12] DEBUG[21563] chan_sip.c: Checking device state for peer 100 [Jun 16 13:19:12] DEBUG[21563] devicestate.c: Changing state for SIP/100 - state 1 (Not in use) [Jun 16 13:19:12] DEBUG[21563] devicestate.c: device 'SIP/100' state '1' [Jun 16 13:19:12] DEBUG[21563] devicestate.c: No provider found, checking channel drivers for SIP - 100 [Jun 16 13:19:12] DEBUG[21563] chan_sip.c: Checking device state for peer 100 [Jun 16 13:19:12] DEBUG[21563] devicestate.c: Changing state for SIP/100 - state 1 (Not in use) [Jun 16 13:19:12] DEBUG[21568] app_queue.c: Device 'SIP/100' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 16 13:19:12] DEBUG[21563] devicestate.c: device 'SIP/100' state '1' [Jun 16 13:19:12] DEBUG[21568] app_queue.c: Device 'SIP/100' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 16 13:19:12] VERBOSE[21576] chan_sip.c: <--- SIP read from UDP:213.235.212.193:5061 ---> SIP/2.0 200 OK To: ;tag=5b06c4d1e3a4a8f0i1 From: "Phone B" ;tag=as14a144f4 Call-ID: 59a5edf26ceca76d4d41ad4e2a0f0e25@86.59.114.69 CSeq: 103 BYE Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK4042bb1f Server: Linksys/SPA941-5.1.8 Content-Length: 0 <-------------> [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Header 1 [ 57]: To: ;tag=5b06c4d1e3a4a8f0i1 [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Header 2 [ 53]: From: "Phone B" ;tag=as14a144f4 [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Header 3 [ 54]: Call-ID: 59a5edf26ceca76d4d41ad4e2a0f0e25@86.59.114.69 [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Header 4 [ 13]: CSeq: 103 BYE [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Header 5 [ 57]: Via: SIP/2.0/UDP 86.59.114.69:5060;branch=z9hG4bK4042bb1f [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Header 6 [ 28]: Server: Linksys/SPA941-5.1.8 [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Header 8 [ 0]: [Jun 16 13:19:12] VERBOSE[21576] chan_sip.c: --- (8 headers 0 lines) --- [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #230 [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Stopping retransmission on '59a5edf26ceca76d4d41ad4e2a0f0e25@86.59.114.69' of Request 103: Match Found [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Destroying SIP dialog 59a5edf26ceca76d4d41ad4e2a0f0e25@86.59.114.69 [Jun 16 13:19:12] VERBOSE[21576] chan_sip.c: Really destroying SIP dialog '59a5edf26ceca76d4d41ad4e2a0f0e25@86.59.114.69' Method: INVITE [Jun 16 13:19:12] DEBUG[21576] chan_sip.c: Destroying SIP dialog b733f348-f76cf54f@192.168.2.170 [Jun 16 13:19:12] VERBOSE[21576] chan_sip.c: Really destroying SIP dialog 'b733f348-f76cf54f@192.168.2.170' Method: BYE