Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:11143 handle_request: **** Received INVITE (5) - Command in SIP INVITE
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:1033 parse_sip_options: * SIP extension value: 39 for call 62671354147200610912@172.17.1.10
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:7155 check_user_full: Setting NAT on RTP to 0
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:7159 check_user_full: Setting NAT on VRTP to 0
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:11143 handle_request: **** Received ACK (6) - Command in SIP ACK
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '62671354147200610912@172.17.1.10' of Response 1: Match Found
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:11143 handle_request: **** Received INVITE (5) - Command in SIP INVITE
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:7155 check_user_full: Setting NAT on RTP to 0
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:7159 check_user_full: Setting NAT on VRTP to 0
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:10497 handle_request_invite: Checking SIP call limits for device 511
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:2209 update_call_counter: Updating call counter for incoming call
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:6137 build_route: build_route: Contact hop: <sip:511@172.17.1.10>
Jul  4 12:09:12 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 511
Jul  4 12:09:12 DEBUG[16036]: channel.c:777 channel_find_locked: Avoiding initial deadlock for 'SIP/511-11c6'
Jul  4 12:09:12 DEBUG[16131]: pbx.c:1677 pbx_extension_helper: Launching 'Goto'
    -- Executing Goto("SIP/511-11c6", "test|100|1") in new stack
    -- Goto (test,100,1)
Jul  4 12:09:12 DEBUG[16131]: pbx.c:1677 pbx_extension_helper: Launching 'Dial'
    -- Executing Dial("SIP/511-11c6", "SIP/537") in new stack
Jul  4 12:09:12 DEBUG[16036]: devicestate.c:187 do_state_change: Changing state for SIP/511 - state 2 (In use)
Jul  4 12:09:12 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 511
Jul  4 12:09:12 DEBUG[16131]: chan_sip.c:3147 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
Jul  4 12:09:12 DEBUG[16131]: chan_sip.c:1874 create_addr_from_peer: Setting NAT on RTP to 0
Jul  4 12:09:12 DEBUG[16131]: chan_sip.c:1878 create_addr_from_peer: Setting NAT on VRTP to 0
Jul  4 12:09:12 DEBUG[16131]: acl.c:211 ast_apply_ha: ##### Testing 172.17.5.37 with 192.168.1.0
Jul  4 12:09:12 DEBUG[16131]: acl.c:211 ast_apply_ha: ##### Testing 172.17.5.37 with 172.17.0.0
Jul  4 12:09:12 DEBUG[16131]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-test-100-1.
Jul  4 12:09:12 DEBUG[16131]: channel.c:2823 ast_channel_inherit_variables: Not copying variable STACK-internal-100-1.
Jul  4 12:09:12 DEBUG[16131]: channel.c:2823 ast_channel_inherit_variables: Not copying variable SIPCALLID.
Jul  4 12:09:12 DEBUG[16131]: channel.c:2823 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT.
Jul  4 12:09:12 DEBUG[16131]: channel.c:2823 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
Jul  4 12:09:12 DEBUG[16131]: channel.c:2823 ast_channel_inherit_variables: Not copying variable SIPURI.
Jul  4 12:09:12 DEBUG[16131]: chan_sip.c:2068 sip_call: Outgoing Call for 537
Jul  4 12:09:12 DEBUG[16131]: chan_sip.c:2209 update_call_counter: Updating call counter for outgoing call
    -- Called 537
Jul  4 12:09:12 DEBUG[16131]: channel.c:2350 set_format: Set channel SIP/537-0d5d to read format alaw
Jul  4 12:09:12 DEBUG[16131]: channel.c:2350 set_format: Set channel SIP/511-11c6 to write format alaw
Jul  4 12:09:12 DEBUG[16131]: channel.c:2350 set_format: Set channel SIP/511-11c6 to read format alaw
Jul  4 12:09:12 DEBUG[16131]: channel.c:2350 set_format: Set channel SIP/537-0d5d to write format alaw
Jul  4 12:09:12 DEBUG[16132]: app_queue.c:523 changethread: Device 'SIP/511' changed to state '2' (In use) but we don't care because they're not a member of any queue.
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:1198 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 30 ms (t1 15 ms (Retrans id #605))
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:1198 retrans_pkt: ** SIP timers: Rescheduling retransmission 3 to 60 ms (t1 15 ms (Retrans id #605))
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:1198 retrans_pkt: ** SIP timers: Rescheduling retransmission 4 to 120 ms (t1 15 ms (Retrans id #605))
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:1198 retrans_pkt: ** SIP timers: Rescheduling retransmission 5 to 240 ms (t1 15 ms (Retrans id #605))
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:1454 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '329fd6e679c299304eeea8c453cda759@pbx.trends.nl' Request 102: Found
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:9584 handle_response_invite: SIP response 180 to standard invite
    -- SIP/537-0d5d is ringing
Jul  4 12:09:12 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
Jul  4 12:09:12 DEBUG[16036]: devicestate.c:187 do_state_change: Changing state for SIP/537 - state 6 (Ringing)
Jul  4 12:09:12 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
Jul  4 12:09:12 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
 Extension Changed 537 new state Ringing for Notify User 584
Jul  4 12:09:12 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
 Extension Changed 537 new state Ringing for Notify User 585
Jul  4 12:09:12 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
 Extension Changed 537 new state Ringing for Notify User 516
Jul  4 12:09:12 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
 Extension Changed 537 new state Ringing for Notify User 517
Jul  4 12:09:12 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
 Extension Changed 537 new state Ringing for Notify User 598
Jul  4 12:09:12 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
 Extension Changed 537 new state Ringing for Notify User 558
Jul  4 12:09:12 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
 Extension Changed 537 new state Ringing for Notify User 547
Jul  4 12:09:12 DEBUG[16133]: app_queue.c:523 changethread: Device 'SIP/537' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c26700d3345-l80dimw9exzw@snom360-000413231A8A' of Request 103: Match Found
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c26700d4e20-crtrmn89n8ul@snom360-0004132306B3' of Request 107: Match Found
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c267009be6e-tc2zwxmzjwva@snom320-0004132429F1' of Request 103: Match Found
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c26700bd467-azb40s7uwy3a@snom320-000413240720' of Request 106: Match Found
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c267009afc8-dl3cwilu2bzl@snom320-0004132445FC' of Request 107: Match Found
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c26700c8647-xahkiv25v6d5@snom360-000413231BA1' of Request 106: Match Found
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c26700caae6-py9zspt86vt5@snom190' of Request 107: Match Found
Jul  4 12:09:12 DEBUG[16043]: acl.c:211 ast_apply_ha: ##### Testing 172.17.5.37 with 192.168.1.0
Jul  4 12:09:12 DEBUG[16043]: acl.c:211 ast_apply_ha: ##### Testing 172.17.5.37 with 172.17.0.0
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:3147 sip_alloc: Allocating new SIP dialog for 3c26700a249f-i0hxl59ghtsd@snom360-00041323068A - REGISTER (No RTP)
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:11143 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:1454 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '329fd6e679c299304eeea8c453cda759@pbx.trends.nl' Request 102: Found
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:9584 handle_response_invite: SIP response 180 to standard invite
    -- SIP/537-0d5d is ringing
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:1454 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '329fd6e679c299304eeea8c453cda759@pbx.trends.nl' Request 102: Found
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:9584 handle_response_invite: SIP response 180 to standard invite
    -- SIP/537-0d5d is ringing
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:1454 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '329fd6e679c299304eeea8c453cda759@pbx.trends.nl' Request 102: Found
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:9584 handle_response_invite: SIP response 180 to standard invite
    -- SIP/537-0d5d is ringing
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:1454 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '329fd6e679c299304eeea8c453cda759@pbx.trends.nl' Request 102: Found
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:9584 handle_response_invite: SIP response 180 to standard invite
    -- SIP/537-0d5d is ringing
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:11143 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER
Jul  4 12:09:12 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
Jul  4 12:09:12 DEBUG[16036]: devicestate.c:187 do_state_change: Changing state for SIP/537 - state 6 (Ringing)
Jul  4 12:09:12 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
Jul  4 12:09:12 DEBUG[16134]: app_queue.c:523 changethread: Device 'SIP/537' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:1454 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '329fd6e679c299304eeea8c453cda759@pbx.trends.nl' Request 102: Found
Jul  4 12:09:12 DEBUG[16043]: chan_sip.c:9584 handle_response_invite: SIP response 180 to standard invite
    -- SIP/537-0d5d is ringing
Jul  4 12:09:13 DEBUG[16043]: acl.c:211 ast_apply_ha: ##### Testing 172.17.5.58 with 192.168.1.0
Jul  4 12:09:13 DEBUG[16043]: acl.c:211 ast_apply_ha: ##### Testing 172.17.5.58 with 172.17.0.0
Jul  4 12:09:13 DEBUG[16043]: chan_sip.c:3147 sip_alloc: Allocating new SIP dialog for 3c267009a393-nqlyfwrggqoo@snom320-0004132445FC - REGISTER (No RTP)
Jul  4 12:09:13 DEBUG[16043]: chan_sip.c:11143 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER
Jul  4 12:09:13 DEBUG[16043]: chan_sip.c:1454 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '329fd6e679c299304eeea8c453cda759@pbx.trends.nl' Request 102: Found
Jul  4 12:09:13 DEBUG[16043]: chan_sip.c:9584 handle_response_invite: SIP response 180 to standard invite
    -- SIP/537-0d5d is ringing
Jul  4 12:09:14 DEBUG[16043]: chan_sip.c:11143 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER
Jul  4 12:09:14 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 558
Jul  4 12:09:14 DEBUG[16036]: devicestate.c:187 do_state_change: Changing state for SIP/558 - state 1 (Not in use)
Jul  4 12:09:14 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 558
Jul  4 12:09:14 DEBUG[16135]: app_queue.c:523 changethread: Device 'SIP/558' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
Jul  4 12:09:14 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer Voipbuster6
Jul  4 12:09:14 DEBUG[16036]: devicestate.c:187 do_state_change: Changing state for SIP/Voipbuster6 - state 1 (Not in use)
Jul  4 12:09:14 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer Voipbuster5
Jul  4 12:09:14 DEBUG[16036]: devicestate.c:187 do_state_change: Changing state for SIP/Voipbuster5 - state 1 (Not in use)
Jul  4 12:09:14 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer Voipbuster4
Jul  4 12:09:14 DEBUG[16036]: devicestate.c:187 do_state_change: Changing state for SIP/Voipbuster4 - state 1 (Not in use)
Jul  4 12:09:14 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer Voipbuster3
Jul  4 12:09:14 DEBUG[16036]: devicestate.c:187 do_state_change: Changing state for SIP/Voipbuster3 - state 1 (Not in use)
Jul  4 12:09:14 DEBUG[16136]: app_queue.c:523 changethread: Device 'SIP/Voipbuster6' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
Jul  4 12:09:14 DEBUG[16137]: app_queue.c:523 changethread: Device 'SIP/Voipbuster5' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
Jul  4 12:09:14 DEBUG[16138]: app_queue.c:523 changethread: Device 'SIP/Voipbuster4' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
Jul  4 12:09:14 DEBUG[16139]: app_queue.c:523 changethread: Device 'SIP/Voipbuster3' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
Jul  4 12:09:14 DEBUG[16131]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes
Jul  4 12:09:14 DEBUG[16043]: acl.c:211 ast_apply_ha: ##### Testing 172.17.5.17 with 192.168.1.0
Jul  4 12:09:14 DEBUG[16043]: acl.c:211 ast_apply_ha: ##### Testing 172.17.5.17 with 172.17.0.0
Jul  4 12:09:14 DEBUG[16043]: chan_sip.c:3147 sip_alloc: Allocating new SIP dialog for 3c26700bc0df-j6r5pmp80mfi@snom320-000413240720 - REGISTER (No RTP)
Jul  4 12:09:14 DEBUG[16043]: chan_sip.c:11143 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER
Jul  4 12:09:14 DEBUG[16043]: chan_sip.c:1379 __sip_ack: Acked pending invite 102
Jul  4 12:09:14 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '329fd6e679c299304eeea8c453cda759@pbx.trends.nl' of Request 102: Match Found
Jul  4 12:09:14 DEBUG[16043]: chan_sip.c:9584 handle_response_invite: SIP response 200 to standard invite
Jul  4 12:09:14 DEBUG[16043]: chan_sip.c:6137 build_route: build_route: Contact hop: <sip:537@172.17.5.37:5060;line=rw9bi3ww>;flow-id=1
    -- SIP/537-0d5d answered SIP/511-11c6
Jul  4 12:09:14 DEBUG[16131]: channel.c:2350 set_format: Set channel SIP/511-11c6 to read format alaw
Jul  4 12:09:14 DEBUG[16131]: channel.c:2350 set_format: Set channel SIP/537-0d5d to write format alaw
Jul  4 12:09:14 DEBUG[16131]: channel.c:2350 set_format: Set channel SIP/537-0d5d to read format alaw
Jul  4 12:09:14 DEBUG[16131]: channel.c:2350 set_format: Set channel SIP/511-11c6 to write format alaw
Jul  4 12:09:14 DEBUG[16131]: chan_sip.c:2540 sip_answer: sip_answer(SIP/511-11c6)
    -- Attempting native bridge of SIP/511-11c6 and SIP/537-0d5d
Jul  4 12:09:14 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
Jul  4 12:09:14 DEBUG[16036]: devicestate.c:187 do_state_change: Changing state for SIP/537 - state 2 (In use)
Jul  4 12:09:14 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
Jul  4 12:09:14 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
 Extension Changed 537 new state InUse for Notify User 584
Jul  4 12:09:14 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
 Extension Changed 537 new state InUse for Notify User 585
Jul  4 12:09:14 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
 Extension Changed 537 new state InUse for Notify User 516
Jul  4 12:09:14 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
 Extension Changed 537 new state InUse for Notify User 517
Jul  4 12:09:14 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
 Extension Changed 537 new state InUse for Notify User 598
Jul  4 12:09:14 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
 Extension Changed 537 new state InUse for Notify User 558
Jul  4 12:09:14 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
 Extension Changed 537 new state InUse for Notify User 547
Jul  4 12:09:14 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 511
Jul  4 12:09:14 DEBUG[16036]: devicestate.c:187 do_state_change: Changing state for SIP/511 - state 2 (In use)
Jul  4 12:09:14 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 511
Jul  4 12:09:14 DEBUG[16140]: app_queue.c:523 changethread: Device 'SIP/537' changed to state '2' (In use) but we don't care because they're not a member of any queue.
Jul  4 12:09:14 DEBUG[16141]: app_queue.c:523 changethread: Device 'SIP/511' changed to state '2' (In use) but we don't care because they're not a member of any queue.
Jul  4 12:09:14 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c267009afc8-dl3cwilu2bzl@snom320-0004132445FC' of Request 108: Match Found
Jul  4 12:09:14 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c26700c8647-xahkiv25v6d5@snom360-000413231BA1' of Request 107: Match Found
Jul  4 12:09:14 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c26700d4e20-crtrmn89n8ul@snom360-0004132306B3' of Request 108: Match Found
Jul  4 12:09:14 DEBUG[16043]: chan_sip.c:1323 __sip_autodestruct: Auto destroying call '1168686935266200673356@172.17.1.10'
Jul  4 12:09:14 DEBUG[16043]: chan_sip.c:11143 handle_request: **** Received ACK (6) - Command in SIP ACK
Jul  4 12:09:14 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '62671354147200610912@172.17.1.10' of Response 2: Match Found
Jul  4 12:09:14 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c267009be6e-tc2zwxmzjwva@snom320-0004132429F1' of Request 104: Match Found
Jul  4 12:09:14 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c26700d3345-l80dimw9exzw@snom360-000413231A8A' of Request 104: Match Found
Jul  4 12:09:14 DEBUG[16043]: chan_sip.c:11143 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER
Jul  4 12:09:14 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 517
Jul  4 12:09:14 DEBUG[16036]: devicestate.c:187 do_state_change: Changing state for SIP/517 - state 1 (Not in use)
Jul  4 12:09:14 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 517
Jul  4 12:09:14 DEBUG[16142]: app_queue.c:523 changethread: Device 'SIP/517' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
Jul  4 12:09:14 DEBUG[16131]: rtp.c:1352 ast_rtp_write: Ooh, format changed from unknown to alaw
Jul  4 12:09:14 DEBUG[16131]: rtp.c:411 ast_rtcp_read: Got RTCP report of 44 bytes
Jul  4 12:09:14 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c26700bd467-azb40s7uwy3a@snom320-000413240720' of Request 107: Match Found
Jul  4 12:09:14 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c26700caae6-py9zspt86vt5@snom190' of Request 108: Match Found
Jul  4 12:09:14 DEBUG[16131]: rtp.c:1352 ast_rtp_write: Ooh, format changed from unknown to alaw
Jul  4 12:09:15 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '329fd6e679c299304eeea8c453cda759@pbx.trends.nl' of Request 102: Match Not Found
Jul  4 12:09:15 DEBUG[16043]: chan_sip.c:9582 handle_response_invite: SIP response 200 to RE-invite on outgoing call 329fd6e679c299304eeea8c453cda759@pbx.trends.nl
Jul  4 12:09:15 DEBUG[16043]: chan_sip.c:6080 build_route: build_route: Retaining previous route: <sip:537@172.17.5.37:5060;line=rw9bi3ww>
Jul  4 12:09:16 DEBUG[16043]: chan_sip.c:1323 __sip_autodestruct: Auto destroying call '1168687156266200673356@172.17.1.10'
Jul  4 12:09:16 DEBUG[16043]: chan_sip.c:1323 __sip_autodestruct: Auto destroying call '3c26700c2bf2-znwrtb9wqc90@snom360-0004132306B3'
Jul  4 12:09:16 DEBUG[16043]: chan_sip.c:11143 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE
Jul  4 12:09:16 DEBUG[16043]: chan_sip.c:10988 handle_request_subscribe: Adding subscription for extension 584 context internal for peer 517
Jul  4 12:09:16 DEBUG[16043]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 584
Jul  4 12:09:16 DEBUG[16043]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 584
Jul  4 12:09:16 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c26700bd467-x0nnczpbsqig@snom320-000413240720' of Request 103: Match Found
Jul  4 12:09:16 DEBUG[16043]: chan_sip.c:11143 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE
Jul  4 12:09:16 DEBUG[16043]: chan_sip.c:10988 handle_request_subscribe: Adding subscription for extension 585 context internal for peer 517
Jul  4 12:09:16 DEBUG[16043]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 585
Jul  4 12:09:16 DEBUG[16043]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 585
Jul  4 12:09:16 DEBUG[16043]: chan_sip.c:11143 handle_request: **** Received BYE (8) - Command in SIP BYE
Jul  4 12:09:16 DEBUG[16131]: channel.c:3275 ast_generic_bridge: Didn't get a frame from channel: SIP/537-0d5d
Jul  4 12:09:16 DEBUG[16131]: channel.c:3550 ast_channel_bridge: Bridge stops bridging channels SIP/511-11c6 and SIP/537-0d5d
Jul  4 12:09:16 DEBUG[16131]: channel.c:1323 ast_hangup: Hanging up channel 'SIP/537-0d5d'
Jul  4 12:09:16 DEBUG[16131]: chan_sip.c:2418 sip_hangup: Hangup call SIP/537-0d5d, SIP callid 329fd6e679c299304eeea8c453cda759@pbx.trends.nl)
Jul  4 12:09:16 DEBUG[16131]: chan_sip.c:2426 sip_hangup: update_call_counter(537) - decrement call limit counter
Jul  4 12:09:16 DEBUG[16131]: chan_sip.c:2209 update_call_counter: Updating call counter for outgoing call
Jul  4 12:09:16 DEBUG[16131]: app_dial.c:1628 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
Jul  4 12:09:16 DEBUG[16131]: pbx.c:2316 __ast_pbx_run: Spawn extension (test,100,1) exited non-zero on 'SIP/511-11c6'
Jul  4 12:09:16 DEBUG[16131]: pbx.c:1677 pbx_extension_helper: Launching 'Macro'
    -- Executing Macro("SIP/511-11c6", "enddial|ANSWER") in new stack
Jul  4 12:09:16 DEBUG[16131]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp'
    -- Executing NoOp("SIP/511-11c6", "Macro-enddial: ANSWER") in new stack
Jul  4 12:09:16 DEBUG[16131]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp'
    -- Executing NoOp("SIP/511-11c6", "Evaluate the call after hangup") in new stack
Jul  4 12:09:16 DEBUG[16131]: pbx.c:1677 pbx_extension_helper: Launching 'Macro'
    -- Executing Macro("SIP/511-11c6", "test") in new stack
Jul  4 12:09:16 DEBUG[16131]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp'
    -- Executing NoOp("SIP/511-11c6", "Test macro Line1") in new stack
Jul  4 12:09:16 DEBUG[16131]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp'
    -- Executing NoOp("SIP/511-11c6", "Test macro Line2") in new stack
Jul  4 12:09:16 DEBUG[16131]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp'
    -- Executing NoOp("SIP/511-11c6", "Test macro Line3") in new stack
Jul  4 12:09:16 DEBUG[16131]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp'
    -- Executing NoOp("SIP/511-11c6", "end macro enddial") in new stack
Jul  4 12:09:16 DEBUG[16131]: pbx.c:1677 pbx_extension_helper: Launching 'Hangup'
    -- Executing Hangup("SIP/511-11c6", "") in new stack
Jul  4 12:09:16 DEBUG[16131]: pbx.c:2454 __ast_pbx_run: Spawn extension (test,h,2) exited non-zero on 'SIP/511-11c6'
Jul  4 12:09:16 DEBUG[16131]: cdr.c:992 ast_cdr_detach: Dropping CDR !
Jul  4 12:09:16 DEBUG[16131]: channel.c:1323 ast_hangup: Hanging up channel 'SIP/511-11c6'
Jul  4 12:09:16 DEBUG[16131]: chan_sip.c:2418 sip_hangup: Hangup call SIP/511-11c6, SIP callid 62671354147200610912@172.17.1.10)
Jul  4 12:09:16 DEBUG[16131]: chan_sip.c:2426 sip_hangup: update_call_counter(511) - decrement call limit counter
Jul  4 12:09:16 DEBUG[16131]: chan_sip.c:2209 update_call_counter: Updating call counter for incoming call
Jul  4 12:09:16 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
Jul  4 12:09:16 DEBUG[16036]: devicestate.c:187 do_state_change: Changing state for SIP/537 - state 1 (Not in use)
Jul  4 12:09:16 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
Jul  4 12:09:16 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
 Extension Changed 537 new state Idle for Notify User 584
Jul  4 12:09:16 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
 Extension Changed 537 new state Idle for Notify User 585
Jul  4 12:09:16 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
 Extension Changed 537 new state Idle for Notify User 516
Jul  4 12:09:16 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
 Extension Changed 537 new state Idle for Notify User 517
Jul  4 12:09:16 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
 Extension Changed 537 new state Idle for Notify User 598
Jul  4 12:09:16 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
 Extension Changed 537 new state Idle for Notify User 558
Jul  4 12:09:16 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
 Extension Changed 537 new state Idle for Notify User 547
Jul  4 12:09:16 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 511
Jul  4 12:09:16 DEBUG[16036]: devicestate.c:187 do_state_change: Changing state for SIP/511 - state 1 (Not in use)
Jul  4 12:09:16 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 511
Jul  4 12:09:16 DEBUG[16143]: app_queue.c:523 changethread: Device 'SIP/537' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
Jul  4 12:09:16 DEBUG[16144]: app_queue.c:523 changethread: Device 'SIP/511' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
Jul  4 12:09:16 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '62671354147200610912@172.17.1.10' of Request 102: Match Found
Jul  4 12:09:16 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c26700d3345-l80dimw9exzw@snom360-000413231A8A' of Request 105: Match Found
Jul  4 12:09:16 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c26700c8647-xahkiv25v6d5@snom360-000413231BA1' of Request 108: Match Found
Jul  4 12:09:17 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c26700d4e20-crtrmn89n8ul@snom360-0004132306B3' of Request 109: Match Found
Jul  4 12:09:17 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c26700bd6d8-gbepnqgp6fa6@snom320-000413240720' of Request 103: Match Found
Jul  4 12:09:17 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c267009be6e-tc2zwxmzjwva@snom320-0004132429F1' of Request 105: Match Found
Jul  4 12:09:17 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c26700bd467-azb40s7uwy3a@snom320-000413240720' of Request 108: Match Found
Jul  4 12:09:17 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c267009afc8-dl3cwilu2bzl@snom320-0004132445FC' of Request 109: Match Found
Jul  4 12:09:17 DEBUG[16043]: chan_sip.c:11143 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE
Jul  4 12:09:17 DEBUG[16043]: chan_sip.c:10988 handle_request_subscribe: Adding subscription for extension 537 context internal for peer 517
Jul  4 12:09:17 DEBUG[16043]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
Jul  4 12:09:17 DEBUG[16043]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 537
Jul  4 12:09:17 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c26700caae6-py9zspt86vt5@snom190' of Request 109: Match Found
Jul  4 12:09:17 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c26700bd467-azb40s7uwy3a@snom320-000413240720' of Request 109: Match Found
Jul  4 12:09:17 DEBUG[16043]: chan_sip.c:11143 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE
Jul  4 12:09:17 DEBUG[16043]: chan_sip.c:10988 handle_request_subscribe: Adding subscription for extension 547 context internal for peer 517
Jul  4 12:09:17 DEBUG[16043]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 547
Jul  4 12:09:17 DEBUG[16043]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 547
Jul  4 12:09:17 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c26700bd467-1b085hqsb1z9@snom320-000413240720' of Request 103: Match Found
Jul  4 12:09:17 DEBUG[16043]: chan_sip.c:11143 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE
Jul  4 12:09:17 DEBUG[16043]: chan_sip.c:10988 handle_request_subscribe: Adding subscription for extension 516 context internal for peer 517
Jul  4 12:09:17 DEBUG[16043]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 516
Jul  4 12:09:17 DEBUG[16043]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 516
Jul  4 12:09:17 DEBUG[16043]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '3c26700bd1f6-yp2nlwa1h3a4@snom320-000413240720' of Request 103: Match Found
Jul  4 12:09:17 DEBUG[16043]: acl.c:211 ast_apply_ha: ##### Testing 172.17.5.84 with 192.168.1.0
Jul  4 12:09:17 DEBUG[16043]: acl.c:211 ast_apply_ha: ##### Testing 172.17.5.84 with 172.17.0.0
Jul  4 12:09:17 DEBUG[16043]: chan_sip.c:3147 sip_alloc: Allocating new SIP dialog for 3c26700bd949-ylc82ej6twi9@snom360-000413231A8A - REGISTER (No RTP)
Jul  4 12:09:17 DEBUG[16043]: chan_sip.c:11143 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER
Jul  4 12:09:18 DEBUG[16043]: chan_sip.c:11143 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER
Jul  4 12:09:18 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 584
Jul  4 12:09:18 DEBUG[16036]: devicestate.c:187 do_state_change: Changing state for SIP/584 - state 1 (Not in use)
Jul  4 12:09:18 DEBUG[16036]: chan_sip.c:11674 sip_devicestate: Checking device state for peer 584
Jul  4 12:09:18 DEBUG[16145]: app_queue.c:492 changethread: Device 'SIP/584' changed to state '1' (Not in use)
Jul  4 12:09:18 DEBUG[16043]: chan_sip.c:1323 __sip_autodestruct: Auto destroying call '3c26700a3d09-x0ht59c4oz70@snom360-000413231BA1'