[Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:8088 find_call: = Looking for Call ID: 4989f87ac39d498882ba90e86679be04 (Checking From) --From tag b74822e52cbb45a99492d985fa0e0432 --To-tag [Mar 12 18:20:25] DEBUG[7868]: acl.c:728 ast_ouraddrfor: For destination '10.1.50.254', our source address is '10.1.52.57'. [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.1.52.57:5060 [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:7768 sip_alloc: Allocating new SIP dialog for 4989f87ac39d498882ba90e86679be04 - REGISTER (No RTP) [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:25049 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER [Mar 12 18:20:25] DEBUG[7868]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.86.0.50:61363' into... [Mar 12 18:20:25] DEBUG[7868]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.86.0.50' and port '61363'. [Mar 12 18:20:25] DEBUG[7868]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.1.52.57' into... [Mar 12 18:20:25] DEBUG[7868]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.1.52.57' and port ''. [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:638 substituted: substituted: string: 'dc=showingtime,dc=com' => 'dc=showingtime,dc=com' [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:665 cleaned_basedn: basedn: 'dc=showingtime,dc=com' => 'dc=showingtime,dc=com' [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:1736 ldap_reconnect: Everything seems fine. [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:702 append_var_and_value_to_filter: name='name' value='14484442' [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:702 append_var_and_value_to_filter: name='host' value='dynamic' [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: sn LDAP value: 14484442 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: objectClass LDAP value: inetOrgPerson [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: objectClass LDAP value: AsteriskQueueMember [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: objectClass LDAP value: AsteriskSIPUser [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: objectClass LDAP value: AsteriskExtension [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: callerid LDAP value: "Andrew CSR" <2001> [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: canreinvite LDAP value: no [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: context LDAP value: manual_dial [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: dtmfmode LDAP value: rfc2833 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: allow LDAP value: ulaw [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstAccountName LDAP value: 14484442 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: nat LDAP value: yes [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: qualify LDAP value: yes [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: type LDAP value: friend [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: host LDAP value: dynamic [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstAccountSecret LDAP value: FF9260DEC84DB1A527FA2C94985C3BEB6E1D45B9 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstQueueInterface LDAP value: SIP/14484442 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstQueueMembername LDAP value: andrew.csr [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstQueueMemberof LDAP value: ApptCenter [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: uid LDAP value: 2001 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstApplication LDAP value: Dial [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstApplicationData LDAP value: SIP/14484442 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstContext LDAP value: AC_Users [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstExtension LDAP value: 2001 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstPriority LDAP value: 1 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: name LDAP value: 14484442 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstQueuePaused LDAP value: 0 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: ipaddr LDAP value: (null) [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: port LDAP value: (null) [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: regseconds LDAP value: 1331593016 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: defaultuser LDAP value: 14484442 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: lastms LDAP value: 2 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: sn value: 14484442 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: objectClass value: inetOrgPerson [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: objectClass value: AsteriskQueueMember [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: objectClass value: AsteriskSIPUser [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: objectClass value: AsteriskExtension [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: callerid value: "Andrew CSR" <2001> [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: canreinvite value: no [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: context value: manual_dial [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: dtmfmode value: rfc2833 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: allow value: ulaw [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstAccountName value: 14484442 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: nat value: yes [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: qualify value: yes [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: type value: friend [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: host value: dynamic [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstAccountSecret value: FF9260DEC84DB1A527FA2C94985C3BEB6E1D45B9 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstQueueInterface value: SIP/14484442 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstQueueMembername value: andrew.csr [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstQueueMemberof value: ApptCenter [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: uid value: 2001 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstApplication value: Dial [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstApplicationData value: SIP/14484442 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstContext value: AC_Users [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstExtension value: 2001 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstPriority value: 1 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: name value: 14484442 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstQueuePaused value: 0 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: ipaddr value: (null) [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: port value: (null) [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: regseconds value: 1331593016 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: defaultuser value: 14484442 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: lastms value: 2 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:533 realtime_ldap_result_to_vars: LINE(533) Added to vars - non static [Mar 12 18:20:25] DEBUG[7868]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '(null)' into... [Mar 12 18:20:25] DEBUG[7868]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '(null)' and port ''. [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:27751 build_peer: Not an IPv4 nor IPv6 address, cannot get port. [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:27754 build_peer: Not an IPv4 nor IPv6 address, cannot set port. [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:27756 build_peer: Not an IPv4 nor IPv6 address, cannot get port. [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:27759 build_peer: Not an IPv4 nor IPv6 address, cannot set port. [Mar 12 18:20:25] DEBUG[7868]: db.c:337 ast_db_del: Unable to find key '14484442' in family 'SIP/PeerMethods' [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:27772 build_peer: Bah, we're expired (1409/1331593016/1331594425)! [Mar 12 18:20:25] DEBUG[7868]: db.c:293 ast_db_get: Unable to find key '14484442' in family 'SIP/Registry' [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:4969 realtime_peer: -REALTIME- loading peer from database to memory. Name: 14484442. Peer objects: 0 [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:14065 parse_register_contact: Store REGISTER's src-IP:port for call routing. -- Registered SIP '14484442' at 10.1.50.254:61363 [Mar 12 18:20:25] DEBUG[7906]: manager.c:4216 match_filter: Examining event: Event: PeerStatus Privilege: system,all ChannelType: SIP Peer: SIP/14484442 PeerStatus: Registered Address: 10.1.50.254:61363 [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:7768 sip_alloc: Allocating new SIP dialog for 71009b4b5c50ad08576810fa116aef19@10.1.52.57:5060 - OPTIONS (No RTP) [Mar 12 18:20:25] DEBUG[7868]: acl.c:728 ast_ouraddrfor: For destination '10.1.50.254', our source address is '10.1.52.57'. [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.1.52.57:5060 [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:3073 initialize_initreq: Initializing initreq for method OPTIONS - callid 30567e9838063eca738e16a933e3c519@10.1.52.57:5060 [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:3344 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.1.50.254:61363 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:1736 ldap_reconnect: Everything seems fine. [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:638 substituted: substituted: string: 'dc=showingtime,dc=com' => 'dc=showingtime,dc=com' [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:665 cleaned_basedn: basedn: 'dc=showingtime,dc=com' => 'dc=showingtime,dc=com' [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:702 append_var_and_value_to_filter: name='name' value='14484442' [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:1319 update_ldap: LINE(1319) Modifying name=14484442 hits: 1 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:1322 update_ldap: LINE(1322) AstAccountIpaddr=10.1.50.254 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:1322 update_ldap: LINE(1322) AstAccountPort=61363 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:1322 update_ldap: LINE(1322) AstAccountExpirationTimestamp=1331594485 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:1322 update_ldap: LINE(1322) AstAccountDefaultuser=14484442 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:1324 update_ldap: LINE(1324) deleting AstAccountUserAgent [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:1322 update_ldap: LINE(1322) AstAccountLastms=-1 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:1322 update_ldap: LINE(1322) AstAccountFullContact=sip:14484442@10.86.0.50:61363;ob [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:3344 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.1.50.254:61363 [Mar 12 18:20:25] DEBUG[7868]: devicestate.c:491 ast_devstate_changed_literal: ast_devstate_changed_literal Device state change SIP/14484442 0 [Mar 12 18:20:25] DEBUG[7871]: devicestate.c:548 do_devstate_changes: do_devstate_changes state change -201319224 [Mar 12 18:20:25] DEBUG[7871]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 14484442 [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:8088 find_call: = Looking for Call ID: 30567e9838063eca738e16a933e3c519@10.1.52.57:5060 (Checking To) --From tag as6ec8485f --To-tag z9hG4bK15c353b9 [Mar 12 18:20:25] DEBUG[7871]: chan_sip.c:26317 sip_devicestate: Checking device state for peer 14484442 [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:4029 __sip_ack: Stopping retransmission on '30567e9838063eca738e16a933e3c519@10.1.52.57:5060' of Request 102: Match Found [Mar 12 18:20:25] DEBUG[7871]: devicestate.c:458 do_state_change: Changing state for SIP/14484442 - state 5 (Unavailable) [Mar 12 18:20:25] DEBUG[7871]: devicestate.c:438 devstate_event: device 'SIP/14484442' state '5' [Mar 12 18:20:25] NOTICE[7868]: chan_sip.c:20768 handle_response_peerpoke: Peer '14484442' is now Reachable. (10ms / 2000ms) [Mar 12 18:20:25] DEBUG[7868]: devicestate.c:491 ast_devstate_changed_literal: ast_devstate_changed_literal Device state change SIP/14484442 0 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:1736 ldap_reconnect: Everything seems fine. [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:638 substituted: substituted: string: 'dc=showingtime,dc=com' => 'dc=showingtime,dc=com' [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:665 cleaned_basedn: basedn: 'dc=showingtime,dc=com' => 'dc=showingtime,dc=com' [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:702 append_var_and_value_to_filter: name='name' value='14484442' [Mar 12 18:20:25] DEBUG[7869]: app_queue.c:1485 handle_statechange: Device 'SIP/14484442' changed to state '5' (Unavailable) [Mar 12 18:20:25] DEBUG[7906]: manager.c:4216 match_filter: Examining event: Event: QueueMemberStatus Privilege: agent,all Queue: ApptCenter Location: SIP/14484442 MemberName: andrew.csr Membership: realtime Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 5 Paused: 0 [Mar 12 18:20:25] DEBUG[7871]: devicestate.c:548 do_devstate_changes: do_devstate_changes state change -201281320 [Mar 12 18:20:25] DEBUG[7871]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 14484442 [Mar 12 18:20:25] DEBUG[7871]: chan_sip.c:26317 sip_devicestate: Checking device state for peer 14484442 [Mar 12 18:20:25] DEBUG[7871]: devicestate.c:458 do_state_change: Changing state for SIP/14484442 - state 1 (Not in use) [Mar 12 18:20:25] DEBUG[7871]: devicestate.c:438 devstate_event: device 'SIP/14484442' state '1' [Mar 12 18:20:25] DEBUG[7869]: app_queue.c:1485 handle_statechange: Device 'SIP/14484442' changed to state '1' (Not in use) [Mar 12 18:20:25] DEBUG[7906]: manager.c:4216 match_filter: Examining event: Event: QueueMemberStatus Privilege: agent,all Queue: ApptCenter Location: SIP/14484442 MemberName: andrew.csr Membership: realtime Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 1 Paused: 0 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:1319 update_ldap: LINE(1319) Modifying name=14484442 hits: 1 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:1322 update_ldap: LINE(1322) AstAccountLastms=10 [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:6048 sip_destroy: Destroying SIP dialog 30567e9838063eca738e16a933e3c519@10.1.52.57:5060 [Mar 12 18:20:25] DEBUG[7906]: manager.c:4216 match_filter: Examining event: Event: PeerStatus Privilege: system,all ChannelType: SIP Peer: SIP/14484442 PeerStatus: Reachable Time: 10 [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:8088 find_call: = Looking for Call ID: 4989f87ac39d498882ba90e86679be04 (Checking From) --From tag 21f5035e06de41909e1cb2c7962b7bce --To-tag [Mar 12 18:20:25] DEBUG[7868]: acl.c:728 ast_ouraddrfor: For destination '10.1.50.254', our source address is '10.1.52.57'. [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.1.52.57:5060 [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:7768 sip_alloc: Allocating new SIP dialog for 4989f87ac39d498882ba90e86679be04 - REGISTER (No RTP) [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:25049 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER [Mar 12 18:20:25] DEBUG[7868]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.1.50.254:61363' into... [Mar 12 18:20:25] DEBUG[7868]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.1.50.254' and port '61363'. [Mar 12 18:20:25] DEBUG[7868]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.1.52.57' into... [Mar 12 18:20:25] DEBUG[7868]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.1.52.57' and port ''. [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:14065 parse_register_contact: Store REGISTER's src-IP:port for call routing. [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:7768 sip_alloc: Allocating new SIP dialog for 4107aec45d65986c4440a98255fff5ad@10.1.52.57:5060 - OPTIONS (No RTP) [Mar 12 18:20:25] DEBUG[7868]: acl.c:728 ast_ouraddrfor: For destination '10.1.50.254', our source address is '10.1.52.57'. [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.1.52.57:5060 [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:3073 initialize_initreq: Initializing initreq for method OPTIONS - callid 0ae9c5f3379cbd301f5a9ab47726ac59@10.1.52.57:5060 [Mar 12 18:20:25] DEBUG[7906]: manager.c:4216 match_filter: Examining event: Event: PeerStatus Privilege: system,all ChannelType: SIP Peer: SIP/14484442 PeerStatus: Registered Address: 10.1.50.254:61363 [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:3344 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.1.50.254:61363 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:1736 ldap_reconnect: Everything seems fine. [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:638 substituted: substituted: string: 'dc=showingtime,dc=com' => 'dc=showingtime,dc=com' [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:665 cleaned_basedn: basedn: 'dc=showingtime,dc=com' => 'dc=showingtime,dc=com' [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:702 append_var_and_value_to_filter: name='name' value='14484442' [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:1319 update_ldap: LINE(1319) Modifying name=14484442 hits: 1 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:1322 update_ldap: LINE(1322) AstAccountIpaddr=10.1.50.254 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:1322 update_ldap: LINE(1322) AstAccountPort=61363 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:1322 update_ldap: LINE(1322) AstAccountExpirationTimestamp=1331594485 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:1322 update_ldap: LINE(1322) AstAccountDefaultuser=14484442 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:1324 update_ldap: LINE(1324) deleting AstAccountUserAgent [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:1322 update_ldap: LINE(1322) AstAccountLastms=10 [Mar 12 18:20:25] DEBUG[7868]: res_config_ldap.c:1322 update_ldap: LINE(1322) AstAccountFullContact=sip:14484442@10.1.50.254:61363;transport=UDP;ob [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:3344 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.1.50.254:61363 [Mar 12 18:20:25] DEBUG[7868]: devicestate.c:491 ast_devstate_changed_literal: ast_devstate_changed_literal Device state change SIP/14484442 0 [Mar 12 18:20:25] DEBUG[7871]: devicestate.c:548 do_devstate_changes: do_devstate_changes state change -201276856 [Mar 12 18:20:25] DEBUG[7871]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 14484442 [Mar 12 18:20:25] DEBUG[7871]: chan_sip.c:26317 sip_devicestate: Checking device state for peer 14484442 [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:8088 find_call: = Looking for Call ID: 0ae9c5f3379cbd301f5a9ab47726ac59@10.1.52.57:5060 (Checking To) --From tag as38f48174 --To-tag z9hG4bK1f99d486 [Mar 12 18:20:25] DEBUG[7871]: devicestate.c:458 do_state_change: Changing state for SIP/14484442 - state 1 (Not in use) [Mar 12 18:20:25] DEBUG[7871]: devicestate.c:438 devstate_event: device 'SIP/14484442' state '1' [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:4029 __sip_ack: Stopping retransmission on '0ae9c5f3379cbd301f5a9ab47726ac59@10.1.52.57:5060' of Request 102: Match Found [Mar 12 18:20:25] DEBUG[7868]: chan_sip.c:6048 sip_destroy: Destroying SIP dialog 0ae9c5f3379cbd301f5a9ab47726ac59@10.1.52.57:5060 [Mar 12 18:20:25] DEBUG[7869]: app_queue.c:1485 handle_statechange: Device 'SIP/14484442' changed to state '1' (Not in use) [Mar 12 18:20:25] DEBUG[7906]: manager.c:4216 match_filter: Examining event: Event: QueueMemberStatus Privilege: agent,all Queue: ApptCenter Location: SIP/14484442 MemberName: andrew.csr Membership: realtime Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 1 Paused: 0 [Mar 12 18:20:25] DEBUG[7906]: manager.c:4623 process_message: Running action 'QueuePause' [Mar 12 18:20:25] DEBUG[7906]: res_config_ldap.c:1736 ldap_reconnect: Everything seems fine. [Mar 12 18:20:25] DEBUG[7906]: res_config_ldap.c:638 substituted: substituted: string: 'dc=showingtime,dc=com' => 'dc=showingtime,dc=com' [Mar 12 18:20:25] DEBUG[7906]: res_config_ldap.c:665 cleaned_basedn: basedn: 'dc=showingtime,dc=com' => 'dc=showingtime,dc=com' [Mar 12 18:20:25] DEBUG[7906]: res_config_ldap.c:702 append_var_and_value_to_filter: name='uniqueid' value='2001' [Mar 12 18:20:25] DEBUG[7906]: res_config_ldap.c:1319 update_ldap: LINE(1319) Modifying uniqueid=2001 hits: 1 [Mar 12 18:20:25] DEBUG[7906]: res_config_ldap.c:1322 update_ldap: LINE(1322) AstQueuePaused=1 [Mar 12 18:20:25] DEBUG[7906]: db.c:337 ast_db_del: Unable to find key 'ApptCenter' in family 'Queue/PersistentMembers' [Mar 12 18:20:25] DEBUG[7906]: manager.c:4216 match_filter: Examining event: Event: QueueMemberPaused Privilege: agent,all Queue: ApptCenter Location: SIP/14484442 MemberName: andrew.csr Paused: 1 Reason: New Login [Mar 12 18:20:25] DEBUG[7906]: manager.c:4623 process_message: Running action 'QueueLog' [Mar 12 18:20:25] DEBUG[7906]: manager.c:4623 process_message: Running action 'QueuePause' [Mar 12 18:20:25] DEBUG[7906]: res_config_ldap.c:1736 ldap_reconnect: Everything seems fine. [Mar 12 18:20:25] DEBUG[7906]: res_config_ldap.c:638 substituted: substituted: string: 'dc=showingtime,dc=com' => 'dc=showingtime,dc=com' [Mar 12 18:20:25] DEBUG[7906]: res_config_ldap.c:665 cleaned_basedn: basedn: 'dc=showingtime,dc=com' => 'dc=showingtime,dc=com' [Mar 12 18:20:25] DEBUG[7906]: res_config_ldap.c:702 append_var_and_value_to_filter: name='uniqueid' value='2001' [Mar 12 18:20:25] DEBUG[7906]: res_config_ldap.c:1319 update_ldap: LINE(1319) Modifying uniqueid=2001 hits: 1 [Mar 12 18:20:25] DEBUG[7906]: res_config_ldap.c:1322 update_ldap: LINE(1322) AstQueuePaused=0 [Mar 12 18:20:25] DEBUG[7906]: db.c:337 ast_db_del: Unable to find key 'ApptCenter' in family 'Queue/PersistentMembers' [Mar 12 18:20:25] DEBUG[7906]: manager.c:4216 match_filter: Examining event: Event: QueueMemberPaused Privilege: agent,all Queue: ApptCenter Location: SIP/14484442 MemberName: andrew.csr Paused: 0 [Mar 12 18:20:28] DEBUG[7868]: chan_sip.c:8088 find_call: = Looking for Call ID: 4989f87ac39d498882ba90e86679be04 (Checking From) --From tag ea634abff3114bf09e331fd96c456a38 --To-tag [Mar 12 18:20:28] DEBUG[7868]: acl.c:728 ast_ouraddrfor: For destination '10.1.50.254', our source address is '10.1.52.57'. [Mar 12 18:20:28] DEBUG[7868]: chan_sip.c:3498 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.1.52.57:5060 [Mar 12 18:20:28] DEBUG[7868]: chan_sip.c:7768 sip_alloc: Allocating new SIP dialog for 4989f87ac39d498882ba90e86679be04 - REGISTER (No RTP) [Mar 12 18:20:28] DEBUG[7868]: chan_sip.c:25049 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER [Mar 12 18:20:28] DEBUG[7868]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.1.50.254:61363' into... [Mar 12 18:20:28] DEBUG[7868]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.1.50.254' and port '61363'. [Mar 12 18:20:28] DEBUG[7868]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.1.52.57' into... [Mar 12 18:20:28] DEBUG[7868]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.1.52.57' and port ''. -- Unregistered SIP '14484442' [Mar 12 18:20:28] DEBUG[7868]: db.c:337 ast_db_del: Unable to find key '14484442' in family 'SIP/PeerMethods' [Mar 12 18:20:28] DEBUG[7868]: devicestate.c:491 ast_devstate_changed_literal: ast_devstate_changed_literal Device state change SIP/14484442 0 [Mar 12 18:20:28] DEBUG[7868]: chan_sip.c:13712 expire_register: -REALTIME- peer expired registration. Name: 14484442. Realtime peer objects now 0 [Mar 12 18:20:28] DEBUG[7868]: res_config_ldap.c:1736 ldap_reconnect: Everything seems fine. [Mar 12 18:20:28] DEBUG[7871]: devicestate.c:548 do_devstate_changes: do_devstate_changes state change -201275496 [Mar 12 18:20:28] DEBUG[7868]: res_config_ldap.c:638 substituted: substituted: string: 'dc=showingtime,dc=com' => 'dc=showingtime,dc=com' [Mar 12 18:20:28] DEBUG[7871]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 14484442 [Mar 12 18:20:28] DEBUG[7868]: res_config_ldap.c:665 cleaned_basedn: basedn: 'dc=showingtime,dc=com' => 'dc=showingtime,dc=com' [Mar 12 18:20:28] DEBUG[7868]: res_config_ldap.c:702 append_var_and_value_to_filter: name='name' value='14484442' [Mar 12 18:20:28] DEBUG[7871]: chan_sip.c:26317 sip_devicestate: Checking device state for peer 14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:638 substituted: substituted: string: 'dc=showingtime,dc=com' => 'dc=showingtime,dc=com' [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:665 cleaned_basedn: basedn: 'dc=showingtime,dc=com' => 'dc=showingtime,dc=com' [Mar 12 18:20:28] DEBUG[7906]: manager.c:4216 match_filter: Examining event: Event: PeerStatus Privilege: system,all ChannelType: SIP Peer: SIP/14484442 PeerStatus: Unregistered Cause: Expired [Mar 12 18:20:28] DEBUG[7868]: res_config_ldap.c:1319 update_ldap: LINE(1319) Modifying name=14484442 hits: 1 [Mar 12 18:20:28] DEBUG[7868]: res_config_ldap.c:1322 update_ldap: LINE(1322) AstAccountIpaddr=(null) [Mar 12 18:20:28] DEBUG[7868]: res_config_ldap.c:1322 update_ldap: LINE(1322) AstAccountPort=(null) [Mar 12 18:20:28] DEBUG[7868]: res_config_ldap.c:1322 update_ldap: LINE(1322) AstAccountExpirationTimestamp=1331594428 [Mar 12 18:20:28] DEBUG[7868]: res_config_ldap.c:1322 update_ldap: LINE(1322) AstAccountDefaultuser=14484442 [Mar 12 18:20:28] DEBUG[7868]: res_config_ldap.c:1324 update_ldap: LINE(1324) deleting AstAccountUserAgent [Mar 12 18:20:28] DEBUG[7868]: res_config_ldap.c:1322 update_ldap: LINE(1322) AstAccountLastms=2 [Mar 12 18:20:28] DEBUG[7868]: res_config_ldap.c:1322 update_ldap: LINE(1322) AstAccountFullContact=sip:14484442@10.1.50.254:61363;transport=UDP;ob [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:1736 ldap_reconnect: Everything seems fine. [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:702 append_var_and_value_to_filter: name='name' value='14484442' [Mar 12 18:20:28] DEBUG[7868]: chan_sip.c:3344 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.1.50.254:61363 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:702 append_var_and_value_to_filter: name='host' value='dynamic' [Mar 12 18:20:28] DEBUG[7868]: devicestate.c:491 ast_devstate_changed_literal: ast_devstate_changed_literal Device state change SIP/14484442 0 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: sn LDAP value: 14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: objectClass LDAP value: inetOrgPerson [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: objectClass LDAP value: AsteriskQueueMember [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: objectClass LDAP value: AsteriskSIPUser [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: objectClass LDAP value: AsteriskExtension [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: callerid LDAP value: "Andrew CSR" <2001> [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: canreinvite LDAP value: no [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: context LDAP value: manual_dial [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: dtmfmode LDAP value: rfc2833 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: allow LDAP value: ulaw [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstAccountName LDAP value: 14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: nat LDAP value: yes [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: qualify LDAP value: yes [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: type LDAP value: friend [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: host LDAP value: dynamic [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstAccountSecret LDAP value: FF9260DEC84DB1A527FA2C94985C3BEB6E1D45B9 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstQueueInterface LDAP value: SIP/14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstQueueMembername LDAP value: andrew.csr [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstQueueMemberof LDAP value: ApptCenter [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: uid LDAP value: 2001 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstApplication LDAP value: Dial [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstApplicationData LDAP value: SIP/14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstContext LDAP value: AC_Users [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstExtension LDAP value: 2001 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstPriority LDAP value: 1 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: name LDAP value: 14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstQueuePaused LDAP value: 0 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: ipaddr LDAP value: (null) [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: port LDAP value: (null) [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: regseconds LDAP value: 1331594428 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: defaultuser LDAP value: 14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: lastms LDAP value: 2 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: fullcontact LDAP value: sip:14484442@10.1.50.254:61363;transport=UDP;ob [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: sn value: 14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: objectClass value: inetOrgPerson [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: objectClass value: AsteriskQueueMember [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: objectClass value: AsteriskSIPUser [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: objectClass value: AsteriskExtension [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: callerid value: "Andrew CSR" <2001> [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: canreinvite value: no [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: context value: manual_dial [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: dtmfmode value: rfc2833 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: allow value: ulaw [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstAccountName value: 14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: nat value: yes [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: qualify value: yes [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: type value: friend [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: host value: dynamic [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstAccountSecret value: FF9260DEC84DB1A527FA2C94985C3BEB6E1D45B9 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstQueueInterface value: SIP/14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstQueueMembername value: andrew.csr [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstQueueMemberof value: ApptCenter [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: uid value: 2001 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstApplication value: Dial [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstApplicationData value: SIP/14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstContext value: AC_Users [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstExtension value: 2001 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstPriority value: 1 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: name value: 14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstQueuePaused value: 0 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: ipaddr value: (null) [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: port value: (null) [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: regseconds value: 1331594428 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: defaultuser value: 14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: lastms value: 2 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:441 realtime_ldap_result_to_vars: LINE(441) is delimited 2 times: sip:14484442@10.1.50.254:61363;transport=UDP;ob [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 0 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 1 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 2 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 3 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 4 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 5 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 6 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 7 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 8 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 9 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 10 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 11 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 12 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 13 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 14 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 15 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 16 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 17 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 18 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 19 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 20 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 21 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 22 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 23 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 24 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 25 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 26 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 27 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 28 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 29 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 30 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:455 realtime_ldap_result_to_vars: LINE(455) DELIM - attribute_name: fullcontact value: sip:14484442@10.1.50.254:61363 pos: 0 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 31 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 32 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 33 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 34 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 35 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 36 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 37 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 38 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 39 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 40 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 41 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 42 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 43 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 44 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:455 realtime_ldap_result_to_vars: LINE(455) DELIM - attribute_name: fullcontact value: transport=UDP pos: 31 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 45 i: 45 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 45 i: 46 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:473 realtime_ldap_result_to_vars: LINE(473) DELIM pos: 45 i: 47 delim_count: 0 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:475 realtime_ldap_result_to_vars: LINE(475) DELIM - attribute_name: fullcontact value: ob pos: 45 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:491 realtime_ldap_result_to_vars: LINE(491) DELIM pos: 0 i: 47 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:533 realtime_ldap_result_to_vars: LINE(533) Added to vars - non static [Mar 12 18:20:28] DEBUG[7871]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '(null)' into... [Mar 12 18:20:28] DEBUG[7871]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '(null)' and port ''. [Mar 12 18:20:28] DEBUG[7871]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.1.50.254:61363' into... [Mar 12 18:20:28] DEBUG[7871]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.1.50.254' and port '61363'. [Mar 12 18:20:28] DEBUG[7871]: chan_sip.c:27756 build_peer: Not an IPv4 nor IPv6 address, cannot get port. [Mar 12 18:20:28] DEBUG[7871]: chan_sip.c:27759 build_peer: Not an IPv4 nor IPv6 address, cannot set port. [Mar 12 18:20:28] DEBUG[7871]: chan_sip.c:4969 realtime_peer: -REALTIME- loading peer from database to memory. Name: 14484442. Peer objects: 0 [Mar 12 18:20:28] DEBUG[7871]: chan_sip.c:4611 sip_destroy_peer: Destroying SIP peer 14484442 [Mar 12 18:20:28] DEBUG[7871]: devicestate.c:458 do_state_change: Changing state for SIP/14484442 - state 1 (Not in use) [Mar 12 18:20:28] DEBUG[7871]: devicestate.c:438 devstate_event: device 'SIP/14484442' state '1' [Mar 12 18:20:28] DEBUG[7871]: devicestate.c:548 do_devstate_changes: do_devstate_changes state change -201316136 [Mar 12 18:20:28] DEBUG[7871]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 14484442 [Mar 12 18:20:28] DEBUG[7871]: chan_sip.c:26317 sip_devicestate: Checking device state for peer 14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:638 substituted: substituted: string: 'dc=showingtime,dc=com' => 'dc=showingtime,dc=com' [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:665 cleaned_basedn: basedn: 'dc=showingtime,dc=com' => 'dc=showingtime,dc=com' [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:1736 ldap_reconnect: Everything seems fine. [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:702 append_var_and_value_to_filter: name='name' value='14484442' [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:702 append_var_and_value_to_filter: name='host' value='dynamic' [Mar 12 18:20:28] DEBUG[7869]: app_queue.c:1485 handle_statechange: Device 'SIP/14484442' changed to state '1' (Not in use) [Mar 12 18:20:28] DEBUG[7906]: manager.c:4216 match_filter: Examining event: Event: QueueMemberStatus Privilege: agent,all Queue: ApptCenter Location: SIP/14484442 MemberName: andrew.csr Membership: realtime Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 1 Paused: 0 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: sn LDAP value: 14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: objectClass LDAP value: inetOrgPerson [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: objectClass LDAP value: AsteriskQueueMember [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: objectClass LDAP value: AsteriskSIPUser [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: objectClass LDAP value: AsteriskExtension [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: callerid LDAP value: "Andrew CSR" <2001> [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: canreinvite LDAP value: no [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: context LDAP value: manual_dial [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: dtmfmode LDAP value: rfc2833 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: allow LDAP value: ulaw [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstAccountName LDAP value: 14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: nat LDAP value: yes [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: qualify LDAP value: yes [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: type LDAP value: friend [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: host LDAP value: dynamic [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstAccountSecret LDAP value: FF9260DEC84DB1A527FA2C94985C3BEB6E1D45B9 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstQueueInterface LDAP value: SIP/14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstQueueMembername LDAP value: andrew.csr [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstQueueMemberof LDAP value: ApptCenter [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: uid LDAP value: 2001 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstApplication LDAP value: Dial [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstApplicationData LDAP value: SIP/14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstContext LDAP value: AC_Users [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstExtension LDAP value: 2001 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstPriority LDAP value: 1 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: name LDAP value: 14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: AstQueuePaused LDAP value: 0 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: ipaddr LDAP value: (null) [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: port LDAP value: (null) [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: regseconds LDAP value: 1331594428 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: defaultuser LDAP value: 14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: lastms LDAP value: 2 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:306 realtime_ldap_entry_to_var: LINE(306) attribute_name: fullcontact LDAP value: sip:14484442@10.1.50.254:61363;transport=UDP;ob [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: sn value: 14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: objectClass value: inetOrgPerson [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: objectClass value: AsteriskQueueMember [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: objectClass value: AsteriskSIPUser [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: objectClass value: AsteriskExtension [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: callerid value: "Andrew CSR" <2001> [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: canreinvite value: no [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: context value: manual_dial [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: dtmfmode value: rfc2833 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: allow value: ulaw [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstAccountName value: 14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: nat value: yes [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: qualify value: yes [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: type value: friend [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: host value: dynamic [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstAccountSecret value: FF9260DEC84DB1A527FA2C94985C3BEB6E1D45B9 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstQueueInterface value: SIP/14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstQueueMembername value: andrew.csr [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstQueueMemberof value: ApptCenter [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: uid value: 2001 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstApplication value: Dial [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstApplicationData value: SIP/14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstContext value: AC_Users [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstExtension value: 2001 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstPriority value: 1 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: name value: 14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: AstQueuePaused value: 0 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: ipaddr value: (null) [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: port value: (null) [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: regseconds value: 1331594428 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: defaultuser value: 14484442 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:498 realtime_ldap_result_to_vars: LINE(498) attribute_name: lastms value: 2 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:441 realtime_ldap_result_to_vars: LINE(441) is delimited 2 times: sip:14484442@10.1.50.254:61363;transport=UDP;ob [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 0 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 1 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 2 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 3 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 4 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 5 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 6 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 7 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 8 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 9 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 10 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 11 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 12 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 13 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 14 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 15 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 16 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 17 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 18 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 19 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 20 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 21 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 22 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 23 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 24 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 25 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 26 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 27 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 28 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 29 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 0 i: 30 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:455 realtime_ldap_result_to_vars: LINE(455) DELIM - attribute_name: fullcontact value: sip:14484442@10.1.50.254:61363 pos: 0 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 31 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 32 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 33 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 34 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 35 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 36 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 37 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 38 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 39 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 40 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 41 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 42 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 43 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 31 i: 44 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:455 realtime_ldap_result_to_vars: LINE(455) DELIM - attribute_name: fullcontact value: transport=UDP pos: 31 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 45 i: 45 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:451 realtime_ldap_result_to_vars: LINE(451) DELIM pos: 45 i: 46 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:473 realtime_ldap_result_to_vars: LINE(473) DELIM pos: 45 i: 47 delim_count: 0 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:475 realtime_ldap_result_to_vars: LINE(475) DELIM - attribute_name: fullcontact value: ob pos: 45 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:491 realtime_ldap_result_to_vars: LINE(491) DELIM pos: 0 i: 47 [Mar 12 18:20:28] DEBUG[7871]: res_config_ldap.c:533 realtime_ldap_result_to_vars: LINE(533) Added to vars - non static [Mar 12 18:20:28] DEBUG[7871]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '(null)' into... [Mar 12 18:20:28] DEBUG[7871]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '(null)' and port ''. [Mar 12 18:20:28] DEBUG[7871]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.1.50.254:61363' into... [Mar 12 18:20:28] DEBUG[7871]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.1.50.254' and port '61363'. [Mar 12 18:20:28] DEBUG[7871]: chan_sip.c:27756 build_peer: Not an IPv4 nor IPv6 address, cannot get port. [Mar 12 18:20:28] DEBUG[7871]: chan_sip.c:27759 build_peer: Not an IPv4 nor IPv6 address, cannot set port. [Mar 12 18:20:28] DEBUG[7871]: chan_sip.c:4969 realtime_peer: -REALTIME- loading peer from database to memory. Name: 14484442. Peer objects: 0 [Mar 12 18:20:28] DEBUG[7871]: chan_sip.c:4611 sip_destroy_peer: Destroying SIP peer 14484442 [Mar 12 18:20:28] DEBUG[7871]: devicestate.c:458 do_state_change: Changing state for SIP/14484442 - state 1 (Not in use) [Mar 12 18:20:28] DEBUG[7871]: devicestate.c:438 devstate_event: device 'SIP/14484442' state '1' [Mar 12 18:20:28] DEBUG[7869]: app_queue.c:1485 handle_statechange: Device 'SIP/14484442' changed to state '1' (Not in use) [Mar 12 18:20:28] DEBUG[7906]: manager.c:4216 match_filter: Examining event: Event: QueueMemberStatus Privilege: agent,all Queue: ApptCenter Location: SIP/14484442 MemberName: andrew.csr Membership: realtime Penalty: 0 CallsTaken: 0 LastCall: 0 Status: 1 Paused: 0