[Mar 28 18:42:59] [1;37;40mAsterisk Ready.
[0;37;40m]1;Asterisk]2;Asterisk Console on 'PowerKey.norcast.net' (pid 12354)*CLI> [Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m7293[0;37;40m [1;37;40mtransmit_register[0;37;40m: Scheduled a registration timeout for 10.50.10.2 id  #31 
[Mar 28 18:42:59] REGISTER attempt 1 to 8055480017@10.50.10.2
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4361[0;37;40m [1;37;40mfind_call[0;37;40m: = No match Their Call ID: 62164ccd5e4ddf75411fa4752fd2b36b@127.0.0.1 Their Tag  Our tag: as4577da54
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4361[0;37;40m [1;37;40mfind_call[0;37;40m: = Found Their Call ID: 7e86bd7270965961312c052b4182057c@10.50.10.171 Their Tag  Our tag: as50e6beba
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2089[0;37;40m [1;37;40m__sip_ack[0;37;40m: Stopping retransmission on '7e86bd7270965961312c052b4182057c@10.50.10.171' of Request 102: Match Not Found
[Mar 28 18:42:59] [1;33;40mNOTICE[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m12140[0;37;40m [1;37;40mhandle_response_peerpoke[0;37;40m: Peer '8055488091' is now Reachable. (20ms / 900ms)
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m303[0;37;40m [1;37;40m__ast_device_state_changed_literal[0;37;40m: Notification of state change to be queued on device/channel SIP/8055488091
[Mar 28 18:42:59] Really destroying SIP dialog '7e86bd7270965961312c052b4182057c@10.50.10.171' Method: OPTIONS
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4361[0;37;40m [1;37;40mfind_call[0;37;40m: = No match Their Call ID: 62164ccd5e4ddf75411fa4752fd2b36b@127.0.0.1 Their Tag  Our tag: as4577da54
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4361[0;37;40m [1;37;40mfind_call[0;37;40m: = Found Their Call ID: 57cb99d94c374e8f5851b7291dd03ad0@127.0.0.1 Their Tag  Our tag: as64c78684
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2089[0;37;40m [1;37;40m__sip_ack[0;37;40m: Stopping retransmission on '57cb99d94c374e8f5851b7291dd03ad0@127.0.0.1' of Request 103: Match Not Found
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m12045[0;37;40m [1;37;40mhandle_response_register[0;37;40m: Registration successful
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m12048[0;37;40m [1;37;40mhandle_response_register[0;37;40m: Cancelling timeout 26
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12358]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m161[0;37;40m [1;37;40mast_device_state[0;37;40m: No provider found, checking channel drivers for SIP - 8055488091
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4361[0;37;40m [1;37;40mfind_call[0;37;40m: = Found Their Call ID: 62164ccd5e4ddf75411fa4752fd2b36b@127.0.0.1 Their Tag  Our tag: as4577da54
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2089[0;37;40m [1;37;40m__sip_ack[0;37;40m: Stopping retransmission on '62164ccd5e4ddf75411fa4752fd2b36b@127.0.0.1' of Request 102: Match Not Found
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m1621[0;37;40m [1;37;40minitialize_initreq[0;37;40m: Initializing already initialized SIP dialog 62164ccd5e4ddf75411fa4752fd2b36b@127.0.0.1 (presumably reinvite)
[Mar 28 18:42:59] REGISTER attempt 2 to 8055480017@10.50.10.2
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4361[0;37;40m [1;37;40mfind_call[0;37;40m: = Found Their Call ID: 62164ccd5e4ddf75411fa4752fd2b36b@127.0.0.1 Their Tag  Our tag: as6db23702
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2089[0;37;40m [1;37;40m__sip_ack[0;37;40m: Stopping retransmission on '62164ccd5e4ddf75411fa4752fd2b36b@127.0.0.1' of Request 103: Match Not Found
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m12045[0;37;40m [1;37;40mhandle_response_register[0;37;40m: Registration successful
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m12048[0;37;40m [1;37;40mhandle_response_register[0;37;40m: Cancelling timeout 31
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12358]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m15244[0;37;40m [1;37;40msip_devicestate[0;37;40m: Checking device state for peer 8055488091
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12358]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m287[0;37;40m [1;37;40mdo_state_change[0;37;40m: Changing state for SIP/8055488091 - state 1 (Not in use)
*CLI> [Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12384]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m546[0;37;40m [1;37;40mchangethread[0;37;40m: Device 'SIP/8055488091' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4310[0;37;40m [1;37;40msip_alloc[0;37;40m: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4310[0;37;40m [1;37;40msip_alloc[0;37;40m: Allocating new SIP dialog for 7154d98a372984eb25f32b5f71c62a43@127.0.0.1 - REGISTER (No RTP)
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m7293[0;37;40m [1;37;40mtransmit_register[0;37;40m: Scheduled a registration timeout for 10.50.10.2 id  #41 
[Mar 28 18:42:59] REGISTER attempt 1 to 8055488091@10.50.10.2
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4361[0;37;40m [1;37;40mfind_call[0;37;40m: = No match Their Call ID: 7154d98a372984eb25f32b5f71c62a43@127.0.0.1 Their Tag  Our tag: as14ee3740
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4361[0;37;40m [1;37;40mfind_call[0;37;40m: = Found Their Call ID: 2c9bf22f1ee79ecd77269a5c0e8f5b94@10.50.10.171 Their Tag  Our tag: as0af69859
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2089[0;37;40m [1;37;40m__sip_ack[0;37;40m: Stopping retransmission on '2c9bf22f1ee79ecd77269a5c0e8f5b94@10.50.10.171' of Request 102: Match Not Found
[Mar 28 18:42:59] [1;33;40mNOTICE[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m12140[0;37;40m [1;37;40mhandle_response_peerpoke[0;37;40m: Peer 'metaswitch0002' is now Reachable. (7ms / 900ms)
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m303[0;37;40m [1;37;40m__ast_device_state_changed_literal[0;37;40m: Notification of state change to be queued on device/channel SIP/metaswitch0002
[Mar 28 18:42:59] Really destroying SIP dialog '2c9bf22f1ee79ecd77269a5c0e8f5b94@10.50.10.171' Method: OPTIONS
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4361[0;37;40m [1;37;40mfind_call[0;37;40m: = Found Their Call ID: 7154d98a372984eb25f32b5f71c62a43@127.0.0.1 Their Tag  Our tag: as14ee3740
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12358]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m161[0;37;40m [1;37;40mast_device_state[0;37;40m: No provider found, checking channel drivers for SIP - metaswitch0002
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12358]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m15244[0;37;40m [1;37;40msip_devicestate[0;37;40m: Checking device state for peer metaswitch0002
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12358]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m287[0;37;40m [1;37;40mdo_state_change[0;37;40m: Changing state for SIP/metaswitch0002 - state 1 (Not in use)
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2089[0;37;40m [1;37;40m__sip_ack[0;37;40m: Stopping retransmission on '7154d98a372984eb25f32b5f71c62a43@127.0.0.1' of Request 102: Match Not Found
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m1621[0;37;40m [1;37;40minitialize_initreq[0;37;40m: Initializing already initialized SIP dialog 7154d98a372984eb25f32b5f71c62a43@127.0.0.1 (presumably reinvite)
[Mar 28 18:42:59] REGISTER attempt 2 to 8055488091@10.50.10.2
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12385]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m546[0;37;40m [1;37;40mchangethread[0;37;40m: Device 'SIP/metaswitch0002' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4361[0;37;40m [1;37;40mfind_call[0;37;40m: = Found Their Call ID: 7154d98a372984eb25f32b5f71c62a43@127.0.0.1 Their Tag  Our tag: as0fad6319
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2089[0;37;40m [1;37;40m__sip_ack[0;37;40m: Stopping retransmission on '7154d98a372984eb25f32b5f71c62a43@127.0.0.1' of Request 103: Match Not Found
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m12045[0;37;40m [1;37;40mhandle_response_register[0;37;40m: Registration successful
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m12048[0;37;40m [1;37;40mhandle_response_register[0;37;40m: Cancelling timeout 41
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4310[0;37;40m [1;37;40msip_alloc[0;37;40m: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4361[0;37;40m [1;37;40mfind_call[0;37;40m: = Found Their Call ID: 7cce9a4035be080a3943f1330f2328a3@10.50.10.171 Their Tag  Our tag: as17d35d8e
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2089[0;37;40m [1;37;40m__sip_ack[0;37;40m: Stopping retransmission on '7cce9a4035be080a3943f1330f2328a3@10.50.10.171' of Request 102: Match Not Found
[Mar 28 18:42:59] [1;33;40mNOTICE[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m12140[0;37;40m [1;37;40mhandle_response_peerpoke[0;37;40m: Peer 'metaswitch0001' is now Reachable. (1ms / 900ms)
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m303[0;37;40m [1;37;40m__ast_device_state_changed_literal[0;37;40m: Notification of state change to be queued on device/channel SIP/metaswitch0001
[Mar 28 18:42:59] Really destroying SIP dialog '7cce9a4035be080a3943f1330f2328a3@10.50.10.171' Method: OPTIONS
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12358]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m161[0;37;40m [1;37;40mast_device_state[0;37;40m: No provider found, checking channel drivers for SIP - metaswitch0001
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12358]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m15244[0;37;40m [1;37;40msip_devicestate[0;37;40m: Checking device state for peer metaswitch0001
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12358]: [1;37;40mdevicestate.c[0;37;40m:[1;37;40m287[0;37;40m [1;37;40mdo_state_change[0;37;40m: Changing state for SIP/metaswitch0001 - state 1 (Not in use)
[Mar 28 18:42:59] [1;32;40mDEBUG[0;37;40m[12386]: [1;37;40mapp_queue.c[0;37;40m:[1;37;40m546[0;37;40m [1;37;40mchangethread[0;37;40m: Device 'SIP/metaswitch0001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Mar 28 18:43:00] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4361[0;37;40m [1;37;40mfind_call[0;37;40m: = No match Their Call ID: 7154d98a372984eb25f32b5f71c62a43@127.0.0.1 Their Tag metaswitch+1+0+7caa670b Our tag: as0fad6319
[Mar 28 18:43:00] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4361[0;37;40m [1;37;40mfind_call[0;37;40m: = No match Their Call ID: 62164ccd5e4ddf75411fa4752fd2b36b@127.0.0.1 Their Tag metaswitch+1+0+5e90fd5d Our tag: as6db23702
[Mar 28 18:43:00] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4361[0;37;40m [1;37;40mfind_call[0;37;40m: = No match Their Call ID: 57cb99d94c374e8f5851b7291dd03ad0@127.0.0.1 Their Tag metaswitch+1+0+1d993600 Our tag: as64c78684
[Mar 28 18:43:00] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4310[0;37;40m [1;37;40msip_alloc[0;37;40m: Allocating new SIP dialog for 9A1CC282@metaswitch - OPTIONS (No RTP)
[Mar 28 18:43:00] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14633[0;37;40m [1;37;40mhandle_request[0;37;40m: **** Received OPTIONS (3) - Command in SIP OPTIONS
[Mar 28 18:43:00] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14850[0;37;40m [1;37;40msipsock_read[0;37;40m: SIP message could not be handled, bad request: 9A1CC282@metaswitch                                                   
core set debug 4
[0;37;40mCore debug was 5 and is now 4
*CLI> core set verbose 4
[0;37;40mVerbosity was 5 and is now 4
*CLI> [Mar 28 18:43:19] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4310[0;37;40m [1;37;40msip_alloc[0;37;40m: Allocating new SIP dialog for 75F572CC@metaswitch - OPTIONS (No RTP)
[Mar 28 18:43:19] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14633[0;37;40m [1;37;40mhandle_request[0;37;40m: **** Received OPTIONS (3) - Command in SIP OPTIONS
[Mar 28 18:43:19] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14850[0;37;40m [1;37;40msipsock_read[0;37;40m: SIP message could not be handled, bad request: 75F572CC@metaswitch                                                   
sip set debug
[0;37;40mSIP Debugging enabled
*CLI> [Mar 28 18:43:30] 
<--- SIP read from 10.50.10.2:5060 --->
INVITE sip:metaswitch0001@10.50.10.171:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 10.50.10.2:5060;rport;branch=z9hG4bK-2a9d6fdcdcf7bdf26f7d6607ddd3dbad-metaswitch-1
Allow-Events: message-summary
Allow-Events: refer
Allow-Events: dialog
Allow-Events: line-seize
Max-Forwards: 70
Call-ID: 96A6D0C7@metaswitch
From: Norcast <sip:8055488000@10.50.10.2:5060;transport=udp>;tag=metaswitch+1+4dd07+8972feeb;isup-oli=00
To: <sip:8055480013@10.50.10.171>
CSeq: 249424786 INVITE
Expires: 180
Organization: 
Supported: 100rel
Content-Length: 164
Content-Type: application/sdp
Contact: Norcast <sip:8055488000@10.50.10.2:5060;transport=udp>;isup-oli=00

v=0
o=- 2606553446 2606553446 IN IP4 10.50.10.13
s=-
c=IN IP4 10.50.10.13
t=0 0
m=audio 32950 RTP/AVP 18 0 101
a=rtpmap:101 telephone-event/8000
a=ptime:20

<------------->
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 0: INVITE sip:metaswitch0001@10.50.10.171:5060;transport=udp SIP/2.0 (65)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 1: Via: SIP/2.0/UDP 10.50.10.2:5060;rport;branch=z9hG4bK-2a9d6fdcdcf7bdf26f7d6607ddd3dbad-metaswitch-1 (99)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 2: Allow-Events: message-summary (29)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 3: Allow-Events: refer (19)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 4: Allow-Events: dialog (20)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 5: Allow-Events: line-seize (24)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 6: Max-Forwards: 70 (16)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 7: Call-ID: 96A6D0C7@metaswitch (28)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 8: From: Norcast <sip:8055488000@10.50.10.2:5060;transport=udp>;tag=metaswitch+1+4dd07+8972feeb;isup-oli=00 (104)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 9: To: <sip:8055480013@10.50.10.171> (33)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 10: CSeq: 249424786 INVITE (22)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 11: Expires: 180 (12)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 12: Organization:  (14)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 13: Supported: 100rel (17)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 14: Content-Length: 164 (19)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 15: Content-Type: application/sdp (29)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 16: Contact: Norcast <sip:8055488000@10.50.10.2:5060;transport=udp>;isup-oli=00 (75)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 17:  (0)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4605[0;37;40m [1;37;40mparse_request[0;37;40m: Line: v=0 (3)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4605[0;37;40m [1;37;40mparse_request[0;37;40m: Line: o=- 2606553446 2606553446 IN IP4 10.50.10.13 (44)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4605[0;37;40m [1;37;40mparse_request[0;37;40m: Line: s=- (3)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4605[0;37;40m [1;37;40mparse_request[0;37;40m: Line: c=IN IP4 10.50.10.13 (20)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4605[0;37;40m [1;37;40mparse_request[0;37;40m: Line: t=0 0 (5)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4605[0;37;40m [1;37;40mparse_request[0;37;40m: Line: m=audio 32950 RTP/AVP 18 0 101 (30)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4605[0;37;40m [1;37;40mparse_request[0;37;40m: Line: a=rtpmap:101 telephone-event/8000 (33)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4605[0;37;40m [1;37;40mparse_request[0;37;40m: Line: a=ptime:20 (10)
[Mar 28 18:43:30] --- (17 headers 8 lines) ---
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2575[0;37;40m [1;37;40mdo_setnat[0;37;40m: Setting NAT on RTP to Off
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4310[0;37;40m [1;37;40msip_alloc[0;37;40m: Allocating new SIP dialog for 96A6D0C7@metaswitch - INVITE (With RTP)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14633[0;37;40m [1;37;40mhandle_request[0;37;40m: **** Received INVITE (5) - Command in SIP INVITE
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m1680[0;37;40m [1;37;40mparse_sip_options[0;37;40m: Begin: parsing SIP "Supported: 100rel"
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m1688[0;37;40m [1;37;40mparse_sip_options[0;37;40m: Found SIP option: -100rel-
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m1694[0;37;40m [1;37;40mparse_sip_options[0;37;40m: Matched SIP option: 100rel
[Mar 28 18:43:30] Sending to 10.50.10.2 : 5060 (NAT)
[Mar 28 18:43:30] Using INVITE request as basis request - 96A6D0C7@metaswitch
[Mar 28 18:43:30] Found peer 'line1'
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2575[0;37;40m [1;37;40mdo_setnat[0;37;40m: Setting NAT on RTP to Off
[Mar 28 18:43:30] 
<--- Reliably Transmitting (no NAT) to 10.50.10.2:5060 --->
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/UDP 10.50.10.2:5060;branch=z9hG4bK-2a9d6fdcdcf7bdf26f7d6607ddd3dbad-metaswitch-1;received=10.50.10.2;rport=5060
From: Norcast <sip:8055488000@10.50.10.2:5060;transport=udp>;tag=metaswitch+1+4dd07+8972feeb;isup-oli=00
To: <sip:8055480013@10.50.10.171>;tag=as553d29dc
Call-ID: 96A6D0C7@metaswitch
CSeq: 249424786 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="4bc64e2e"
Content-Length: 0


<------------>
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m1975[0;37;40m [1;37;40m__sip_reliable_xmit[0;37;40m: *** SIP TIMER: Initalizing retransmit timer on packet: Id  #52
[Mar 28 18:43:30] Scheduling destruction of SIP dialog '96A6D0C7@metaswitch' in 32000 ms (Method: INVITE)
[Mar 28 18:43:30] 
<--- SIP read from 10.50.10.2:5060 --->
ACK sip:metaswitch0001@10.50.10.171:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 10.50.10.2:5060;rport;branch=z9hG4bK-2a9d6fdcdcf7bdf26f7d6607ddd3dbad-metaswitch-1
Allow-Events: message-summary
Allow-Events: refer
Allow-Events: dialog
Allow-Events: line-seize
Max-Forwards: 70
Call-ID: 96A6D0C7@metaswitch
From: Norcast <sip:8055488000@10.50.10.2:5060;transport=udp>;tag=metaswitch+1+4dd07+8972feeb;isup-oli=00
To: <sip:8055480013@10.50.10.171>;tag=as553d29dc
CSeq: 249424786    ACK
Expires: 180
Organization: 
Supported: 100rel
Content-Length: 0
Content-Type: application/sdp
Contact: Norcast <sip:8055488000@10.50.10.2:5060;transport=udp>;isup-oli=00


<------------->
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 0: ACK sip:metaswitch0001@10.50.10.171:5060;transport=udp SIP/2.0 (62)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 1: Via: SIP/2.0/UDP 10.50.10.2:5060;rport;branch=z9hG4bK-2a9d6fdcdcf7bdf26f7d6607ddd3dbad-metaswitch-1 (99)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 2: Allow-Events: message-summary (29)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 3: Allow-Events: refer (19)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 4: Allow-Events: dialog (20)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 5: Allow-Events: line-seize (24)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 6: Max-Forwards: 70 (16)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 7: Call-ID: 96A6D0C7@metaswitch (28)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 8: From: Norcast <sip:8055488000@10.50.10.2:5060;transport=udp>;tag=metaswitch+1+4dd07+8972feeb;isup-oli=00 (104)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 9: To: <sip:8055480013@10.50.10.171>;tag=as553d29dc (48)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 10: CSeq: 249424786    ACK (22)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 11: Expires: 180 (12)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 12: Organization:  (14)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 13: Supported: 100rel (17)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 14: Content-Length: 0 (17)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 15: Content-Type: application/sdp (29)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 16: Contact: Norcast <sip:8055488000@10.50.10.2:5060;transport=udp>;isup-oli=00 (75)
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4573[0;37;40m [1;37;40mparse_request[0;37;40m: Header 17:  (0)
[Mar 28 18:43:30] --- (17 headers 0 lines) ---
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14633[0;37;40m [1;37;40mhandle_request[0;37;40m: **** Received ACK (6) - Command in SIP ACK
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2079[0;37;40m [1;37;40m__sip_ack[0;37;40m: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #52
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2089[0;37;40m [1;37;40m__sip_ack[0;37;40m: Stopping retransmission on '96A6D0C7@metaswitch' of Response 249424786: Match Not Found
[Mar 28 18:43:30] [1;31;40mWARNING[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m4771[0;37;40m [1;37;40mprocess_sdp[0;37;40m: Insufficient information for SDP (m = '', c = '')
[Mar 28 18:43:30] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m14850[0;37;40m [1;37;40msipsock_read[0;37;40m: SIP message could not be handled, bad request: 96A6D0C7@metaswitch                                                   
[Mar 28 18:43:31] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2010[0;37;40m [1;37;40m__sip_autodestruct[0;37;40m: Auto destroying SIP dialog '57cb99d94c374e8f5851b7291dd03ad0@127.0.0.1'
[Mar 28 18:43:31] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3109[0;37;40m [1;37;40msip_destroy[0;37;40m: Destroying SIP dialog 57cb99d94c374e8f5851b7291dd03ad0@127.0.0.1
[Mar 28 18:43:31] Really destroying SIP dialog '57cb99d94c374e8f5851b7291dd03ad0@127.0.0.1' Method: REGISTER
[Mar 28 18:43:31] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2010[0;37;40m [1;37;40m__sip_autodestruct[0;37;40m: Auto destroying SIP dialog '62164ccd5e4ddf75411fa4752fd2b36b@127.0.0.1'
[Mar 28 18:43:31] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3109[0;37;40m [1;37;40msip_destroy[0;37;40m: Destroying SIP dialog 62164ccd5e4ddf75411fa4752fd2b36b@127.0.0.1
[Mar 28 18:43:31] Really destroying SIP dialog '62164ccd5e4ddf75411fa4752fd2b36b@127.0.0.1' Method: REGISTER
[Mar 28 18:43:31] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2010[0;37;40m [1;37;40m__sip_autodestruct[0;37;40m: Auto destroying SIP dialog '7154d98a372984eb25f32b5f71c62a43@127.0.0.1'
[Mar 28 18:43:31] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3109[0;37;40m [1;37;40msip_destroy[0;37;40m: Destroying SIP dialog 7154d98a372984eb25f32b5f71c62a43@127.0.0.1
[Mar 28 18:43:31] Really destroying SIP dialog '7154d98a372984eb25f32b5f71c62a43@127.0.0.1' Method: REGISTER
[Mar 28 18:43:32] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m2010[0;37;40m [1;37;40m__sip_autodestruct[0;37;40m: Auto destroying SIP dialog '9A1CC282@metaswitch'
[Mar 28 18:43:32] [1;32;40mDEBUG[0;37;40m[12380]: [1;37;40mchan_sip.c[0;37;40m:[1;37;40m3109[0;37;40m [1;37;40msip_destroy[0;37;40m: Destroying SIP dialog 9A1CC282@metaswitch
[Mar 28 18:43:32] Really destroying SIP dialog '9A1CC282@metaswitch' Method: OPTIONS
sip set debug[13Dcore set verbose 4[9Ddebug 4[K[16Dstop now[K
[0;37;40m[Mar 28 18:43:44] Beginning asterisk shutdown....
[Mar 28 18:43:44] Executing last minute cleanups
[Mar 28 18:43:44]   == Destroying musiconhold processes
[Mar 28 18:43:44] Asterisk cleanly ending (0).