[May 16 19:11:27] DEBUG[29112] pbx.c: Expression result is '1' [May 16 19:11:27] DEBUG[29112] app_macro.c: Last app: Set|ThisCallOptions=Tt [May 16 19:11:27] DEBUG[29112] pbx.c: Launching 'Dial' [May 16 19:11:27] VERBOSE[29112] logger.c: -- Executing [s@macro-dial:39] Dial("SIP/1102-09551818", "SIP/1101|100|Tt") in new stack [May 16 19:11:27] DEBUG[29112] chan_sip.c: Asked to create a SIP channel with formats: 0x8 (alaw) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Our T38 capability (3840) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Setting NAT on RTP to Off [May 16 19:11:27] DEBUG[29112] chan_sip.c: Setting NAT on UDPTL to Off [May 16 19:11:27] DEBUG[29112] chan_sip.c: *** Our native formats are 0x8 (alaw) [May 16 19:11:27] DEBUG[29112] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [May 16 19:11:27] DEBUG[29112] chan_sip.c: *** Our capabilities are 0x108 (alaw|g729) [May 16 19:11:27] DEBUG[29112] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [May 16 19:11:27] DEBUG[29112] chan_sip.c: *** Our preferred formats from the incoming channel are 0x8 (alaw) [May 16 19:11:27] DEBUG[29112] chan_sip.c: This channel will not be able to handle video. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable MACRO_DEPTH. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable ThisCallOptions. [May 16 19:11:27] DEBUG[29112] channel.c: Copying hard-transferable variable TRANSFER_CONTEXT. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable CallPort. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable THISTIMEOUT. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable MACRO_PRIORITY. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable MACRO_CONTEXT. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable MACRO_EXTEN. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable DB_RESULT. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable REALCALLERIDNUM. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable SYSTEMSTATUS. [May 16 19:11:27] DEBUG[29112] channel.c: Copying hard-transferable variable CallUniqueId. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable MonitorCalledCosAgent. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable MonitorCalledCosExten. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable CallerNum. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable MonitorThisCosAgent. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable MonitorThisCosExten. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable CalledNumCos. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable Called. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable ARG2. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable ARG1. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable CallerAgentNum. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable CallerAgentExt. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable Caller. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable UNIQCLID. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable NumCos. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable OurNum. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable SIPCALLID. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable SIPUSERAGENT. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable SIPDOMAIN. [May 16 19:11:27] DEBUG[29112] channel.c: Not copying variable SIPURI. [May 16 19:11:27] DEBUG[29112] chan_sip.c: Outgoing Call for 1101 [May 16 19:11:27] DEBUG[29112] chan_sip.c: Updating call counter for outgoing call [May 16 19:11:27] DEBUG[29112] chan_sip.c: Call to peer '1101' is 1 out of 10 [May 16 19:11:27] DEBUG[29112] devicestate.c: Notification of state change to be queued on device/channel SIP/1101 [May 16 19:11:27] DEBUG[29112] chan_sip.c: Our T38 capability (3840), joint T38 capability (3840) [May 16 19:11:27] DEBUG[29112] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: False [May 16 19:11:27] DEBUG[29112] chan_sip.c: ** Our prefcodec: 0x8 (alaw) [May 16 19:11:27] VERBOSE[29112] logger.c: Audio is at 10.0.2.1 port 13816 [May 16 19:11:27] VERBOSE[29112] logger.c: Adding codec 0x8 (alaw) to SDP [May 16 19:11:27] VERBOSE[29112] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [May 16 19:11:27] DEBUG[29112] chan_sip.c: -- Done with adding codecs to SDP [May 16 19:11:27] DEBUG[29112] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Header 0: INVITE sip:1101@10.0.2.101:5060 SIP/2.0 (39) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK61fd98a6;rport (59) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Header 2: From: "Operator 2" ;tag=as78bc2e30 (52) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Header 3: To: (30) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Header 4: Contact: (27) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Header 5: Call-ID: 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 (50) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Header 8: Max-Forwards: 70 (16) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Header 9: Date: Fri, 16 May 2008 15:11:27 GMT (35) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Header 11: Supported: replaces (19) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Header 12: Content-Type: application/sdp (29) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Header 13: Content-Length: 205 (19) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Header 14: (0) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Line: v=0 (3) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Line: o=root 24555 24555 IN IP4 10.0.2.1 (34) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Line: s=session (9) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Line: c=IN IP4 10.0.2.1 (17) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Line: t=0 0 (5) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Line: m=audio 13816 RTP/AVP 8 101 (27) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Line: a=fmtp:101 0-16 (15) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Line: a=ptime:20 (10) [May 16 19:11:27] DEBUG[29112] chan_sip.c: Line: a=sendrecv (10) [May 16 19:11:27] VERBOSE[29112] logger.c: Reliably Transmitting (no NAT) to 10.0.2.101:5060: INVITE sip:1101@10.0.2.101:5060 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK61fd98a6;rport From: "Operator 2" ;tag=as78bc2e30 To: Contact: Call-ID: 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Fri, 16 May 2008 15:11:27 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 205 v=0 o=root 24555 24555 IN IP4 10.0.2.1 s=session c=IN IP4 10.0.2.1 t=0 0 m=audio 13816 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- [May 16 19:11:27] DEBUG[29112] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [May 16 19:11:27] VERBOSE[29112] logger.c: -- Called 1101 [May 16 19:11:27] VERBOSE[24568] logger.c: <--- SIP read from 10.0.2.101:5060 ---> SIP/2.0 100 Trying To: From: "Operator 2" ;tag=as78bc2e30 Call-ID: 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 CSeq: 102 INVITE Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK61fd98a6 Server: Linksys/SPA942-4.1.18 Content-Length: 0 <-------------> [May 16 19:11:27] DEBUG[24568] chan_sip.c: Header 0: SIP/2.0 100 Trying (18) [May 16 19:11:27] DEBUG[24568] chan_sip.c: Header 1: To: (30) [May 16 19:11:27] DEBUG[24568] chan_sip.c: Header 2: From: "Operator 2" ;tag=as78bc2e30 (52) [May 16 19:11:27] DEBUG[24568] chan_sip.c: Header 3: Call-ID: 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 (50) [May 16 19:11:27] DEBUG[24568] chan_sip.c: Header 4: CSeq: 102 INVITE (16) [May 16 19:11:27] DEBUG[24568] chan_sip.c: Header 5: Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK61fd98a6 (53) [May 16 19:11:27] DEBUG[24568] chan_sip.c: Header 6: Server: Linksys/SPA942-4.1.18 (29) [May 16 19:11:27] DEBUG[24568] chan_sip.c: Header 7: Content-Length: 0 (17) [May 16 19:11:27] DEBUG[24568] chan_sip.c: Header 8: (0) [May 16 19:11:27] VERBOSE[24568] logger.c: --- (8 headers 0 lines) --- [May 16 19:11:27] DEBUG[24568] chan_sip.c: = Found Their Call ID: 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 Their Tag Our tag: as78bc2e30 [May 16 19:11:27] DEBUG[24568] chan_sip.c: *** SIP TIMER: Cancelling retransmission #174 - INVITE (got response) [May 16 19:11:27] DEBUG[24568] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '6a531d5f689c5e7d26d16dc514181316@10.0.2.1' Request 102: Found [May 16 19:11:27] DEBUG[24568] chan_sip.c: SIP response 100 to standard invite [May 16 19:11:27] VERBOSE[24568] logger.c: <--- SIP read from 10.0.2.101:5060 ---> SIP/2.0 180 Ringing To: ;tag=712c400c8778bff1i0 From: "Operator 2" ;tag=as78bc2e30 Call-ID: 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 CSeq: 102 INVITE Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK61fd98a6 Server: Linksys/SPA942-4.1.18 Content-Length: 0 <-------------> [May 16 19:11:27] DEBUG[24568] chan_sip.c: Header 0: SIP/2.0 180 Ringing (19) [May 16 19:11:27] DEBUG[24568] chan_sip.c: Header 1: To: ;tag=712c400c8778bff1i0 (53) [May 16 19:11:27] DEBUG[24568] chan_sip.c: Header 2: From: "Operator 2" ;tag=as78bc2e30 (52) [May 16 19:11:27] DEBUG[24568] chan_sip.c: Header 3: Call-ID: 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 (50) [May 16 19:11:27] DEBUG[24568] chan_sip.c: Header 4: CSeq: 102 INVITE (16) [May 16 19:11:27] DEBUG[24568] chan_sip.c: Header 5: Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK61fd98a6 (53) [May 16 19:11:27] DEBUG[24568] chan_sip.c: Header 6: Server: Linksys/SPA942-4.1.18 (29) [May 16 19:11:27] DEBUG[24568] chan_sip.c: Header 7: Content-Length: 0 (17) [May 16 19:11:27] DEBUG[24568] chan_sip.c: Header 8: (0) [May 16 19:11:27] VERBOSE[24568] logger.c: --- (8 headers 0 lines) --- [May 16 19:11:27] DEBUG[24568] chan_sip.c: = Found Their Call ID: 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 Their Tag Our tag: as78bc2e30 [May 16 19:11:27] DEBUG[24568] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '6a531d5f689c5e7d26d16dc514181316@10.0.2.1' Request 102: Found [May 16 19:11:27] DEBUG[24568] chan_sip.c: SIP response 180 to standard invite [May 16 19:11:27] DEBUG[24568] devicestate.c: Notification of state change to be queued on device/channel SIP/1101-0955e720 [May 16 19:11:27] DEBUG[24568] devicestate.c: Notification of state change to be queued on device/channel SIP/1101 [May 16 19:11:27] VERBOSE[29112] logger.c: -- SIP/1101-0955e720 is ringing [May 16 19:11:27] VERBOSE[29112] logger.c: <--- Transmitting (no NAT) to 10.0.2.200:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.0.2.200;branch=z9hG4bK0a0002c80000001f482da49c25b54abf0000001b;received=10.0.2.200;rport=5060 From: "unknown";tag=406500183754473053 To: ;tag=as1d57e467 Call-ID: A568ECA8-1DD1-11B2-8B63-8DD5A8419765@10.0.2.200 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [May 16 19:11:30] DEBUG[24559] devicestate.c: Changing state for SIP/1102-095719c0 - state 4 (Invalid) [May 16 19:11:30] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for SIP - 1102 [May 16 19:11:30] DEBUG[24567] app_queue.c: Device 'SIP/1102-095719c0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [May 16 19:11:30] DEBUG[24559] chan_sip.c: Checking device state for peer 1102 [May 16 19:11:30] DEBUG[24559] devicestate.c: Changing state for SIP/1102 - state 2 (In use) [May 16 19:11:30] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for sip - 1102 [May 16 19:11:30] DEBUG[24567] app_queue.c: Device 'SIP/1102' changed to state '2' (In use) but we don't care because they're not a member of any queue. [May 16 19:11:30] DEBUG[24559] chan_sip.c: Checking device state for peer 1102 [May 16 19:11:30] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for sip - 1102 [May 16 19:11:30] DEBUG[24559] chan_sip.c: Checking device state for peer 1102 [May 16 19:11:30] VERBOSE[24559] logger.c: Reliably Transmitting (no NAT) to 10.0.2.100:5060: NOTIFY sip:1100@10.0.2.100:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK70233fb6;rport From: ;tag=as3780e971 To: ;tag=8eb257850a85e728 Contact: Call-ID: d5642264023de13d@10.0.2.100 CSeq: 107 NOTIFY User-Agent: Asterisk PBX Max-Forwards: 70 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 200 confirmed --- [May 16 19:11:30] DEBUG[24559] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [May 16 19:11:30] VERBOSE[24559] logger.c: Extension Changed 1102[local-ext] new state InUse for Notify User 1100 [May 16 19:11:30] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for SIP - 1101 [May 16 19:11:30] DEBUG[24559] chan_sip.c: Checking device state for peer 1101 [May 16 19:11:30] DEBUG[24559] devicestate.c: Changing state for SIP/1101 - state 6 (Ringing) [May 16 19:11:30] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for sip - 1101 [May 16 19:11:30] DEBUG[24567] app_queue.c: Device 'SIP/1101' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [May 16 19:11:30] DEBUG[24559] chan_sip.c: Checking device state for peer 1101 [May 16 19:11:30] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for sip - 1101 [May 16 19:11:30] DEBUG[24559] chan_sip.c: Checking device state for peer 1101 [May 16 19:11:30] VERBOSE[24559] logger.c: Reliably Transmitting (no NAT) to 10.0.2.100:5060: NOTIFY sip:1100@10.0.2.100:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK73833b89;rport From: ;tag=as32fbb72a To: ;tag=1638a1388001aff0 Contact: Call-ID: 141eb56d33fcec24@10.0.2.100 CSeq: 111 NOTIFY User-Agent: Asterisk PBX Max-Forwards: 70 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 218 early --- [May 16 19:11:30] DEBUG[24559] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [May 16 19:11:30] VERBOSE[24559] logger.c: Extension Changed 1101[local-ext] new state Ringing for Notify User 1100 [May 16 19:11:30] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for SIP - 1101-0955b448 [May 16 19:11:30] DEBUG[24559] chan_sip.c: Checking device state for peer 1101-0955b448 [May 16 19:11:30] VERBOSE[24568] logger.c: <--- SIP read from 10.0.2.100:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK70233fb6;rport From: ;tag=as3780e971 To: ;tag=8eb257850a85e728 Call-ID: d5642264023de13d@10.0.2.100 CSeq: 107 NOTIFY User-Agent: Grandstream GXP2000 1.1.6.16 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE Supported: replaces, timer Content-Length: 0 <-------------> [May 16 19:11:30] DEBUG[24568] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [May 16 19:11:30] DEBUG[24568] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK70233fb6;rport (59) [May 16 19:11:30] DEBUG[24568] chan_sip.c: Header 2: From: ;tag=as3780e971 (40) [May 16 19:11:30] DEBUG[24568] chan_sip.c: Header 3: To: ;tag=8eb257850a85e728 (44) [May 16 19:11:30] DEBUG[24568] chan_sip.c: Header 4: Call-ID: d5642264023de13d@10.0.2.100 (36) [May 16 19:11:30] DEBUG[24568] chan_sip.c: Header 5: CSeq: 107 NOTIFY (16) [May 16 19:11:30] DEBUG[24568] chan_sip.c: Header 6: User-Agent: Grandstream GXP2000 1.1.6.16 (40) [May 16 19:11:30] DEBUG[24568] chan_sip.c: Header 7: Contact: (49) [May 16 19:11:30] DEBUG[24568] chan_sip.c: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE (85) [May 16 19:11:30] DEBUG[24568] chan_sip.c: Header 9: Supported: replaces, timer (26) [May 16 19:11:30] DEBUG[24568] chan_sip.c: Header 10: Content-Length: 0 (17) [May 16 19:11:30] DEBUG[24568] chan_sip.c: Header 11: (0) [May 16 19:11:30] VERBOSE[24568] logger.c: --- (11 headers 0 lines) --- [May 16 19:11:30] DEBUG[24568] chan_sip.c: = No match Their Call ID: 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 Their Tag 712c400c8778bff1i0 Our tag: as78bc2e30 [May 16 19:11:30] DEBUG[24568] chan_sip.c: = No match Their Call ID: A568ECA8-1DD1-11B2-8B63-8DD5A8419765@10.0.2.200 Their Tag 406500183754473053 Our tag: as1d57e467 [May 16 19:11:30] DEBUG[24568] chan_sip.c: = No match Their Call ID: 878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 Their Tag 40649517241994678566 Our tag: as3fd6d731 [May 16 19:11:30] DEBUG[24568] chan_sip.c: = No match Their Call ID: 1e4646cfc7864472@10.0.2.100 Their Tag 005f704e3382ec0d Our tag: as7f4a604b [May 16 19:11:30] DEBUG[24568] chan_sip.c: = No match Their Call ID: cc428c423a89561b@10.0.2.100 Their Tag f9fa6174823b0f17 Our tag: as710aa077 [May 16 19:11:30] DEBUG[24568] chan_sip.c: = No match Their Call ID: 1b5b73ee29545b2a@10.0.2.100 Their Tag 2896e796b5dd916f Our tag: as35d63675 [May 16 19:11:30] DEBUG[24568] chan_sip.c: = No match Their Call ID: 604f9802ea0208a4@10.0.2.100 Their Tag 975f7a4f874cd22e Our tag: as6c949944 [May 16 19:11:30] DEBUG[24568] chan_sip.c: = Found Their Call ID: d5642264023de13d@10.0.2.100 Their Tag 8eb257850a85e728 Our tag: as3780e971 [May 16 19:11:30] DEBUG[24568] chan_sip.c: Acked pending invite 107 [May 16 19:11:30] DEBUG[24568] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #176 [May 16 19:11:30] DEBUG[24568] chan_sip.c: Stopping retransmission on 'd5642264023de13d@10.0.2.100' of Request 107: Match Found [May 16 19:11:30] VERBOSE[24568] logger.c: SIP Response message for INCOMING dialog NOTIFY arrived [May 16 19:11:30] VERBOSE[24568] logger.c: <--- SIP read from 10.0.2.100:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK73833b89;rport From: ;tag=as32fbb72a To: ;tag=1638a1388001aff0 Call-ID: 141eb56d33fcec24@10.0.2.100 CSeq: 111 NOTIFY User-Agent: Grandstream GXP2000 1.1.6.16 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE Supported: replaces, timer Content-Length: 0 <-------------> [May 16 19:11:30] DEBUG[24568] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [May 16 19:11:30] DEBUG[24568] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK73833b89;rport (59) [May 16 19:11:30] DEBUG[24568] chan_sip.c: Header 2: From: ;tag=as32fbb72a (40) [May 16 19:11:30] DEBUG[24568] chan_sip.c: Header 3: To: ;tag=1638a1388001aff0 (44) [May 16 19:11:30] DEBUG[24568] chan_sip.c: Header 4: Call-ID: 141eb56d33fcec24@10.0.2.100 (36) [May 16 19:11:30] DEBUG[24568] chan_sip.c: Header 5: CSeq: 111 NOTIFY (16) [May 16 19:11:30] DEBUG[24568] chan_sip.c: Header 6: User-Agent: Grandstream GXP2000 1.1.6.16 (40) [May 16 19:11:30] DEBUG[24568] chan_sip.c: Header 7: Contact: (49) [May 16 19:11:30] DEBUG[24568] chan_sip.c: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE (85) [May 16 19:11:30] DEBUG[24568] chan_sip.c: Header 9: Supported: replaces, timer (26) [May 16 19:11:30] DEBUG[24568] chan_sip.c: Header 10: Content-Length: 0 (17) [May 16 19:11:30] DEBUG[24568] chan_sip.c: Header 11: (0) [May 16 19:11:30] VERBOSE[24568] logger.c: --- (11 headers 0 lines) --- [May 16 19:11:30] DEBUG[24568] chan_sip.c: = No match Their Call ID: 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 Their Tag 712c400c8778bff1i0 Our tag: as78bc2e30 [May 16 19:11:30] DEBUG[24568] chan_sip.c: = No match Their Call ID: A568ECA8-1DD1-11B2-8B63-8DD5A8419765@10.0.2.200 Their Tag 406500183754473053 Our tag: as1d57e467 [May 16 19:11:30] DEBUG[24568] chan_sip.c: = No match Their Call ID: 878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 Their Tag 40649517241994678566 Our tag: as3fd6d731 [May 16 19:11:30] DEBUG[24568] chan_sip.c: = No match Their Call ID: 1e4646cfc7864472@10.0.2.100 Their Tag 005f704e3382ec0d Our tag: as7f4a604b [May 16 19:11:30] DEBUG[24568] chan_sip.c: = No match Their Call ID: cc428c423a89561b@10.0.2.100 Their Tag f9fa6174823b0f17 Our tag: as710aa077 [May 16 19:11:30] DEBUG[24568] chan_sip.c: = No match Their Call ID: 1b5b73ee29545b2a@10.0.2.100 Their Tag 2896e796b5dd916f Our tag: as35d63675 [May 16 19:11:30] DEBUG[24568] chan_sip.c: = No match Their Call ID: 604f9802ea0208a4@10.0.2.100 Their Tag 975f7a4f874cd22e Our tag: as6c949944 [May 16 19:11:30] DEBUG[24568] chan_sip.c: = No match Their Call ID: d5642264023de13d@10.0.2.100 Their Tag 8eb257850a85e728 Our tag: as3780e971 [May 16 19:11:30] DEBUG[24568] chan_sip.c: = Found Their Call ID: 141eb56d33fcec24@10.0.2.100 Their Tag 1638a1388001aff0 Our tag: as32fbb72a [May 16 19:11:30] DEBUG[24568] chan_sip.c: Acked pending invite 111 [May 16 19:11:30] DEBUG[24568] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #177 [May 16 19:11:30] DEBUG[24568] chan_sip.c: Stopping retransmission on '141eb56d33fcec24@10.0.2.100' of Request 111: Match Found [May 16 19:11:30] VERBOSE[24568] logger.c: SIP Response message for INCOMING dialog NOTIFY arrived [May 16 19:11:37] VERBOSE[24568] logger.c: <--- SIP read from 10.0.2.200:5060 ---> OPTIONS sip:10.0.2.1 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.200;rport;branch=z9hG4bK0a0002c800000010482da4a551730b880000001e Content-Length: 0 Call-ID: 878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 CSeq: 4 OPTIONS From: ;tag=4065011729250343880 Max-Forwards: 70 To: <-------------> [May 16 19:11:37] DEBUG[24568] chan_sip.c: Header 0: OPTIONS sip:10.0.2.1 SIP/2.0 (28) [May 16 19:11:37] DEBUG[24568] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.0.2.200;rport;branch=z9hG4bK0a0002c800000010482da4a551730b880000001e (88) [May 16 19:11:37] DEBUG[24568] chan_sip.c: Header 2: Content-Length: 0 (17) [May 16 19:11:37] DEBUG[24568] chan_sip.c: Header 3: Call-ID: 878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 (56) [May 16 19:11:37] DEBUG[24568] chan_sip.c: Header 4: CSeq: 4 OPTIONS (15) [May 16 19:11:37] DEBUG[24568] chan_sip.c: Header 5: From: ;tag=4065011729250343880 (49) [May 16 19:11:37] DEBUG[24568] chan_sip.c: Header 6: Max-Forwards: 70 (16) [May 16 19:11:37] DEBUG[24568] chan_sip.c: Header 7: To: (18) [May 16 19:11:37] DEBUG[24568] chan_sip.c: Header 8: (0) [May 16 19:11:37] VERBOSE[24568] logger.c: --- (8 headers 0 lines) --- [May 16 19:11:37] DEBUG[24568] chan_sip.c: = No match Their Call ID: 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 Their Tag 712c400c8778bff1i0 Our tag: as78bc2e30 [May 16 19:11:37] DEBUG[24568] chan_sip.c: = No match Their Call ID: A568ECA8-1DD1-11B2-8B63-8DD5A8419765@10.0.2.200 Their Tag 406500183754473053 Our tag: as1d57e467 [May 16 19:11:37] DEBUG[24568] chan_sip.c: = Found Their Call ID: 878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 Their Tag 40649517241994678566 Our tag: as3fd6d731 [May 16 19:11:37] DEBUG[24568] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [May 16 19:11:37] VERBOSE[24568] logger.c: Looking for s in inbound (domain 10.0.2.1) [May 16 19:11:37] VERBOSE[24568] logger.c: <--- Transmitting (no NAT) to 10.0.2.200:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.2.200;branch=z9hG4bK0a0002c800000010482da4a551730b880000001e;received=10.0.2.200;rport=5060 From: ;tag=4065011729250343880 To: ;tag=as3fd6d731 Call-ID: 878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 CSeq: 4 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> [May 16 19:11:37] VERBOSE[24568] logger.c: Scheduling destruction of SIP dialog '878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200' in 32000 ms (Method: OPTIONS) [May 16 19:11:40] DEBUG[24559] devicestate.c: Changing state for SIP/1101-0955b448 - state 4 (Invalid) [May 16 19:11:40] DEBUG[24567] app_queue.c: Device 'SIP/1101-0955b448' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [May 16 19:11:40] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for SIP - 1101 [May 16 19:11:40] DEBUG[24559] chan_sip.c: Checking device state for peer 1101 [May 16 19:11:40] DEBUG[24559] devicestate.c: Changing state for SIP/1101 - state 6 (Ringing) [May 16 19:11:40] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for sip - 1101 [May 16 19:11:40] DEBUG[24567] app_queue.c: Device 'SIP/1101' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [May 16 19:11:40] DEBUG[24559] chan_sip.c: Checking device state for peer 1101 [May 16 19:11:40] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for SIP - 1102 [May 16 19:11:40] DEBUG[24559] chan_sip.c: Checking device state for peer 1102 [May 16 19:11:40] DEBUG[24559] devicestate.c: Changing state for SIP/1102 - state 2 (In use) [May 16 19:11:40] DEBUG[24567] app_queue.c: Device 'SIP/1102' changed to state '2' (In use) but we don't care because they're not a member of any queue. [May 16 19:11:40] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for sip - 1102 [May 16 19:11:40] DEBUG[24559] chan_sip.c: Checking device state for peer 1102 [May 16 19:11:40] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for SIP - 1102-09551818 [May 16 19:11:40] DEBUG[24559] chan_sip.c: Checking device state for peer 1102-09551818 [May 16 19:11:41] VERBOSE[24568] logger.c: <--- SIP read from 10.0.2.101:5060 ---> SIP/2.0 200 OK To: ;tag=712c400c8778bff1i0 From: "Operator 2" ;tag=as78bc2e30 Call-ID: 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 CSeq: 102 INVITE Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK61fd98a6 Contact: "Linksys SPA 942" Server: Linksys/SPA942-4.1.18 Content-Length: 206 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Content-Type: application/sdp v=0 o=- 19377678 19377678 IN IP4 10.0.2.101 s=- c=IN IP4 10.0.2.101 t=0 0 m=audio 16466 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [May 16 19:11:41] DEBUG[24568] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Header 1: To: ;tag=712c400c8778bff1i0 (53) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Header 2: From: "Operator 2" ;tag=as78bc2e30 (52) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Header 3: Call-ID: 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 (50) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Header 4: CSeq: 102 INVITE (16) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Header 5: Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK61fd98a6 (53) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Header 6: Contact: "Linksys SPA 942" (53) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Header 7: Server: Linksys/SPA942-4.1.18 (29) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Header 8: Content-Length: 206 (19) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Header 9: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Header 10: Content-Type: application/sdp (29) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Header 11: (0) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Line: v=0 (3) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Line: o=- 19377678 19377678 IN IP4 10.0.2.101 (39) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Line: s=- (3) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Line: c=IN IP4 10.0.2.101 (19) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Line: t=0 0 (5) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Line: m=audio 16466 RTP/AVP 8 101 (27) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Line: a=fmtp:101 0-15 (15) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Line: a=ptime:30 (10) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Line: a=sendrecv (10) [May 16 19:11:41] VERBOSE[24568] logger.c: --- (11 headers 11 lines) --- [May 16 19:11:41] DEBUG[24568] chan_sip.c: = Found Their Call ID: 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 Their Tag 712c400c8778bff1i0 Our tag: as78bc2e30 [May 16 19:11:41] DEBUG[24568] chan_sip.c: Acked pending invite 102 [May 16 19:11:41] DEBUG[24568] chan_sip.c: Stopping retransmission on '6a531d5f689c5e7d26d16dc514181316@10.0.2.1' of Request 102: Match Found [May 16 19:11:41] DEBUG[24568] chan_sip.c: SIP response 200 to standard invite [May 16 19:11:41] VERBOSE[24568] logger.c: Found RTP audio format 8 [May 16 19:11:41] VERBOSE[24568] logger.c: Found RTP audio format 101 [May 16 19:11:41] DEBUG[24568] chan_sip.c: Peer doesn't provide T.38 UDPTL [May 16 19:11:41] VERBOSE[24568] logger.c: Peer audio RTP is at port 10.0.2.101:16466 [May 16 19:11:41] VERBOSE[24568] logger.c: Found audio description format PCMA for ID 8 [May 16 19:11:41] VERBOSE[24568] logger.c: Found audio description format telephone-event for ID 101 [May 16 19:11:41] VERBOSE[24568] logger.c: Got unsupported a:fmtp in SDP offer [May 16 19:11:41] DEBUG[24568] chan_sip.c: T38 state changed to 0 on channel SIP/1101-0955e720 [May 16 19:11:41] VERBOSE[24568] logger.c: Capabilities: us - 0x108 (alaw|g729), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) [May 16 19:11:41] VERBOSE[24568] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [May 16 19:11:41] VERBOSE[24568] logger.c: Peer audio RTP is at port 10.0.2.101:16466 [May 16 19:11:41] DEBUG[24568] chan_sip.c: We're settling with these formats: 0x8 (alaw) [May 16 19:11:41] DEBUG[24568] chan_sip.c: We have an owner, now see if we need to change this call [May 16 19:11:41] DEBUG[24568] chan_sip.c: Updating call counter for outgoing call [May 16 19:11:41] DEBUG[24568] devicestate.c: Notification of state change to be queued on device/channel SIP/1101 [May 16 19:11:41] DEBUG[24568] chan_sip.c: build_route: Contact hop: "Linksys SPA 942" [May 16 19:11:41] VERBOSE[24568] logger.c: list_route: hop: [May 16 19:11:41] DEBUG[24568] chan_sip.c: Strict routing enforced for session 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 [May 16 19:11:41] VERBOSE[24568] logger.c: set_destination: Parsing for address/port to send to [May 16 19:11:41] VERBOSE[24568] logger.c: set_destination: set destination to 10.0.2.101, port 5060 [May 16 19:11:41] VERBOSE[24568] logger.c: Transmitting (no NAT) to 10.0.2.101:5060: ACK sip:1101@10.0.2.101:5060 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK5af7a7f5;rport From: "Operator 2" ;tag=as78bc2e30 To: ;tag=712c400c8778bff1i0 Contact: Call-ID: 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [May 16 19:11:41] DEBUG[29112] devicestate.c: Notification of state change to be queued on device/channel SIP/1101-0955e720 [May 16 19:11:41] DEBUG[29112] devicestate.c: Notification of state change to be queued on device/channel SIP/1101 [May 16 19:11:41] VERBOSE[29112] logger.c: -- SIP/1101-0955e720 answered SIP/1102-09551818 [May 16 19:11:41] DEBUG[29112] devicestate.c: Notification of state change to be queued on device/channel SIP/1102-09551818 [May 16 19:11:41] DEBUG[29112] devicestate.c: Notification of state change to be queued on device/channel SIP/1102 [May 16 19:11:41] DEBUG[29112] chan_sip.c: SIP answering channel: SIP/1102-09551818 [May 16 19:11:41] DEBUG[29112] chan_sip.c: Setting framing from config on incoming call [May 16 19:11:41] DEBUG[29112] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: True [May 16 19:11:41] DEBUG[29112] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [May 16 19:11:41] VERBOSE[29112] logger.c: Audio is at 10.0.2.1 port 18896 [May 16 19:11:41] VERBOSE[29112] logger.c: Adding codec 0x8 (alaw) to SDP [May 16 19:11:41] VERBOSE[29112] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [May 16 19:11:41] DEBUG[29112] chan_sip.c: -- Done with adding codecs to SDP [May 16 19:11:41] DEBUG[29112] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=24) [May 16 19:11:41] DEBUG[29112] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw) [May 16 19:11:41] VERBOSE[29112] logger.c: <--- Reliably Transmitting (no NAT) to 10.0.2.200:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.2.200;branch=z9hG4bK0a0002c80000001f482da49c25b54abf0000001b;received=10.0.2.200;rport=5060 From: "unknown";tag=406500183754473053 To: ;tag=as1d57e467 Call-ID: A568ECA8-1DD1-11B2-8B63-8DD5A8419765@10.0.2.200 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 205 v=0 o=root 24555 24555 IN IP4 10.0.2.1 s=session c=IN IP4 10.0.2.1 t=0 0 m=audio 18896 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> [May 16 19:11:41] DEBUG[29112] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [May 16 19:11:41] VERBOSE[24568] logger.c: <--- SIP read from 10.0.2.200:5060 ---> ACK sip:1101@10.0.2.1 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.200;rport;branch=z9hG4bK0a0002c80000001f482da4aa67f77a3100000021 Content-Length: 0 Call-ID: A568ECA8-1DD1-11B2-8B63-8DD5A8419765@10.0.2.200 CSeq: 2 ACK From: "unknown";tag=406500183754473053 Max-Forwards: 70 To: ;tag=as1d57e467 User-Agent: SJphone/1.60.299a/L (SJ Labs) <-------------> [May 16 19:11:41] DEBUG[24568] chan_sip.c: Header 0: ACK sip:1101@10.0.2.1 SIP/2.0 (29) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.0.2.200;rport;branch=z9hG4bK0a0002c80000001f482da4aa67f77a3100000021 (88) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Header 2: Content-Length: 0 (17) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Header 3: Call-ID: A568ECA8-1DD1-11B2-8B63-8DD5A8419765@10.0.2.200 (56) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Header 4: CSeq: 2 ACK (11) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Header 5: From: "unknown";tag=406500183754473053 (57) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Header 6: Max-Forwards: 70 (16) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Header 7: To: ;tag=as1d57e467 (38) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Header 8: User-Agent: SJphone/1.60.299a/L (SJ Labs) (41) [May 16 19:11:41] DEBUG[24568] chan_sip.c: Header 9: (0) [May 16 19:11:41] VERBOSE[24568] logger.c: --- (9 headers 0 lines) --- [May 16 19:11:41] DEBUG[24568] chan_sip.c: = No match Their Call ID: 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 Their Tag 712c400c8778bff1i0 Our tag: as78bc2e30 [May 16 19:11:41] DEBUG[24568] chan_sip.c: = Found Their Call ID: A568ECA8-1DD1-11B2-8B63-8DD5A8419765@10.0.2.200 Their Tag 406500183754473053 Our tag: as1d57e467 [May 16 19:11:41] DEBUG[24568] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [May 16 19:11:41] DEBUG[24568] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #179 [May 16 19:11:41] DEBUG[24568] chan_sip.c: Stopping retransmission on 'A568ECA8-1DD1-11B2-8B63-8DD5A8419765@10.0.2.200' of Response 2: Match Found [May 16 19:11:41] DEBUG[29112] rtp.c: Ooh, format changed from unknown to alaw [May 16 19:11:41] DEBUG[29112] rtp.c: Created smoother: format: 8 ms: 20 len: 160 [May 16 19:11:41] DEBUG[29112] rtp.c: Ooh, format changed from unknown to alaw [May 16 19:11:41] DEBUG[29112] rtp.c: Created smoother: format: 8 ms: 20 len: 160 [May 16 19:11:50] DEBUG[24559] devicestate.c: Changing state for SIP/1102-09551818 - state 4 (Invalid) [May 16 19:11:50] DEBUG[24567] app_queue.c: Device 'SIP/1102-09551818' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [May 16 19:11:50] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for SIP - 1102 [May 16 19:11:50] DEBUG[24559] chan_sip.c: Checking device state for peer 1102 [May 16 19:11:50] DEBUG[24559] devicestate.c: Changing state for SIP/1102 - state 2 (In use) [May 16 19:11:50] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for sip - 1102 [May 16 19:11:50] DEBUG[24567] app_queue.c: Device 'SIP/1102' changed to state '2' (In use) but we don't care because they're not a member of any queue. [May 16 19:11:50] DEBUG[24559] chan_sip.c: Checking device state for peer 1102 [May 16 19:11:50] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for SIP - 1101 [May 16 19:11:50] DEBUG[24559] chan_sip.c: Checking device state for peer 1101 [May 16 19:11:50] DEBUG[24559] devicestate.c: Changing state for SIP/1101 - state 2 (In use) [May 16 19:11:50] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for sip - 1101 [May 16 19:11:50] DEBUG[24567] app_queue.c: Device 'SIP/1101' changed to state '2' (In use) but we don't care because they're not a member of any queue. [May 16 19:11:50] DEBUG[24559] chan_sip.c: Checking device state for peer 1101 [May 16 19:11:50] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for sip - 1101 [May 16 19:11:50] DEBUG[24559] chan_sip.c: Checking device state for peer 1101 [May 16 19:11:50] VERBOSE[24559] logger.c: Reliably Transmitting (no NAT) to 10.0.2.100:5060: NOTIFY sip:1100@10.0.2.100:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK7d97e522;rport From: ;tag=as32fbb72a To: ;tag=1638a1388001aff0 Contact: Call-ID: 141eb56d33fcec24@10.0.2.100 CSeq: 112 NOTIFY User-Agent: Asterisk PBX Max-Forwards: 70 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 201 confirmed --- [May 16 19:11:50] DEBUG[24559] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [May 16 19:11:50] VERBOSE[24559] logger.c: Extension Changed 1101[local-ext] new state InUse for Notify User 1100 [May 16 19:11:50] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for SIP - 1101-0955e720 [May 16 19:11:50] DEBUG[24559] chan_sip.c: Checking device state for peer 1101-0955e720 [May 16 19:11:50] VERBOSE[24568] logger.c: <--- SIP read from 10.0.2.100:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK7d97e522;rport From: ;tag=as32fbb72a To: ;tag=1638a1388001aff0 Call-ID: 141eb56d33fcec24@10.0.2.100 CSeq: 112 NOTIFY User-Agent: Grandstream GXP2000 1.1.6.16 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE Supported: replaces, timer Content-Length: 0 <-------------> [May 16 19:11:50] DEBUG[24568] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [May 16 19:11:50] DEBUG[24568] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK7d97e522;rport (59) [May 16 19:11:50] DEBUG[24568] chan_sip.c: Header 2: From: ;tag=as32fbb72a (40) [May 16 19:11:50] DEBUG[24568] chan_sip.c: Header 3: To: ;tag=1638a1388001aff0 (44) [May 16 19:11:50] DEBUG[24568] chan_sip.c: Header 4: Call-ID: 141eb56d33fcec24@10.0.2.100 (36) [May 16 19:11:50] DEBUG[24568] chan_sip.c: Header 5: CSeq: 112 NOTIFY (16) [May 16 19:11:50] DEBUG[24568] chan_sip.c: Header 6: User-Agent: Grandstream GXP2000 1.1.6.16 (40) [May 16 19:11:50] DEBUG[24568] chan_sip.c: Header 7: Contact: (49) [May 16 19:11:50] DEBUG[24568] chan_sip.c: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE (85) [May 16 19:11:50] DEBUG[24568] chan_sip.c: Header 9: Supported: replaces, timer (26) [May 16 19:11:50] DEBUG[24568] chan_sip.c: Header 10: Content-Length: 0 (17) [May 16 19:11:50] DEBUG[24568] chan_sip.c: Header 11: (0) [May 16 19:11:50] VERBOSE[24568] logger.c: --- (11 headers 0 lines) --- [May 16 19:11:50] DEBUG[24568] chan_sip.c: = No match Their Call ID: 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 Their Tag 712c400c8778bff1i0 Our tag: as78bc2e30 [May 16 19:11:50] DEBUG[24568] chan_sip.c: = No match Their Call ID: A568ECA8-1DD1-11B2-8B63-8DD5A8419765@10.0.2.200 Their Tag 406500183754473053 Our tag: as1d57e467 [May 16 19:11:50] DEBUG[24568] chan_sip.c: = No match Their Call ID: 878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 Their Tag 40649517241994678566 Our tag: as3fd6d731 [May 16 19:11:50] DEBUG[24568] chan_sip.c: = No match Their Call ID: 1e4646cfc7864472@10.0.2.100 Their Tag 005f704e3382ec0d Our tag: as7f4a604b [May 16 19:11:50] DEBUG[24568] chan_sip.c: = No match Their Call ID: cc428c423a89561b@10.0.2.100 Their Tag f9fa6174823b0f17 Our tag: as710aa077 [May 16 19:11:50] DEBUG[24568] chan_sip.c: = No match Their Call ID: 1b5b73ee29545b2a@10.0.2.100 Their Tag 2896e796b5dd916f Our tag: as35d63675 [May 16 19:11:50] DEBUG[24568] chan_sip.c: = No match Their Call ID: 604f9802ea0208a4@10.0.2.100 Their Tag 975f7a4f874cd22e Our tag: as6c949944 [May 16 19:11:50] DEBUG[24568] chan_sip.c: = No match Their Call ID: d5642264023de13d@10.0.2.100 Their Tag 8eb257850a85e728 Our tag: as3780e971 [May 16 19:11:50] DEBUG[24568] chan_sip.c: = Found Their Call ID: 141eb56d33fcec24@10.0.2.100 Their Tag 1638a1388001aff0 Our tag: as32fbb72a [May 16 19:11:50] DEBUG[24568] chan_sip.c: Acked pending invite 112 [May 16 19:11:50] DEBUG[24568] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #182 [May 16 19:11:50] DEBUG[24568] chan_sip.c: Stopping retransmission on '141eb56d33fcec24@10.0.2.100' of Request 112: Match Found [May 16 19:11:50] VERBOSE[24568] logger.c: SIP Response message for INCOMING dialog NOTIFY arrived [May 16 19:11:57] VERBOSE[24568] logger.c: <--- SIP read from 10.0.2.200:5060 ---> OPTIONS sip:10.0.2.1 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.200;rport;branch=z9hG4bK0a0002c800000010482da4b93594ac1900000022 Content-Length: 0 Call-ID: 878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 CSeq: 5 OPTIONS From: ;tag=40650317311291958984 Max-Forwards: 70 To: <-------------> [May 16 19:11:57] DEBUG[24568] chan_sip.c: Header 0: OPTIONS sip:10.0.2.1 SIP/2.0 (28) [May 16 19:11:57] DEBUG[24568] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.0.2.200;rport;branch=z9hG4bK0a0002c800000010482da4b93594ac1900000022 (88) [May 16 19:11:57] DEBUG[24568] chan_sip.c: Header 2: Content-Length: 0 (17) [May 16 19:11:57] DEBUG[24568] chan_sip.c: Header 3: Call-ID: 878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 (56) [May 16 19:11:57] DEBUG[24568] chan_sip.c: Header 4: CSeq: 5 OPTIONS (15) [May 16 19:11:57] DEBUG[24568] chan_sip.c: Header 5: From: ;tag=40650317311291958984 (50) [May 16 19:11:57] DEBUG[24568] chan_sip.c: Header 6: Max-Forwards: 70 (16) [May 16 19:11:57] DEBUG[24568] chan_sip.c: Header 7: To: (18) [May 16 19:11:57] DEBUG[24568] chan_sip.c: Header 8: (0) [May 16 19:11:57] VERBOSE[24568] logger.c: --- (8 headers 0 lines) --- [May 16 19:11:57] DEBUG[24568] chan_sip.c: = No match Their Call ID: 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 Their Tag 712c400c8778bff1i0 Our tag: as78bc2e30 [May 16 19:11:57] DEBUG[24568] chan_sip.c: = No match Their Call ID: A568ECA8-1DD1-11B2-8B63-8DD5A8419765@10.0.2.200 Their Tag 406500183754473053 Our tag: as1d57e467 [May 16 19:11:57] DEBUG[24568] chan_sip.c: = Found Their Call ID: 878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 Their Tag 40649517241994678566 Our tag: as3fd6d731 [May 16 19:11:57] DEBUG[24568] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [May 16 19:11:57] VERBOSE[24568] logger.c: Looking for s in inbound (domain 10.0.2.1) [May 16 19:11:57] VERBOSE[24568] logger.c: <--- Transmitting (no NAT) to 10.0.2.200:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.2.200;branch=z9hG4bK0a0002c800000010482da4b93594ac1900000022;received=10.0.2.200;rport=5060 From: ;tag=40650317311291958984 To: ;tag=as3fd6d731 Call-ID: 878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 CSeq: 5 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> [May 16 19:11:57] VERBOSE[24568] logger.c: Scheduling destruction of SIP dialog '878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200' in 32000 ms (Method: OPTIONS) [May 16 19:11:59] VERBOSE[24568] logger.c: <--- SIP read from 10.0.2.101:5060 ---> BYE sip:102@10.0.2.1 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.101:5060;branch=z9hG4bK-df749415 From: ;tag=712c400c8778bff1i0 To: "Operator 2" ;tag=as78bc2e30 Call-ID: 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 CSeq: 101 BYE Max-Forwards: 70 User-Agent: Linksys/SPA942-4.1.18 Content-Length: 0 <-------------> [May 16 19:11:59] DEBUG[24568] chan_sip.c: Header 0: BYE sip:102@10.0.2.1 SIP/2.0 (28) [May 16 19:11:59] DEBUG[24568] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.0.2.101:5060;branch=z9hG4bK-df749415 (56) [May 16 19:11:59] DEBUG[24568] chan_sip.c: Header 2: From: ;tag=712c400c8778bff1i0 (55) [May 16 19:11:59] DEBUG[24568] chan_sip.c: Header 3: To: "Operator 2" ;tag=as78bc2e30 (50) [May 16 19:11:59] DEBUG[24568] chan_sip.c: Header 4: Call-ID: 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 (50) [May 16 19:11:59] DEBUG[24568] chan_sip.c: Header 5: CSeq: 101 BYE (13) [May 16 19:11:59] DEBUG[24568] chan_sip.c: Header 6: Max-Forwards: 70 (16) [May 16 19:11:59] DEBUG[24568] chan_sip.c: Header 7: User-Agent: Linksys/SPA942-4.1.18 (33) [May 16 19:11:59] DEBUG[24568] chan_sip.c: Header 8: Content-Length: 0 (17) [May 16 19:11:59] DEBUG[24568] chan_sip.c: Header 9: (0) [May 16 19:11:59] VERBOSE[24568] logger.c: --- (9 headers 0 lines) --- [May 16 19:11:59] DEBUG[24568] chan_sip.c: = Found Their Call ID: 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 Their Tag 712c400c8778bff1i0 Our tag: as78bc2e30 [May 16 19:11:59] DEBUG[24568] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [May 16 19:11:59] VERBOSE[24568] logger.c: Sending to 10.0.2.101 : 5060 (no NAT) [May 16 19:11:59] DEBUG[24568] chan_sip.c: Setting SIP_ALREADYGONE on dialog 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 [May 16 19:11:59] DEBUG[24568] chan_sip.c: Received bye, issuing owner hangup [May 16 19:11:59] VERBOSE[24568] logger.c: <--- Transmitting (no NAT) to 10.0.2.101:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.2.101:5060;branch=z9hG4bK-df749415;received=10.0.2.101 From: ;tag=712c400c8778bff1i0 To: "Operator 2" ;tag=as78bc2e30 Call-ID: 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 CSeq: 101 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [May 16 19:11:59] DEBUG[29112] channel.c: Didn't get a frame from channel: SIP/1101-0955e720 [May 16 19:11:59] DEBUG[29112] channel.c: Bridge stops bridging channels SIP/1102-09551818 and SIP/1101-0955e720 [May 16 19:11:59] DEBUG[29112] channel.c: Hanging up channel 'SIP/1101-0955e720' [May 16 19:11:59] DEBUG[29112] chan_sip.c: Hangup call SIP/1101-0955e720, SIP callid 6a531d5f689c5e7d26d16dc514181316@10.0.2.1) [May 16 19:11:59] DEBUG[29112] chan_sip.c: update_call_counter(1101) - decrement call limit counter on hangup [May 16 19:11:59] DEBUG[29112] chan_sip.c: Updating call counter for outgoing call [May 16 19:11:59] DEBUG[29112] chan_sip.c: Call to peer '1101' removed from call limit 10 [May 16 19:11:59] DEBUG[29112] devicestate.c: Notification of state change to be queued on device/channel SIP/1101 [May 16 19:11:59] DEBUG[29112] devicestate.c: Notification of state change to be queued on device/channel SIP/1101-0955e720 [May 16 19:11:59] DEBUG[29112] devicestate.c: Notification of state change to be queued on device/channel SIP/1101 [May 16 19:11:59] DEBUG[29112] rtp.c: Channel '' has no RTP, not doing anything [May 16 19:11:59] DEBUG[29112] app_dial.c: Exiting with DIALSTATUS=ANSWER. [May 16 19:11:59] DEBUG[29112] app_macro.c: Spawn extension (macro-dial,s,39) exited non-zero on 'SIP/1102-09551818' in macro 'dial' [May 16 19:11:59] DEBUG[29112] pbx.c: Spawn extension (macro-dial,s,39) exited non-zero on 'SIP/1102-09551818' [May 16 19:11:59] VERBOSE[29112] logger.c: == Spawn extension (macro-dial, s, 39) exited non-zero on 'SIP/1102-09551818' [May 16 19:11:59] DEBUG[29112] channel.c: Soft-Hanging up channel 'SIP/1102-09551818' [May 16 19:11:59] DEBUG[29112] channel.c: Hanging up channel 'SIP/1102-09551818' [May 16 19:11:59] DEBUG[29112] chan_sip.c: Hangup call SIP/1102-09551818, SIP callid A568ECA8-1DD1-11B2-8B63-8DD5A8419765@10.0.2.200) [May 16 19:11:59] DEBUG[29112] chan_sip.c: update_call_counter(1102) - decrement call limit counter on hangup [May 16 19:11:59] DEBUG[29112] chan_sip.c: Updating call counter for incoming call [May 16 19:11:59] DEBUG[29112] chan_sip.c: Call from peer '1102' removed from call limit 10 [May 16 19:11:59] DEBUG[29112] devicestate.c: Notification of state change to be queued on device/channel SIP/1102 [May 16 19:11:59] VERBOSE[29112] logger.c: Scheduling destruction of SIP dialog 'A568ECA8-1DD1-11B2-8B63-8DD5A8419765@10.0.2.200' in 32000 ms (Method: ACK) [May 16 19:11:59] DEBUG[29112] chan_sip.c: Strict routing enforced for session A568ECA8-1DD1-11B2-8B63-8DD5A8419765@10.0.2.200 [May 16 19:11:59] VERBOSE[29112] logger.c: set_destination: Parsing for address/port to send to [May 16 19:11:59] VERBOSE[29112] logger.c: set_destination: set destination to 10.0.2.200, port 5060 [May 16 19:11:59] VERBOSE[29112] logger.c: Reliably Transmitting (no NAT) to 10.0.2.200:5060: BYE sip:1102@10.0.2.200:5060 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK60e00368;rport From: ;tag=as1d57e467 To: "unknown";tag=406500183754473053 Call-ID: A568ECA8-1DD1-11B2-8B63-8DD5A8419765@10.0.2.200 CSeq: 102 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [May 16 19:11:59] DEBUG[29112] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [May 16 19:11:59] DEBUG[29112] devicestate.c: Notification of state change to be queued on device/channel SIP/1102-09551818 [May 16 19:11:59] DEBUG[29112] devicestate.c: Notification of state change to be queued on device/channel SIP/1102 [May 16 19:11:59] DEBUG[29112] pbx.c: Function result is '"Operator 2" <1102>' [May 16 19:11:59] DEBUG[29112] pbx.c: Function result is '1102' [May 16 19:11:59] DEBUG[29112] pbx.c: Function result is '1101' [May 16 19:11:59] DEBUG[29112] pbx.c: Function result is 'internal-cos1' [May 16 19:11:59] DEBUG[29112] pbx.c: Function result is 'SIP/1102-09551818' [May 16 19:11:59] DEBUG[29112] pbx.c: Function result is 'SIP/1101-0955e720' [May 16 19:11:59] DEBUG[29112] pbx.c: Function result is 'Dial' [May 16 19:11:59] DEBUG[29112] pbx.c: Function result is 'SIP/1101|100|Tt' [May 16 19:11:59] DEBUG[29112] pbx.c: Function result is '2008-05-16 19:11:27' [May 16 19:11:59] DEBUG[29112] pbx.c: Function result is '2008-05-16 19:11:41' [May 16 19:11:59] DEBUG[29112] pbx.c: Function result is '2008-05-16 19:11:59' [May 16 19:11:59] DEBUG[29112] pbx.c: Function result is '32' [May 16 19:11:59] DEBUG[29112] pbx.c: Function result is '18' [May 16 19:11:59] DEBUG[29112] pbx.c: Function result is 'ANSWERED' [May 16 19:11:59] DEBUG[29112] pbx.c: Function result is 'DOCUMENTATION' [May 16 19:11:59] DEBUG[29112] pbx.c: Function result is '' [May 16 19:11:59] DEBUG[29112] pbx.c: Function result is '1210950687.20' [May 16 19:11:59] DEBUG[29112] pbx.c: Function result is '' [May 16 19:11:59] VERBOSE[24568] logger.c: <--- SIP read from 10.0.2.200:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.2.1:5060;rport=5060;received=10.0.2.1;branch=z9hG4bK60e00368 Content-Length: 0 Call-ID: A568ECA8-1DD1-11B2-8B63-8DD5A8419765@10.0.2.200 CSeq: 102 BYE From: ;tag=as1d57e467 Server: SJphone/1.60.299a/L (SJ Labs) To: "unknown";tag=406500183754473053 <-------------> [May 16 19:11:59] DEBUG[24568] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [May 16 19:11:59] DEBUG[24568] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.0.2.1:5060;rport=5060;received=10.0.2.1;branch=z9hG4bK60e00368 (82) [May 16 19:11:59] DEBUG[24568] chan_sip.c: Header 2: Content-Length: 0 (17) [May 16 19:11:59] DEBUG[24568] chan_sip.c: Header 3: Call-ID: A568ECA8-1DD1-11B2-8B63-8DD5A8419765@10.0.2.200 (56) [May 16 19:11:59] DEBUG[24568] chan_sip.c: Header 4: CSeq: 102 BYE (13) [May 16 19:11:59] DEBUG[24568] chan_sip.c: Header 5: From: ;tag=as1d57e467 (40) [May 16 19:11:59] DEBUG[24568] chan_sip.c: Header 6: Server: SJphone/1.60.299a/L (SJ Labs) (37) [May 16 19:11:59] DEBUG[24568] chan_sip.c: Header 7: To: "unknown";tag=406500183754473053 (55) [May 16 19:11:59] DEBUG[24568] chan_sip.c: Header 8: (0) [May 16 19:11:59] VERBOSE[24568] logger.c: --- (8 headers 0 lines) --- [May 16 19:11:59] DEBUG[24568] chan_sip.c: = No match Their Call ID: 6a531d5f689c5e7d26d16dc514181316@10.0.2.1 Their Tag 712c400c8778bff1i0 Our tag: as78bc2e30 [May 16 19:11:59] DEBUG[24568] chan_sip.c: = Found Their Call ID: A568ECA8-1DD1-11B2-8B63-8DD5A8419765@10.0.2.200 Their Tag 406500183754473053 Our tag: as1d57e467 [May 16 19:11:59] DEBUG[24568] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #185 [May 16 19:11:59] DEBUG[24568] chan_sip.c: Stopping retransmission on 'A568ECA8-1DD1-11B2-8B63-8DD5A8419765@10.0.2.200' of Request 102: Match Found [May 16 19:11:59] VERBOSE[24568] logger.c: SIP Response message for INCOMING dialog BYE arrived [May 16 19:11:59] VERBOSE[24568] logger.c: Really destroying SIP dialog '6a531d5f689c5e7d26d16dc514181316@10.0.2.1' Method: BYE [May 16 19:11:59] VERBOSE[24568] logger.c: Really destroying SIP dialog 'A568ECA8-1DD1-11B2-8B63-8DD5A8419765@10.0.2.200' Method: ACK [May 16 19:12:00] DEBUG[24559] devicestate.c: Changing state for SIP/1101-0955e720 - state 4 (Invalid) [May 16 19:12:00] DEBUG[24567] app_queue.c: Device 'SIP/1101-0955e720' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [May 16 19:12:00] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for SIP - 1101 [May 16 19:12:00] DEBUG[24559] chan_sip.c: Checking device state for peer 1101 [May 16 19:12:00] DEBUG[24559] devicestate.c: Changing state for SIP/1101 - state 1 (Not in use) [May 16 19:12:00] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for sip - 1101 [May 16 19:12:00] DEBUG[24567] app_queue.c: Device 'SIP/1101' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 16 19:12:00] DEBUG[24559] chan_sip.c: Checking device state for peer 1101 [May 16 19:12:00] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for sip - 1101 [May 16 19:12:00] DEBUG[24559] chan_sip.c: Checking device state for peer 1101 [May 16 19:12:00] VERBOSE[24559] logger.c: Reliably Transmitting (no NAT) to 10.0.2.100:5060: NOTIFY sip:1100@10.0.2.100:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK2e258e5c;rport From: ;tag=as32fbb72a To: ;tag=1638a1388001aff0 Contact: Call-ID: 141eb56d33fcec24@10.0.2.100 CSeq: 113 NOTIFY User-Agent: Asterisk PBX Max-Forwards: 70 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 202 terminated --- [May 16 19:12:00] DEBUG[24559] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [May 16 19:12:00] VERBOSE[24559] logger.c: Extension Changed 1101[local-ext] new state Idle for Notify User 1100 [May 16 19:12:00] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for SIP - 1101 [May 16 19:12:00] DEBUG[24559] chan_sip.c: Checking device state for peer 1101 [May 16 19:12:00] DEBUG[24559] devicestate.c: Changing state for SIP/1101 - state 1 (Not in use) [May 16 19:12:00] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for sip - 1101 [May 16 19:12:00] DEBUG[24567] app_queue.c: Device 'SIP/1101' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 16 19:12:00] DEBUG[24559] chan_sip.c: Checking device state for peer 1101 [May 16 19:12:00] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for SIP - 1101-0955e720 [May 16 19:12:00] DEBUG[24559] chan_sip.c: Checking device state for peer 1101-0955e720 [May 16 19:12:00] VERBOSE[24568] logger.c: <--- SIP read from 10.0.2.100:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK2e258e5c;rport From: ;tag=as32fbb72a To: ;tag=1638a1388001aff0 Call-ID: 141eb56d33fcec24@10.0.2.100 CSeq: 113 NOTIFY User-Agent: Grandstream GXP2000 1.1.6.16 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE Supported: replaces, timer Content-Length: 0 <-------------> [May 16 19:12:00] DEBUG[24568] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [May 16 19:12:00] DEBUG[24568] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK2e258e5c;rport (59) [May 16 19:12:00] DEBUG[24568] chan_sip.c: Header 2: From: ;tag=as32fbb72a (40) [May 16 19:12:00] DEBUG[24568] chan_sip.c: Header 3: To: ;tag=1638a1388001aff0 (44) [May 16 19:12:00] DEBUG[24568] chan_sip.c: Header 4: Call-ID: 141eb56d33fcec24@10.0.2.100 (36) [May 16 19:12:00] DEBUG[24568] chan_sip.c: Header 5: CSeq: 113 NOTIFY (16) [May 16 19:12:00] DEBUG[24568] chan_sip.c: Header 6: User-Agent: Grandstream GXP2000 1.1.6.16 (40) [May 16 19:12:00] DEBUG[24568] chan_sip.c: Header 7: Contact: (49) [May 16 19:12:00] DEBUG[24568] chan_sip.c: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE (85) [May 16 19:12:00] DEBUG[24568] chan_sip.c: Header 9: Supported: replaces, timer (26) [May 16 19:12:00] DEBUG[24568] chan_sip.c: Header 10: Content-Length: 0 (17) [May 16 19:12:00] DEBUG[24568] chan_sip.c: Header 11: (0) [May 16 19:12:00] VERBOSE[24568] logger.c: --- (11 headers 0 lines) --- [May 16 19:12:00] DEBUG[24568] chan_sip.c: = No match Their Call ID: 878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 Their Tag 40649517241994678566 Our tag: as3fd6d731 [May 16 19:12:00] DEBUG[24568] chan_sip.c: = No match Their Call ID: 1e4646cfc7864472@10.0.2.100 Their Tag 005f704e3382ec0d Our tag: as7f4a604b [May 16 19:12:00] DEBUG[24568] chan_sip.c: = No match Their Call ID: cc428c423a89561b@10.0.2.100 Their Tag f9fa6174823b0f17 Our tag: as710aa077 [May 16 19:12:00] DEBUG[24568] chan_sip.c: = No match Their Call ID: 1b5b73ee29545b2a@10.0.2.100 Their Tag 2896e796b5dd916f Our tag: as35d63675 [May 16 19:12:00] DEBUG[24568] chan_sip.c: = No match Their Call ID: 604f9802ea0208a4@10.0.2.100 Their Tag 975f7a4f874cd22e Our tag: as6c949944 [May 16 19:12:00] DEBUG[24568] chan_sip.c: = No match Their Call ID: d5642264023de13d@10.0.2.100 Their Tag 8eb257850a85e728 Our tag: as3780e971 [May 16 19:12:00] DEBUG[24568] chan_sip.c: = Found Their Call ID: 141eb56d33fcec24@10.0.2.100 Their Tag 1638a1388001aff0 Our tag: as32fbb72a [May 16 19:12:00] DEBUG[24568] chan_sip.c: Acked pending invite 113 [May 16 19:12:00] DEBUG[24568] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #186 [May 16 19:12:00] DEBUG[24568] chan_sip.c: Stopping retransmission on '141eb56d33fcec24@10.0.2.100' of Request 113: Match Found [May 16 19:12:00] VERBOSE[24568] logger.c: SIP Response message for INCOMING dialog NOTIFY arrived [May 16 19:12:01] VERBOSE[24557] logger.c: -- Remote UNIX connection [May 16 19:12:02] VERBOSE[29127] logger.c: -- Remote UNIX connection disconnected [May 16 19:12:10] DEBUG[24559] devicestate.c: Changing state for SIP/1101-0955e720 - state 4 (Invalid) [May 16 19:12:10] DEBUG[24567] app_queue.c: Device 'SIP/1101-0955e720' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [May 16 19:12:10] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for SIP - 1101 [May 16 19:12:10] DEBUG[24559] chan_sip.c: Checking device state for peer 1101 [May 16 19:12:10] DEBUG[24559] devicestate.c: Changing state for SIP/1101 - state 1 (Not in use) [May 16 19:12:10] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for sip - 1101 [May 16 19:12:10] DEBUG[24567] app_queue.c: Device 'SIP/1101' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 16 19:12:10] DEBUG[24559] chan_sip.c: Checking device state for peer 1101 [May 16 19:12:10] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for SIP - 1102-09551818 [May 16 19:12:10] DEBUG[24559] chan_sip.c: Checking device state for peer 1102-09551818 [May 16 19:12:17] VERBOSE[24568] logger.c: <--- SIP read from 10.0.2.200:5060 ---> OPTIONS sip:10.0.2.1 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.200;rport;branch=z9hG4bK0a0002c800000010482da4cd17eca30d00000025 Content-Length: 0 Call-ID: 878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 CSeq: 6 OPTIONS From: ;tag=4065051734839900370 Max-Forwards: 70 To: <-------------> [May 16 19:12:17] DEBUG[24568] chan_sip.c: Header 0: OPTIONS sip:10.0.2.1 SIP/2.0 (28) [May 16 19:12:17] DEBUG[24568] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.0.2.200;rport;branch=z9hG4bK0a0002c800000010482da4cd17eca30d00000025 (88) [May 16 19:12:17] DEBUG[24568] chan_sip.c: Header 2: Content-Length: 0 (17) [May 16 19:12:17] DEBUG[24568] chan_sip.c: Header 3: Call-ID: 878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 (56) [May 16 19:12:17] DEBUG[24568] chan_sip.c: Header 4: CSeq: 6 OPTIONS (15) [May 16 19:12:17] DEBUG[24568] chan_sip.c: Header 5: From: ;tag=4065051734839900370 (49) [May 16 19:12:17] DEBUG[24568] chan_sip.c: Header 6: Max-Forwards: 70 (16) [May 16 19:12:17] DEBUG[24568] chan_sip.c: Header 7: To: (18) [May 16 19:12:17] DEBUG[24568] chan_sip.c: Header 8: (0) [May 16 19:12:17] VERBOSE[24568] logger.c: --- (8 headers 0 lines) --- [May 16 19:12:17] DEBUG[24568] chan_sip.c: = Found Their Call ID: 878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 Their Tag 40649517241994678566 Our tag: as3fd6d731 [May 16 19:12:17] DEBUG[24568] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [May 16 19:12:17] VERBOSE[24568] logger.c: Looking for s in inbound (domain 10.0.2.1) [May 16 19:12:17] VERBOSE[24568] logger.c: <--- Transmitting (no NAT) to 10.0.2.200:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.2.200;branch=z9hG4bK0a0002c800000010482da4cd17eca30d00000025;received=10.0.2.200;rport=5060 From: ;tag=4065051734839900370 To: ;tag=as3fd6d731 Call-ID: 878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 CSeq: 6 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> [May 16 19:12:17] VERBOSE[24568] logger.c: Scheduling destruction of SIP dialog '878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200' in 32000 ms (Method: OPTIONS) [May 16 19:12:18] VERBOSE[24568] logger.c: <--- SIP read from 10.0.2.200:5060 ---> REGISTER sip:10.0.2.1 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.200;rport;branch=z9hG4bK0a0002c800000010482da4ce18020b5e00000027 Content-Length: 0 Contact: Call-ID: 7C2EAA62-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 CSeq: 3 REGISTER From: ;tag=40650526951747262876 Max-Forwards: 70 To: User-Agent: SJphone/1.60.299a/L (SJ Labs) <-------------> [May 16 19:12:18] DEBUG[24568] chan_sip.c: Header 0: REGISTER sip:10.0.2.1 SIP/2.0 (29) [May 16 19:12:18] DEBUG[24568] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.0.2.200;rport;branch=z9hG4bK0a0002c800000010482da4ce18020b5e00000027 (88) [May 16 19:12:18] DEBUG[24568] chan_sip.c: Header 2: Content-Length: 0 (17) [May 16 19:12:18] DEBUG[24568] chan_sip.c: Header 3: Contact: (35) [May 16 19:12:18] DEBUG[24568] chan_sip.c: Header 4: Call-ID: 7C2EAA62-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 (56) [May 16 19:12:18] DEBUG[24568] chan_sip.c: Header 5: CSeq: 3 REGISTER (16) [May 16 19:12:18] DEBUG[24568] chan_sip.c: Header 6: From: ;tag=40650526951747262876 (50) [May 16 19:12:18] DEBUG[24568] chan_sip.c: Header 7: Max-Forwards: 70 (16) [May 16 19:12:18] DEBUG[24568] chan_sip.c: Header 8: To: (23) [May 16 19:12:18] DEBUG[24568] chan_sip.c: Header 9: User-Agent: SJphone/1.60.299a/L (SJ Labs) (41) [May 16 19:12:18] DEBUG[24568] chan_sip.c: Header 10: (0) [May 16 19:12:18] VERBOSE[24568] logger.c: --- (10 headers 0 lines) --- [May 16 19:12:18] DEBUG[24568] chan_sip.c: = No match Their Call ID: 878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 Their Tag 40649517241994678566 Our tag: as3fd6d731 [May 16 19:12:18] DEBUG[24568] chan_sip.c: = No match Their Call ID: 1e4646cfc7864472@10.0.2.100 Their Tag 005f704e3382ec0d Our tag: as7f4a604b [May 16 19:12:18] DEBUG[24568] chan_sip.c: = No match Their Call ID: cc428c423a89561b@10.0.2.100 Their Tag f9fa6174823b0f17 Our tag: as710aa077 [May 16 19:12:18] DEBUG[24568] chan_sip.c: = No match Their Call ID: 1b5b73ee29545b2a@10.0.2.100 Their Tag 2896e796b5dd916f Our tag: as35d63675 [May 16 19:12:18] DEBUG[24568] chan_sip.c: = No match Their Call ID: 604f9802ea0208a4@10.0.2.100 Their Tag 975f7a4f874cd22e Our tag: as6c949944 [May 16 19:12:18] DEBUG[24568] chan_sip.c: = No match Their Call ID: d5642264023de13d@10.0.2.100 Their Tag 8eb257850a85e728 Our tag: as3780e971 [May 16 19:12:18] DEBUG[24568] chan_sip.c: = No match Their Call ID: 141eb56d33fcec24@10.0.2.100 Their Tag 1638a1388001aff0 Our tag: as32fbb72a [May 16 19:12:18] DEBUG[24568] chan_sip.c: Allocating new SIP dialog for 7C2EAA62-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 - REGISTER (No RTP) [May 16 19:12:18] DEBUG[24568] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [May 16 19:12:18] VERBOSE[24568] logger.c: Using latest REGISTER request as basis request [May 16 19:12:18] VERBOSE[24568] logger.c: Sending to 10.0.2.200 : 5060 (NAT) [May 16 19:12:18] VERBOSE[24568] logger.c: <--- Transmitting (no NAT) to 10.0.2.200:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.0.2.200;branch=z9hG4bK0a0002c800000010482da4ce18020b5e00000027;received=10.0.2.200;rport=5060 From: ;tag=40650526951747262876 To: Call-ID: 7C2EAA62-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 CSeq: 3 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [May 16 19:12:18] VERBOSE[24568] logger.c: <--- Transmitting (no NAT) to 10.0.2.200:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.0.2.200;branch=z9hG4bK0a0002c800000010482da4ce18020b5e00000027;received=10.0.2.200;rport=5060 From: ;tag=40650526951747262876 To: ;tag=as62c277aa Call-ID: 7C2EAA62-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 CSeq: 3 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="496887d7" Content-Length: 0 <------------> [May 16 19:12:18] VERBOSE[24568] logger.c: Scheduling destruction of SIP dialog '7C2EAA62-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200' in 32000 ms (Method: REGISTER) [May 16 19:12:18] VERBOSE[24568] logger.c: <--- SIP read from 10.0.2.200:5060 ---> REGISTER sip:10.0.2.1 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.200;rport;branch=z9hG4bK0a0002c800000010482da4ce30323a380000002a Content-Length: 0 Contact: Call-ID: 7C2EAA62-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 CSeq: 4 REGISTER From: ;tag=40650527011316603604 Max-Forwards: 70 To: User-Agent: SJphone/1.60.299a/L (SJ Labs) Authorization: Digest username="1102",realm="asterisk",nonce="496887d7",uri="sip:10.0.2.1",response="3a0f50d8e449433c39018176fea147ad",algorithm="MD5" <-------------> [May 16 19:12:18] DEBUG[24568] chan_sip.c: Header 0: REGISTER sip:10.0.2.1 SIP/2.0 (29) [May 16 19:12:18] DEBUG[24568] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.0.2.200;rport;branch=z9hG4bK0a0002c800000010482da4ce30323a380000002a (88) [May 16 19:12:18] DEBUG[24568] chan_sip.c: Header 2: Content-Length: 0 (17) [May 16 19:12:18] DEBUG[24568] chan_sip.c: Header 3: Contact: (35) [May 16 19:12:18] DEBUG[24568] chan_sip.c: Header 4: Call-ID: 7C2EAA62-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 (56) [May 16 19:12:18] DEBUG[24568] chan_sip.c: Header 5: CSeq: 4 REGISTER (16) [May 16 19:12:18] DEBUG[24568] chan_sip.c: Header 6: From: ;tag=40650527011316603604 (50) [May 16 19:12:18] DEBUG[24568] chan_sip.c: Header 7: Max-Forwards: 70 (16) [May 16 19:12:18] DEBUG[24568] chan_sip.c: Header 8: To: (23) [May 16 19:12:18] DEBUG[24568] chan_sip.c: Header 9: User-Agent: SJphone/1.60.299a/L (SJ Labs) (41) [May 16 19:12:18] DEBUG[24568] chan_sip.c: Header 10: Authorization: Digest username="1102",realm="asterisk",nonce="496887d7",uri="sip:10.0.2.1",response="3a0f50d8e449433c39018176fea147ad",algorithm="MD5" (150) [May 16 19:12:18] DEBUG[24568] chan_sip.c: Header 11: (0) [May 16 19:12:18] VERBOSE[24568] logger.c: --- (11 headers 0 lines) --- [May 16 19:12:18] DEBUG[24568] chan_sip.c: = Found Their Call ID: 7C2EAA62-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 Their Tag 40650526951747262876 Our tag: as62c277aa [May 16 19:12:18] DEBUG[24568] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [May 16 19:12:18] VERBOSE[24568] logger.c: Using latest REGISTER request as basis request [May 16 19:12:18] VERBOSE[24568] logger.c: Sending to 10.0.2.200 : 5060 (NAT) [May 16 19:12:18] VERBOSE[24568] logger.c: <--- Transmitting (no NAT) to 10.0.2.200:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.0.2.200;branch=z9hG4bK0a0002c800000010482da4ce30323a380000002a;received=10.0.2.200;rport=5060 From: ;tag=40650527011316603604 To: Call-ID: 7C2EAA62-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 CSeq: 4 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [May 16 19:12:18] VERBOSE[24568] logger.c: <--- Transmitting (no NAT) to 10.0.2.200:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.2.200;branch=z9hG4bK0a0002c800000010482da4ce30323a380000002a;received=10.0.2.200;rport=5060 From: ;tag=40650527011316603604 To: ;tag=as62c277aa Call-ID: 7C2EAA62-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 CSeq: 4 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Expires: 120 Contact: ;expires=120 Date: Fri, 16 May 2008 15:12:18 GMT Content-Length: 0 <------------> [May 16 19:12:18] DEBUG[24568] devicestate.c: Notification of state change to be queued on device/channel SIP/1102 [May 16 19:12:18] VERBOSE[24568] logger.c: Scheduling destruction of SIP dialog '7C2EAA62-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200' in 32000 ms (Method: REGISTER) [May 16 19:12:20] DEBUG[24559] devicestate.c: Changing state for SIP/1102-09551818 - state 4 (Invalid) [May 16 19:12:20] DEBUG[24567] app_queue.c: Device 'SIP/1102-09551818' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [May 16 19:12:20] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for SIP - 1102 [May 16 19:12:20] DEBUG[24559] chan_sip.c: Checking device state for peer 1102 [May 16 19:12:20] DEBUG[24559] devicestate.c: Changing state for SIP/1102 - state 1 (Not in use) [May 16 19:12:20] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for sip - 1102 [May 16 19:12:20] DEBUG[24567] app_queue.c: Device 'SIP/1102' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 16 19:12:20] DEBUG[24559] chan_sip.c: Checking device state for peer 1102 [May 16 19:12:20] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for sip - 1102 [May 16 19:12:20] DEBUG[24559] chan_sip.c: Checking device state for peer 1102 [May 16 19:12:20] VERBOSE[24559] logger.c: Reliably Transmitting (no NAT) to 10.0.2.100:5060: NOTIFY sip:1100@10.0.2.100:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK5a36c2f6;rport From: ;tag=as3780e971 To: ;tag=8eb257850a85e728 Contact: Call-ID: d5642264023de13d@10.0.2.100 CSeq: 108 NOTIFY User-Agent: Asterisk PBX Max-Forwards: 70 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 201 terminated --- [May 16 19:12:20] DEBUG[24559] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [May 16 19:12:20] VERBOSE[24559] logger.c: Extension Changed 1102[local-ext] new state Idle for Notify User 1100 [May 16 19:12:20] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for SIP - 1101 [May 16 19:12:20] DEBUG[24559] chan_sip.c: Checking device state for peer 1101 [May 16 19:12:20] DEBUG[24559] devicestate.c: Changing state for SIP/1101 - state 1 (Not in use) [May 16 19:12:20] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for sip - 1101 [May 16 19:12:20] DEBUG[24567] app_queue.c: Device 'SIP/1101' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 16 19:12:20] DEBUG[24559] chan_sip.c: Checking device state for peer 1101 [May 16 19:12:20] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for SIP - 1101-0955e720 [May 16 19:12:20] DEBUG[24559] chan_sip.c: Checking device state for peer 1101-0955e720 [May 16 19:12:20] VERBOSE[24568] logger.c: <--- SIP read from 10.0.2.100:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK5a36c2f6;rport From: ;tag=as3780e971 To: ;tag=8eb257850a85e728 Call-ID: d5642264023de13d@10.0.2.100 CSeq: 108 NOTIFY User-Agent: Grandstream GXP2000 1.1.6.16 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE Supported: replaces, timer Content-Length: 0 <-------------> [May 16 19:12:20] DEBUG[24568] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [May 16 19:12:20] DEBUG[24568] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.0.2.1:5060;branch=z9hG4bK5a36c2f6;rport (59) [May 16 19:12:20] DEBUG[24568] chan_sip.c: Header 2: From: ;tag=as3780e971 (40) [May 16 19:12:20] DEBUG[24568] chan_sip.c: Header 3: To: ;tag=8eb257850a85e728 (44) [May 16 19:12:20] DEBUG[24568] chan_sip.c: Header 4: Call-ID: d5642264023de13d@10.0.2.100 (36) [May 16 19:12:20] DEBUG[24568] chan_sip.c: Header 5: CSeq: 108 NOTIFY (16) [May 16 19:12:20] DEBUG[24568] chan_sip.c: Header 6: User-Agent: Grandstream GXP2000 1.1.6.16 (40) [May 16 19:12:20] DEBUG[24568] chan_sip.c: Header 7: Contact: (49) [May 16 19:12:20] DEBUG[24568] chan_sip.c: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK,MESSAGE (85) [May 16 19:12:20] DEBUG[24568] chan_sip.c: Header 9: Supported: replaces, timer (26) [May 16 19:12:20] DEBUG[24568] chan_sip.c: Header 10: Content-Length: 0 (17) [May 16 19:12:20] DEBUG[24568] chan_sip.c: Header 11: (0) [May 16 19:12:20] VERBOSE[24568] logger.c: --- (11 headers 0 lines) --- [May 16 19:12:20] DEBUG[24568] chan_sip.c: = No match Their Call ID: 7C2EAA62-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 Their Tag 40650526951747262876 Our tag: as62c277aa [May 16 19:12:20] DEBUG[24568] chan_sip.c: = No match Their Call ID: 878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 Their Tag 40649517241994678566 Our tag: as3fd6d731 [May 16 19:12:20] DEBUG[24568] chan_sip.c: = No match Their Call ID: 1e4646cfc7864472@10.0.2.100 Their Tag 005f704e3382ec0d Our tag: as7f4a604b [May 16 19:12:20] DEBUG[24568] chan_sip.c: = No match Their Call ID: cc428c423a89561b@10.0.2.100 Their Tag f9fa6174823b0f17 Our tag: as710aa077 [May 16 19:12:20] DEBUG[24568] chan_sip.c: = No match Their Call ID: 1b5b73ee29545b2a@10.0.2.100 Their Tag 2896e796b5dd916f Our tag: as35d63675 [May 16 19:12:20] DEBUG[24568] chan_sip.c: = No match Their Call ID: 604f9802ea0208a4@10.0.2.100 Their Tag 975f7a4f874cd22e Our tag: as6c949944 [May 16 19:12:20] DEBUG[24568] chan_sip.c: = Found Their Call ID: d5642264023de13d@10.0.2.100 Their Tag 8eb257850a85e728 Our tag: as3780e971 [May 16 19:12:20] DEBUG[24568] chan_sip.c: Acked pending invite 108 [May 16 19:12:20] DEBUG[24568] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #191 [May 16 19:12:20] DEBUG[24568] chan_sip.c: Stopping retransmission on 'd5642264023de13d@10.0.2.100' of Request 108: Match Found [May 16 19:12:20] VERBOSE[24568] logger.c: SIP Response message for INCOMING dialog NOTIFY arrived [May 16 19:12:30] DEBUG[24559] devicestate.c: Changing state for SIP/1101-0955e720 - state 4 (Invalid) [May 16 19:12:30] DEBUG[24567] app_queue.c: Device 'SIP/1101-0955e720' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [May 16 19:12:30] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for SIP - 1101 [May 16 19:12:30] DEBUG[24559] chan_sip.c: Checking device state for peer 1101 [May 16 19:12:30] DEBUG[24559] devicestate.c: Changing state for SIP/1101 - state 1 (Not in use) [May 16 19:12:30] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for sip - 1101 [May 16 19:12:30] DEBUG[24567] app_queue.c: Device 'SIP/1101' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 16 19:12:30] DEBUG[24559] chan_sip.c: Checking device state for peer 1101 [May 16 19:12:30] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for SIP - 1102 [May 16 19:12:30] DEBUG[24559] chan_sip.c: Checking device state for peer 1102 [May 16 19:12:30] DEBUG[24559] devicestate.c: Changing state for SIP/1102 - state 1 (Not in use) [May 16 19:12:30] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for sip - 1102 [May 16 19:12:30] DEBUG[24567] app_queue.c: Device 'SIP/1102' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 16 19:12:30] DEBUG[24559] chan_sip.c: Checking device state for peer 1102 [May 16 19:12:30] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for SIP - 1102-09551818 [May 16 19:12:30] DEBUG[24559] chan_sip.c: Checking device state for peer 1102-09551818 [May 16 19:12:37] VERBOSE[24568] logger.c: <--- SIP read from 10.0.2.200:5060 ---> OPTIONS sip:10.0.2.1 SIP/2.0 Via: SIP/2.0/UDP 10.0.2.200;rport;branch=z9hG4bK0a0002c800000010482da4e16f36f26d0000002d Content-Length: 0 Call-ID: 878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 CSeq: 7 OPTIONS From: ;tag=4065071735997222777 Max-Forwards: 70 To: <-------------> [May 16 19:12:37] DEBUG[24568] chan_sip.c: Header 0: OPTIONS sip:10.0.2.1 SIP/2.0 (28) [May 16 19:12:37] DEBUG[24568] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.0.2.200;rport;branch=z9hG4bK0a0002c800000010482da4e16f36f26d0000002d (88) [May 16 19:12:37] DEBUG[24568] chan_sip.c: Header 2: Content-Length: 0 (17) [May 16 19:12:37] DEBUG[24568] chan_sip.c: Header 3: Call-ID: 878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 (56) [May 16 19:12:37] DEBUG[24568] chan_sip.c: Header 4: CSeq: 7 OPTIONS (15) [May 16 19:12:37] DEBUG[24568] chan_sip.c: Header 5: From: ;tag=4065071735997222777 (49) [May 16 19:12:37] DEBUG[24568] chan_sip.c: Header 6: Max-Forwards: 70 (16) [May 16 19:12:37] DEBUG[24568] chan_sip.c: Header 7: To: (18) [May 16 19:12:37] DEBUG[24568] chan_sip.c: Header 8: (0) [May 16 19:12:37] VERBOSE[24568] logger.c: --- (8 headers 0 lines) --- [May 16 19:12:37] DEBUG[24568] chan_sip.c: = No match Their Call ID: 7C2EAA62-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 Their Tag 40650526951747262876 Our tag: as62c277aa [May 16 19:12:37] DEBUG[24568] chan_sip.c: = Found Their Call ID: 878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 Their Tag 40649517241994678566 Our tag: as3fd6d731 [May 16 19:12:37] DEBUG[24568] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [May 16 19:12:37] VERBOSE[24568] logger.c: Looking for s in inbound (domain 10.0.2.1) [May 16 19:12:37] VERBOSE[24568] logger.c: <--- Transmitting (no NAT) to 10.0.2.200:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.2.200;branch=z9hG4bK0a0002c800000010482da4e16f36f26d0000002d;received=10.0.2.200;rport=5060 From: ;tag=4065071735997222777 To: ;tag=as3fd6d731 Call-ID: 878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200 CSeq: 7 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> [May 16 19:12:37] VERBOSE[24568] logger.c: Scheduling destruction of SIP dialog '878A71F2-1DD2-11B2-8B62-8DD5A8419765@10.0.2.200' in 32000 ms (Method: OPTIONS) [May 16 19:12:40] DEBUG[24559] devicestate.c: Changing state for SIP/1102-09551818 - state 4 (Invalid) [May 16 19:12:40] DEBUG[24567] app_queue.c: Device 'SIP/1102-09551818' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [May 16 19:12:40] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for SIP - 1102 [May 16 19:12:40] DEBUG[24559] chan_sip.c: Checking device state for peer 1102 [May 16 19:12:40] DEBUG[24559] devicestate.c: Changing state for SIP/1102 - state 1 (Not in use) [May 16 19:12:40] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for sip - 1102 [May 16 19:12:40] DEBUG[24567] app_queue.c: Device 'SIP/1102' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 16 19:12:40] DEBUG[24559] chan_sip.c: Checking device state for peer 1102 [May 16 19:12:40] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for SIP - 1102 [May 16 19:12:40] DEBUG[24559] chan_sip.c: Checking device state for peer 1102 [May 16 19:12:40] DEBUG[24559] devicestate.c: Changing state for SIP/1102 - state 1 (Not in use) [May 16 19:12:40] DEBUG[24559] devicestate.c: No provider found, checking channel drivers for sip - 1102 [May 16 19:12:40] DEBUG[24567] app_queue.c: Device 'SIP/1102' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 16 19:12:40] DEBUG[24559] chan_sip.c: Checking device state for peer 1102 [May 16 19:12:42] VERBOSE[29035] logger.c: -- Remote UNIX connection disconnected [May 16 19:12:46] VERBOSE[24587] logger.c: Beginning asterisk shutdown.... [May 16 19:12:46] VERBOSE[24587] logger.c: Executing last minute cleanups [May 16 19:12:46] VERBOSE[24587] logger.c: == Destroying musiconhold processes [May 16 19:12:46] VERBOSE[24587] logger.c: Asterisk cleanly ending (0). [May 16 19:12:46] DEBUG[24587] asterisk.c: Asterisk ending (0).