[Apr 17 12:35:53] Asterisk 1.4.19, Copyright (C) 1999 - 2008 Digium, Inc. and others.

[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:4548 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 0521b9be48c652b70097ca9e2a96b520@10.50.10.170 (Checking To) --From tag as5967f25a --To-tag metaswitch+1+0+8a9c575a  
[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 0521b9be48c652b70097ca9e2a96b520@10.50.10.170 Their Tag  Our tag: as5967f25a
[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '0521b9be48c652b70097ca9e2a96b520@10.50.10.170' of Request 102: Match Found
[Apr 17 12:37:53] Really destroying SIP dialog '0521b9be48c652b70097ca9e2a96b520@10.50.10.170' Method: OPTIONS
[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 81B53564@metaswitch (Checking From) --From tag metaswitch+1+0+3b613541 --To-tag   
[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: E73CFD1D@metaswitch Their Tag metaswitch+1+0+75312db2 Our tag: as16aab549
[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: dd10b1a34738ab4d Their Tag 77b7d14f5b Our tag: as1dd0a475
[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 837ea325767f1de9 Their Tag 3f51b44f9f Our tag: as280c4623
[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 15d1348704521dd4 Their Tag 4c422d9bd3 Our tag: as37f8b3bb
[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: ea1422d6da5d499c Their Tag 97db527ab7 Our tag: as7e3d39aa
[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: d35f662f5741e7de Their Tag 699674b6a1 Our tag: as7d40c545
[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 2e09dea5d18da88f Their Tag d868bb9945 Our tag: as10a69e64
[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 79c354cc2cd65ce5 Their Tag dcbb8dd9fa Our tag: as49dca80c
[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 96684172b017967a Their Tag a54d687528 Our tag: as533bcc6b
[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 67567c41516cb7d4 Their Tag f997f07c7f Our tag: as02447e94
[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 013c92beb64b3dcb Their Tag ceb95399a7 Our tag: as0fffe3d0
[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 48a1004e033532b8 Their Tag 8014521d7f Our tag: as7c1ce0cf
[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 9725a45b6329ec40 Their Tag 7848c7d68a Our tag: as7a00d7fe
[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 437cf766cb9011fb Their Tag f9005d88bd Our tag: as20b545b1
[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: c66cf5021199e243 Their Tag 1cd0a9d42c Our tag: as42f4bf02
[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 86c539d635a51342 Their Tag 63f589bc79 Our tag: as217100d9
[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 1f142aad15273705 Their Tag 1778dd6ec5 Our tag: as2dadd904
[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:4548 sip_alloc: Allocating new SIP dialog for 81B53564@metaswitch - OPTIONS (No RTP)
[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:15258 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS
[Apr 17 12:37:53] DEBUG[12278]: chan_sip.c:15480 sipsock_read: SIP message could not be handled, bad request: 81B53564@metaswitch                                                   
[Apr 17 12:37:55] DEBUG[12278]: chan_sip.c:2096 __sip_autodestruct: Auto destroying SIP dialog 'E73CFD1D@metaswitch'
[Apr 17 12:37:55] DEBUG[12278]: chan_sip.c:3314 sip_destroy: Destroying SIP dialog E73CFD1D@metaswitch
[Apr 17 12:37:55] Really destroying SIP dialog 'E73CFD1D@metaswitch' Method: OPTIONS
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: E5590329@metaswitch (Checking From) --From tag metaswitch+1+152c4c+1bd0e43a --To-tag   
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 81B53564@metaswitch Their Tag metaswitch+1+0+3b613541 Our tag: as362a406f
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: dd10b1a34738ab4d Their Tag 77b7d14f5b Our tag: as1dd0a475
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 837ea325767f1de9 Their Tag 3f51b44f9f Our tag: as280c4623
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 15d1348704521dd4 Their Tag 4c422d9bd3 Our tag: as37f8b3bb
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: ea1422d6da5d499c Their Tag 97db527ab7 Our tag: as7e3d39aa
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: d35f662f5741e7de Their Tag 699674b6a1 Our tag: as7d40c545
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 2e09dea5d18da88f Their Tag d868bb9945 Our tag: as10a69e64
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 79c354cc2cd65ce5 Their Tag dcbb8dd9fa Our tag: as49dca80c
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 96684172b017967a Their Tag a54d687528 Our tag: as533bcc6b
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 67567c41516cb7d4 Their Tag f997f07c7f Our tag: as02447e94
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 013c92beb64b3dcb Their Tag ceb95399a7 Our tag: as0fffe3d0
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 48a1004e033532b8 Their Tag 8014521d7f Our tag: as7c1ce0cf
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 9725a45b6329ec40 Their Tag 7848c7d68a Our tag: as7a00d7fe
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 437cf766cb9011fb Their Tag f9005d88bd Our tag: as20b545b1
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: c66cf5021199e243 Their Tag 1cd0a9d42c Our tag: as42f4bf02
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 86c539d635a51342 Their Tag 63f589bc79 Our tag: as217100d9
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 1f142aad15273705 Their Tag 1778dd6ec5 Our tag: as2dadd904
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2760 do_setnat: Setting NAT on RTP to Off
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4548 sip_alloc: Allocating new SIP dialog for E5590329@metaswitch - INVITE (With RTP)
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:15258 handle_request: **** Received INVITE (5) - Command in SIP INVITE
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2760 do_setnat: Setting NAT on RTP to Off
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:5451 process_sdp: T38 state changed to 0 on channel <none>
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:5531 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:13927 handle_request_invite: Checking SIP call limits for device 
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:3205 update_call_counter: Updating call counter for incoming call
[Apr 17 12:38:00] DEBUG[12278]: frame.c:1294 ast_codec_choose: Could not find preferred codec - Going for the best codec
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4032 sip_new: *** Our native formats are 0x4 (ulaw) 
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4033 sip_new: *** Joint capabilities are 0x4 (ulaw) 
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4034 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) 
[Apr 17 12:38:00] DEBUG[12278]: frame.c:1294 ast_codec_choose: Could not find preferred codec - Going for the best codec
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4035 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4058 sip_new: This channel will not be able to handle video.
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:8305 build_route: build_route: Contact hop: MICHAEL GAYALDO <sip:8054584444@10.50.10.2:5060;transport=udp>;isup-oli=62
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:14006 handle_request_invite: SIP/5060-01ed9ea0: New call is still down.... Trying... 
[Apr 17 12:38:00] DEBUG[12278]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5060-01ed9ea0
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5060-01ed9ea0
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5060-01ed9ea0
[Apr 17 12:38:00] DEBUG[12278]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5060
[Apr 17 12:38:00] DEBUG[12329]: pbx.c:1842 pbx_extension_helper: Launching 'Goto'
[Apr 17 12:38:00]     -- Executing [8055488091@sip:1] Goto("SIP/5060-01ed9ea0", "line1|8055488091|1") in new stack
[Apr 17 12:38:00]     -- Goto (line1,8055488091,1)
[Apr 17 12:38:00] DEBUG[12329]: pbx.c:1842 pbx_extension_helper: Launching 'Macro'
[Apr 17 12:38:00]     -- Executing [8055488091@line1:1] Macro("SIP/5060-01ed9ea0", "slaline|line1") in new stack
[Apr 17 12:38:00] DEBUG[12329]: pbx.c:1842 pbx_extension_helper: Launching 'SLATrunk'
[Apr 17 12:38:00]     -- Executing [s@macro-slaline:1] SLATrunk("SIP/5060-01ed9ea0", "line1") in new stack
[Apr 17 12:38:00] DEBUG[12329]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station1_line1
[Apr 17 12:38:00] DEBUG[12329]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station2_line1
[Apr 17 12:38:00] DEBUG[12329]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station3_line1
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/5060-01ed9ea0 - state 4 (Invalid)
[Apr 17 12:38:00] DEBUG[12329]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station4_line1
[Apr 17 12:38:00] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/5060-01ed9ea0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5060
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5060
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/5060 - state 4 (Invalid)
[Apr 17 12:38:00] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/5060' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station1_line1
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:00] DEBUG[12329]: chan_zap.c:7901 zt_request: Using channel -2
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SLA:station1_line1 - state 6 (Ringing)
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station1_line1
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station1_line1
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:00] DEBUG[12329]: channel.c:2784 set_format: Set channel Zap/pseudo-1510813994 to read format slin
[Apr 17 12:38:00] DEBUG[12329]: channel.c:2784 set_format: Set channel Zap/pseudo-1510813994 to write format slin
[Apr 17 12:38:00]  Extension Changed station1_line1[sla_stations] new state Ringing for Notify User station1 
[Apr 17 12:38:00]     -- Created MeetMe conference 1023 for conference 'SLA_line1'
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station2_line1
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SLA:station2_line1 - state 6 (Ringing)
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station2_line1
[Apr 17 12:38:00] DEBUG[12329]: channel.c:2372 ast_indicate_data: Driver for channel 'SIP/5060-01ed9ea0' does not support indication 3, emulating it
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station2_line1
[Apr 17 12:38:00] DEBUG[12329]: channel.c:2528 ast_prod: Prodding channel 'SIP/5060-01ed9ea0'
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:00] DEBUG[12329]: chan_sip.c:6726 transmit_response_with_sdp: Setting framing from config on incoming call
[Apr 17 12:38:00]  Extension Changed station2_line1[sla_stations] new state Ringing for Notify User station2 
[Apr 17 12:38:00] DEBUG[12329]: chan_sip.c:6490 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station3_line1
[Apr 17 12:38:00] DEBUG[12329]: chan_sip.c:6491 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:00] DEBUG[12329]: chan_sip.c:6622 add_sdp: -- Done with adding codecs to SDP
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SLA:station3_line1 - state 6 (Ringing)
[Apr 17 12:38:00] DEBUG[12329]: channel.c:2318 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24)
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station3_line1
[Apr 17 12:38:00] DEBUG[12329]: chan_sip.c:6667 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station3_line1
[Apr 17 12:38:00] DEBUG[12329]: channel.c:2784 set_format: Set channel SIP/5060-01ed9ea0 to write format slin
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:00] DEBUG[12329]: channel.c:1804 ast_settimeout: Scheduling timer at 160 sample intervals
[Apr 17 12:38:00]  Extension Changed station3_line1[sla_stations] new state Ringing for Notify User station3 
[Apr 17 12:38:00] DEBUG[12329]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel meetme:SLA_line1
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station4_line1
[Apr 17 12:38:00] DEBUG[12329]: channel.c:2784 set_format: Set channel SIP/5060-01ed9ea0 to write format ulaw
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:00] DEBUG[12329]: channel.c:1804 ast_settimeout: Scheduling timer at 0 sample intervals
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SLA:station4_line1 - state 6 (Ringing)
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station4_line1
[Apr 17 12:38:00] DEBUG[12329]: channel.c:2784 set_format: Set channel SIP/5060-01ed9ea0 to write format slin
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station4_line1
[Apr 17 12:38:00] DEBUG[12329]: channel.c:2784 set_format: Set channel SIP/5060-01ed9ea0 to read format slin
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:00] DEBUG[12329]: app_meetme.c:1676 conf_run: Placed channel SIP/5060-01ed9ea0 in ZAP conf 1023
[Apr 17 12:38:00]  Extension Changed station4_line1[sla_stations] new state Ringing for Notify User station4 
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "meetme" - number: SLA_line1
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with meetme
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider Meetme with meetme
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for meetme:SLA_line1 - state 2 (In use)
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:15963 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:4548 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:2760 do_setnat: Setting NAT on RTP to Off
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:4032 sip_new: *** Our native formats are 0x4 (ulaw) 
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:4033 sip_new: *** Joint capabilities are 0x0 (nothing) 
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:4034 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw) 
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:4035 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:4037 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) 
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:4058 sip_new: This channel will not be able to handle video.
[Apr 17 12:38:00] DEBUG[12296]: channel.c:3299 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH.
[Apr 17 12:38:00] DEBUG[12296]: channel.c:3299 ast_channel_inherit_variables: Not copying variable ARG1.
[Apr 17 12:38:00] DEBUG[12296]: channel.c:3299 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY.
[Apr 17 12:38:00] DEBUG[12296]: channel.c:3299 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT.
[Apr 17 12:38:00] DEBUG[12296]: channel.c:3299 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN.
[Apr 17 12:38:00] DEBUG[12296]: channel.c:3299 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Apr 17 12:38:00] DEBUG[12296]: channel.c:3299 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Apr 17 12:38:00] DEBUG[12296]: channel.c:3299 ast_channel_inherit_variables: Not copying variable SIPURI.
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:3018 sip_call: Outgoing Call for station1
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:3205 update_call_counter: Updating call counter for outgoing call
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:3282 update_call_counter: Call to peer 'station1' is 1 out of 1
[Apr 17 12:38:00] DEBUG[12296]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station1
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station1
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:3033 sip_call: Our T38 capability (0), joint T38 capability (0)
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station1
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/station1 - state 6 (Ringing)
[Apr 17 12:38:00] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/station1' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480616
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480616
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station1
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station1
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480616
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480616
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station1
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station1
[Apr 17 12:38:00]  Extension Changed 21[BLF] new state Ringing for Notify User 5480003 
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:6490 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: False
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:6491 add_sdp: ** Our prefcodec: 0x4 (ulaw) 
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:6622 add_sdp: -- Done with adding codecs to SDP
[Apr 17 12:38:00] DEBUG[12296]: channel.c:2318 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=31)
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:6667 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw)
[Apr 17 12:38:00]     -- Called station1
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:15963 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:4548 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:2760 do_setnat: Setting NAT on RTP to Off
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:4032 sip_new: *** Our native formats are 0x4 (ulaw) 
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:4033 sip_new: *** Joint capabilities are 0x0 (nothing) 
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:4034 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw) 
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:4035 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:4037 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) 
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:4058 sip_new: This channel will not be able to handle video.
[Apr 17 12:38:00] DEBUG[12296]: channel.c:3299 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH.
[Apr 17 12:38:00] DEBUG[12296]: channel.c:3299 ast_channel_inherit_variables: Not copying variable ARG1.
[Apr 17 12:38:00] DEBUG[12296]: channel.c:3299 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY.
[Apr 17 12:38:00] DEBUG[12296]: channel.c:3299 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT.
[Apr 17 12:38:00] DEBUG[12296]: channel.c:3299 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN.
[Apr 17 12:38:00] DEBUG[12296]: channel.c:3299 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Apr 17 12:38:00] DEBUG[12296]: channel.c:3299 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Apr 17 12:38:00] DEBUG[12296]: channel.c:3299 ast_channel_inherit_variables: Not copying variable SIPURI.
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:3018 sip_call: Outgoing Call for station2
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:3205 update_call_counter: Updating call counter for outgoing call
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:3282 update_call_counter: Call to peer 'station2' is 1 out of 1
[Apr 17 12:38:00] DEBUG[12296]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station2
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:3033 sip_call: Our T38 capability (0), joint T38 capability (0)
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station2
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station2
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/station2 - state 6 (Ringing)
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480617
[Apr 17 12:38:00] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/station2' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480617
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station2
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station2
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480617
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480617
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station2
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station2
[Apr 17 12:38:00]  Extension Changed 22[BLF] new state Ringing for Notify User 5480003 
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480617
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480617
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station2
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station2
[Apr 17 12:38:00]  Extension Changed 22[BLF] new state Ringing for Notify User 5480616 
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:6490 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: False
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:6491 add_sdp: ** Our prefcodec: 0x4 (ulaw) 
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:6622 add_sdp: -- Done with adding codecs to SDP
[Apr 17 12:38:00] DEBUG[12296]: channel.c:2318 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=34)
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:6667 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw)
[Apr 17 12:38:00]     -- Called station2
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:15963 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:4548 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:2760 do_setnat: Setting NAT on RTP to Off
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:4032 sip_new: *** Our native formats are 0x4 (ulaw) 
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:4033 sip_new: *** Joint capabilities are 0x0 (nothing) 
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:4034 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw) 
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:4035 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:4037 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) 
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:4058 sip_new: This channel will not be able to handle video.
[Apr 17 12:38:00] DEBUG[12296]: channel.c:3299 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH.
[Apr 17 12:38:00] DEBUG[12296]: channel.c:3299 ast_channel_inherit_variables: Not copying variable ARG1.
[Apr 17 12:38:00] DEBUG[12296]: channel.c:3299 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY.
[Apr 17 12:38:00] DEBUG[12296]: channel.c:3299 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT.
[Apr 17 12:38:00] DEBUG[12296]: channel.c:3299 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN.
[Apr 17 12:38:00] DEBUG[12296]: channel.c:3299 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Apr 17 12:38:00] DEBUG[12296]: channel.c:3299 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Apr 17 12:38:00] DEBUG[12296]: channel.c:3299 ast_channel_inherit_variables: Not copying variable SIPURI.
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:3018 sip_call: Outgoing Call for station3
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:3205 update_call_counter: Updating call counter for outgoing call
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:3282 update_call_counter: Call to peer 'station3' is 1 out of 1
[Apr 17 12:38:00] DEBUG[12296]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station3
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station3
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/station3 - state 6 (Ringing)
[Apr 17 12:38:00] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/station3' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480003
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480003
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station3
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480003
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480003
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station3
[Apr 17 12:38:00]  Extension Changed 23[BLF] new state Ringing for Notify User 5480003 
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480003
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480003
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station3
[Apr 17 12:38:00]  Extension Changed 23[BLF] new state Ringing for Notify User 5480004 
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480003
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480003
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station3
[Apr 17 12:38:00]  Extension Changed 23[BLF] new state Ringing for Notify User 5480617 
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480003
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480003
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station3
[Apr 17 12:38:00]  Extension Changed 23[BLF] new state Ringing for Notify User 5480616 
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:3033 sip_call: Our T38 capability (0), joint T38 capability (0)
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:6490 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: False
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:6491 add_sdp: ** Our prefcodec: 0x4 (ulaw) 
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:6622 add_sdp: -- Done with adding codecs to SDP
[Apr 17 12:38:00] DEBUG[12296]: channel.c:2318 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=37)
[Apr 17 12:38:00] DEBUG[12296]: chan_sip.c:6667 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw)
[Apr 17 12:38:00]     -- Called station3
[Apr 17 12:38:00] DEBUG[12329]: rtp.c:2772 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Apr 17 12:38:00] DEBUG[12329]: rtp.c:2789 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 2e09dea5d18da88f (Checking To) --From tag as10a69e64 --To-tag d868bb9945  
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 53652af21c2b7da91cc348474759fd67@10.50.10.170 Their Tag  Our tag: as6b3ec070
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag  Our tag: as51601a0d
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 00fcf5a919c0925d367f3e50058a815d@10.50.10.170 Their Tag  Our tag: as0c6d66ab
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: E5590329@metaswitch Their Tag metaswitch+1+152c4c+1bd0e43a Our tag: as4e3f5fce
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 81B53564@metaswitch Their Tag metaswitch+1+0+3b613541 Our tag: as362a406f
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: dd10b1a34738ab4d Their Tag 77b7d14f5b Our tag: as1dd0a475
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 837ea325767f1de9 Their Tag 3f51b44f9f Our tag: as280c4623
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 15d1348704521dd4 Their Tag 4c422d9bd3 Our tag: as37f8b3bb
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: ea1422d6da5d499c Their Tag 97db527ab7 Our tag: as7e3d39aa
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: d35f662f5741e7de Their Tag 699674b6a1 Our tag: as7d40c545
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 2e09dea5d18da88f Their Tag d868bb9945 Our tag: as10a69e64
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2159 __sip_ack: Acked pending invite 103
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '2e09dea5d18da88f' of Request 103: Match Found
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: ea1422d6da5d499c (Checking To) --From tag as7e3d39aa --To-tag 97db527ab7  
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 53652af21c2b7da91cc348474759fd67@10.50.10.170 Their Tag  Our tag: as6b3ec070
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag  Our tag: as51601a0d
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 00fcf5a919c0925d367f3e50058a815d@10.50.10.170 Their Tag  Our tag: as0c6d66ab
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: E5590329@metaswitch Their Tag metaswitch+1+152c4c+1bd0e43a Our tag: as4e3f5fce
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 81B53564@metaswitch Their Tag metaswitch+1+0+3b613541 Our tag: as362a406f
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: dd10b1a34738ab4d Their Tag 77b7d14f5b Our tag: as1dd0a475
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 837ea325767f1de9 Their Tag 3f51b44f9f Our tag: as280c4623
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 15d1348704521dd4 Their Tag 4c422d9bd3 Our tag: as37f8b3bb
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: ea1422d6da5d499c Their Tag 97db527ab7 Our tag: as7e3d39aa
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2159 __sip_ack: Acked pending invite 104
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on 'ea1422d6da5d499c' of Request 104: Match Found
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 (Checking To) --From tag as51601a0d --To-tag 2122920226  
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 53652af21c2b7da91cc348474759fd67@10.50.10.170 Their Tag  Our tag: as6b3ec070
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag  Our tag: as51601a0d
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2236 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170' Request 102: Found
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:12062 handle_response_invite: SIP response 180 to standard invite
[Apr 17 12:38:00] DEBUG[12278]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station2-ac08ec00
[Apr 17 12:38:00] DEBUG[12278]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station2
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station2-ac08ec00
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station2-ac08ec00
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/station2-ac08ec00 - state 4 (Invalid)
[Apr 17 12:38:00] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/station2-ac08ec00' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station2
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station2
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/station2 - state 6 (Ringing)
[Apr 17 12:38:00] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/station2' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480617
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480617
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station2
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station2
[Apr 17 12:38:00]     -- SIP/station2-ac08ec00 is ringing
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 53652af21c2b7da91cc348474759fd67@10.50.10.170 (Checking To) --From tag as6b3ec070 --To-tag 3224944591  
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 53652af21c2b7da91cc348474759fd67@10.50.10.170 Their Tag  Our tag: as6b3ec070
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2236 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '53652af21c2b7da91cc348474759fd67@10.50.10.170' Request 102: Found
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:12062 handle_response_invite: SIP response 180 to standard invite
[Apr 17 12:38:00] DEBUG[12278]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station3-01eff570
[Apr 17 12:38:00] DEBUG[12278]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station3
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3-01eff570
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station3-01eff570
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/station3-01eff570 - state 4 (Invalid)
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3
[Apr 17 12:38:00] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/station3-01eff570' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station3
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/station3 - state 6 (Ringing)
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480003
[Apr 17 12:38:00] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/station3' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480003
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station3
[Apr 17 12:38:00]     -- SIP/station3-01eff570 is ringing
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 9725a45b6329ec40 (Checking To) --From tag as7a00d7fe --To-tag 7848c7d68a  
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 53652af21c2b7da91cc348474759fd67@10.50.10.170 Their Tag 3224944591 Our tag: as6b3ec070
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 00fcf5a919c0925d367f3e50058a815d@10.50.10.170 Their Tag  Our tag: as0c6d66ab
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: E5590329@metaswitch Their Tag metaswitch+1+152c4c+1bd0e43a Our tag: as4e3f5fce
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 81B53564@metaswitch Their Tag metaswitch+1+0+3b613541 Our tag: as362a406f
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: dd10b1a34738ab4d Their Tag 77b7d14f5b Our tag: as1dd0a475
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 837ea325767f1de9 Their Tag 3f51b44f9f Our tag: as280c4623
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 15d1348704521dd4 Their Tag 4c422d9bd3 Our tag: as37f8b3bb
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: ea1422d6da5d499c Their Tag 97db527ab7 Our tag: as7e3d39aa
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: d35f662f5741e7de Their Tag 699674b6a1 Our tag: as7d40c545
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 2e09dea5d18da88f Their Tag d868bb9945 Our tag: as10a69e64
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 79c354cc2cd65ce5 Their Tag dcbb8dd9fa Our tag: as49dca80c
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 96684172b017967a Their Tag a54d687528 Our tag: as533bcc6b
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 67567c41516cb7d4 Their Tag f997f07c7f Our tag: as02447e94
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 013c92beb64b3dcb Their Tag ceb95399a7 Our tag: as0fffe3d0
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 48a1004e033532b8 Their Tag 8014521d7f Our tag: as7c1ce0cf
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 9725a45b6329ec40 Their Tag 7848c7d68a Our tag: as7a00d7fe
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2159 __sip_ack: Acked pending invite 105
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '9725a45b6329ec40' of Request 105: Match Found
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 00fcf5a919c0925d367f3e50058a815d@10.50.10.170 (Checking To) --From tag as0c6d66ab --To-tag 237078023  
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 53652af21c2b7da91cc348474759fd67@10.50.10.170 Their Tag 3224944591 Our tag: as6b3ec070
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 00fcf5a919c0925d367f3e50058a815d@10.50.10.170 Their Tag  Our tag: as0c6d66ab
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2236 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '00fcf5a919c0925d367f3e50058a815d@10.50.10.170' Request 102: Found
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:12062 handle_response_invite: SIP response 180 to standard invite
[Apr 17 12:38:00] DEBUG[12278]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station1-01ee3cb0
[Apr 17 12:38:00] DEBUG[12278]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station1
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station1-01ee3cb0
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station1-01ee3cb0
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/station1-01ee3cb0 - state 4 (Invalid)
[Apr 17 12:38:00] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/station1-01ee3cb0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station1
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station1
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/station1 - state 6 (Ringing)
[Apr 17 12:38:00] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/station1' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480616
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480616
[Apr 17 12:38:00] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station1
[Apr 17 12:38:00] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station1
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 013c92beb64b3dcb (Checking To) --From tag as0fffe3d0 --To-tag ceb95399a7  
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 53652af21c2b7da91cc348474759fd67@10.50.10.170 Their Tag 3224944591 Our tag: as6b3ec070
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 00fcf5a919c0925d367f3e50058a815d@10.50.10.170 Their Tag 237078023 Our tag: as0c6d66ab
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: E5590329@metaswitch Their Tag metaswitch+1+152c4c+1bd0e43a Our tag: as4e3f5fce
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 81B53564@metaswitch Their Tag metaswitch+1+0+3b613541 Our tag: as362a406f
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: dd10b1a34738ab4d Their Tag 77b7d14f5b Our tag: as1dd0a475
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 837ea325767f1de9 Their Tag 3f51b44f9f Our tag: as280c4623
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 15d1348704521dd4 Their Tag 4c422d9bd3 Our tag: as37f8b3bb
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: ea1422d6da5d499c Their Tag 97db527ab7 Our tag: as7e3d39aa
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: d35f662f5741e7de Their Tag 699674b6a1 Our tag: as7d40c545
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 2e09dea5d18da88f Their Tag d868bb9945 Our tag: as10a69e64
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 79c354cc2cd65ce5 Their Tag dcbb8dd9fa Our tag: as49dca80c
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 96684172b017967a Their Tag a54d687528 Our tag: as533bcc6b
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 67567c41516cb7d4 Their Tag f997f07c7f Our tag: as02447e94
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 013c92beb64b3dcb Their Tag ceb95399a7 Our tag: as0fffe3d0
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2159 __sip_ack: Acked pending invite 103
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '013c92beb64b3dcb' of Request 103: Match Found
[Apr 17 12:38:00]     -- SIP/station1-01ee3cb0 is ringing
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 67567c41516cb7d4 (Checking To) --From tag as02447e94 --To-tag f997f07c7f  
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 53652af21c2b7da91cc348474759fd67@10.50.10.170 Their Tag 3224944591 Our tag: as6b3ec070
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 00fcf5a919c0925d367f3e50058a815d@10.50.10.170 Their Tag 237078023 Our tag: as0c6d66ab
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: E5590329@metaswitch Their Tag metaswitch+1+152c4c+1bd0e43a Our tag: as4e3f5fce
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 81B53564@metaswitch Their Tag metaswitch+1+0+3b613541 Our tag: as362a406f
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: dd10b1a34738ab4d Their Tag 77b7d14f5b Our tag: as1dd0a475
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 837ea325767f1de9 Their Tag 3f51b44f9f Our tag: as280c4623
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 15d1348704521dd4 Their Tag 4c422d9bd3 Our tag: as37f8b3bb
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: ea1422d6da5d499c Their Tag 97db527ab7 Our tag: as7e3d39aa
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: d35f662f5741e7de Their Tag 699674b6a1 Our tag: as7d40c545
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 2e09dea5d18da88f Their Tag d868bb9945 Our tag: as10a69e64
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 79c354cc2cd65ce5 Their Tag dcbb8dd9fa Our tag: as49dca80c
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 96684172b017967a Their Tag a54d687528 Our tag: as533bcc6b
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 67567c41516cb7d4 Their Tag f997f07c7f Our tag: as02447e94
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2159 __sip_ack: Acked pending invite 104
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '67567c41516cb7d4' of Request 104: Match Found
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 79c354cc2cd65ce5 (Checking To) --From tag as49dca80c --To-tag dcbb8dd9fa  
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 53652af21c2b7da91cc348474759fd67@10.50.10.170 Their Tag 3224944591 Our tag: as6b3ec070
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 00fcf5a919c0925d367f3e50058a815d@10.50.10.170 Their Tag 237078023 Our tag: as0c6d66ab
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: E5590329@metaswitch Their Tag metaswitch+1+152c4c+1bd0e43a Our tag: as4e3f5fce
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 81B53564@metaswitch Their Tag metaswitch+1+0+3b613541 Our tag: as362a406f
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: dd10b1a34738ab4d Their Tag 77b7d14f5b Our tag: as1dd0a475
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 837ea325767f1de9 Their Tag 3f51b44f9f Our tag: as280c4623
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 15d1348704521dd4 Their Tag 4c422d9bd3 Our tag: as37f8b3bb
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: ea1422d6da5d499c Their Tag 97db527ab7 Our tag: as7e3d39aa
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: d35f662f5741e7de Their Tag 699674b6a1 Our tag: as7d40c545
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 2e09dea5d18da88f Their Tag d868bb9945 Our tag: as10a69e64
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 79c354cc2cd65ce5 Their Tag dcbb8dd9fa Our tag: as49dca80c
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2159 __sip_ack: Acked pending invite 103
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '79c354cc2cd65ce5' of Request 103: Match Found
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: c66cf5021199e243 (Checking To) --From tag as42f4bf02 --To-tag 1cd0a9d42c  
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 53652af21c2b7da91cc348474759fd67@10.50.10.170 Their Tag 3224944591 Our tag: as6b3ec070
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 00fcf5a919c0925d367f3e50058a815d@10.50.10.170 Their Tag 237078023 Our tag: as0c6d66ab
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: E5590329@metaswitch Their Tag metaswitch+1+152c4c+1bd0e43a Our tag: as4e3f5fce
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 81B53564@metaswitch Their Tag metaswitch+1+0+3b613541 Our tag: as362a406f
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: dd10b1a34738ab4d Their Tag 77b7d14f5b Our tag: as1dd0a475
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 837ea325767f1de9 Their Tag 3f51b44f9f Our tag: as280c4623
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 15d1348704521dd4 Their Tag 4c422d9bd3 Our tag: as37f8b3bb
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: ea1422d6da5d499c Their Tag 97db527ab7 Our tag: as7e3d39aa
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: d35f662f5741e7de Their Tag 699674b6a1 Our tag: as7d40c545
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 2e09dea5d18da88f Their Tag d868bb9945 Our tag: as10a69e64
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 79c354cc2cd65ce5 Their Tag dcbb8dd9fa Our tag: as49dca80c
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 96684172b017967a Their Tag a54d687528 Our tag: as533bcc6b
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 67567c41516cb7d4 Their Tag f997f07c7f Our tag: as02447e94
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 013c92beb64b3dcb Their Tag ceb95399a7 Our tag: as0fffe3d0
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 48a1004e033532b8 Their Tag 8014521d7f Our tag: as7c1ce0cf
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 9725a45b6329ec40 Their Tag 7848c7d68a Our tag: as7a00d7fe
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 437cf766cb9011fb Their Tag f9005d88bd Our tag: as20b545b1
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: c66cf5021199e243 Their Tag 1cd0a9d42c Our tag: as42f4bf02
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2159 __sip_ack: Acked pending invite 103
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on 'c66cf5021199e243' of Request 103: Match Found
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 86c539d635a51342 (Checking To) --From tag as217100d9 --To-tag 63f589bc79  
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 53652af21c2b7da91cc348474759fd67@10.50.10.170 Their Tag 3224944591 Our tag: as6b3ec070
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 00fcf5a919c0925d367f3e50058a815d@10.50.10.170 Their Tag 237078023 Our tag: as0c6d66ab
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: E5590329@metaswitch Their Tag metaswitch+1+152c4c+1bd0e43a Our tag: as4e3f5fce
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 81B53564@metaswitch Their Tag metaswitch+1+0+3b613541 Our tag: as362a406f
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: dd10b1a34738ab4d Their Tag 77b7d14f5b Our tag: as1dd0a475
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 837ea325767f1de9 Their Tag 3f51b44f9f Our tag: as280c4623
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 15d1348704521dd4 Their Tag 4c422d9bd3 Our tag: as37f8b3bb
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: ea1422d6da5d499c Their Tag 97db527ab7 Our tag: as7e3d39aa
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: d35f662f5741e7de Their Tag 699674b6a1 Our tag: as7d40c545
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 2e09dea5d18da88f Their Tag d868bb9945 Our tag: as10a69e64
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 79c354cc2cd65ce5 Their Tag dcbb8dd9fa Our tag: as49dca80c
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 96684172b017967a Their Tag a54d687528 Our tag: as533bcc6b
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 67567c41516cb7d4 Their Tag f997f07c7f Our tag: as02447e94
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 013c92beb64b3dcb Their Tag ceb95399a7 Our tag: as0fffe3d0
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 48a1004e033532b8 Their Tag 8014521d7f Our tag: as7c1ce0cf
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 9725a45b6329ec40 Their Tag 7848c7d68a Our tag: as7a00d7fe
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 437cf766cb9011fb Their Tag f9005d88bd Our tag: as20b545b1
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: c66cf5021199e243 Their Tag 1cd0a9d42c Our tag: as42f4bf02
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 86c539d635a51342 Their Tag 63f589bc79 Our tag: as217100d9
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2159 __sip_ack: Acked pending invite 103
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '86c539d635a51342' of Request 103: Match Found
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 15d1348704521dd4 (Checking To) --From tag as37f8b3bb --To-tag 4c422d9bd3  
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 53652af21c2b7da91cc348474759fd67@10.50.10.170 Their Tag 3224944591 Our tag: as6b3ec070
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 00fcf5a919c0925d367f3e50058a815d@10.50.10.170 Their Tag 237078023 Our tag: as0c6d66ab
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: E5590329@metaswitch Their Tag metaswitch+1+152c4c+1bd0e43a Our tag: as4e3f5fce
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 81B53564@metaswitch Their Tag metaswitch+1+0+3b613541 Our tag: as362a406f
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: dd10b1a34738ab4d Their Tag 77b7d14f5b Our tag: as1dd0a475
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 837ea325767f1de9 Their Tag 3f51b44f9f Our tag: as280c4623
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 15d1348704521dd4 Their Tag 4c422d9bd3 Our tag: as37f8b3bb
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2159 __sip_ack: Acked pending invite 103
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '15d1348704521dd4' of Request 103: Match Found
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 1f142aad15273705 (Checking To) --From tag as2dadd904 --To-tag 1778dd6ec5  
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 53652af21c2b7da91cc348474759fd67@10.50.10.170 Their Tag 3224944591 Our tag: as6b3ec070
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 00fcf5a919c0925d367f3e50058a815d@10.50.10.170 Their Tag 237078023 Our tag: as0c6d66ab
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: E5590329@metaswitch Their Tag metaswitch+1+152c4c+1bd0e43a Our tag: as4e3f5fce
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 81B53564@metaswitch Their Tag metaswitch+1+0+3b613541 Our tag: as362a406f
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: dd10b1a34738ab4d Their Tag 77b7d14f5b Our tag: as1dd0a475
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 837ea325767f1de9 Their Tag 3f51b44f9f Our tag: as280c4623
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 15d1348704521dd4 Their Tag 4c422d9bd3 Our tag: as37f8b3bb
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: ea1422d6da5d499c Their Tag 97db527ab7 Our tag: as7e3d39aa
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: d35f662f5741e7de Their Tag 699674b6a1 Our tag: as7d40c545
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 2e09dea5d18da88f Their Tag d868bb9945 Our tag: as10a69e64
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 79c354cc2cd65ce5 Their Tag dcbb8dd9fa Our tag: as49dca80c
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 96684172b017967a Their Tag a54d687528 Our tag: as533bcc6b
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 67567c41516cb7d4 Their Tag f997f07c7f Our tag: as02447e94
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 013c92beb64b3dcb Their Tag ceb95399a7 Our tag: as0fffe3d0
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 48a1004e033532b8 Their Tag 8014521d7f Our tag: as7c1ce0cf
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 9725a45b6329ec40 Their Tag 7848c7d68a Our tag: as7a00d7fe
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 437cf766cb9011fb Their Tag f9005d88bd Our tag: as20b545b1
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: c66cf5021199e243 Their Tag 1cd0a9d42c Our tag: as42f4bf02
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 86c539d635a51342 Their Tag 63f589bc79 Our tag: as217100d9
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 1f142aad15273705 Their Tag 1778dd6ec5 Our tag: as2dadd904
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2159 __sip_ack: Acked pending invite 104
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '1f142aad15273705' of Request 104: Match Found
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 837ea325767f1de9 (Checking To) --From tag as280c4623 --To-tag 3f51b44f9f  
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 53652af21c2b7da91cc348474759fd67@10.50.10.170 Their Tag 3224944591 Our tag: as6b3ec070
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 00fcf5a919c0925d367f3e50058a815d@10.50.10.170 Their Tag 237078023 Our tag: as0c6d66ab
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: E5590329@metaswitch Their Tag metaswitch+1+152c4c+1bd0e43a Our tag: as4e3f5fce
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 81B53564@metaswitch Their Tag metaswitch+1+0+3b613541 Our tag: as362a406f
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: dd10b1a34738ab4d Their Tag 77b7d14f5b Our tag: as1dd0a475
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 837ea325767f1de9 Their Tag 3f51b44f9f Our tag: as280c4623
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2159 __sip_ack: Acked pending invite 103
[Apr 17 12:38:00] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '837ea325767f1de9' of Request 103: Match Found
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 (Checking To) --From tag as51601a0d --To-tag 2122920226  
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 53652af21c2b7da91cc348474759fd67@10.50.10.170 Their Tag 3224944591 Our tag: as6b3ec070
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2159 __sip_ack: Acked pending invite 102
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170' of Request 102: Match Found
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:12062 handle_response_invite: SIP response 200 to standard invite
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:5451 process_sdp: T38 state changed to 0 on channel SIP/station2-ac08ec00
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:5531 process_sdp: We're settling with these formats: 0xc (ulaw|alaw)
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:5538 process_sdp: We have an owner, now see if we need to change this call
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:3205 update_call_counter: Updating call counter for outgoing call
[Apr 17 12:38:11] DEBUG[12278]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station2
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:8305 build_route: build_route: Contact hop: PowerPBX 22 <sip:station2@10.50.10.188:5060;transport=udp>
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station2
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station2
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/station2 - state 3 (Busy)
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480617
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480617
[Apr 17 12:38:11] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/station2' changed to state '3' (Busy) but we don't care because they're not a member of any queue.
[Apr 17 12:38:11] DEBUG[12331]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station2-ac08ec00
[Apr 17 12:38:11] DEBUG[12331]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station2
[Apr 17 12:38:11]     -- SIP/station2-ac08ec00 answered
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station2
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station2
[Apr 17 12:38:11] DEBUG[12296]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5060-01ed9ea0
[Apr 17 12:38:11] DEBUG[12296]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5060
[Apr 17 12:38:11] DEBUG[12296]: chan_sip.c:3678 sip_answer: SIP answering channel: SIP/5060-01ed9ea0
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480617
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480617
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station2
[Apr 17 12:38:11] DEBUG[12296]: chan_sip.c:6726 transmit_response_with_sdp: Setting framing from config on incoming call
[Apr 17 12:38:11] DEBUG[12296]: chan_sip.c:6490 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station2
[Apr 17 12:38:11] DEBUG[12296]: chan_sip.c:6491 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Apr 17 12:38:11] DEBUG[12296]: chan_sip.c:6622 add_sdp: -- Done with adding codecs to SDP
[Apr 17 12:38:11] DEBUG[12296]: channel.c:2318 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24)
[Apr 17 12:38:11] DEBUG[12296]: chan_sip.c:6667 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Apr 17 12:38:11]  Extension Changed 22[BLF] new state InUse for Notify User 5480003 
[Apr 17 12:38:11] DEBUG[12296]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station1_line1
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480617
[Apr 17 12:38:11] DEBUG[12296]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station2_line1
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480617
[Apr 17 12:38:11] DEBUG[12296]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station3_line1
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station2
[Apr 17 12:38:11] DEBUG[12296]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station4_line1
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station2
[Apr 17 12:38:11]  Extension Changed 22[BLF] new state InUse for Notify User 5480616 
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station2-ac08ec00
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station2-ac08ec00
[Apr 17 12:38:11] DEBUG[12336]: channel.c:2784 set_format: Set channel SIP/station2-ac08ec00 to write format slin
[Apr 17 12:38:11] DEBUG[12336]: channel.c:2784 set_format: Set channel SIP/station2-ac08ec00 to read format slin
[Apr 17 12:38:11] DEBUG[12336]: app_meetme.c:1676 conf_run: Placed channel SIP/station2-ac08ec00 in ZAP conf 1023
[Apr 17 12:38:11] DEBUG[12296]: channel.c:1483 ast_hangup: Hanging up channel 'SIP/station3-01eff570'
[Apr 17 12:38:11] DEBUG[12296]: chan_sip.c:3517 sip_hangup: Hangup call SIP/station3-01eff570, SIP callid 53652af21c2b7da91cc348474759fd67@10.50.10.170)
[Apr 17 12:38:11] DEBUG[12296]: chan_sip.c:3205 update_call_counter: Updating call counter for outgoing call
[Apr 17 12:38:11] DEBUG[12296]: chan_sip.c:3256 update_call_counter: Call to peer 'station3' removed from call limit 1
[Apr 17 12:38:11] DEBUG[12296]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station3
[Apr 17 12:38:11] DEBUG[12296]: chan_sip.c:3540 sip_hangup: Hanging up channel in state Ringing (not UP)
[Apr 17 12:38:11] DEBUG[12296]: chan_sip.c:2159 __sip_ack: Acked pending invite 102
[Apr 17 12:38:11] DEBUG[12296]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '53652af21c2b7da91cc348474759fd67@10.50.10.170' of Request 102: Match Found
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/station2-ac08ec00 - state 4 (Invalid)
[Apr 17 12:38:11] DEBUG[12296]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station3-01eff570
[Apr 17 12:38:11] DEBUG[12296]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station3
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station2
[Apr 17 12:38:11] DEBUG[12296]: channel.c:1483 ast_hangup: Hanging up channel 'SIP/station1-01ee3cb0'
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station2
[Apr 17 12:38:11] DEBUG[12296]: chan_sip.c:3517 sip_hangup: Hangup call SIP/station1-01ee3cb0, SIP callid 00fcf5a919c0925d367f3e50058a815d@10.50.10.170)
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/station2 - state 3 (Busy)
[Apr 17 12:38:11] DEBUG[12296]: chan_sip.c:3205 update_call_counter: Updating call counter for outgoing call
[Apr 17 12:38:11] DEBUG[12296]: chan_sip.c:3256 update_call_counter: Call to peer 'station1' removed from call limit 1
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480617
[Apr 17 12:38:11] DEBUG[12296]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station1
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480617
[Apr 17 12:38:11] DEBUG[12296]: chan_sip.c:3540 sip_hangup: Hanging up channel in state Ringing (not UP)
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station2
[Apr 17 12:38:11] DEBUG[12296]: chan_sip.c:2159 __sip_ack: Acked pending invite 102
[Apr 17 12:38:11] DEBUG[12296]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '00fcf5a919c0925d367f3e50058a815d@10.50.10.170' of Request 102: Match Found
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station2
[Apr 17 12:38:11] DEBUG[12296]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station1-01ee3cb0
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5060-01ed9ea0
[Apr 17 12:38:11] DEBUG[12296]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station1
[Apr 17 12:38:11] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/station2-ac08ec00' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Apr 17 12:38:11] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/station2' changed to state '3' (Busy) but we don't care because they're not a member of any queue.
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5060-01ed9ea0
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/5060-01ed9ea0 - state 4 (Invalid)
[Apr 17 12:38:11] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/5060-01ed9ea0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5060
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5060
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/5060 - state 4 (Invalid)
[Apr 17 12:38:11] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/5060' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station1_line1
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SLA:station1_line1 - state 2 (In use)
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station1_line1
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station1_line1
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:11]  Extension Changed station1_line1[sla_stations] new state InUse for Notify User station1 
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station2_line1
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SLA:station2_line1 - state 2 (In use)
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station2_line1
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station2_line1
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:11]  Extension Changed station2_line1[sla_stations] new state InUse for Notify User station2 
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station3_line1
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SLA:station3_line1 - state 2 (In use)
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: E5590329@metaswitch (Checking From) --From tag metaswitch+1+152c4c+1bd0e43a --To-tag as4e3f5fce  
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 53652af21c2b7da91cc348474759fd67@10.50.10.170 Their Tag 3224944591 Our tag: as6b3ec070
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 00fcf5a919c0925d367f3e50058a815d@10.50.10.170 Their Tag 237078023 Our tag: as0c6d66ab
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: E5590329@metaswitch Their Tag metaswitch+1+152c4c+1bd0e43a Our tag: as4e3f5fce
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:15258 handle_request: **** Received ACK (6) - Command in SIP ACK
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on 'E5590329@metaswitch' of Response 168901901: Match Found
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station3_line1
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station3_line1
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:11]  Extension Changed station3_line1[sla_stations] new state InUse for Notify User station3 
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station4_line1
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SLA:station4_line1 - state 2 (In use)
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station4_line1
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station4_line1
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:11]  Extension Changed station4_line1[sla_stations] new state InUse for Notify User station4 
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station3
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/station3 - state 1 (Not in use)
[Apr 17 12:38:11] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/station3' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480003
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480003
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station3
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480003
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480003
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station3
[Apr 17 12:38:11]  Extension Changed 23[BLF] new state Idle for Notify User 5480003 
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480003
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480003
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station3
[Apr 17 12:38:11]  Extension Changed 23[BLF] new state Idle for Notify User 5480004 
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480003
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480003
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station3
[Apr 17 12:38:11]  Extension Changed 23[BLF] new state Idle for Notify User 5480617 
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480003
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480003
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station3
[Apr 17 12:38:11]  Extension Changed 23[BLF] new state Idle for Notify User 5480616 
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3-01eff570
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station3-01eff570
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/station3-01eff570 - state 4 (Invalid)
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3
[Apr 17 12:38:11] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/station3-01eff570' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station3
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/station3 - state 1 (Not in use)
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480003
[Apr 17 12:38:11] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/station3' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480003
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station3
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station1
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station1
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/station1 - state 1 (Not in use)
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480616
[Apr 17 12:38:11] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/station1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480616
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station1
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station1
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480616
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480616
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station1
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station1
[Apr 17 12:38:11]  Extension Changed 21[BLF] new state Idle for Notify User 5480003 
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station1-01ee3cb0
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station1-01ee3cb0
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/station1-01ee3cb0 - state 4 (Invalid)
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station1
[Apr 17 12:38:11] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/station1-01ee3cb0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station1
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/station1 - state 1 (Not in use)
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480616
[Apr 17 12:38:11] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/station1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480616
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station1
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station1
[Apr 17 12:38:11] DEBUG[12329]: rtp.c:2789 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Apr 17 12:38:11] DEBUG[12336]: rtp.c:2772 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Apr 17 12:38:11] DEBUG[12336]: rtp.c:2789 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 2e09dea5d18da88f (Checking To) --From tag as10a69e64 --To-tag d868bb9945  
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 53652af21c2b7da91cc348474759fd67@10.50.10.170 Their Tag 3224944591 Our tag: as6b3ec070
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 00fcf5a919c0925d367f3e50058a815d@10.50.10.170 Their Tag 237078023 Our tag: as0c6d66ab
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: E5590329@metaswitch Their Tag metaswitch+1+152c4c+1bd0e43a Our tag: as4e3f5fce
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 81B53564@metaswitch Their Tag metaswitch+1+0+3b613541 Our tag: as362a406f
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: dd10b1a34738ab4d Their Tag 77b7d14f5b Our tag: as1dd0a475
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 837ea325767f1de9 Their Tag 3f51b44f9f Our tag: as280c4623
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 15d1348704521dd4 Their Tag 4c422d9bd3 Our tag: as37f8b3bb
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: ea1422d6da5d499c Their Tag 97db527ab7 Our tag: as7e3d39aa
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: d35f662f5741e7de Their Tag 699674b6a1 Our tag: as7d40c545
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 2e09dea5d18da88f Their Tag d868bb9945 Our tag: as10a69e64
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2159 __sip_ack: Acked pending invite 104
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '2e09dea5d18da88f' of Request 104: Match Found
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: ea1422d6da5d499c (Checking To) --From tag as7e3d39aa --To-tag 97db527ab7  
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 53652af21c2b7da91cc348474759fd67@10.50.10.170 Their Tag 3224944591 Our tag: as6b3ec070
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 00fcf5a919c0925d367f3e50058a815d@10.50.10.170 Their Tag 237078023 Our tag: as0c6d66ab
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: E5590329@metaswitch Their Tag metaswitch+1+152c4c+1bd0e43a Our tag: as4e3f5fce
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 81B53564@metaswitch Their Tag metaswitch+1+0+3b613541 Our tag: as362a406f
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: dd10b1a34738ab4d Their Tag 77b7d14f5b Our tag: as1dd0a475
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 837ea325767f1de9 Their Tag 3f51b44f9f Our tag: as280c4623
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 15d1348704521dd4 Their Tag 4c422d9bd3 Our tag: as37f8b3bb
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: ea1422d6da5d499c Their Tag 97db527ab7 Our tag: as7e3d39aa
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2159 __sip_ack: Acked pending invite 105
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on 'ea1422d6da5d499c' of Request 105: Match Found
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 53652af21c2b7da91cc348474759fd67@10.50.10.170 (Checking To) --From tag as6b3ec070 --To-tag 3224944591  
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 53652af21c2b7da91cc348474759fd67@10.50.10.170 Their Tag 3224944591 Our tag: as6b3ec070
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '53652af21c2b7da91cc348474759fd67@10.50.10.170' of Request 102: Match Found
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 53652af21c2b7da91cc348474759fd67@10.50.10.170 (Checking To) --From tag as6b3ec070 --To-tag 3224944591  
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 53652af21c2b7da91cc348474759fd67@10.50.10.170 Their Tag 3224944591 Our tag: as6b3ec070
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '53652af21c2b7da91cc348474759fd67@10.50.10.170' of Request 102: Match Not Found
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:12062 handle_response_invite: SIP response 487 to standard invite
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:3205 update_call_counter: Updating call counter for outgoing call
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:3256 update_call_counter: Call to peer 'station3' removed from call limit 1
[Apr 17 12:38:11] DEBUG[12278]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station3
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:1656 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 53652af21c2b7da91cc348474759fd67@10.50.10.170
[Apr 17 12:38:11] Really destroying SIP dialog '53652af21c2b7da91cc348474759fd67@10.50.10.170' Method: INVITE
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station3
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/station3 - state 1 (Not in use)
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480003
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480003
[Apr 17 12:38:11] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/station3' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station3
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station3
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 9725a45b6329ec40 (Checking To) --From tag as7a00d7fe --To-tag 7848c7d68a  
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 00fcf5a919c0925d367f3e50058a815d@10.50.10.170 Their Tag 237078023 Our tag: as0c6d66ab
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: E5590329@metaswitch Their Tag metaswitch+1+152c4c+1bd0e43a Our tag: as4e3f5fce
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 81B53564@metaswitch Their Tag metaswitch+1+0+3b613541 Our tag: as362a406f
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: dd10b1a34738ab4d Their Tag 77b7d14f5b Our tag: as1dd0a475
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 837ea325767f1de9 Their Tag 3f51b44f9f Our tag: as280c4623
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 15d1348704521dd4 Their Tag 4c422d9bd3 Our tag: as37f8b3bb
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: ea1422d6da5d499c Their Tag 97db527ab7 Our tag: as7e3d39aa
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: d35f662f5741e7de Their Tag 699674b6a1 Our tag: as7d40c545
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 2e09dea5d18da88f Their Tag d868bb9945 Our tag: as10a69e64
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 79c354cc2cd65ce5 Their Tag dcbb8dd9fa Our tag: as49dca80c
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 96684172b017967a Their Tag a54d687528 Our tag: as533bcc6b
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 67567c41516cb7d4 Their Tag f997f07c7f Our tag: as02447e94
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 013c92beb64b3dcb Their Tag ceb95399a7 Our tag: as0fffe3d0
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 48a1004e033532b8 Their Tag 8014521d7f Our tag: as7c1ce0cf
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 9725a45b6329ec40 Their Tag 7848c7d68a Our tag: as7a00d7fe
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2159 __sip_ack: Acked pending invite 106
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '9725a45b6329ec40' of Request 106: Match Found
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 67567c41516cb7d4 (Checking To) --From tag as02447e94 --To-tag f997f07c7f  
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 00fcf5a919c0925d367f3e50058a815d@10.50.10.170 Their Tag 237078023 Our tag: as0c6d66ab
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: E5590329@metaswitch Their Tag metaswitch+1+152c4c+1bd0e43a Our tag: as4e3f5fce
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 81B53564@metaswitch Their Tag metaswitch+1+0+3b613541 Our tag: as362a406f
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: dd10b1a34738ab4d Their Tag 77b7d14f5b Our tag: as1dd0a475
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 837ea325767f1de9 Their Tag 3f51b44f9f Our tag: as280c4623
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 15d1348704521dd4 Their Tag 4c422d9bd3 Our tag: as37f8b3bb
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: ea1422d6da5d499c Their Tag 97db527ab7 Our tag: as7e3d39aa
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: d35f662f5741e7de Their Tag 699674b6a1 Our tag: as7d40c545
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 2e09dea5d18da88f Their Tag d868bb9945 Our tag: as10a69e64
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 79c354cc2cd65ce5 Their Tag dcbb8dd9fa Our tag: as49dca80c
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 96684172b017967a Their Tag a54d687528 Our tag: as533bcc6b
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 67567c41516cb7d4 Their Tag f997f07c7f Our tag: as02447e94
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2159 __sip_ack: Acked pending invite 105
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '67567c41516cb7d4' of Request 105: Match Found
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 00fcf5a919c0925d367f3e50058a815d@10.50.10.170 (Checking To) --From tag as0c6d66ab --To-tag 237078023  
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 00fcf5a919c0925d367f3e50058a815d@10.50.10.170 Their Tag 237078023 Our tag: as0c6d66ab
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '00fcf5a919c0925d367f3e50058a815d@10.50.10.170' of Request 102: Match Found
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 00fcf5a919c0925d367f3e50058a815d@10.50.10.170 (Checking To) --From tag as0c6d66ab --To-tag 237078023  
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 00fcf5a919c0925d367f3e50058a815d@10.50.10.170 Their Tag 237078023 Our tag: as0c6d66ab
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '00fcf5a919c0925d367f3e50058a815d@10.50.10.170' of Request 102: Match Not Found
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:12062 handle_response_invite: SIP response 487 to standard invite
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:3205 update_call_counter: Updating call counter for outgoing call
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:3256 update_call_counter: Call to peer 'station1' removed from call limit 1
[Apr 17 12:38:11] DEBUG[12278]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station1
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:1656 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 00fcf5a919c0925d367f3e50058a815d@10.50.10.170
[Apr 17 12:38:11] Really destroying SIP dialog '00fcf5a919c0925d367f3e50058a815d@10.50.10.170' Method: INVITE
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station1
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station1
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/station1 - state 1 (Not in use)
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480616
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480616
[Apr 17 12:38:11] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/station1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 17 12:38:11] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station1
[Apr 17 12:38:11] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station1
[Apr 17 12:38:11] DEBUG[12336]: rtp.c:880 ast_rtcp_read: Got RTCP report of 20 bytes
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 15d1348704521dd4 (Checking To) --From tag as37f8b3bb --To-tag 4c422d9bd3  
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: E5590329@metaswitch Their Tag metaswitch+1+152c4c+1bd0e43a Our tag: as4e3f5fce
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 81B53564@metaswitch Their Tag metaswitch+1+0+3b613541 Our tag: as362a406f
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: dd10b1a34738ab4d Their Tag 77b7d14f5b Our tag: as1dd0a475
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 837ea325767f1de9 Their Tag 3f51b44f9f Our tag: as280c4623
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 15d1348704521dd4 Their Tag 4c422d9bd3 Our tag: as37f8b3bb
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2159 __sip_ack: Acked pending invite 104
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '15d1348704521dd4' of Request 104: Match Found
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 013c92beb64b3dcb (Checking To) --From tag as0fffe3d0 --To-tag ceb95399a7  
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: E5590329@metaswitch Their Tag metaswitch+1+152c4c+1bd0e43a Our tag: as4e3f5fce
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 81B53564@metaswitch Their Tag metaswitch+1+0+3b613541 Our tag: as362a406f
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: dd10b1a34738ab4d Their Tag 77b7d14f5b Our tag: as1dd0a475
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 837ea325767f1de9 Their Tag 3f51b44f9f Our tag: as280c4623
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 15d1348704521dd4 Their Tag 4c422d9bd3 Our tag: as37f8b3bb
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: ea1422d6da5d499c Their Tag 97db527ab7 Our tag: as7e3d39aa
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: d35f662f5741e7de Their Tag 699674b6a1 Our tag: as7d40c545
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 2e09dea5d18da88f Their Tag d868bb9945 Our tag: as10a69e64
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 79c354cc2cd65ce5 Their Tag dcbb8dd9fa Our tag: as49dca80c
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 96684172b017967a Their Tag a54d687528 Our tag: as533bcc6b
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 67567c41516cb7d4 Their Tag f997f07c7f Our tag: as02447e94
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 013c92beb64b3dcb Their Tag ceb95399a7 Our tag: as0fffe3d0
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2159 __sip_ack: Acked pending invite 104
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '013c92beb64b3dcb' of Request 104: Match Found
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 837ea325767f1de9 (Checking To) --From tag as280c4623 --To-tag 3f51b44f9f  
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: E5590329@metaswitch Their Tag metaswitch+1+152c4c+1bd0e43a Our tag: as4e3f5fce
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 81B53564@metaswitch Their Tag metaswitch+1+0+3b613541 Our tag: as362a406f
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: dd10b1a34738ab4d Their Tag 77b7d14f5b Our tag: as1dd0a475
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 837ea325767f1de9 Their Tag 3f51b44f9f Our tag: as280c4623
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2159 __sip_ack: Acked pending invite 104
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '837ea325767f1de9' of Request 104: Match Found
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 79c354cc2cd65ce5 (Checking To) --From tag as49dca80c --To-tag dcbb8dd9fa  
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: E5590329@metaswitch Their Tag metaswitch+1+152c4c+1bd0e43a Our tag: as4e3f5fce
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 81B53564@metaswitch Their Tag metaswitch+1+0+3b613541 Our tag: as362a406f
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: dd10b1a34738ab4d Their Tag 77b7d14f5b Our tag: as1dd0a475
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 837ea325767f1de9 Their Tag 3f51b44f9f Our tag: as280c4623
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 15d1348704521dd4 Their Tag 4c422d9bd3 Our tag: as37f8b3bb
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: ea1422d6da5d499c Their Tag 97db527ab7 Our tag: as7e3d39aa
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: d35f662f5741e7de Their Tag 699674b6a1 Our tag: as7d40c545
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 2e09dea5d18da88f Their Tag d868bb9945 Our tag: as10a69e64
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 79c354cc2cd65ce5 Their Tag dcbb8dd9fa Our tag: as49dca80c
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2159 __sip_ack: Acked pending invite 104
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '79c354cc2cd65ce5' of Request 104: Match Found
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 86c539d635a51342 (Checking To) --From tag as217100d9 --To-tag 63f589bc79  
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: E5590329@metaswitch Their Tag metaswitch+1+152c4c+1bd0e43a Our tag: as4e3f5fce
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 81B53564@metaswitch Their Tag metaswitch+1+0+3b613541 Our tag: as362a406f
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: dd10b1a34738ab4d Their Tag 77b7d14f5b Our tag: as1dd0a475
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 837ea325767f1de9 Their Tag 3f51b44f9f Our tag: as280c4623
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 15d1348704521dd4 Their Tag 4c422d9bd3 Our tag: as37f8b3bb
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: ea1422d6da5d499c Their Tag 97db527ab7 Our tag: as7e3d39aa
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: d35f662f5741e7de Their Tag 699674b6a1 Our tag: as7d40c545
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 2e09dea5d18da88f Their Tag d868bb9945 Our tag: as10a69e64
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 79c354cc2cd65ce5 Their Tag dcbb8dd9fa Our tag: as49dca80c
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 96684172b017967a Their Tag a54d687528 Our tag: as533bcc6b
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 67567c41516cb7d4 Their Tag f997f07c7f Our tag: as02447e94
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 013c92beb64b3dcb Their Tag ceb95399a7 Our tag: as0fffe3d0
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 48a1004e033532b8 Their Tag 8014521d7f Our tag: as7c1ce0cf
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 9725a45b6329ec40 Their Tag 7848c7d68a Our tag: as7a00d7fe
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 437cf766cb9011fb Their Tag f9005d88bd Our tag: as20b545b1
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: c66cf5021199e243 Their Tag 1cd0a9d42c Our tag: as42f4bf02
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 86c539d635a51342 Their Tag 63f589bc79 Our tag: as217100d9
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2159 __sip_ack: Acked pending invite 104
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '86c539d635a51342' of Request 104: Match Found
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: c66cf5021199e243 (Checking To) --From tag as42f4bf02 --To-tag 1cd0a9d42c  
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: E5590329@metaswitch Their Tag metaswitch+1+152c4c+1bd0e43a Our tag: as4e3f5fce
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 81B53564@metaswitch Their Tag metaswitch+1+0+3b613541 Our tag: as362a406f
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: dd10b1a34738ab4d Their Tag 77b7d14f5b Our tag: as1dd0a475
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 837ea325767f1de9 Their Tag 3f51b44f9f Our tag: as280c4623
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 15d1348704521dd4 Their Tag 4c422d9bd3 Our tag: as37f8b3bb
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: ea1422d6da5d499c Their Tag 97db527ab7 Our tag: as7e3d39aa
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: d35f662f5741e7de Their Tag 699674b6a1 Our tag: as7d40c545
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 2e09dea5d18da88f Their Tag d868bb9945 Our tag: as10a69e64
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 79c354cc2cd65ce5 Their Tag dcbb8dd9fa Our tag: as49dca80c
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 96684172b017967a Their Tag a54d687528 Our tag: as533bcc6b
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 67567c41516cb7d4 Their Tag f997f07c7f Our tag: as02447e94
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 013c92beb64b3dcb Their Tag ceb95399a7 Our tag: as0fffe3d0
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 48a1004e033532b8 Their Tag 8014521d7f Our tag: as7c1ce0cf
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 9725a45b6329ec40 Their Tag 7848c7d68a Our tag: as7a00d7fe
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 437cf766cb9011fb Their Tag f9005d88bd Our tag: as20b545b1
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: c66cf5021199e243 Their Tag 1cd0a9d42c Our tag: as42f4bf02
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2159 __sip_ack: Acked pending invite 104
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on 'c66cf5021199e243' of Request 104: Match Found
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 1f142aad15273705 (Checking To) --From tag as2dadd904 --To-tag 1778dd6ec5  
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: E5590329@metaswitch Their Tag metaswitch+1+152c4c+1bd0e43a Our tag: as4e3f5fce
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 81B53564@metaswitch Their Tag metaswitch+1+0+3b613541 Our tag: as362a406f
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: dd10b1a34738ab4d Their Tag 77b7d14f5b Our tag: as1dd0a475
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 837ea325767f1de9 Their Tag 3f51b44f9f Our tag: as280c4623
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 15d1348704521dd4 Their Tag 4c422d9bd3 Our tag: as37f8b3bb
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: ea1422d6da5d499c Their Tag 97db527ab7 Our tag: as7e3d39aa
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: d35f662f5741e7de Their Tag 699674b6a1 Our tag: as7d40c545
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 2e09dea5d18da88f Their Tag d868bb9945 Our tag: as10a69e64
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 79c354cc2cd65ce5 Their Tag dcbb8dd9fa Our tag: as49dca80c
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 96684172b017967a Their Tag a54d687528 Our tag: as533bcc6b
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 67567c41516cb7d4 Their Tag f997f07c7f Our tag: as02447e94
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 013c92beb64b3dcb Their Tag ceb95399a7 Our tag: as0fffe3d0
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 48a1004e033532b8 Their Tag 8014521d7f Our tag: as7c1ce0cf
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 9725a45b6329ec40 Their Tag 7848c7d68a Our tag: as7a00d7fe
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 437cf766cb9011fb Their Tag f9005d88bd Our tag: as20b545b1
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: c66cf5021199e243 Their Tag 1cd0a9d42c Our tag: as42f4bf02
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 86c539d635a51342 Their Tag 63f589bc79 Our tag: as217100d9
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 1f142aad15273705 Their Tag 1778dd6ec5 Our tag: as2dadd904
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2159 __sip_ack: Acked pending invite 105
[Apr 17 12:38:11] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '1f142aad15273705' of Request 105: Match Found
[Apr 17 12:38:15] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 (Checking From) --From tag 2122920226 --To-tag as51601a0d  
[Apr 17 12:38:15] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:15] DEBUG[12278]: chan_sip.c:15258 handle_request: **** Received BYE (8) - Command in SIP BYE
[Apr 17 12:38:15] DEBUG[12278]: chan_sip.c:1656 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170
[Apr 17 12:38:15] DEBUG[12278]: chan_sip.c:14798 handle_request_bye: Received bye, issuing owner hangup
[Apr 17 12:38:15] DEBUG[12336]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station1_line1
[Apr 17 12:38:15] DEBUG[12336]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station2_line1
[Apr 17 12:38:15] DEBUG[12336]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station3_line1
[Apr 17 12:38:15] DEBUG[12336]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station4_line1
[Apr 17 12:38:15] DEBUG[12336]: channel.c:1483 ast_hangup: Hanging up channel 'SIP/station2-ac08ec00'
[Apr 17 12:38:15] DEBUG[12336]: chan_sip.c:3517 sip_hangup: Hangup call SIP/station2-ac08ec00, SIP callid 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170)
[Apr 17 12:38:15] DEBUG[12336]: chan_sip.c:3205 update_call_counter: Updating call counter for outgoing call
[Apr 17 12:38:15] DEBUG[12336]: chan_sip.c:3256 update_call_counter: Call to peer 'station2' removed from call limit 1
[Apr 17 12:38:15] DEBUG[12336]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station2
[Apr 17 12:38:15] DEBUG[12336]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station2-ac08ec00
[Apr 17 12:38:15] DEBUG[12336]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/station2
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station1_line1
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SLA:station1_line1 - state 1 (Not in use)
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station1_line1
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station1_line1
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:15]  Extension Changed station1_line1[sla_stations] new state Idle for Notify User station1 
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station2_line1
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SLA:station2_line1 - state 1 (Not in use)
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station2_line1
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station2_line1
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:15]  Extension Changed station2_line1[sla_stations] new state Idle for Notify User station2 
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station3_line1
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SLA:station3_line1 - state 1 (Not in use)
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station3_line1
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station3_line1
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:15]  Extension Changed station3_line1[sla_stations] new state Idle for Notify User station3 
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station4_line1
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SLA:station4_line1 - state 1 (Not in use)
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station4_line1
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station4_line1
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:15]  Extension Changed station4_line1[sla_stations] new state Idle for Notify User station4 
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station2
[Apr 17 12:38:15] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station2
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/station2 - state 1 (Not in use)
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480617
[Apr 17 12:38:15] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/station2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 17 12:38:15] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480617
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station2
[Apr 17 12:38:15] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station2
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480617
[Apr 17 12:38:15] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480617
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station2
[Apr 17 12:38:15] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station2
[Apr 17 12:38:15]  Extension Changed 22[BLF] new state Idle for Notify User 5480003 
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480617
[Apr 17 12:38:15] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480617
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station2
[Apr 17 12:38:15] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station2
[Apr 17 12:38:15]  Extension Changed 22[BLF] new state Idle for Notify User 5480616 
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station2-ac08ec00
[Apr 17 12:38:15] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station2-ac08ec00
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/station2-ac08ec00 - state 4 (Invalid)
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station2
[Apr 17 12:38:15] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/station2-ac08ec00' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Apr 17 12:38:15] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station2
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/station2 - state 1 (Not in use)
[Apr 17 12:38:15] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/station2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5480617
[Apr 17 12:38:15] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5480617
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - station2
[Apr 17 12:38:15] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer station2
[Apr 17 12:38:15] DEBUG[12329]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel meetme:SLA_line1
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "meetme" - number: SLA_line1
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with meetme
[Apr 17 12:38:15] DEBUG[12329]: channel.c:1483 ast_hangup: Hanging up channel 'Zap/pseudo-1510813994'
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider Meetme with meetme
[Apr 17 12:38:15] DEBUG[12329]: chan_zap.c:2424 zt_hangup: zt_hangup(Zap/pseudo-1510813994)
[Apr 17 12:38:15] DEBUG[12329]: chan_zap.c:2458 zt_hangup: Hangup: channel: -2 index = 0, normal = 26, callwait = -1, thirdcall = -1
[Apr 17 12:38:15] DEBUG[12329]: chan_zap.c:2888 zt_setoption: Set option TDD MODE, value: OFF(0) on Zap/pseudo-1510813994
[Apr 17 12:38:15] DEBUG[12329]: chan_zap.c:1410 update_conf: Updated conferencing on -2, with 0 conference users
[Apr 17 12:38:15]     -- Hungup 'Zap/pseudo-1510813994'
[Apr 17 12:38:15] DEBUG[12329]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/pseudo-1510813994
[Apr 17 12:38:15] DEBUG[12329]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/pseudo
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for meetme:SLA_line1 - state 4 (Invalid)
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - pseudo-1510813994
[Apr 17 12:38:15] DEBUG[12329]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station1_line1
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for Zap/pseudo-1510813994 - state 0 (Unknown)
[Apr 17 12:38:15] DEBUG[12329]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station2_line1
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - pseudo
[Apr 17 12:38:15] DEBUG[12329]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station3_line1
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for Zap/pseudo - state 0 (Unknown)
[Apr 17 12:38:15] DEBUG[12329]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SLA:station4_line1
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station1_line1
[Apr 17 12:38:15] DEBUG[12329]: app_macro.c:337 _macro_exec: Executed application: SLATrunk
[Apr 17 12:38:15] DEBUG[12329]: pbx.c:1842 pbx_extension_helper: Launching 'Goto'
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:15]     -- Executing [s@macro-slaline:2] Goto("SIP/5060-01ed9ea0", "s-SUCCESS|1") in new stack
[Apr 17 12:38:15] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'Zap/pseudo-1510813994' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Apr 17 12:38:15] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'Zap/pseudo' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Apr 17 12:38:15]     -- Goto (macro-slaline,s-SUCCESS,1)
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SLA:station1_line1 - state 1 (Not in use)
[Apr 17 12:38:15] DEBUG[12329]: app_macro.c:337 _macro_exec: Executed application: Goto
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station1_line1
[Apr 17 12:38:15]   == Auto fallthrough, channel 'SIP/5060-01ed9ea0' status is 'UNKNOWN'
[Apr 17 12:38:15] DEBUG[12329]: channel.c:1384 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/5060-01ed9ea0'
[Apr 17 12:38:15] DEBUG[12329]: channel.c:1483 ast_hangup: Hanging up channel 'SIP/5060-01ed9ea0'
[Apr 17 12:38:15] DEBUG[12329]: chan_sip.c:3517 sip_hangup: Hangup call SIP/5060-01ed9ea0, SIP callid E5590329@metaswitch)
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station2_line1
[Apr 17 12:38:15] DEBUG[12329]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5060-01ed9ea0
[Apr 17 12:38:15] DEBUG[12329]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5060
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SLA:station2_line1 - state 1 (Not in use)
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station2_line1
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station3_line1
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SLA:station3_line1 - state 1 (Not in use)
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station3_line1
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station4_line1
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SLA:station4_line1 - state 1 (Not in use)
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:157 ast_device_state: Checking if I can find provider for "SLA" - number: station4_line1
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:230 getproviderstate: Checking provider SLA with SLA
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5060-01ed9ea0
[Apr 17 12:38:15] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5060-01ed9ea0
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/5060-01ed9ea0 - state 4 (Invalid)
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5060
[Apr 17 12:38:15] DEBUG[12272]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 5060
[Apr 17 12:38:15] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/5060-01ed9ea0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Apr 17 12:38:15] DEBUG[12272]: devicestate.c:287 do_state_change: Changing state for SIP/5060 - state 4 (Invalid)
[Apr 17 12:38:15] DEBUG[12298]: app_queue.c:659 handle_statechange: Device 'SIP/5060' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Apr 17 12:38:15] DEBUG[12278]: chan_sip.c:4585 find_call: = Looking for  Call ID: E5590329@metaswitch (Checking To) --From tag as4e3f5fce --To-tag metaswitch+1+152c4c+1bd0e43a  
[Apr 17 12:38:15] DEBUG[12278]: chan_sip.c:4601 find_call: = No match Their Call ID: 61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170 Their Tag 2122920226 Our tag: as51601a0d
[Apr 17 12:38:15] DEBUG[12278]: chan_sip.c:4601 find_call: = Found Their Call ID: E5590329@metaswitch Their Tag metaswitch+1+152c4c+1bd0e43a Our tag: as4e3f5fce
[Apr 17 12:38:15] DEBUG[12278]: chan_sip.c:2195 __sip_ack: Stopping retransmission on 'E5590329@metaswitch' of Request 102: Match Found
[Apr 17 12:38:15] Really destroying SIP dialog '61fe3f5b055e6e4b605c08a41ab2e188@10.50.10.170' Method: BYE
[Apr 17 12:38:15] Really destroying SIP dialog 'E5590329@metaswitch' Method: ACK