Event: SuccessfulAuth Privilege: security,all EventTV: 2015-06-06T14:19:15.955+0530 Severity: Informational Service: AMI EventVersion: 1 AccountID: ngucc SessionID: 0x7ff3e42a0b48 LocalAddress: IPV4/TCP/0.0.0.0/5038 RemoteAddress: IPV4/TCP/127.0.0.1/55656 UsingPassword: 0 SessionTV: 2015-06-06T14:19:15.955+0530 [Jun 6 14:19:30] DEBUG[30114]: manager.c:6130 process_message: Running action 'Originate' [Jun 6 14:19:30] DEBUG[30025]: config.c:3634 ast_parse_arg: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Jun 6 14:19:30] DEBUG[30025]: config.c:3543 ast_parse_arg: extract int from [0] in [0, 86400] gives [0](0) [Jun 6 14:19:30] DEBUG[30025]: config.c:3634 ast_parse_arg: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [Jun 6 14:19:30] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a UAC dialog created [Jun 6 14:19:30] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a Module Outbound Authentica added as dialog usage, data=0x7ff3f4007ce0 [Jun 6 14:19:30] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a Module mod-invite added as dialog usage, data=0x7ff3f40081e8 [Jun 6 14:19:30] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a .Session count inc to 2 by mod-invite [Jun 6 14:19:30] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a Module mod-100rel added as dialog usage, data=0x7ff3f40083a8 [Jun 6 14:19:30] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a 100rel module attached [Jun 6 14:19:30] DEBUG[30025]: pjsip:0 : inv0x7ff3f400a UAC invite session created for dialog dlg0x7ff3f400aa38 [Jun 6 14:19:30] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a .Session count inc to 2 by Session Module [Jun 6 14:19:30] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a Module Session Module added as dialog usage, data=(nil) [Jun 6 14:19:30] DEBUG[29988]: threadpool.c:508 grow: Increasing threadpool stasis-core's size by 1 [Jun 6 14:19:30] DEBUG[30032]: manager.c:5685 match_filter: Examining AMI event: Event: Newchannel Privilege: call,all Channel: PJSIP/4001-00000000 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1433580570.0 [Jun 6 14:19:30] DEBUG[30032]: manager.c:5685 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: PJSIP/4001-00000000 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1433580570.0 Extension: s Application: AppDial2 AppData: (Outgoing Line) [Jun 6 14:19:30] DEBUG[30025]: rtp_engine.c:421 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7ff3f4008ba8' [Jun 6 14:19:30] DEBUG[30025]: res_rtp_asterisk.c:2441 ast_rtp_new: Allocated port 16304 for RTP instance '0x7ff3f4008ba8' [Jun 6 14:19:30] DEBUG[30025]: pjsip:0 : icess0x7ff3f40 ICE session created, comp_cnt=2, role is Unknown agent [Jun 6 14:19:30] DEBUG[30025]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.7' into... [Jun 6 14:19:30] DEBUG[30025]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.7' and port ''. [Jun 6 14:19:30] DEBUG[30025]: pjsip:0 : icess0x7ff3f40 Candidate 0 added: comp_id=1, type=host, foundation=Hc0a80107, addr=192.168.1.7:16304, base=192.168.1.7:16304, prio=0x7effffff (2130706431) -- Called 4001 [Jun 6 14:19:30] DEBUG[30032]: manager.c:5685 match_filter: Examining AMI event: Event: DialBegin Privilege: call,all DestChannel: PJSIP/4001-00000000 DestChannelState: 0 DestChannelStateDesc: Down DestCallerIDNum: DestCallerIDName: DestConnectedLineNum: DestConnectedLineName: DestLanguage: en DestAccountCode: DestContext: default DestExten: s DestPriority: 1 DestUniqueid: 1433580570.0 DialString: 4001 [Jun 6 14:19:30] DEBUG[30025]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '14.140.220.106' into... [Jun 6 14:19:30] DEBUG[30025]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '14.140.220.106' and port ''. [Jun 6 14:19:30] DEBUG[30025]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.7' into... [Jun 6 14:19:30] DEBUG[30025]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.7' and port ''. [Jun 6 14:19:30] DEBUG[30025]: pjsip:0 : icess0x7ff3f40 Candidate 1 added: comp_id=1, type=srflx, foundation=Se8cdc6a, addr=14.140.220.106:16304, base=192.168.1.7:16304, prio=0x64ffffff (1694498815) [Jun 6 14:19:30] DEBUG[30025]: rtp_engine.c:430 ast_rtp_instance_new: RTP instance '0x7ff3f4008ba8' is setup and ready to go [Jun 6 14:19:30] DEBUG[30025]: res_rtp_asterisk.c:4686 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7ff3f4008ba8' [Jun 6 14:19:30] DEBUG[30025]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.7' into... [Jun 6 14:19:30] DEBUG[30025]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.7' and port ''. [Jun 6 14:19:30] DEBUG[30025]: pjsip:0 : icess0x7ff3f40 Candidate 2 added: comp_id=2, type=host, foundation=Hc0a80107, addr=192.168.1.7:16305, base=192.168.1.7:16305, prio=0x7efffffe (2130706430) [Jun 6 14:19:31] DEBUG[30025]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '14.140.220.106' into... [Jun 6 14:19:31] DEBUG[30025]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '14.140.220.106' and port ''. [Jun 6 14:19:31] DEBUG[30025]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.7' into... [Jun 6 14:19:31] DEBUG[30025]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.7' and port ''. [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : icess0x7ff3f40 Candidate 3 added: comp_id=2, type=srflx, foundation=Se8cdc6a, addr=14.140.220.106:16305, base=192.168.1.7:16305, prio=0x64fffffe (1694498814) [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : icess0x7ff3f40 Destroying ICE session 0x7ff3f4011128 [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : stuse0x7ff3f40 STUN session 0x7ff3f4013138 destroy request, ref_cnt=4 [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : stuse0x7ff3f40 STUN session 0x7ff3f4014138 destroy request, ref_cnt=3 [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : ice_session.c ICE session 0x7ff3f4011128 destroyed [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : stun_session.c STUN session 0x7ff3f4013138 destroyed [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : stun_session.c STUN session 0x7ff3f4014138 destroyed [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : endpoint Request msg INVITE/cseq=3208 (tdta0x7ff3f4005e00) created. [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2133 handle_outgoing_request: Method is INVITE [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a Module WebSocket Transport Module added as dialog usage, data=(nil) [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a Module NAT added as dialog usage, data=(nil) [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : inv0x7ff3f400a .Sending Request msg INVITE/cseq=3208 (tdta0x7ff3f4005e00) [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a ..Sending Request msg INVITE/cseq=3208 (tdta0x7ff3f4005e00) [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : tsx0x7ff3f4006 ...Transaction created for Request msg INVITE/cseq=3207 (tdta0x7ff3f4005e00) [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : tsx0x7ff3f4006 ..Sending Request msg INVITE/cseq=3207 (tdta0x7ff3f4005e00) in state Null [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : sip_resolve.c ...Target '192.168.1.183:53372' type=Unspecified resolved to '192.168.1.183:53372' type=UDP (UDP transport) [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_multihomed.c:157 multihomed_on_tx_message: Re-wrote Contact URI host/port to 192.168.1.7:5060 [Jun 6 14:19:31] DEBUG[30025]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '0.0.0.0:5060' into... [Jun 6 14:19:31] DEBUG[30025]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '0.0.0.0' and port '5060'. [Jun 6 14:19:31] DEBUG[30025]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.183:53372' into... [Jun 6 14:19:31] DEBUG[30025]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.183' and port '53372'. [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : tsx0x7ff3f4006 ...State changed from Null to Calling, event=TX_MSG [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a ....Transaction tsx0x7ff3f4006eb8 state changed to Calling [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2040 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2052 __print_debug_details: The state change pertains to the endpoint '4001(PJSIP/4001-00000000)' [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2057 __print_debug_details: The inv session still has an invite_tsx (0x7ff3f4006eb8) [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2072 __print_debug_details: There is no transaction involved in this state change [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2074 __print_debug_details: The current inv state is CALLING [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2216 session_inv_on_state_changed: Source of transaction state change is TX_MSG [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2160 handle_outgoing: Sending request [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2133 handle_outgoing_request: Method is INVITE [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2040 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2052 __print_debug_details: The state change pertains to the endpoint '4001(PJSIP/4001-00000000)' [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2057 __print_debug_details: The inv session still has an invite_tsx (0x7ff3f4006eb8) [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2063 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7ff3f4006eb8 [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2067 __print_debug_details: The current transaction state is Calling [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2069 __print_debug_details: The transaction state change event is TX_MSG [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2074 __print_debug_details: The current inv state is CALLING [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2160 handle_outgoing: Sending request [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2133 handle_outgoing_request: Method is INVITE [Jun 6 14:19:31] DEBUG[30030]: pjsip:0 : sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=3207 (rdata0x7ff3e8000d78) [Jun 6 14:19:31] DEBUG[30030]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.183:53372' into... [Jun 6 14:19:31] DEBUG[30030]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.183' and port '53372'. [Jun 6 14:19:31] DEBUG[30030]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '0.0.0.0:5060' into... [Jun 6 14:19:31] DEBUG[30030]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '0.0.0.0' and port '5060'. [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=3207 (rdata0x7ff3e8004228) [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : tsx0x7ff3f4006 .Incoming Response msg 100/INVITE/cseq=3207 (rdata0x7ff3e8004228) in state Calling [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : tsx0x7ff3f4006 ..State changed from Calling to Proceeding, event=RX_MSG [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a ...Received Response msg 100/INVITE/cseq=3207 (rdata0x7ff3e8004228) [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a ...Transaction tsx0x7ff3f4006eb8 state changed to Proceeding [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2040 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2052 __print_debug_details: The state change pertains to the endpoint '4001(PJSIP/4001-00000000)' [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2057 __print_debug_details: The inv session still has an invite_tsx (0x7ff3f4006eb8) [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2063 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7ff3f4006eb8 [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2067 __print_debug_details: The current transaction state is Proceeding [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2069 __print_debug_details: The transaction state change event is RX_MSG [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2074 __print_debug_details: The current inv state is CALLING [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2117 handle_incoming: Received response [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2101 handle_incoming_response: Response is 100 Trying [Jun 6 14:19:31] DEBUG[30030]: pjsip:0 : sip_endpoint.c Processing incoming message: Response msg 180/INVITE/cseq=3207 (rdata0x7ff3e8000d78) [Jun 6 14:19:31] DEBUG[30030]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.183:53372' into... [Jun 6 14:19:31] DEBUG[30030]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.183' and port '53372'. [Jun 6 14:19:31] DEBUG[30030]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '0.0.0.0:5060' into... [Jun 6 14:19:31] DEBUG[30030]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '0.0.0.0' and port '5060'. [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Response msg 180/INVITE/cseq=3207 (rdata0x7ff3e80055f8) [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : tsx0x7ff3f4006 .Incoming Response msg 180/INVITE/cseq=3207 (rdata0x7ff3e80055f8) in state Proceeding [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : tsx0x7ff3f4006 ..State changed from Proceeding to Proceeding, event=RX_MSG [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a ...Received Response msg 180/INVITE/cseq=3207 (rdata0x7ff3e80055f8) [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a ....Route-set updated [Jun 6 14:19:31] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a ...Transaction tsx0x7ff3f4006eb8 state changed to Proceeding [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2040 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2052 __print_debug_details: The state change pertains to the endpoint '4001(PJSIP/4001-00000000)' [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2057 __print_debug_details: The inv session still has an invite_tsx (0x7ff3f4006eb8) [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2072 __print_debug_details: There is no transaction involved in this state change [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2074 __print_debug_details: The current inv state is EARLY [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2216 session_inv_on_state_changed: Source of transaction state change is RX_MSG [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2117 handle_incoming: Received response [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2101 handle_incoming_response: Response is 180 Ringing [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2040 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2052 __print_debug_details: The state change pertains to the endpoint '4001(PJSIP/4001-00000000)' [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2057 __print_debug_details: The inv session still has an invite_tsx (0x7ff3f4006eb8) [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2063 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7ff3f4006eb8 [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2067 __print_debug_details: The current transaction state is Proceeding [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2069 __print_debug_details: The transaction state change event is RX_MSG [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2074 __print_debug_details: The current inv state is EARLY [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2117 handle_incoming: Received response [Jun 6 14:19:31] DEBUG[30025]: res_pjsip_session.c:2101 handle_incoming_response: Response is 180 Ringing [Jun 6 14:19:31] DEBUG[30032]: manager.c:5685 match_filter: Examining AMI event: Event: Newstate Privilege: call,all Channel: PJSIP/4001-00000000 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1433580570.0 [Jun 6 14:19:31] DEBUG[30000]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for PJSIP - 4001 [Jun 6 14:19:31] DEBUG[30000]: devicestate.c:464 do_state_change: Changing state for PJSIP/4001 - state 6 (Ringing) [Jun 6 14:19:31] DEBUG[30032]: manager.c:5685 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: PJSIP/4001 State: RINGING [Jun 6 14:19:31] DEBUG[30087]: app_queue.c:2374 device_state_cb: Device 'PJSIP/4001' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. -- PJSIP/4001-00000000 is ringing [Jun 6 14:19:33] DEBUG[30027]: threadpool.c:1107 worker_idle: Worker thread idle timeout reached. Dying. [Jun 6 14:19:33] DEBUG[30024]: threadpool.c:968 worker_thread_destroy: Destroying worker thread 7 [Jun 6 14:19:33] DEBUG[30028]: threadpool.c:1107 worker_idle: Worker thread idle timeout reached. Dying. [Jun 6 14:19:33] DEBUG[30029]: threadpool.c:1107 worker_idle: Worker thread idle timeout reached. Dying. [Jun 6 14:19:33] DEBUG[30024]: threadpool.c:968 worker_thread_destroy: Destroying worker thread 8 [Jun 6 14:19:33] DEBUG[30024]: threadpool.c:968 worker_thread_destroy: Destroying worker thread 9 [Jun 6 14:19:35] DEBUG[30036]: threadpool.c:1107 worker_idle: Worker thread idle timeout reached. Dying. [Jun 6 14:19:35] DEBUG[29987]: threadpool.c:968 worker_thread_destroy: Destroying worker thread 11 [Jun 6 14:19:35] DEBUG[30030]: pjsip:0 : sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=3207 (rdata0x7ff3e8000d78) [Jun 6 14:19:35] DEBUG[30030]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.183:53372' into... [Jun 6 14:19:35] DEBUG[30030]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.183' and port '53372'. [Jun 6 14:19:35] DEBUG[30030]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '0.0.0.0:5060' into... [Jun 6 14:19:35] DEBUG[30030]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '0.0.0.0' and port '5060'. [Jun 6 14:19:35] DEBUG[30025]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Response msg 200/INVITE/cseq=3207 (rdata0x7ff3e8004418) [Jun 6 14:19:35] DEBUG[30025]: pjsip:0 : tsx0x7ff3f4006 .Incoming Response msg 200/INVITE/cseq=3207 (rdata0x7ff3e8004418) in state Proceeding [Jun 6 14:19:35] DEBUG[30025]: pjsip:0 : tsx0x7ff3f4006 ..State changed from Proceeding to Terminated, event=RX_MSG [Jun 6 14:19:35] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a ...Received Response msg 200/INVITE/cseq=3207 (rdata0x7ff3e8004418) [Jun 6 14:19:35] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a ....Route-set updated [Jun 6 14:19:35] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a ....Route-set frozen [Jun 6 14:19:35] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a ...Transaction tsx0x7ff3f4006eb8 state changed to Terminated [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2040 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2052 __print_debug_details: The state change pertains to the endpoint '4001(PJSIP/4001-00000000)' [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2057 __print_debug_details: The inv session still has an invite_tsx (0x7ff3f4006eb8) [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2072 __print_debug_details: There is no transaction involved in this state change [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2074 __print_debug_details: The current inv state is CONNECTING [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2216 session_inv_on_state_changed: Source of transaction state change is RX_MSG [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2117 handle_incoming: Received response [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2101 handle_incoming_response: Response is 200 OK [Jun 6 14:19:35] DEBUG[30025]: pjsip:0 : inv0x7ff3f400a ....Got SDP answer in Response msg 200/INVITE/cseq=3207 (rdata0x7ff3e8004418) [Jun 6 14:19:35] DEBUG[30025]: pjsip:0 : inv0x7ff3f400a ....SDP negotiation done, status=0 [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:325 handle_negotiated_sdp_session_media: Applying negotiated SDP media stream 'audio' using audio SDP handler [Jun 6 14:19:35] DEBUG[30025]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.183' into... [Jun 6 14:19:35] DEBUG[30025]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.183' and port ''. [Jun 6 14:19:35] DEBUG[30025]: res_rtp_asterisk.c:4741 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7ff3f4008ba8' [Jun 6 14:19:35] DEBUG[30025]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 (0x7ff3f4007978) based on m type on 0x7ff3bac64cc0 [Jun 6 14:19:35] DEBUG[30025]: rtp_engine.c:664 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 (0x7ff3f4007978) based on m type on 0x7ff3bac64cc0 [Jun 6 14:19:35] DEBUG[30025]: rtp_engine.c:626 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7ff3f40188c8) from 0x7ff3bac64cc0 to 0x7ff3f4008d70 [Jun 6 14:19:35] DEBUG[30025]: rtp_engine.c:626 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7ff3f400a8d8) from 0x7ff3bac64cc0 to 0x7ff3f4008d70 [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:331 handle_negotiated_sdp_session_media: Applied negotiated SDP media stream 'audio' using audio SDP handler [Jun 6 14:19:35] DEBUG[30025]: pjsip:0 : inv0x7ff3f400a ....Received Response msg 200/INVITE/cseq=3207 (rdata0x7ff3e8004418), sending ACK [Jun 6 14:19:35] DEBUG[30025]: pjsip:0 : endpoint ....Request msg ACK/cseq=3207 (tdta0x7ff3e8002df0) created. [Jun 6 14:19:35] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a .....Sending Request msg ACK/cseq=3207 (tdta0x7ff3e8002df0) [Jun 6 14:19:35] DEBUG[30025]: pjsip:0 : sip_resolve.c .....Target '192.168.1.183:53372' type=Unspecified resolved to '192.168.1.183:53372' type=UDP (UDP transport) [Jun 6 14:19:35] DEBUG[30025]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '0.0.0.0:5060' into... [Jun 6 14:19:35] DEBUG[30025]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '0.0.0.0' and port '5060'. [Jun 6 14:19:35] DEBUG[30025]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.183:53372' into... [Jun 6 14:19:35] DEBUG[30025]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.183' and port '53372'. [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2040 __print_debug_details: Function session_inv_on_state_changed called on event TX_MSG [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2052 __print_debug_details: The state change pertains to the endpoint '4001(PJSIP/4001-00000000)' [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2057 __print_debug_details: The inv session still has an invite_tsx (0x7ff3f4006eb8) [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2072 __print_debug_details: There is no transaction involved in this state change [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2074 __print_debug_details: The current inv state is CONFIRMED [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2160 handle_outgoing: Sending request [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2133 handle_outgoing_request: Method is ACK [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2040 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2052 __print_debug_details: The state change pertains to the endpoint '4001(PJSIP/4001-00000000)' [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2060 __print_debug_details: The inv session does NOT have an invite_tsx [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2063 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7ff3f4006eb8 [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2067 __print_debug_details: The current transaction state is Terminated [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2069 __print_debug_details: The transaction state change event is RX_MSG [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2074 __print_debug_details: The current inv state is CONFIRMED [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2117 handle_incoming: Received response [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2101 handle_incoming_response: Response is 200 OK -- PJSIP/4001-00000000 answered > Launching AGI(agi://192.168.1.220/) on PJSIP/4001-00000000 [Jun 6 14:19:35] DEBUG[30177]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.220' into... [Jun 6 14:19:35] DEBUG[30000]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for PJSIP - 4001 [Jun 6 14:19:35] DEBUG[30177]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.220' and port ''. [Jun 6 14:19:35] DEBUG[30000]: devicestate.c:464 do_state_change: Changing state for PJSIP/4001 - state 2 (In use) [Jun 6 14:19:35] DEBUG[30032]: manager.c:5685 match_filter: Examining AMI event: Event: Newstate Privilege: call,all Channel: PJSIP/4001-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1433580570.0 [Jun 6 14:19:35] DEBUG[30087]: app_queue.c:2374 device_state_cb: Device 'PJSIP/4001' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 6 14:19:35] DEBUG[30114]: manager.c:5685 match_filter: Examining AMI event: Event: Newchannel Privilege: call,all Channel: PJSIP/4001-00000000 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1433580570.0 [Jun 6 14:19:35] DEBUG[30114]: manager.c:5685 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: PJSIP/4001-00000000 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1433580570.0 Extension: s Application: AppDial2 AppData: (Outgoing Line) [Jun 6 14:19:35] DEBUG[30032]: manager.c:5685 match_filter: Examining AMI event: Event: DialEnd Privilege: call,all DestChannel: PJSIP/4001-00000000 DestChannelState: 6 DestChannelStateDesc: Up DestCallerIDNum: DestCallerIDName: DestConnectedLineNum: DestConnectedLineName: DestLanguage: en DestAccountCode: DestContext: default DestExten: s DestPriority: 1 DestUniqueid: 1433580570.0 DialStatus: ANSWER [Jun 6 14:19:35] DEBUG[30032]: manager.c:5685 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: PJSIP/4001 State: INUSE [Jun 6 14:19:35] DEBUG[30114]: manager.c:5685 match_filter: Examining AMI event: Event: DialBegin Privilege: call,all DestChannel: PJSIP/4001-00000000 DestChannelState: 0 DestChannelStateDesc: Down DestCallerIDNum: DestCallerIDName: DestConnectedLineNum: DestConnectedLineName: DestLanguage: en DestAccountCode: DestContext: default DestExten: s DestPriority: 1 DestUniqueid: 1433580570.0 DialString: 4001 [Jun 6 14:19:35] DEBUG[30114]: manager.c:5685 match_filter: Examining AMI event: Event: Newstate Privilege: call,all Channel: PJSIP/4001-00000000 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1433580570.0 [Jun 6 14:19:35] DEBUG[30114]: manager.c:5685 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: PJSIP/4001 State: RINGING [Jun 6 14:19:35] DEBUG[30114]: manager.c:5685 match_filter: Examining AMI event: Event: Newstate Privilege: call,all Channel: PJSIP/4001-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1433580570.0 [Jun 6 14:19:35] DEBUG[30114]: manager.c:5685 match_filter: Examining AMI event: Event: DialEnd Privilege: call,all DestChannel: PJSIP/4001-00000000 DestChannelState: 6 DestChannelStateDesc: Up DestCallerIDNum: DestCallerIDName: DestConnectedLineNum: DestConnectedLineName: DestLanguage: en DestAccountCode: DestContext: default DestExten: s DestPriority: 1 DestUniqueid: 1433580570.0 DialStatus: ANSWER [Jun 6 14:19:35] DEBUG[30114]: manager.c:5685 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: PJSIP/4001 State: INUSE [Jun 6 14:19:35] DEBUG[30177]: res_agi.c:1749 launch_netscript: Wow, connected! [Jun 6 14:19:35] DEBUG[30177]: res_rtp_asterisk.c:3962 ast_rtcp_read: Got RTCP report of 64 bytes [Jun 6 14:19:35] DEBUG[30177]: acl.c:958 ast_find_ourip: Not an IPv4 nor IPv6 address, cannot get port. [Jun 6 14:19:35] DEBUG[30177]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'server7' into... [Jun 6 14:19:35] DEBUG[30177]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'server7' and port ''. [Jun 6 14:19:35] DEBUG[30177]: acl.c:958 ast_find_ourip: Not an IPv4 nor IPv6 address, cannot get port. [Jun 6 14:19:35] DEBUG[30177]: acl.c:963 ast_find_ourip: Attached to given IP address [Jun 6 14:19:35] DEBUG[30177]: res_rtp_asterisk.c:3962 ast_rtcp_read: Got RTCP report of 64 bytes [Jun 6 14:19:35] DEBUG[30177]: acl.c:958 ast_find_ourip: Not an IPv4 nor IPv6 address, cannot get port. [Jun 6 14:19:35] DEBUG[30177]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'server7' into... [Jun 6 14:19:35] DEBUG[30177]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'server7' and port ''. [Jun 6 14:19:35] DEBUG[30085]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.183:4023' into... [Jun 6 14:19:35] DEBUG[30085]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.183' and port '4023'. [Jun 6 14:19:35] DEBUG[30085]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '127.0.1.1:0' into... [Jun 6 14:19:35] DEBUG[30177]: acl.c:958 ast_find_ourip: Not an IPv4 nor IPv6 address, cannot get port. [Jun 6 14:19:35] DEBUG[30085]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '127.0.1.1' and port '0'. [Jun 6 14:19:35] DEBUG[30177]: acl.c:963 ast_find_ourip: Attached to given IP address [Jun 6 14:19:35] DEBUG[30177]: res_rtp_asterisk.c:4307 ast_rtp_read: 0x7ff3f400e6a0 -- Probation learning mode pass with source address 192.168.1.183:4022 > 0x7ff3f400e6a0 -- Probation passed - setting RTP source address to 192.168.1.183:4022 [Jun 6 14:19:35] DEBUG[30085]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.183:4023' into... [Jun 6 14:19:35] DEBUG[30085]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.183' and port '4023'. [Jun 6 14:19:35] DEBUG[30085]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '127.0.1.1:0' into... [Jun 6 14:19:35] DEBUG[30085]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '127.0.1.1' and port '0'. [Jun 6 14:19:35] DEBUG[30114]: manager.c:5685 match_filter: Examining AMI event: Event: RTCPReceived Privilege: reporting,all Channel: PJSIP/4001-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1433580570.0 To: 127.0.1.1:0 From: 192.168.1.183:4023 RTT: 0.0000 SSRC: 0x6e9e6cde PT: 201(RR) ReportCount: 1 Report0SourceSSRC: 0x00000000 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 0 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 0 Report0DLSR: 0.0000 [Jun 6 14:19:35] DEBUG[30114]: manager.c:5685 match_filter: Examining AMI event: Event: RTCPReceived Privilege: reporting,all Channel: PJSIP/4001-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1433580570.0 To: 127.0.1.1:0 From: 192.168.1.183:4023 RTT: 0.0000 SSRC: 0x6e9e6cde PT: 201(RR) ReportCount: 1 Report0SourceSSRC: 0x00000000 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 0 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 0 Report0DLSR: 0.0000 [Jun 6 14:19:35] DEBUG[30030]: pjsip:0 : tsx0x7ff3f4006 Timeout timer event [Jun 6 14:19:35] DEBUG[30030]: pjsip:0 : tsx0x7ff3f4006 .State changed from Terminated to Destroyed, event=TIMER [Jun 6 14:19:35] DEBUG[30030]: pjsip:0 : tsx0x7ff3f4006 Transaction destroyed! [Jun 6 14:19:35] DEBUG[30114]: manager.c:5685 match_filter: Examining AMI event: Event: AGIExecStart Privilege: agi,all Channel: PJSIP/4001-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1433580570.0 CommandId: 1630892278 Command: SET EXTENSION 4002 [Jun 6 14:19:35] DEBUG[30114]: manager.c:5685 match_filter: Examining AMI event: Event: AGIExecEnd Privilege: agi,all Channel: PJSIP/4001-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1433580570.0 CommandId: 1630892278 ResultCode: 200 Command: SET EXTENSION 4002 Result: Success [Jun 6 14:19:35] DEBUG[30114]: manager.c:5685 match_filter: Examining AMI event: Event: AGIExecStart Privilege: agi,all Channel: PJSIP/4001-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1433580570.0 CommandId: 1760776641 Command: SET CONTEXT default [Jun 6 14:19:35] DEBUG[30114]: manager.c:5685 match_filter: Examining AMI event: Event: AGIExecEnd Privilege: agi,all Channel: PJSIP/4001-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1433580570.0 CommandId: 1760776641 ResultCode: 200 Command: SET CONTEXT default Result: Success [Jun 6 14:19:35] DEBUG[30114]: manager.c:5685 match_filter: Examining AMI event: Event: AGIExecStart Privilege: agi,all Channel: PJSIP/4001-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1433580570.0 CommandId: 1773032161 Command: SET PRIORITY 1 [Jun 6 14:19:35] DEBUG[30114]: manager.c:5685 match_filter: Examining AMI event: Event: AGIExecEnd Privilege: agi,all Channel: PJSIP/4001-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1433580570.0 CommandId: 1773032161 ResultCode: 200 Command: SET PRIORITY 1 Result: Success -- AGI Script agi://192.168.1.220/ completed, returning 0 [Jun 6 14:19:35] DEBUG[30177]: channel.c:2682 ast_hangup: Hanging up channel 'PJSIP/4001-00000000' [Jun 6 14:19:35] DEBUG[30177]: chan_pjsip.c:1691 hangup_cause2sip: AST hangup cause 0 (no match found in PJSIP) [Jun 6 14:19:35] DEBUG[30114]: manager.c:5685 match_filter: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/4001-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: s Priority: 1 Uniqueid: 1433580570.0 Variable: AGISTATUS Value: SUCCESS [Jun 6 14:19:35] DEBUG[30025]: pjsip:0 : endpoint .Request msg BYE/cseq=3209 (tdta0x7ff3f400b6b0) created. [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2133 handle_outgoing_request: Method is BYE [Jun 6 14:19:35] DEBUG[30025]: pjsip:0 : inv0x7ff3f400a .Sending Request msg BYE/cseq=3209 (tdta0x7ff3f400b6b0) [Jun 6 14:19:35] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a ..Sending Request msg BYE/cseq=3209 (tdta0x7ff3f400b6b0) [Jun 6 14:19:35] DEBUG[30025]: pjsip:0 : tsx0x7ff3f4006 ...Transaction created for Request msg BYE/cseq=3208 (tdta0x7ff3f400b6b0) [Jun 6 14:19:35] DEBUG[30025]: pjsip:0 : tsx0x7ff3f4006 ..Sending Request msg BYE/cseq=3208 (tdta0x7ff3f400b6b0) in state Null [Jun 6 14:19:35] DEBUG[30025]: pjsip:0 : sip_resolve.c ...Target '192.168.1.183:53372' type=Unspecified resolved to '192.168.1.183:53372' type=UDP (UDP transport) [Jun 6 14:19:35] DEBUG[30025]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '0.0.0.0:5060' into... [Jun 6 14:19:35] DEBUG[30025]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '0.0.0.0' and port '5060'. [Jun 6 14:19:35] DEBUG[30025]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.183:53372' into... [Jun 6 14:19:35] DEBUG[30025]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.183' and port '53372'. [Jun 6 14:19:35] DEBUG[30025]: pjsip:0 : tsx0x7ff3f4006 ...State changed from Null to Calling, event=TX_MSG [Jun 6 14:19:35] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a ....Transaction tsx0x7ff3f4006eb8 state changed to Calling [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2040 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2052 __print_debug_details: The state change pertains to the endpoint '4001(PJSIP/4001-00000000)' [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2060 __print_debug_details: The inv session does NOT have an invite_tsx [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2063 __print_debug_details: The UAC BYE transaction involved in this state change is 0x7ff3f4006eb8 [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2067 __print_debug_details: The current transaction state is Calling [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2069 __print_debug_details: The transaction state change event is TX_MSG [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2074 __print_debug_details: The current inv state is CONFIRMED [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2160 handle_outgoing: Sending request [Jun 6 14:19:35] DEBUG[30025]: res_pjsip_session.c:2133 handle_outgoing_request: Method is BYE [Jun 6 14:19:35] DEBUG[30005]: cdr.c:1266 cdr_object_finalize: Finalized CDR for PJSIP/4001-00000000 - start 1433580570.852695 answer 1433580575.660786 end 1433580575.688081 dispo ANSWERED [Jun 6 14:19:35] DEBUG[30032]: manager.c:5685 match_filter: Examining AMI event: Event: Hangup Privilege: call,all Channel: PJSIP/4001-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: 4002 Priority: 1 Uniqueid: 1433580570.0 Cause: 0 Cause-txt: Unknown [Jun 6 14:19:35] DEBUG[30114]: manager.c:5685 match_filter: Examining AMI event: Event: Hangup Privilege: call,all Channel: PJSIP/4001-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: 4002 Priority: 1 Uniqueid: 1433580570.0 Cause: 0 Cause-txt: Unknown [Jun 6 14:19:35] DEBUG[30000]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for PJSIP - 4001 [Jun 6 14:19:35] DEBUG[30000]: devicestate.c:464 do_state_change: Changing state for PJSIP/4001 - state 1 (Not in use) [Jun 6 14:19:35] DEBUG[30087]: app_queue.c:2374 device_state_cb: Device 'PJSIP/4001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 6 14:19:35] DEBUG[30032]: manager.c:5685 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: PJSIP/4001 State: NOT_INUSE [Jun 6 14:19:35] DEBUG[30114]: manager.c:5685 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: PJSIP/4001 State: NOT_INUSE [Jun 6 14:19:36] DEBUG[30030]: pjsip:0 : sip_endpoint.c Processing incoming message: Response msg 200/BYE/cseq=3208 (rdata0x7ff3e8000d78) [Jun 6 14:19:36] DEBUG[30030]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.1.183:53372' into... [Jun 6 14:19:36] DEBUG[30030]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.1.183' and port '53372'. [Jun 6 14:19:36] DEBUG[30030]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '0.0.0.0:5060' into... [Jun 6 14:19:36] DEBUG[30030]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '0.0.0.0' and port '5060'. [Jun 6 14:19:36] DEBUG[30025]: pjsip:0 : sip_endpoint.c Distributing rdata to modules: Response msg 200/BYE/cseq=3208 (rdata0x7ff3e8007448) [Jun 6 14:19:36] DEBUG[30025]: pjsip:0 : tsx0x7ff3f4006 .Incoming Response msg 200/BYE/cseq=3208 (rdata0x7ff3e8007448) in state Calling [Jun 6 14:19:36] DEBUG[30025]: pjsip:0 : tsx0x7ff3f4006 ..State changed from Calling to Completed, event=RX_MSG [Jun 6 14:19:36] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a ...Received Response msg 200/BYE/cseq=3208 (rdata0x7ff3e8007448) [Jun 6 14:19:36] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a ...Transaction tsx0x7ff3f4006eb8 state changed to Completed [Jun 6 14:19:36] DEBUG[30025]: res_pjsip_session.c:2040 __print_debug_details: Function session_inv_on_state_changed called on event TSX_STATE [Jun 6 14:19:36] DEBUG[30025]: res_pjsip_session.c:2052 __print_debug_details: The state change pertains to the endpoint '4001()' [Jun 6 14:19:36] DEBUG[30025]: res_pjsip_session.c:2060 __print_debug_details: The inv session does NOT have an invite_tsx [Jun 6 14:19:36] DEBUG[30025]: res_pjsip_session.c:2072 __print_debug_details: There is no transaction involved in this state change [Jun 6 14:19:36] DEBUG[30025]: res_pjsip_session.c:2074 __print_debug_details: The current inv state is DISCONNCTD [Jun 6 14:19:36] DEBUG[30025]: res_pjsip_session.c:2216 session_inv_on_state_changed: Source of transaction state change is RX_MSG [Jun 6 14:19:36] DEBUG[30025]: res_pjsip_session.c:2117 handle_incoming: Received response [Jun 6 14:19:36] DEBUG[30025]: res_pjsip_session.c:2101 handle_incoming_response: Response is 200 OK [Jun 6 14:19:36] DEBUG[30025]: res_pjsip_session.c:1161 session_destructor: Destroying SIP session with endpoint 4001 [Jun 6 14:19:36] DEBUG[30025]: res_rtp_asterisk.c:4741 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7ff3f4008ba8' [Jun 6 14:19:36] DEBUG[30025]: rtp_engine.c:364 instance_destructor: Destroyed RTP instance '0x7ff3f4008ba8' [Jun 6 14:19:36] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a .....Session count dec to 2 by Session Module [Jun 6 14:19:36] DEBUG[30025]: pjsip:0 : tdta0x7ff3e800 ....Destroying txdata Request msg ACK/cseq=3207 (tdta0x7ff3e8002df0) [Jun 6 14:19:36] DEBUG[30025]: pjsip:0 : tdta0x7ff3f400 ....Destroying txdata Request msg INVITE/cseq=3207 (tdta0x7ff3f4005e00) [Jun 6 14:19:36] DEBUG[30025]: pjsip:0 : dlg0x7ff3f400a .....Session count dec to 1 by mod-invite [Jun 6 14:19:36] DEBUG[30025]: res_pjsip_session.c:2040 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jun 6 14:19:36] DEBUG[30025]: res_pjsip_session.c:2050 __print_debug_details: inv_session 0x7ff3f40081e8 has no ast session [Jun 6 14:19:36] DEBUG[30025]: res_pjsip_session.c:2060 __print_debug_details: The inv session does NOT have an invite_tsx [Jun 6 14:19:36] DEBUG[30025]: res_pjsip_session.c:2063 __print_debug_details: The UAC BYE transaction involved in this state change is 0x7ff3f4006eb8 [Jun 6 14:19:36] DEBUG[30025]: res_pjsip_session.c:2067 __print_debug_details: The current transaction state is Completed [Jun 6 14:19:36] DEBUG[30025]: res_pjsip_session.c:2069 __print_debug_details: The transaction state change event is RX_MSG [Jun 6 14:19:36] DEBUG[30025]: res_pjsip_session.c:2074 __print_debug_details: The current inv state is DISCONNCTD [Jun 6 14:19:36] DEBUG[30025]: taskprocessor.c:484 tps_taskprocessor_destroy: destroying taskprocessor 'aae64d49-6807-4f3e-9028-63f68b311f25' [Jun 6 14:19:36] DEBUG[30035]: threadpool.c:1107 worker_idle: Worker thread idle timeout reached. Dying. [Jun 6 14:19:36] DEBUG[29987]: threadpool.c:968 worker_thread_destroy: Destroying worker thread 10 [Jun 6 14:19:41] DEBUG[30030]: pjsip:0 : tsx0x7ff3f4006 Timeout timer event [Jun 6 14:19:41] DEBUG[30030]: pjsip:0 : tsx0x7ff3f4006 .State changed from Completed to Terminated, event=TIMER [Jun 6 14:19:41] DEBUG[30030]: pjsip:0 : dlg0x7ff3f400a ..Transaction tsx0x7ff3f4006eb8 state changed to Terminated [Jun 6 14:19:41] DEBUG[30030]: res_pjsip_session.c:2040 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jun 6 14:19:41] DEBUG[30030]: res_pjsip_session.c:2050 __print_debug_details: inv_session 0x7ff3f40081e8 has no ast session [Jun 6 14:19:41] DEBUG[30030]: res_pjsip_session.c:2060 __print_debug_details: The inv session does NOT have an invite_tsx [Jun 6 14:19:41] DEBUG[30030]: res_pjsip_session.c:2063 __print_debug_details: The UAC BYE transaction involved in this state change is 0x7ff3f4006eb8 [Jun 6 14:19:41] DEBUG[30030]: res_pjsip_session.c:2067 __print_debug_details: The current transaction state is Terminated [Jun 6 14:19:41] DEBUG[30030]: res_pjsip_session.c:2069 __print_debug_details: The transaction state change event is TIMER [Jun 6 14:19:41] DEBUG[30030]: res_pjsip_session.c:2074 __print_debug_details: The current inv state is DISCONNCTD [Jun 6 14:19:41] DEBUG[30030]: pjsip:0 : dlg0x7ff3f400a ...Dialog destroyed [Jun 6 14:19:41] DEBUG[30030]: pjsip:0 : tsx0x7ff3f4006 Timeout timer event [Jun 6 14:19:41] DEBUG[30030]: pjsip:0 : tsx0x7ff3f4006 .State changed from Terminated to Destroyed, event=TIMER [Jun 6 14:19:41] DEBUG[30030]: pjsip:0 : tdta0x7ff3f400 ..Destroying txdata Request msg BYE/cseq=3208 (tdta0x7ff3f400b6b0) [Jun 6 14:19:41] DEBUG[30030]: pjsip:0 : tsx0x7ff3f4006 Transaction destroyed! [Jun 6 14:19:43] DEBUG[30026]: threadpool.c:1107 worker_idle: Worker thread idle timeout reached. Dying. [Jun 6 14:19:43] DEBUG[30024]: threadpool.c:968 worker_thread_destroy: Destroying worker thread 6