[2016-05-10 12:06:15] DEBUG[27690] netsock2.c: ...host '10.21.15.114' and port '4003'. [2016-05-10 12:06:15] DEBUG[27690] netsock2.c: Splitting '10.21.24.132:0' into... [2016-05-10 12:06:15] DEBUG[27690] netsock2.c: ...host '10.21.24.132' and port '0'. [2016-05-10 12:06:15] DEBUG[27570] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2016-05-10 12:06:15] DEBUG[27570] netsock2.c: Splitting 'bsrvvoce02' into... [2016-05-10 12:06:15] DEBUG[27570] netsock2.c: ...host 'bsrvvoce02' and port ''. [2016-05-10 12:06:15] DEBUG[27570] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2016-05-10 12:06:15] DEBUG[27570] acl.c: Attached to given IP address [2016-05-10 12:06:15] DEBUG[27690] netsock2.c: Splitting '10.21.24.132:0' into... [2016-05-10 12:06:15] DEBUG[27690] netsock2.c: ...host '10.21.24.132' and port '0'. [2016-05-10 12:06:15] DEBUG[27690] netsock2.c: Splitting '10.21.15.199:4007' into... [2016-05-10 12:06:15] DEBUG[27690] netsock2.c: ...host '10.21.15.199' and port '4007'. [2016-05-10 12:06:15] DEBUG[19238] res_rtp_asterisk.c: Got RTCP report of 84 bytes [2016-05-10 12:06:15] DEBUG[19238] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2016-05-10 12:06:15] DEBUG[19238] netsock2.c: Splitting 'bsrvvoce02' into... [2016-05-10 12:06:15] DEBUG[19238] netsock2.c: ...host 'bsrvvoce02' and port ''. [2016-05-10 12:06:15] DEBUG[19238] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2016-05-10 12:06:15] DEBUG[19238] acl.c: Attached to given IP address [2016-05-10 12:06:15] DEBUG[27690] netsock2.c: Splitting '10.21.15.115:4007' into... [2016-05-10 12:06:15] DEBUG[27690] netsock2.c: ...host '10.21.15.115' and port '4007'. [2016-05-10 12:06:15] DEBUG[27690] netsock2.c: Splitting '10.21.24.132:0' into... [2016-05-10 12:06:15] DEBUG[27690] netsock2.c: ...host '10.21.24.132' and port '0'. [2016-05-10 12:06:15] DEBUG[19250] res_rtp_asterisk.c: Got RTCP report of 84 bytes [2016-05-10 12:06:15] DEBUG[19250] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2016-05-10 12:06:15] DEBUG[19250] netsock2.c: Splitting 'bsrvvoce02' into... [2016-05-10 12:06:15] DEBUG[19250] netsock2.c: ...host 'bsrvvoce02' and port ''. [2016-05-10 12:06:15] DEBUG[19250] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2016-05-10 12:06:15] DEBUG[19250] acl.c: Attached to given IP address [2016-05-10 12:06:15] DEBUG[27690] netsock2.c: Splitting '10.21.15.119:4001' into... [2016-05-10 12:06:15] DEBUG[27690] netsock2.c: ...host '10.21.15.119' and port '4001'. [2016-05-10 12:06:15] DEBUG[27690] netsock2.c: Splitting '10.21.24.132:0' into... [2016-05-10 12:06:15] DEBUG[27690] netsock2.c: ...host '10.21.24.132' and port '0'. [2016-05-10 12:06:16] DEBUG[27570] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2016-05-10 12:06:16] DEBUG[27570] netsock2.c: Splitting 'bsrvvoce02' into... [2016-05-10 12:06:16] DEBUG[27570] netsock2.c: ...host 'bsrvvoce02' and port ''. [2016-05-10 12:06:16] DEBUG[27570] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2016-05-10 12:06:16] DEBUG[27570] acl.c: Attached to given IP address [2016-05-10 12:06:16] DEBUG[27690] netsock2.c: Splitting '10.21.24.132:0' into... [2016-05-10 12:06:16] DEBUG[27690] netsock2.c: ...host '10.21.24.132' and port '0'. [2016-05-10 12:06:16] DEBUG[27690] netsock2.c: Splitting '10.21.15.199:4013' into... [2016-05-10 12:06:16] DEBUG[27690] netsock2.c: ...host '10.21.15.199' and port '4013'. [2016-05-10 12:06:16] DEBUG[17287] res_rtp_asterisk.c: Got RTCP report of 84 bytes [2016-05-10 12:06:16] DEBUG[17287] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2016-05-10 12:06:16] DEBUG[17287] netsock2.c: Splitting 'bsrvvoce02' into... [2016-05-10 12:06:16] DEBUG[17287] netsock2.c: ...host 'bsrvvoce02' and port ''. [2016-05-10 12:06:16] DEBUG[17287] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2016-05-10 12:06:16] DEBUG[17287] acl.c: Attached to given IP address [2016-05-10 12:06:16] DEBUG[27690] netsock2.c: Splitting '10.21.15.199:4007' into... [2016-05-10 12:06:16] DEBUG[27690] netsock2.c: ...host '10.21.15.199' and port '4007'. [2016-05-10 12:06:16] DEBUG[27690] netsock2.c: Splitting '10.21.24.132:0' into... [2016-05-10 12:06:16] DEBUG[27690] netsock2.c: ...host '10.21.24.132' and port '0'. [2016-05-10 12:06:17] DEBUG[27570] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2016-05-10 12:06:17] DEBUG[27570] netsock2.c: Splitting 'bsrvvoce02' into... [2016-05-10 12:06:17] DEBUG[27570] netsock2.c: ...host 'bsrvvoce02' and port ''. [2016-05-10 12:06:17] DEBUG[27570] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2016-05-10 12:06:17] DEBUG[27570] acl.c: Attached to given IP address [2016-05-10 12:06:17] DEBUG[27690] netsock2.c: Splitting '10.21.24.132:0' into... [2016-05-10 12:06:17] DEBUG[27690] netsock2.c: ...host '10.21.24.132' and port '0'. [2016-05-10 12:06:17] DEBUG[27690] netsock2.c: Splitting '10.21.15.114:4003' into... [2016-05-10 12:06:17] DEBUG[27690] netsock2.c: ...host '10.21.15.114' and port '4003'. [2016-05-10 12:06:17] DEBUG[13979] pjproject: endpoint Request msg OPTIONS/cseq=28905 (tdta0x7f34f0090720) created. [2016-05-10 12:06:17] DEBUG[13979] config.c: extract uint from [3] in [0, 4294967295] gives [3](0) [2016-05-10 12:06:17] DEBUG[13979] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2016-05-10 12:06:17] DEBUG[13979] config.c: extract uint from [2] in [0, 4294967295] gives [2](0) [2016-05-10 12:06:17] DEBUG[13979] res_pjsip.c: 0x7f35cc167a38: Wrapper created [2016-05-10 12:06:17] DEBUG[13979] res_pjsip.c: 0x7f35cc167a38: Set timer to 3000 msec [2016-05-10 12:06:17] DEBUG[13979] pjproject: tsx0x7f35cc010 .Transaction created for Request msg OPTIONS/cseq=28905 (tdta0x7f34f0090720) [2016-05-10 12:06:17] DEBUG[13979] pjproject: tsx0x7f35cc010 Sending Request msg OPTIONS/cseq=28905 (tdta0x7f34f0090720) in state Null [2016-05-10 12:06:17] DEBUG[13979] pjproject: sip_resolve.c .Target '10.21.25.159:5060' type=Unspecified resolved to '10.21.25.159:5060' type=UDP (UDP transport) [2016-05-10 12:06:17] DEBUG[13979] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 10.21.24.132:5061 [2016-05-10 12:06:17] DEBUG[13979] netsock2.c: Splitting '0.0.0.0:5061' into... [2016-05-10 12:06:17] DEBUG[13979] netsock2.c: ...host '0.0.0.0' and port '5061'. [2016-05-10 12:06:17] DEBUG[13979] netsock2.c: Splitting '10.21.25.159:5060' into... [2016-05-10 12:06:17] DEBUG[13979] netsock2.c: ...host '10.21.25.159' and port '5060'. [2016-05-10 12:06:17] DEBUG[13979] pjproject: tsx0x7f35cc010 .State changed from Null to Calling, event=TX_MSG [2016-05-10 12:06:17] DEBUG[13978] pjproject: sip_endpoint.c Processing incoming message: Response msg 200/OPTIONS/cseq=28905 (rdata0x7f34f0003238) [2016-05-10 12:06:17] DEBUG[13978] netsock2.c: Splitting '10.21.25.159:5060' into... [2016-05-10 12:06:17] DEBUG[13978] netsock2.c: ...host '10.21.25.159' and port '5060'. [2016-05-10 12:06:17] DEBUG[13978] netsock2.c: Splitting '0.0.0.0:5061' into... [2016-05-10 12:06:17] DEBUG[13978] netsock2.c: ...host '0.0.0.0' and port '5061'. [2016-05-10 12:06:17] DEBUG[13978] res_pjsip/pjsip_distributor.c: No dialog serializer for response Response msg 200/OPTIONS/cseq=28905 (rdata0x7f34f0003238). Using request transaction as basis [2016-05-10 12:06:17] DEBUG[13978] res_pjsip/pjsip_distributor.c: Found serializer pjsip/default-0000000c on transaction tsx0x7f35cc0106b8 [2016-05-10 12:06:17] DEBUG[13979] pjproject: sip_endpoint.c Distributing rdata to modules: Response msg 200/OPTIONS/cseq=28905 (rdata0x7f34f0092f28) [2016-05-10 12:06:17] DEBUG[13979] pjproject: tsx0x7f35cc010 .Incoming Response msg 200/OPTIONS/cseq=28905 (rdata0x7f34f0092f28) in state Calling [2016-05-10 12:06:17] DEBUG[13979] pjproject: tsx0x7f35cc010 ..State changed from Calling to Completed, event=RX_MSG [2016-05-10 12:06:17] DEBUG[13979] res_pjsip.c: 0x7f35cc167a38: PJSIP tsx response received [2016-05-10 12:06:17] DEBUG[13979] res_pjsip.c: 0x7f35cc167a38: Cancelling timer [2016-05-10 12:06:17] DEBUG[13979] res_pjsip.c: 0x7f35cc167a38: Timer cancelled [2016-05-10 12:06:17] DEBUG[13979] config.c: extract uint from [3] in [0, 4294967295] gives [3](0) [2016-05-10 12:06:17] DEBUG[13979] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2016-05-10 12:06:17] DEBUG[13979] config.c: extract uint from [2] in [0, 4294967295] gives [2](0) [2016-05-10 12:06:17] DEBUG[13979] res_pjsip.c: 0x7f35cc167a38: Callbacks executed [2016-05-10 12:06:17] DEBUG[13979] res_pjsip.c: 0x7f35cc167a38: wrapper destroyed [2016-05-10 12:06:17] DEBUG[14023] res_pjsip/pjsip_configuration.c: Contact ToMxOneBySIP/sip:10.21.25.159:5060 status didn't change: Reachable, RTT: 25.962 msec [2016-05-10 12:06:18] DEBUG[13978] pjproject: tsx0x7f35cc02e Timeout timer event [2016-05-10 12:06:18] DEBUG[13978] pjproject: tsx0x7f35cc02e .State changed from Completed to Terminated, event=TIMER [2016-05-10 12:06:18] DEBUG[13978] pjproject: tsx0x7f35cc02e Timeout timer event [2016-05-10 12:06:18] DEBUG[13978] pjproject: tsx0x7f35cc02e .State changed from Terminated to Destroyed, event=TIMER [2016-05-10 12:06:18] DEBUG[13978] pjproject: tdta0x7f34f000 ..Destroying txdata Request msg OPTIONS/cseq=17652 (tdta0x7f34f0007ff0) [2016-05-10 12:06:18] DEBUG[13978] pjproject: tsx0x7f35cc02e Transaction destroyed! [2016-05-10 12:06:18] DEBUG[13978] pjproject: tsx0x7f35cc00a Timeout timer event [2016-05-10 12:06:18] DEBUG[13978] pjproject: tsx0x7f35cc00a .State changed from Completed to Terminated, event=TIMER [2016-05-10 12:06:18] DEBUG[13978] pjproject: tsx0x7f35cc00a Timeout timer event [2016-05-10 12:06:18] DEBUG[13978] pjproject: tsx0x7f35cc00a .State changed from Terminated to Destroyed, event=TIMER [2016-05-10 12:06:18] DEBUG[13978] pjproject: tdta0x7f34f007 ..Destroying txdata Request msg OPTIONS/cseq=52826 (tdta0x7f34f007fb80) [2016-05-10 12:06:18] DEBUG[13978] pjproject: tsx0x7f35cc00a Transaction destroyed! [2016-05-10 12:06:18] DEBUG[27570] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2016-05-10 12:06:18] DEBUG[27570] netsock2.c: Splitting 'bsrvvoce02' into... [2016-05-10 12:06:18] DEBUG[27570] netsock2.c: ...host 'bsrvvoce02' and port ''. [2016-05-10 12:06:18] DEBUG[27570] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2016-05-10 12:06:18] DEBUG[27570] acl.c: Attached to given IP address [2016-05-10 12:06:18] DEBUG[27690] netsock2.c: Splitting '10.21.24.132:0' into... [2016-05-10 12:06:18] DEBUG[27690] netsock2.c: ...host '10.21.24.132' and port '0'. [2016-05-10 12:06:18] DEBUG[27690] netsock2.c: Splitting '10.21.15.115:4007' into... [2016-05-10 12:06:18] DEBUG[27690] netsock2.c: ...host '10.21.15.115' and port '4007'. [2016-05-10 12:06:18] DEBUG[18309] res_rtp_asterisk.c: Got RTCP report of 84 bytes [2016-05-10 12:06:18] DEBUG[18309] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2016-05-10 12:06:18] DEBUG[18309] netsock2.c: Splitting 'bsrvvoce02' into... [2016-05-10 12:06:18] DEBUG[18309] netsock2.c: ...host 'bsrvvoce02' and port ''. [2016-05-10 12:06:18] DEBUG[18309] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2016-05-10 12:06:18] DEBUG[18309] acl.c: Attached to given IP address [2016-05-10 12:06:18] DEBUG[27690] netsock2.c: Splitting '10.21.15.199:4013' into... [2016-05-10 12:06:18] DEBUG[27690] netsock2.c: ...host '10.21.15.199' and port '4013'. [2016-05-10 12:06:18] DEBUG[27690] netsock2.c: Splitting '10.21.24.132:0' into... [2016-05-10 12:06:18] DEBUG[27690] netsock2.c: ...host '10.21.24.132' and port '0'. [2016-05-10 12:06:18] DEBUG[19361] http.c: HTTP opening session. Top level [2016-05-10 12:06:18] DEBUG[19361] http.c: HTTP Request URI is /ARI/events/user/ClientCommand?application=Robot [2016-05-10 12:06:18] DEBUG[19361] http.c: match request [ARI/events/user/ClientCommand] with handler [httpstatus] len 10 [2016-05-10 12:06:18] DEBUG[19361] http.c: match request [ARI/events/user/ClientCommand] with handler [static] len 6 [2016-05-10 12:06:18] DEBUG[19361] http.c: match request [ARI/events/user/ClientCommand] with handler [ari] len 3 [2016-05-10 12:06:18] DEBUG[19361] http.c: Match made with [ari] [2016-05-10 12:06:18] DEBUG[19361] res_ari.c: Finding handler for events [2016-05-10 12:06:18] DEBUG[19361] res_ari.c: Checking events [2016-05-10 12:06:18] DEBUG[19361] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19361] res_ari.c: Finding handler for user [2016-05-10 12:06:18] DEBUG[19361] res_ari.c: Checking user [2016-05-10 12:06:18] DEBUG[19361] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19361] res_ari.c: Finding handler for ClientCommand [2016-05-10 12:06:18] DEBUG[19361] res_ari.c: Checking eventName [2016-05-10 12:06:18] DEBUG[19361] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19361] http.c: HTTP consuming request body [2016-05-10 12:06:18] DEBUG[19361] res_ari.c: Examining ARI response: 204 No Content [2016-05-10 12:06:18] DEBUG[19361] http.c: HTTP keeping session open. status_code:204 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 391 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 391 [2016-05-10 12:06:18] DEBUG[19348] http.c: HTTP Request URI is /ari/channels?timeout=600&app=Robot&endpoint=PJSIP%2F1078&appArgs=InsertConference%2C0e1ab657-8a62-4927-9565-ba605f85c446%2C2&callerId=241_0e1ab657-8a62-4927-9565-ba605f85c446_3 [2016-05-10 12:06:18] DEBUG[19348] http.c: match request [ari/channels] with handler [httpstatus] len 10 [2016-05-10 12:06:18] DEBUG[19348] http.c: match request [ari/channels] with handler [static] len 6 [2016-05-10 12:06:18] DEBUG[19348] http.c: match request [ari/channels] with handler [ari] len 3 [2016-05-10 12:06:18] DEBUG[19348] http.c: Match made with [ari] [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Finding handler for channels [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking events [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking sounds [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking asterisk [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking deviceStates [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking playbacks [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking bridges [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking channels [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[13979] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [2016-05-10 12:06:18] DEBUG[13979] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [2016-05-10 12:06:18] DEBUG[13979] config.c: extract uint from [60] in [0, 86400] gives [60](0) [2016-05-10 12:06:18] DEBUG[13979] pjproject: dlg0x7f35cc00a UAC dialog created [2016-05-10 12:06:18] DEBUG[13979] pjproject: dlg0x7f35cc00a Module Outbound INVITE Auth added as dialog usage, data=(nil) [2016-05-10 12:06:18] DEBUG[13979] pjproject: dlg0x7f35cc00a Module mod-invite added as dialog usage, data=0x7f35cc184ff8 [2016-05-10 12:06:18] DEBUG[13979] pjproject: dlg0x7f35cc00a .Session count inc to 2 by mod-invite [2016-05-10 12:06:18] DEBUG[13979] pjproject: dlg0x7f35cc00a Module mod-100rel added as dialog usage, data=0x7f35cc184a90 [2016-05-10 12:06:18] DEBUG[13979] pjproject: dlg0x7f35cc00a 100rel module attached [2016-05-10 12:06:18] DEBUG[13979] pjproject: inv0x7f35cc00a UAC invite session created for dialog dlg0x7f35cc00a878 [2016-05-10 12:06:18] DEBUG[13979] pjproject: dlg0x7f35cc00a .Session count inc to 2 by Session Module [2016-05-10 12:06:18] DEBUG[13979] pjproject: dlg0x7f35cc00a Module Session Module added as dialog usage, data=(nil) [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket string of length 267 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket text frame, length 267 [2016-05-10 12:06:18] DEBUG[13571] res_odbc.c: Connecting MSSQLSERVER(0x7f35f4085a08) [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket string of length 545 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket text frame, length 545 [2016-05-10 12:06:18] DEBUG[19348] res_stasis.c: Robot: Subscribing to 1462871178.139 [2016-05-10 12:06:18] DEBUG[19348] stasis/app.c: Channel '1462871178.139' is 1 interested in Robot [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket string of length 618 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket text frame, length 618 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket string of length 677 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket text frame, length 677 [2016-05-10 12:06:18] DEBUG[19348] http.c: HTTP keeping session open. status_code:200 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket string of length 629 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket text frame, length 629 [2016-05-10 12:06:18] VERBOSE[19362] dial.c: Called 1078 [2016-05-10 12:06:18] DEBUG[13979] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f35cc190ad8' [2016-05-10 12:06:18] DEBUG[13979] res_rtp_asterisk.c: Allocated port 15978 for RTP instance '0x7f35cc190ad8' [2016-05-10 12:06:18] DEBUG[13979] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:15978 (15978) for RTP instance '0x7f35cc190ad8' [2016-05-10 12:06:18] DEBUG[13979] pjproject: icess0x7f35cc1 ICE session created, comp_cnt=2, role is Unknown agent [2016-05-10 12:06:18] DEBUG[13979] netsock2.c: Splitting '10.21.24.132' into... [2016-05-10 12:06:18] DEBUG[13979] netsock2.c: ...host '10.21.24.132' and port ''. [2016-05-10 12:06:18] DEBUG[13979] pjproject: icess0x7f35cc1 Candidate 0 added: comp_id=1, type=host, foundation=Ha151884, addr=10.21.24.132:15978, base=10.21.24.132:15978, prio=0x7effffff (2130706431) [2016-05-10 12:06:18] DEBUG[13979] rtp_engine.c: RTP instance '0x7f35cc190ad8' is setup and ready to go [2016-05-10 12:06:18] DEBUG[13979] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f35cc190ad8' [2016-05-10 12:06:18] DEBUG[13979] netsock2.c: Splitting '10.21.24.132' into... [2016-05-10 12:06:18] DEBUG[13979] netsock2.c: ...host '10.21.24.132' and port ''. [2016-05-10 12:06:18] DEBUG[13979] pjproject: icess0x7f35cc1 Candidate 1 added: comp_id=2, type=host, foundation=Ha151884, addr=10.21.24.132:15979, base=10.21.24.132:15979, prio=0x7efffffe (2130706430) [2016-05-10 12:06:18] DEBUG[13979] pjproject: icess0x7f35cc1 Destroying ICE session 0x7f35cc196b48 [2016-05-10 12:06:18] DEBUG[13979] pjproject: stuse0x7f35cc1 STUN session 0x7f35cc198f68 destroy request, ref_cnt=4 [2016-05-10 12:06:18] DEBUG[13979] pjproject: stuse0x7f35cc1 STUN session 0x7f35cc199f68 destroy request, ref_cnt=3 [2016-05-10 12:06:18] DEBUG[13979] pjproject: ice_session.c ICE session 0x7f35cc196b48 destroyed [2016-05-10 12:06:18] DEBUG[13979] pjproject: stun_session.c STUN session 0x7f35cc198f68 destroyed [2016-05-10 12:06:18] DEBUG[13979] pjproject: stun_session.c STUN session 0x7f35cc199f68 destroyed [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_t38.c: Not creating outgoing SDP stream: T.38 not enabled [2016-05-10 12:06:18] DEBUG[13979] pjproject: endpoint Request msg INVITE/cseq=25646 (tdta0x7f34f007fb80) created. [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Method is INVITE [2016-05-10 12:06:18] DEBUG[13979] pjproject: dlg0x7f35cc00a Module NAT added as dialog usage, data=(nil) [2016-05-10 12:06:18] DEBUG[13979] pjproject: dlg0x7f35cc00a Module WebSocket Transport Module added as dialog usage, data=(nil) [2016-05-10 12:06:18] DEBUG[13979] pjproject: inv0x7f35cc00a .Sending Request msg INVITE/cseq=25646 (tdta0x7f34f007fb80) [2016-05-10 12:06:18] DEBUG[13979] pjproject: dlg0x7f35cc00a ..Sending Request msg INVITE/cseq=25646 (tdta0x7f34f007fb80) [2016-05-10 12:06:18] DEBUG[13979] pjproject: tsx0x7f35cc02e ...Transaction created for Request msg INVITE/cseq=25645 (tdta0x7f34f007fb80) [2016-05-10 12:06:18] DEBUG[13979] pjproject: tsx0x7f35cc02e ..Sending Request msg INVITE/cseq=25645 (tdta0x7f34f007fb80) in state Null [2016-05-10 12:06:18] DEBUG[13979] pjproject: sip_resolve.c ...Target '10.21.15.118:5060' type=Unspecified resolved to '10.21.15.118:5060' type=UDP (UDP transport) [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 10.21.24.132:5061 [2016-05-10 12:06:18] DEBUG[13979] netsock2.c: Splitting '0.0.0.0:5061' into... [2016-05-10 12:06:18] DEBUG[13979] netsock2.c: ...host '0.0.0.0' and port '5061'. [2016-05-10 12:06:18] DEBUG[13979] netsock2.c: Splitting '10.21.15.118:5060' into... [2016-05-10 12:06:18] DEBUG[13979] netsock2.c: ...host '10.21.15.118' and port '5060'. [2016-05-10 12:06:18] DEBUG[13979] pjproject: tsx0x7f35cc02e ...State changed from Null to Calling, event=TX_MSG [2016-05-10 12:06:18] DEBUG[13979] pjproject: dlg0x7f35cc00a ....Transaction tsx0x7f35cc02ea38 state changed to Calling [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The state change pertains to the endpoint '1078(PJSIP/1078-00000013)' [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f35cc02ea38) [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: There is no transaction involved in this state change [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The current inv state is CALLING [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Source of transaction state change is TX_MSG [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Sending request [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Method is INVITE [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The state change pertains to the endpoint '1078(PJSIP/1078-00000013)' [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f35cc02ea38) [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f35cc02ea38 [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The current transaction state is Calling [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The transaction state change event is TX_MSG [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The current inv state is CALLING [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Sending request [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Method is INVITE [2016-05-10 12:06:18] DEBUG[13978] pjproject: sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=25645 (rdata0x7f34f0003238) [2016-05-10 12:06:18] DEBUG[13978] netsock2.c: Splitting '10.21.15.118:5060' into... [2016-05-10 12:06:18] DEBUG[13978] netsock2.c: ...host '10.21.15.118' and port '5060'. [2016-05-10 12:06:18] DEBUG[13978] netsock2.c: Splitting '0.0.0.0:5061' into... [2016-05-10 12:06:18] DEBUG[13978] netsock2.c: ...host '0.0.0.0' and port '5061'. [2016-05-10 12:06:18] DEBUG[13978] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f35cc00a878 for Response msg 100/INVITE/cseq=25645 (rdata0x7f34f0003238) [2016-05-10 12:06:18] DEBUG[13978] res_pjsip/pjsip_distributor.c: Found serializer pjsip/session/1078-00000256 on dialog dlg0x7f35cc00a878 [2016-05-10 12:06:18] DEBUG[13979] pjproject: sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=25645 (rdata0x7f34f0093308) [2016-05-10 12:06:18] DEBUG[13979] pjproject: tsx0x7f35cc02e .Incoming Response msg 100/INVITE/cseq=25645 (rdata0x7f34f0093308) in state Calling [2016-05-10 12:06:18] DEBUG[13979] pjproject: tsx0x7f35cc02e ..State changed from Calling to Proceeding, event=RX_MSG [2016-05-10 12:06:18] DEBUG[13979] pjproject: dlg0x7f35cc00a ...Received Response msg 100/INVITE/cseq=25645 (rdata0x7f34f0093308) [2016-05-10 12:06:18] DEBUG[13979] pjproject: dlg0x7f35cc00a ...Transaction tsx0x7f35cc02ea38 state changed to Proceeding [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The state change pertains to the endpoint '1078(PJSIP/1078-00000013)' [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f35cc02ea38) [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f35cc02ea38 [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The current transaction state is Proceeding [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The transaction state change event is RX_MSG [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The current inv state is CALLING [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Received response [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Response is 100 Trying [2016-05-10 12:06:18] DEBUG[13571] res_odbc.c: res_odbc: Connected to MSSQLSERVER [MSSQLSERVER (0x7f35f4085a08)] [2016-05-10 12:06:18] DEBUG[13571] cel_odbc.c: Executing SQL statement: [INSERT INTO cel_bsrvvoce02 (eventtype,eventtime,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,peer,userfield) VALUES ('CHAN_START','2016-05-10 12:06:18.623192','s','from-team','PJSIP/1078-00000013','','',3,'','1462871178.139','','')] [2016-05-10 12:06:18] DEBUG[13571] res_odbc.c: Releasing ODBC handle 0x7f35f4085a08 [2016-05-10 12:06:18] DEBUG[13571] res_odbc.c: Database handle 0x7f35f4085a08 (connection 0x7f35f4012730) deallocated [2016-05-10 12:06:18] DEBUG[13978] pjproject: sip_endpoint.c Processing incoming message: Response msg 180/INVITE/cseq=25645 (rdata0x7f34f0003238) [2016-05-10 12:06:18] DEBUG[13978] netsock2.c: Splitting '10.21.15.118:5060' into... [2016-05-10 12:06:18] DEBUG[13978] netsock2.c: ...host '10.21.15.118' and port '5060'. [2016-05-10 12:06:18] DEBUG[13978] netsock2.c: Splitting '0.0.0.0:5061' into... [2016-05-10 12:06:18] DEBUG[13978] netsock2.c: ...host '0.0.0.0' and port '5061'. [2016-05-10 12:06:18] DEBUG[13978] res_pjsip/pjsip_distributor.c: No dialog serializer for response Response msg 180/INVITE/cseq=25645 (rdata0x7f34f0003238). Using request transaction as basis [2016-05-10 12:06:18] DEBUG[13978] res_pjsip/pjsip_distributor.c: Found serializer pjsip/session/1078-00000256 on transaction tsx0x7f35cc02ea38 [2016-05-10 12:06:18] DEBUG[13979] pjproject: sip_endpoint.c Distributing rdata to modules: Response msg 180/INVITE/cseq=25645 (rdata0x7f34f0093308) [2016-05-10 12:06:18] DEBUG[13979] pjproject: tsx0x7f35cc02e .Incoming Response msg 180/INVITE/cseq=25645 (rdata0x7f34f0093308) in state Proceeding [2016-05-10 12:06:18] DEBUG[13979] pjproject: tsx0x7f35cc02e ..State changed from Proceeding to Proceeding, event=RX_MSG [2016-05-10 12:06:18] DEBUG[13979] pjproject: dlg0x7f35cc00a ...Received Response msg 180/INVITE/cseq=25645 (rdata0x7f34f0093308) [2016-05-10 12:06:18] DEBUG[13979] pjproject: dlg0x7f35cc00a ....Route-set updated [2016-05-10 12:06:18] DEBUG[13979] pjproject: dlg0x7f35cc00a ...Transaction tsx0x7f35cc02ea38 state changed to Proceeding [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The state change pertains to the endpoint '1078(PJSIP/1078-00000013)' [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f35cc02ea38) [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: There is no transaction involved in this state change [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The current inv state is EARLY [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Source of transaction state change is RX_MSG [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Received response [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Response is 180 Ringing [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The state change pertains to the endpoint '1078(PJSIP/1078-00000013)' [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f35cc02ea38) [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f35cc02ea38 [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The current transaction state is Proceeding [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The transaction state change event is RX_MSG [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The current inv state is EARLY [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Received response [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Response is 180 Ringing [2016-05-10 12:06:18] VERBOSE[19362] dial.c: PJSIP/1078-00000013 is ringing [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket string of length 630 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket text frame, length 630 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 616 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 616 [2016-05-10 12:06:18] DEBUG[13478] devicestate.c: No provider found, checking channel drivers for PJSIP - 1078 [2016-05-10 12:06:18] DEBUG[13478] devicestate.c: Changing state for PJSIP/1078 - state 6 (Ringing) [2016-05-10 12:06:18] DEBUG[28044] app_queue.c: Device 'PJSIP/1078' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [2016-05-10 12:06:18] DEBUG[13541] app_queue.c: Extension '1078@ext-local' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [2016-05-10 12:06:18] DEBUG[13541] app_queue.c: Extension '*801078@ext-local' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [2016-05-10 12:06:18] DEBUG[13978] pjproject: sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=25645 (rdata0x7f34f0003238) [2016-05-10 12:06:18] DEBUG[13978] netsock2.c: Splitting '10.21.15.118:5060' into... [2016-05-10 12:06:18] DEBUG[13978] netsock2.c: ...host '10.21.15.118' and port '5060'. [2016-05-10 12:06:18] DEBUG[13978] netsock2.c: Splitting '0.0.0.0:5061' into... [2016-05-10 12:06:18] DEBUG[13978] netsock2.c: ...host '0.0.0.0' and port '5061'. [2016-05-10 12:06:18] DEBUG[13978] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f35cc00a878 for Response msg 200/INVITE/cseq=25645 (rdata0x7f34f0003238) [2016-05-10 12:06:18] DEBUG[13978] res_pjsip/pjsip_distributor.c: Found serializer pjsip/session/1078-00000256 on dialog dlg0x7f35cc00a878 [2016-05-10 12:06:18] DEBUG[13979] pjproject: sip_endpoint.c Distributing rdata to modules: Response msg 200/INVITE/cseq=25645 (rdata0x7f34f00936e8) [2016-05-10 12:06:18] DEBUG[13979] pjproject: tsx0x7f35cc02e .Incoming Response msg 200/INVITE/cseq=25645 (rdata0x7f34f00936e8) in state Proceeding [2016-05-10 12:06:18] DEBUG[13979] pjproject: tsx0x7f35cc02e ..State changed from Proceeding to Terminated, event=RX_MSG [2016-05-10 12:06:18] DEBUG[13979] pjproject: dlg0x7f35cc00a ...Received Response msg 200/INVITE/cseq=25645 (rdata0x7f34f00936e8) [2016-05-10 12:06:18] DEBUG[13979] pjproject: dlg0x7f35cc00a ....Route-set updated [2016-05-10 12:06:18] DEBUG[13979] pjproject: dlg0x7f35cc00a ....Route-set frozen [2016-05-10 12:06:18] DEBUG[13979] pjproject: dlg0x7f35cc00a ...Transaction tsx0x7f35cc02ea38 state changed to Terminated [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The state change pertains to the endpoint '1078(PJSIP/1078-00000013)' [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f35cc02ea38) [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: There is no transaction involved in this state change [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The current inv state is CONNECTING [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Source of transaction state change is RX_MSG [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Received response [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Response is 200 OK [2016-05-10 12:06:18] DEBUG[13979] pjproject: inv0x7f35cc00a ....Got SDP answer in Response msg 200/INVITE/cseq=25645 (rdata0x7f34f00936e8) [2016-05-10 12:06:18] DEBUG[13979] pjproject: inv0x7f35cc00a ....SDP negotiation done, status=0 [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [2016-05-10 12:06:18] DEBUG[13979] netsock2.c: Splitting '10.21.15.118' into... [2016-05-10 12:06:18] DEBUG[13979] netsock2.c: ...host '10.21.15.118' and port ''. [2016-05-10 12:06:18] DEBUG[13979] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f35cc190ad8' [2016-05-10 12:06:18] DEBUG[13979] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f35e0451ab0 [2016-05-10 12:06:18] DEBUG[13979] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7f35e0451ab0 [2016-05-10 12:06:18] DEBUG[13979] rtp_engine.c: Copying payload 0 (0x7f35cc1a0230) from 0x7f35e0451ab0 to 0x7f35cc190ca0 [2016-05-10 12:06:18] DEBUG[13979] rtp_engine.c: Copying payload 101 (0x7f35cc1a37f0) from 0x7f35e0451ab0 to 0x7f35cc190ca0 [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [2016-05-10 12:06:18] DEBUG[13979] pjproject: inv0x7f35cc00a ....Received Response msg 200/INVITE/cseq=25645 (rdata0x7f34f00936e8), sending ACK [2016-05-10 12:06:18] DEBUG[13979] pjproject: endpoint ....Request msg ACK/cseq=25645 (tdta0x7f34f0091ef0) created. [2016-05-10 12:06:18] DEBUG[13979] pjproject: dlg0x7f35cc00a .....Sending Request msg ACK/cseq=25645 (tdta0x7f34f0091ef0) [2016-05-10 12:06:18] DEBUG[19362] res_rtp_asterisk.c: Got RTCP report of 64 bytes [2016-05-10 12:06:18] DEBUG[13979] pjproject: sip_resolve.c .....Target '10.21.15.118:5060' type=Unspecified resolved to '10.21.15.118:5060' type=UDP (UDP transport) [2016-05-10 12:06:18] DEBUG[19362] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2016-05-10 12:06:18] DEBUG[19362] netsock2.c: Splitting 'bsrvvoce02' into... [2016-05-10 12:06:18] DEBUG[19362] netsock2.c: ...host 'bsrvvoce02' and port ''. [2016-05-10 12:06:18] DEBUG[13979] netsock2.c: Splitting '0.0.0.0:5061' into... [2016-05-10 12:06:18] DEBUG[13979] netsock2.c: ...host '0.0.0.0' and port '5061'. [2016-05-10 12:06:18] DEBUG[19362] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2016-05-10 12:06:18] DEBUG[19362] acl.c: Attached to given IP address [2016-05-10 12:06:18] DEBUG[13979] netsock2.c: Splitting '10.21.15.118:5060' into... [2016-05-10 12:06:18] DEBUG[13979] netsock2.c: ...host '10.21.15.118' and port '5060'. [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Function session_inv_on_state_changed called on event TX_MSG [2016-05-10 12:06:18] DEBUG[19362] res_rtp_asterisk.c: Got RTCP report of 64 bytes [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The state change pertains to the endpoint '1078(PJSIP/1078-00000013)' [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f35cc02ea38) [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: There is no transaction involved in this state change [2016-05-10 12:06:18] DEBUG[19362] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2016-05-10 12:06:18] DEBUG[19362] netsock2.c: Splitting 'bsrvvoce02' into... [2016-05-10 12:06:18] DEBUG[19362] netsock2.c: ...host 'bsrvvoce02' and port ''. [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The current inv state is CONFIRMED [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Sending request [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Method is ACK [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The state change pertains to the endpoint '1078(PJSIP/1078-00000013)' [2016-05-10 12:06:18] DEBUG[27690] netsock2.c: Splitting '10.21.15.118:4009' into... [2016-05-10 12:06:18] DEBUG[27690] netsock2.c: ...host '10.21.15.118' and port '4009'. [2016-05-10 12:06:18] DEBUG[27690] netsock2.c: Splitting '10.21.24.132:0' into... [2016-05-10 12:06:18] DEBUG[27690] netsock2.c: ...host '10.21.24.132' and port '0'. [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2016-05-10 12:06:18] DEBUG[19362] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f35cc02ea38 [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The current transaction state is Terminated [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The transaction state change event is RX_MSG [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: The current inv state is CONFIRMED [2016-05-10 12:06:18] DEBUG[19362] acl.c: Attached to given IP address [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Received response [2016-05-10 12:06:18] DEBUG[13979] res_pjsip_session.c: Response is 200 OK [2016-05-10 12:06:18] DEBUG[27690] netsock2.c: Splitting '10.21.15.118:4009' into... [2016-05-10 12:06:18] DEBUG[27690] netsock2.c: ...host '10.21.15.118' and port '4009'. [2016-05-10 12:06:18] DEBUG[27690] netsock2.c: Splitting '10.21.24.132:0' into... [2016-05-10 12:06:18] DEBUG[27690] netsock2.c: ...host '10.21.24.132' and port '0'. [2016-05-10 12:06:18] DEBUG[13571] res_odbc.c: Connecting MSSQLSERVER(0x7f35f4085a08) [2016-05-10 12:06:18] VERBOSE[19362] dial.c: PJSIP/1078-00000013 answered [2016-05-10 12:06:18] DEBUG[13478] devicestate.c: No provider found, checking channel drivers for PJSIP - 1078 [2016-05-10 12:06:18] DEBUG[13478] devicestate.c: Changing state for PJSIP/1078 - state 2 (In use) [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket string of length 625 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket text frame, length 625 [2016-05-10 12:06:18] DEBUG[28044] app_queue.c: Device 'PJSIP/1078' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 611 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 611 [2016-05-10 12:06:18] DEBUG[13541] app_queue.c: Extension '1078@ext-local' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2016-05-10 12:06:18] DEBUG[13541] app_queue.c: Extension '*801078@ext-local' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2016-05-10 12:06:18] DEBUG[19362] stasis/app.c: Channel '1462871178.139' is 2 interested in Robot [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket string of length 665 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket text frame, length 665 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 651 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 651 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 697 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 697 [2016-05-10 12:06:18] DEBUG[19363] http.c: HTTP opening session. Top level [2016-05-10 12:06:18] DEBUG[19363] http.c: HTTP Request URI is /ari/events/user/RemoveIncomingCall?eventName=RemoveIncomingCall&application=1078 [2016-05-10 12:06:18] DEBUG[19363] http.c: match request [ari/events/user/RemoveIncomingCall] with handler [httpstatus] len 10 [2016-05-10 12:06:18] DEBUG[19363] http.c: match request [ari/events/user/RemoveIncomingCall] with handler [static] len 6 [2016-05-10 12:06:18] DEBUG[19363] http.c: match request [ari/events/user/RemoveIncomingCall] with handler [ari] len 3 [2016-05-10 12:06:18] DEBUG[19363] http.c: Match made with [ari] [2016-05-10 12:06:18] DEBUG[19363] res_ari.c: Finding handler for events [2016-05-10 12:06:18] DEBUG[19363] res_ari.c: Checking events [2016-05-10 12:06:18] DEBUG[19363] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19363] res_ari.c: Finding handler for user [2016-05-10 12:06:18] DEBUG[19363] res_ari.c: Checking user [2016-05-10 12:06:18] DEBUG[19363] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19363] res_ari.c: Finding handler for RemoveIncomingCall [2016-05-10 12:06:18] DEBUG[19363] res_ari.c: Checking eventName [2016-05-10 12:06:18] DEBUG[19363] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19363] http.c: HTTP consuming request body [2016-05-10 12:06:18] DEBUG[19363] res_ari.c: Examining ARI response: 204 No Content [2016-05-10 12:06:18] DEBUG[19363] http.c: HTTP keeping session open. status_code:204 [2016-05-10 12:06:18] DEBUG[12370] res_http_websocket.c: Writing websocket string of length 387 [2016-05-10 12:06:18] DEBUG[12370] res_http_websocket.c: Writing websocket text frame, length 387 [2016-05-10 12:06:18] DEBUG[19363] http.c: HTTP idle timeout or peer closed connection. [2016-05-10 12:06:18] DEBUG[19363] http.c: HTTP closing session. Top level [2016-05-10 12:06:18] DEBUG[19348] http.c: HTTP Request URI is /ari/bridges/6b75e0a8-fa33-4caa-b5c5-9674f6e23f1a/addChannel?channel=1462871178.139 [2016-05-10 12:06:18] DEBUG[19348] http.c: match request [ari/bridges/6b75e0a8-fa33-4caa-b5c5-9674f6e23f1a/addChannel] with handler [httpstatus] len 10 [2016-05-10 12:06:18] DEBUG[19348] http.c: match request [ari/bridges/6b75e0a8-fa33-4caa-b5c5-9674f6e23f1a/addChannel] with handler [static] len 6 [2016-05-10 12:06:18] DEBUG[19348] http.c: match request [ari/bridges/6b75e0a8-fa33-4caa-b5c5-9674f6e23f1a/addChannel] with handler [ari] len 3 [2016-05-10 12:06:18] DEBUG[19348] http.c: Match made with [ari] [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Finding handler for bridges [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking events [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking sounds [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking asterisk [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking deviceStates [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking playbacks [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking bridges [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Finding handler for 6b75e0a8-fa33-4caa-b5c5-9674f6e23f1a [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking bridgeId [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Finding handler for addChannel [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking addChannel [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19348] stasis/control.c: 1462871178.139: Sending channel add_to_bridge command [2016-05-10 12:06:18] DEBUG[19362] bridge_roles.c: Roles did not exist on channel PJSIP/1078-00000013 [2016-05-10 12:06:18] DEBUG[19362] stasis/control.c: 1462871178.139: Adding to bridge 6b75e0a8-fa33-4caa-b5c5-9674f6e23f1a [2016-05-10 12:06:18] DEBUG[19362] stasis/app.c: Bridge '6b75e0a8-fa33-4caa-b5c5-9674f6e23f1a' is 7 interested in Robot [2016-05-10 12:06:18] DEBUG[19364] bridge_channel.c: Bridge 6b75e0a8-fa33-4caa-b5c5-9674f6e23f1a: 0x7f3460003e98(PJSIP/1078-00000013) is joining [2016-05-10 12:06:18] DEBUG[19364] bridge_channel.c: Bridge 6b75e0a8-fa33-4caa-b5c5-9674f6e23f1a: pushing 0x7f3460003e98(PJSIP/1078-00000013) [2016-05-10 12:06:18] VERBOSE[19364] bridge_channel.c: Channel PJSIP/1078-00000013 joined 'softmix' stasis-bridge <6b75e0a8-fa33-4caa-b5c5-9674f6e23f1a> [2016-05-10 12:06:18] DEBUG[13516] cdr.c: Finalized CDR for PJSIP/1078-00000013 - start 1462871178.623215 answer 1462871178.635496 end 1462871178.643332 dispo ANSWERED [2016-05-10 12:06:18] DEBUG[19364] bridge.c: Bridge technology native_dahdi does not have any capabilities we want. [2016-05-10 12:06:18] DEBUG[19364] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [2016-05-10 12:06:18] DEBUG[19364] bridge.c: Bridge technology simple_bridge does not have any capabilities we want. [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 988 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 988 [2016-05-10 12:06:18] DEBUG[19364] bridge.c: Bridge technology native_rtp does not have any capabilities we want. [2016-05-10 12:06:18] DEBUG[19364] bridge.c: Chose bridge technology softmix [2016-05-10 12:06:18] DEBUG[19364] bridge.c: Bridge 6b75e0a8-fa33-4caa-b5c5-9674f6e23f1a is already using the new technology. [2016-05-10 12:06:18] DEBUG[19364] bridge.c: Bridge 6b75e0a8-fa33-4caa-b5c5-9674f6e23f1a: 0x7f3460003e98(PJSIP/1078-00000013) is joining softmix technology [2016-05-10 12:06:18] DEBUG[19364] channel.c: Channel PJSIP/1078-00000013 setting read format path: ulaw -> slin [2016-05-10 12:06:18] DEBUG[19364] channel.c: Channel PJSIP/1078-00000013 setting write format path: slin -> ulaw [2016-05-10 12:06:18] DEBUG[19364] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [2016-05-10 12:06:18] DEBUG[19364] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket string of length 755 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 741 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket text frame, length 755 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 741 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 650 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 650 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 741 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 741 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket string of length 755 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket text frame, length 755 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket string of length 755 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket text frame, length 755 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 741 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 741 [2016-05-10 12:06:18] DEBUG[19362] stasis/app.c: App 'Robot' not subscribed to bridge '__AST_BRIDGE_ALL_TOPIC' [2016-05-10 12:06:18] DEBUG[19362] stasis/app.c: Bridge '6b75e0a8-fa33-4caa-b5c5-9674f6e23f1a' is 8 interested in Robot [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Examining ARI response: 204 No Content [2016-05-10 12:06:18] DEBUG[19348] http.c: HTTP keeping session open. status_code:204 [2016-05-10 12:06:18] DEBUG[19364] res_rtp_asterisk.c: 0x7f35cc1940c0 -- Probation learning mode pass with source address 10.21.15.118:4008 [2016-05-10 12:06:18] DEBUG[13571] res_odbc.c: res_odbc: Connected to MSSQLSERVER [MSSQLSERVER (0x7f35f4085a08)] [2016-05-10 12:06:18] DEBUG[13571] cel_odbc.c: Executing SQL statement: [INSERT INTO cel_bsrvvoce02 (eventtype,eventtime,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,peer,userfield) VALUES ('ANSWER','2016-05-10 12:06:18.635482','s','from-team','PJSIP/1078-00000013','AppDial2','(Outgoing Line)',3,'','1462871178.139','','')] [2016-05-10 12:06:18] DEBUG[13978] pjproject: tsx0x7f35cc02e Timeout timer event [2016-05-10 12:06:18] DEBUG[13978] pjproject: tsx0x7f35cc02e .State changed from Terminated to Destroyed, event=TIMER [2016-05-10 12:06:18] DEBUG[13978] pjproject: tsx0x7f35cc02e Transaction destroyed! [2016-05-10 12:06:18] DEBUG[19348] http.c: HTTP Request URI is /ari/channels/1462871178.139/snoop?spy=in&app=Robot&whisper=none [2016-05-10 12:06:18] DEBUG[19348] http.c: match request [ari/channels/1462871178.139/snoop] with handler [httpstatus] len 10 [2016-05-10 12:06:18] DEBUG[19348] http.c: match request [ari/channels/1462871178.139/snoop] with handler [static] len 6 [2016-05-10 12:06:18] DEBUG[19348] http.c: match request [ari/channels/1462871178.139/snoop] with handler [ari] len 3 [2016-05-10 12:06:18] DEBUG[19348] http.c: Match made with [ari] [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Finding handler for channels [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking events [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking sounds [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking asterisk [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking deviceStates [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking playbacks [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking bridges [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking channels [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Finding handler for 1462871178.139 [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking channelId [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Finding handler for snoop [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking continue [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking redirect [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking answer [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking ring [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking dtmf [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking mute [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking hold [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking moh [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking silence [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking play [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking record [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking variable [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking snoop [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19364] bridge.c: Bridge technology native_dahdi does not have any capabilities we want. [2016-05-10 12:06:18] DEBUG[19364] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [2016-05-10 12:06:18] DEBUG[19364] bridge.c: Bridge technology simple_bridge does not have any capabilities we want. [2016-05-10 12:06:18] DEBUG[19364] bridge.c: Bridge technology native_rtp does not have any capabilities we want. [2016-05-10 12:06:18] DEBUG[19364] bridge.c: Chose bridge technology softmix [2016-05-10 12:06:18] DEBUG[19364] bridge.c: Bridge 6b75e0a8-fa33-4caa-b5c5-9674f6e23f1a is already using the new technology. [2016-05-10 12:06:18] DEBUG[19348] http.c: HTTP keeping session open. status_code:200 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 741 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 741 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket string of length 755 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket text frame, length 755 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 650 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 650 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket string of length 755 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket text frame, length 755 [2016-05-10 12:06:18] DEBUG[19365] stasis/app.c: Channel '1462871178.140' is 1 interested in Robot [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket string of length 755 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 741 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket text frame, length 755 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 741 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 741 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 741 [2016-05-10 12:06:18] DEBUG[13571] res_odbc.c: Releasing ODBC handle 0x7f35f4085a08 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 538 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 538 [2016-05-10 12:06:18] DEBUG[13571] res_odbc.c: Database handle 0x7f35f4085a08 (connection 0x7f35f4012730) deallocated [2016-05-10 12:06:18] DEBUG[13571] res_odbc.c: Connecting MSSQLSERVER(0x7f35f4085a08) [2016-05-10 12:06:18] DEBUG[19348] http.c: HTTP Request URI is /ari/channels/1462870663.124 [2016-05-10 12:06:18] DEBUG[19348] http.c: match request [ari/channels/1462870663.124] with handler [httpstatus] len 10 [2016-05-10 12:06:18] DEBUG[19348] http.c: match request [ari/channels/1462870663.124] with handler [static] len 6 [2016-05-10 12:06:18] DEBUG[19348] http.c: match request [ari/channels/1462870663.124] with handler [ari] len 3 [2016-05-10 12:06:18] DEBUG[19348] http.c: Match made with [ari] [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Finding handler for channels [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking events [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking sounds [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking asterisk [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking deviceStates [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking playbacks [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking bridges [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking channels [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Finding handler for 1462870663.124 [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking channelId [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19348] channel.c: Soft-Hanging (0x20) up channel 'Snoop/1462870663.123-00000014' [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Examining ARI response: 204 No Content [2016-05-10 12:06:18] DEBUG[19348] http.c: HTTP keeping session open. status_code:204 [2016-05-10 12:06:18] DEBUG[19251] bridge_channel.c: Setting 0x7f33f8033ff8(Snoop/1462870663.123-00000014) state from:0 to:1 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 564 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 564 [2016-05-10 12:06:18] DEBUG[19251] bridge_channel.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: pulling 0x7f33f8033ff8(Snoop/1462870663.123-00000014) [2016-05-10 12:06:18] VERBOSE[19251] bridge_channel.c: Channel Snoop/1462870663.123-00000014 left 'softmix' stasis-bridge <2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a> [2016-05-10 12:06:18] DEBUG[19251] bridge_channel.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: 0x7f33f8033ff8(Snoop/1462870663.123-00000014) is leaving softmix technology [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 569 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 569 [2016-05-10 12:06:18] DEBUG[13516] cdr.c: Finalized CDR for Snoop/1462870663.123-00000014 - start 1462871152.010579 answer 1462871152.010579 end 1462871178.647088 dispo ANSWERED [2016-05-10 12:06:18] DEBUG[13516] cdr.c: Finalized CDR for DAHDI/i1/241-9 - start 1462870408.311741 answer 1462870408.398952 end 1462871178.647098 dispo ANSWERED [2016-05-10 12:06:18] DEBUG[19251] bridge.c: Bridge technology native_dahdi does not have any capabilities we want. [2016-05-10 12:06:18] DEBUG[19251] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [2016-05-10 12:06:18] DEBUG[19251] bridge.c: Bridge technology softmix does not have any capabilities we want. [2016-05-10 12:06:18] DEBUG[19251] bridge.c: Bridge technology native_rtp does not have any capabilities we want. [2016-05-10 12:06:18] DEBUG[19251] bridge.c: Chose bridge technology simple_bridge [2016-05-10 12:06:18] DEBUG[19251] bridge.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: calling simple_bridge technology constructor [2016-05-10 12:06:18] DEBUG[19251] bridge.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: moving 0x7f343803ee88(Recorder/ARI-0000001f;2) to dummy bridge temporarily [2016-05-10 12:06:18] DEBUG[19251] bridge.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: moving 0x7f348000fac8(DAHDI/i1/241-9) to dummy bridge temporarily [2016-05-10 12:06:18] DEBUG[19251] bridge.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: 0x7f343803ee88(Recorder/ARI-0000001f;2) is leaving softmix technology (dummy) [2016-05-10 12:06:18] DEBUG[19251] bridge.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: 0x7f348000fac8(DAHDI/i1/241-9) is leaving softmix technology (dummy) [2016-05-10 12:06:18] DEBUG[19251] bridge.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: calling softmix technology stop [2016-05-10 12:06:18] DEBUG[19251] bridge.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: 0x7f343803ee88(Recorder/ARI-0000001f;2) is joining simple_bridge technology [2016-05-10 12:06:18] DEBUG[17016][C-0000000b] chan_dahdi.c: Requested indication 26 on channel DAHDI/i1/241-9 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 832 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 832 [2016-05-10 12:06:18] DEBUG[19251] bridge.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: 0x7f348000fac8(DAHDI/i1/241-9) is joining simple_bridge technology [2016-05-10 12:06:18] DEBUG[19251] bridge.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: calling simple_bridge technology start [2016-05-10 12:06:18] DEBUG[19251] bridge.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: deferring softmix technology destructor [2016-05-10 12:06:18] DEBUG[19251] bridge.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: queueing action type:13 sub:1000 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 589 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 589 [2016-05-10 12:06:18] DEBUG[13477][C-0000000b] bridge.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: calling softmix technology destructor (deferred, dummy) [2016-05-10 12:06:18] DEBUG[13477][C-0000000b] bridge_softmix.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: Waiting for mixing thread to die. [2016-05-10 12:06:18] DEBUG[19251] stasis/control.c: 1462870663.124, 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: Channel leaving bridge [2016-05-10 12:06:18] DEBUG[19251] stasis/app.c: bridge '2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a': is 3 interested in Robot [2016-05-10 12:06:18] DEBUG[19251] stasis/control.c: reason: Channel was departed from bridge [2016-05-10 12:06:18] DEBUG[17024] channel.c: Recorder/ARI-0000001f;2: Dropping redundant connected line update "" <241>. [2016-05-10 12:06:18] DEBUG[17834] stasis/control.c: 1462870663.124: Channel departing bridge [2016-05-10 12:06:18] DEBUG[17016][C-0000000b] channel.c: DAHDI/i1/241-9: Dropping redundant connected line update "" <>. [2016-05-10 12:06:18] DEBUG[17834] bridge.c: Waiting for 0x7f33f8033ff8(Snoop/1462870663.123-00000014) bridge thread to die. [2016-05-10 12:06:18] DEBUG[17834] stasis/app.c: App 'Robot' not subscribed to bridge '__AST_BRIDGE_ALL_TOPIC' [2016-05-10 12:06:18] DEBUG[17834] stasis/app.c: channel '1462870663.124': is 0 interested in Robot [2016-05-10 12:06:18] DEBUG[17834] stasis/app.c: channel '1462870663.124' unsubscribed from Robot [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 522 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 522 [2016-05-10 12:06:18] DEBUG[17834] channel.c: Hanging up channel 'Snoop/1462870663.123-00000014' [2016-05-10 12:06:18] DEBUG[19348] http.c: HTTP Request URI is /ari/bridges/2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a/addChannel?channel=1462871178.140 [2016-05-10 12:06:18] DEBUG[19348] http.c: match request [ari/bridges/2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a/addChannel] with handler [httpstatus] len 10 [2016-05-10 12:06:18] DEBUG[19348] http.c: match request [ari/bridges/2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a/addChannel] with handler [static] len 6 [2016-05-10 12:06:18] DEBUG[19348] http.c: match request [ari/bridges/2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a/addChannel] with handler [ari] len 3 [2016-05-10 12:06:18] DEBUG[19348] http.c: Match made with [ari] [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Finding handler for bridges [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking events [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking sounds [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking asterisk [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking deviceStates [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking playbacks [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking bridges [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Finding handler for 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking bridgeId [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Finding handler for addChannel [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Checking addChannel [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19348] stasis/control.c: 1462871178.140: Sending channel add_to_bridge command [2016-05-10 12:06:18] DEBUG[19252][C-0000000b] bridge_softmix.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: stopping mixing thread [2016-05-10 12:06:18] DEBUG[18655] res_rtp_asterisk.c: Got RTCP report of 84 bytes [2016-05-10 12:06:18] DEBUG[18655] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2016-05-10 12:06:18] DEBUG[18655] netsock2.c: Splitting 'bsrvvoce02' into... [2016-05-10 12:06:18] DEBUG[18655] netsock2.c: ...host 'bsrvvoce02' and port ''. [2016-05-10 12:06:18] DEBUG[18655] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [2016-05-10 12:06:18] DEBUG[18655] acl.c: Attached to given IP address [2016-05-10 12:06:18] DEBUG[27690] netsock2.c: Splitting '10.21.15.115:4003' into... [2016-05-10 12:06:18] DEBUG[27690] netsock2.c: ...host '10.21.15.115' and port '4003'. [2016-05-10 12:06:18] DEBUG[27690] netsock2.c: Splitting '10.21.24.132:0' into... [2016-05-10 12:06:18] DEBUG[27690] netsock2.c: ...host '10.21.24.132' and port '0'. [2016-05-10 12:06:18] DEBUG[13571] res_odbc.c: res_odbc: Connected to MSSQLSERVER [MSSQLSERVER (0x7f35f4085a08)] [2016-05-10 12:06:18] DEBUG[13571] cel_odbc.c: Executing SQL statement: [INSERT INTO cel_bsrvvoce02 (eventtype,eventtime,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,peer,userfield) VALUES ('LINKEDID_END','2016-05-10 12:06:18.646072','s','from-team','PJSIP/1078-00000013','Stasis','Robot',3,'','1462871178.139','','')] [2016-05-10 12:06:18] DEBUG[19364] res_rtp_asterisk.c: Ooh, format changed from none to ulaw [2016-05-10 12:06:18] DEBUG[19250] bridge.c: Bridge technology native_dahdi does not have any capabilities we want. [2016-05-10 12:06:18] DEBUG[19250] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [2016-05-10 12:06:18] DEBUG[19250] bridge.c: Bridge technology simple_bridge does not have any capabilities we want. [2016-05-10 12:06:18] DEBUG[19250] bridge.c: Bridge technology native_rtp does not have any capabilities we want. [2016-05-10 12:06:18] DEBUG[19250] bridge.c: Chose bridge technology softmix [2016-05-10 12:06:18] DEBUG[19250] bridge.c: Bridge 6b75e0a8-fa33-4caa-b5c5-9674f6e23f1a is already using the new technology. [2016-05-10 12:06:18] DEBUG[13478] devicestate.c: No provider found, checking channel drivers for Snoop - 1462870663.123 [2016-05-10 12:06:18] DEBUG[13478] devicestate.c: Changing state for Snoop/1462870663.123 - state 4 (Invalid): [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 741 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket string of length 755 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 741 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket text frame, length 755 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 650 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 650 [2016-05-10 12:06:18] DEBUG[28044] app_queue.c: Device 'Snoop/1462870663.123' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket string of length 755 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket text frame, length 755 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 741 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 741 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 741 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 741 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket string of length 755 [2016-05-10 12:06:18] DEBUG[31169] res_http_websocket.c: Writing websocket text frame, length 755 [2016-05-10 12:06:18] DEBUG[13571] res_odbc.c: Releasing ODBC handle 0x7f35f4085a08 [2016-05-10 12:06:18] DEBUG[13571] res_odbc.c: Database handle 0x7f35f4085a08 (connection 0x7f35f4012730) deallocated [2016-05-10 12:06:18] DEBUG[13571] res_odbc.c: Connecting MSSQLSERVER(0x7f35f408c178) [2016-05-10 12:06:18] DEBUG[13571] res_odbc.c: res_odbc: Connected to MSSQLSERVER [MSSQLSERVER (0x7f35f408c178)] [2016-05-10 12:06:18] DEBUG[13571] cel_odbc.c: Executing SQL statement: [INSERT INTO cel_bsrvvoce02 (eventtype,eventtime,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,peer,userfield) VALUES ('BRIDGE_ENTER','2016-05-10 12:06:18.655420','s','from-team','PJSIP/1078-00000013','Stasis','Robot',3,'','1462871178.139','PJSIP/1067-00000012,Snoop/1462870408.93-0000000f,Recorder/ARI-00000020;2,PJSIP/1','')] [2016-05-10 12:06:18] DEBUG[13571] res_odbc.c: Releasing ODBC handle 0x7f35f408c178 [2016-05-10 12:06:18] DEBUG[13571] res_odbc.c: Database handle 0x7f35f408c178 (connection 0x7f35f4012730) deallocated [2016-05-10 12:06:18] DEBUG[13571] res_odbc.c: Connecting MSSQLSERVER(0x7f35f4085a08) [2016-05-10 12:06:18] DEBUG[19365] bridge_roles.c: Roles did not exist on channel Snoop/1462871178.139-00000018 [2016-05-10 12:06:18] DEBUG[19365] stasis/control.c: 1462871178.140: Adding to bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a [2016-05-10 12:06:18] DEBUG[19365] stasis/app.c: Bridge '2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a' is 4 interested in Robot [2016-05-10 12:06:18] DEBUG[19366] bridge_channel.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: 0x7f3490031e68(Snoop/1462871178.139-00000018) is joining [2016-05-10 12:06:18] DEBUG[19366] bridge_channel.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: pushing 0x7f3490031e68(Snoop/1462871178.139-00000018) [2016-05-10 12:06:18] VERBOSE[19366] bridge_channel.c: Channel Snoop/1462871178.139-00000018 joined 'simple_bridge' stasis-bridge <2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a> [2016-05-10 12:06:18] DEBUG[13516] cdr.c: Finalized CDR for Snoop/1462871178.139-00000018 - start 1462871178.645553 answer 1462871178.645553 end 1462871178.665689 dispo ANSWERED [2016-05-10 12:06:18] DEBUG[19366] bridge.c: Bridge technology native_dahdi does not have any capabilities we want. [2016-05-10 12:06:18] DEBUG[19366] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [2016-05-10 12:06:18] DEBUG[19366] bridge.c: Bridge technology simple_bridge does not have any capabilities we want. [2016-05-10 12:06:18] DEBUG[19366] bridge.c: Bridge technology native_rtp does not have any capabilities we want. [2016-05-10 12:06:18] DEBUG[19366] bridge.c: Chose bridge technology softmix [2016-05-10 12:06:18] DEBUG[19366] bridge.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: calling softmix technology constructor [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 865 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 865 [2016-05-10 12:06:18] DEBUG[19366] bridge.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: moving 0x7f343803ee88(Recorder/ARI-0000001f;2) to dummy bridge temporarily [2016-05-10 12:06:18] DEBUG[19366] bridge.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: moving 0x7f348000fac8(DAHDI/i1/241-9) to dummy bridge temporarily [2016-05-10 12:06:18] DEBUG[19366] bridge.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: 0x7f343803ee88(Recorder/ARI-0000001f;2) is leaving simple_bridge technology (dummy) [2016-05-10 12:06:18] DEBUG[19366] bridge.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: 0x7f348000fac8(DAHDI/i1/241-9) is leaving simple_bridge technology (dummy) [2016-05-10 12:06:18] DEBUG[19366] bridge.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: calling simple_bridge technology stop [2016-05-10 12:06:18] DEBUG[19366] bridge.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: 0x7f3490031e68(Snoop/1462871178.139-00000018) is joining softmix technology [2016-05-10 12:06:18] DEBUG[19366] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [2016-05-10 12:06:18] DEBUG[19366] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [2016-05-10 12:06:18] DEBUG[19366] bridge.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: 0x7f343803ee88(Recorder/ARI-0000001f;2) is joining softmix technology [2016-05-10 12:06:18] DEBUG[19366] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [2016-05-10 12:06:18] DEBUG[19366] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [2016-05-10 12:06:18] DEBUG[19366] bridge.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: 0x7f348000fac8(DAHDI/i1/241-9) is joining softmix technology [2016-05-10 12:06:18] DEBUG[19366] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [2016-05-10 12:06:18] DEBUG[19366] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [2016-05-10 12:06:18] DEBUG[19366] bridge.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: calling softmix technology start [2016-05-10 12:06:18] DEBUG[19366] bridge.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: calling simple_bridge technology destructor [2016-05-10 12:06:18] DEBUG[17016][C-0000000b] chan_dahdi.c: Requested indication 26 on channel DAHDI/i1/241-9 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 607 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 607 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket string of length 619 [2016-05-10 12:06:18] DEBUG[31167] res_http_websocket.c: Writing websocket text frame, length 619 [2016-05-10 12:06:18] DEBUG[19367][C-0000000b] bridge_softmix.c: Bridge 2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a: starting mixing thread [2016-05-10 12:06:18] DEBUG[19348] res_ari.c: Examining ARI response: 204 No Content [2016-05-10 12:06:18] DEBUG[19365] stasis/app.c: App 'Robot' not subscribed to bridge '__AST_BRIDGE_ALL_TOPIC' [2016-05-10 12:06:18] DEBUG[19365] stasis/app.c: Bridge '2bcba4a4-bbf8-4bd9-a19d-f7225d63c12a' is 5 interested in Robot [2016-05-10 12:06:18] DEBUG[19348] http.c: HTTP keeping session open. status_code:204 [2016-05-10 12:06:18] DEBUG[19368] http.c: HTTP opening session. Top level [2016-05-10 12:06:18] DEBUG[19368] http.c: HTTP Request URI is /ari/events/user/UpdateConference?eventName=UpdateConference&application=1047 [2016-05-10 12:06:18] DEBUG[19368] http.c: match request [ari/events/user/UpdateConference] with handler [httpstatus] len 10 [2016-05-10 12:06:18] DEBUG[19368] http.c: match request [ari/events/user/UpdateConference] with handler [static] len 6 [2016-05-10 12:06:18] DEBUG[19368] http.c: match request [ari/events/user/UpdateConference] with handler [ari] len 3 [2016-05-10 12:06:18] DEBUG[19368] http.c: Match made with [ari] [2016-05-10 12:06:18] DEBUG[19368] res_ari.c: Finding handler for events [2016-05-10 12:06:18] DEBUG[19368] res_ari.c: Checking events [2016-05-10 12:06:18] DEBUG[19368] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19368] res_ari.c: Finding handler for user [2016-05-10 12:06:18] DEBUG[19368] res_ari.c: Checking user [2016-05-10 12:06:18] DEBUG[19368] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19368] res_ari.c: Finding handler for UpdateConference [2016-05-10 12:06:18] DEBUG[19368] res_ari.c: Checking eventName [2016-05-10 12:06:18] DEBUG[19368] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19368] http.c: HTTP consuming request body [2016-05-10 12:06:18] DEBUG[19368] res_ari.c: Examining ARI response: 204 No Content [2016-05-10 12:06:18] DEBUG[19368] http.c: HTTP keeping session open. status_code:204 [2016-05-10 12:06:18] DEBUG[11928] res_http_websocket.c: Writing websocket string of length 1353 [2016-05-10 12:06:18] DEBUG[11928] res_http_websocket.c: Writing websocket text frame, length 1353 [2016-05-10 12:06:18] DEBUG[19368] http.c: HTTP idle timeout or peer closed connection. [2016-05-10 12:06:18] DEBUG[19368] http.c: HTTP closing session. Top level [2016-05-10 12:06:18] DEBUG[19369] http.c: HTTP opening session. Top level [2016-05-10 12:06:18] DEBUG[19369] http.c: HTTP Request URI is /ari/events/user/UpdateConference?eventName=UpdateConference&application=1067 [2016-05-10 12:06:18] DEBUG[19369] http.c: match request [ari/events/user/UpdateConference] with handler [httpstatus] len 10 [2016-05-10 12:06:18] DEBUG[19369] http.c: match request [ari/events/user/UpdateConference] with handler [static] len 6 [2016-05-10 12:06:18] DEBUG[19369] http.c: match request [ari/events/user/UpdateConference] with handler [ari] len 3 [2016-05-10 12:06:18] DEBUG[19369] http.c: Match made with [ari] [2016-05-10 12:06:18] DEBUG[19369] res_ari.c: Finding handler for events [2016-05-10 12:06:18] DEBUG[19369] res_ari.c: Checking events [2016-05-10 12:06:18] DEBUG[19369] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19369] res_ari.c: Finding handler for user [2016-05-10 12:06:18] DEBUG[19369] res_ari.c: Checking user [2016-05-10 12:06:18] DEBUG[19369] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19369] res_ari.c: Finding handler for UpdateConference [2016-05-10 12:06:18] DEBUG[19369] res_ari.c: Checking eventName [2016-05-10 12:06:18] DEBUG[19369] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19369] http.c: HTTP consuming request body [2016-05-10 12:06:18] DEBUG[19369] res_ari.c: Examining ARI response: 204 No Content [2016-05-10 12:06:18] DEBUG[19369] http.c: HTTP keeping session open. status_code:204 [2016-05-10 12:06:18] DEBUG[12380] res_http_websocket.c: Writing websocket string of length 1353 [2016-05-10 12:06:18] DEBUG[12380] res_http_websocket.c: Writing websocket text frame, length 1353 [2016-05-10 12:06:18] DEBUG[19369] http.c: HTTP idle timeout or peer closed connection. [2016-05-10 12:06:18] DEBUG[19369] http.c: HTTP closing session. Top level [2016-05-10 12:06:18] DEBUG[19370] http.c: HTTP opening session. Top level [2016-05-10 12:06:18] DEBUG[19370] http.c: HTTP Request URI is /ari/events/user/UpdateConference?eventName=UpdateConference&application=1078 [2016-05-10 12:06:18] DEBUG[19370] http.c: match request [ari/events/user/UpdateConference] with handler [httpstatus] len 10 [2016-05-10 12:06:18] DEBUG[19370] http.c: match request [ari/events/user/UpdateConference] with handler [static] len 6 [2016-05-10 12:06:18] DEBUG[19370] http.c: match request [ari/events/user/UpdateConference] with handler [ari] len 3 [2016-05-10 12:06:18] DEBUG[19370] http.c: Match made with [ari] [2016-05-10 12:06:18] DEBUG[19370] res_ari.c: Finding handler for events [2016-05-10 12:06:18] DEBUG[19370] res_ari.c: Checking events [2016-05-10 12:06:18] DEBUG[19370] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19370] res_ari.c: Finding handler for user [2016-05-10 12:06:18] DEBUG[19370] res_ari.c: Checking user [2016-05-10 12:06:18] DEBUG[19370] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19370] res_ari.c: Finding handler for UpdateConference [2016-05-10 12:06:18] DEBUG[19370] res_ari.c: Checking eventName [2016-05-10 12:06:18] DEBUG[19370] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19370] http.c: HTTP consuming request body [2016-05-10 12:06:18] DEBUG[19370] res_ari.c: Examining ARI response: 204 No Content [2016-05-10 12:06:18] DEBUG[19370] http.c: HTTP keeping session open. status_code:204 [2016-05-10 12:06:18] DEBUG[12370] res_http_websocket.c: Writing websocket string of length 1353 [2016-05-10 12:06:18] DEBUG[12370] res_http_websocket.c: Writing websocket text frame, length 1353 [2016-05-10 12:06:18] DEBUG[19370] http.c: HTTP idle timeout or peer closed connection. [2016-05-10 12:06:18] DEBUG[19370] http.c: HTTP closing session. Top level [2016-05-10 12:06:18] DEBUG[13571] res_odbc.c: res_odbc: Connected to MSSQLSERVER [MSSQLSERVER (0x7f35f4085a08)] [2016-05-10 12:06:18] DEBUG[13571] cel_odbc.c: Executing SQL statement: [INSERT INTO cel_bsrvvoce02 (eventtype,eventtime,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,peer,userfield) VALUES ('CHAN_START','2016-05-10 12:06:18.665112','s','default','Snoop/1462871178.139-00000018','','',3,'','1462871178.140','','')] [2016-05-10 12:06:18] DEBUG[19371] http.c: HTTP opening session. Top level [2016-05-10 12:06:18] DEBUG[19371] http.c: HTTP Request URI is /ari/events/user/MonitoringUpdateConference?eventName=MonitoringUpdateConference&application=MonitoringService [2016-05-10 12:06:18] DEBUG[19371] http.c: match request [ari/events/user/MonitoringUpdateConference] with handler [httpstatus] len 10 [2016-05-10 12:06:18] DEBUG[19371] http.c: match request [ari/events/user/MonitoringUpdateConference] with handler [static] len 6 [2016-05-10 12:06:18] DEBUG[19371] http.c: match request [ari/events/user/MonitoringUpdateConference] with handler [ari] len 3 [2016-05-10 12:06:18] DEBUG[19371] http.c: Match made with [ari] [2016-05-10 12:06:18] DEBUG[19371] res_ari.c: Finding handler for events [2016-05-10 12:06:18] DEBUG[19371] res_ari.c: Checking events [2016-05-10 12:06:18] DEBUG[19371] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19371] res_ari.c: Finding handler for user [2016-05-10 12:06:18] DEBUG[19371] res_ari.c: Checking user [2016-05-10 12:06:18] DEBUG[19371] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19371] res_ari.c: Finding handler for MonitoringUpdateConference [2016-05-10 12:06:18] DEBUG[19371] res_ari.c: Checking eventName [2016-05-10 12:06:18] DEBUG[19371] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19371] http.c: HTTP consuming request body [2016-05-10 12:06:18] DEBUG[13571] res_odbc.c: Releasing ODBC handle 0x7f35f4085a08 [2016-05-10 12:06:18] DEBUG[13571] res_odbc.c: Database handle 0x7f35f4085a08 (connection 0x7f35f4012730) deallocated [2016-05-10 12:06:18] DEBUG[19371] res_ari.c: Examining ARI response: 204 No Content [2016-05-10 12:06:18] DEBUG[19371] http.c: HTTP keeping session open. status_code:204 [2016-05-10 12:06:18] DEBUG[31163] res_http_websocket.c: Writing websocket string of length 1347 [2016-05-10 12:06:18] DEBUG[31163] res_http_websocket.c: Writing websocket text frame, length 1347 [2016-05-10 12:06:18] DEBUG[19371] http.c: HTTP idle timeout or peer closed connection. [2016-05-10 12:06:18] DEBUG[19371] http.c: HTTP closing session. Top level [2016-05-10 12:06:18] DEBUG[19373] http.c: HTTP opening session. Top level [2016-05-10 12:06:18] DEBUG[19373] http.c: HTTP Request URI is /ari/events/user/MonitoringUpdateConference?eventName=MonitoringUpdateConference&application=1046 [2016-05-10 12:06:18] DEBUG[19373] http.c: match request [ari/events/user/MonitoringUpdateConference] with handler [httpstatus] len 10 [2016-05-10 12:06:18] DEBUG[19373] http.c: match request [ari/events/user/MonitoringUpdateConference] with handler [static] len 6 [2016-05-10 12:06:18] DEBUG[19373] http.c: match request [ari/events/user/MonitoringUpdateConference] with handler [ari] len 3 [2016-05-10 12:06:18] DEBUG[19373] http.c: Match made with [ari] [2016-05-10 12:06:18] DEBUG[19373] res_ari.c: Finding handler for events [2016-05-10 12:06:18] DEBUG[19373] res_ari.c: Checking events [2016-05-10 12:06:18] DEBUG[19373] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19373] res_ari.c: Finding handler for user [2016-05-10 12:06:18] DEBUG[19373] res_ari.c: Checking user [2016-05-10 12:06:18] DEBUG[19373] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19373] res_ari.c: Finding handler for MonitoringUpdateConference [2016-05-10 12:06:18] DEBUG[19373] res_ari.c: Checking eventName [2016-05-10 12:06:18] DEBUG[19373] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19373] http.c: HTTP consuming request body [2016-05-10 12:06:18] DEBUG[19373] res_ari.c: Examining ARI response: 204 No Content [2016-05-10 12:06:18] DEBUG[19373] http.c: HTTP keeping session open. status_code:204 [2016-05-10 12:06:18] DEBUG[11317] res_http_websocket.c: Writing websocket string of length 1220 [2016-05-10 12:06:18] DEBUG[11317] res_http_websocket.c: Writing websocket text frame, length 1220 [2016-05-10 12:06:18] DEBUG[19373] http.c: HTTP idle timeout or peer closed connection. [2016-05-10 12:06:18] DEBUG[19373] http.c: HTTP closing session. Top level [2016-05-10 12:06:18] DEBUG[19374] http.c: HTTP opening session. Top level [2016-05-10 12:06:18] DEBUG[19374] http.c: HTTP Request URI is /ari/events/user/MonitoringUpdateConference?eventName=MonitoringUpdateConference&application=1047 [2016-05-10 12:06:18] DEBUG[19374] http.c: match request [ari/events/user/MonitoringUpdateConference] with handler [httpstatus] len 10 [2016-05-10 12:06:18] DEBUG[19374] http.c: match request [ari/events/user/MonitoringUpdateConference] with handler [static] len 6 [2016-05-10 12:06:18] DEBUG[19374] http.c: match request [ari/events/user/MonitoringUpdateConference] with handler [ari] len 3 [2016-05-10 12:06:18] DEBUG[19374] http.c: Match made with [ari] [2016-05-10 12:06:18] DEBUG[19374] res_ari.c: Finding handler for events [2016-05-10 12:06:18] DEBUG[19374] res_ari.c: Checking events [2016-05-10 12:06:18] DEBUG[19374] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19374] res_ari.c: Finding handler for user [2016-05-10 12:06:18] DEBUG[19374] res_ari.c: Checking user [2016-05-10 12:06:18] DEBUG[19374] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19374] res_ari.c: Finding handler for MonitoringUpdateConference [2016-05-10 12:06:18] DEBUG[19374] res_ari.c: Checking eventName [2016-05-10 12:06:18] DEBUG[19374] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19374] http.c: HTTP consuming request body [2016-05-10 12:06:18] DEBUG[19374] res_ari.c: Examining ARI response: 204 No Content [2016-05-10 12:06:18] DEBUG[19374] http.c: HTTP keeping session open. status_code:204 [2016-05-10 12:06:18] DEBUG[11928] res_http_websocket.c: Writing websocket string of length 1220 [2016-05-10 12:06:18] DEBUG[11928] res_http_websocket.c: Writing websocket text frame, length 1220 [2016-05-10 12:06:18] DEBUG[19374] http.c: HTTP idle timeout or peer closed connection. [2016-05-10 12:06:18] DEBUG[19374] http.c: HTTP closing session. Top level [2016-05-10 12:06:18] DEBUG[19375] http.c: HTTP opening session. Top level [2016-05-10 12:06:18] DEBUG[19375] http.c: HTTP Request URI is /ari/events/user/MonitoringUpdateConference?eventName=MonitoringUpdateConference&application=1052 [2016-05-10 12:06:18] DEBUG[19375] http.c: match request [ari/events/user/MonitoringUpdateConference] with handler [httpstatus] len 10 [2016-05-10 12:06:18] DEBUG[19375] http.c: match request [ari/events/user/MonitoringUpdateConference] with handler [static] len 6 [2016-05-10 12:06:18] DEBUG[19375] http.c: match request [ari/events/user/MonitoringUpdateConference] with handler [ari] len 3 [2016-05-10 12:06:18] DEBUG[19375] http.c: Match made with [ari] [2016-05-10 12:06:18] DEBUG[19375] res_ari.c: Finding handler for events [2016-05-10 12:06:18] DEBUG[19375] res_ari.c: Checking events [2016-05-10 12:06:18] DEBUG[19375] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19375] res_ari.c: Finding handler for user [2016-05-10 12:06:18] DEBUG[19375] res_ari.c: Checking user [2016-05-10 12:06:18] DEBUG[19375] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19375] res_ari.c: Finding handler for MonitoringUpdateConference [2016-05-10 12:06:18] DEBUG[19375] res_ari.c: Checking eventName [2016-05-10 12:06:18] DEBUG[19375] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19375] http.c: HTTP consuming request body [2016-05-10 12:06:18] DEBUG[19375] res_ari.c: Examining ARI response: 204 No Content [2016-05-10 12:06:18] DEBUG[19375] http.c: HTTP keeping session open. status_code:204 [2016-05-10 12:06:18] DEBUG[12161] res_http_websocket.c: Writing websocket string of length 1220 [2016-05-10 12:06:18] DEBUG[12161] res_http_websocket.c: Writing websocket text frame, length 1220 [2016-05-10 12:06:18] DEBUG[19375] http.c: HTTP idle timeout or peer closed connection. [2016-05-10 12:06:18] DEBUG[19375] http.c: HTTP closing session. Top level [2016-05-10 12:06:18] DEBUG[19376] http.c: HTTP opening session. Top level [2016-05-10 12:06:18] DEBUG[19376] http.c: HTTP Request URI is /ari/events/user/MonitoringUpdateConference?eventName=MonitoringUpdateConference&application=1078 [2016-05-10 12:06:18] DEBUG[19376] http.c: match request [ari/events/user/MonitoringUpdateConference] with handler [httpstatus] len 10 [2016-05-10 12:06:18] DEBUG[19376] http.c: match request [ari/events/user/MonitoringUpdateConference] with handler [static] len 6 [2016-05-10 12:06:18] DEBUG[19376] http.c: match request [ari/events/user/MonitoringUpdateConference] with handler [ari] len 3 [2016-05-10 12:06:18] DEBUG[19376] http.c: Match made with [ari] [2016-05-10 12:06:18] DEBUG[19376] res_ari.c: Finding handler for events [2016-05-10 12:06:18] DEBUG[19376] res_ari.c: Checking events [2016-05-10 12:06:18] DEBUG[19376] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19376] res_ari.c: Finding handler for user [2016-05-10 12:06:18] DEBUG[19376] res_ari.c: Checking user [2016-05-10 12:06:18] DEBUG[19376] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19376] res_ari.c: Finding handler for MonitoringUpdateConference [2016-05-10 12:06:18] DEBUG[19376] res_ari.c: Checking eventName [2016-05-10 12:06:18] DEBUG[19376] res_ari.c: Got it! [2016-05-10 12:06:18] DEBUG[19376] http.c: HTTP consuming request body [2016-05-10 12:06:18] DEBUG[19376] res_ari.c: Examining ARI response: 204 No Content [2016-05-10 12:06:18] DEBUG[19376] http.c: HTTP keeping session open. status_code:204 [2016-05-10 12:06:18] DEBUG[12370] res_http_websocket.c: Writing websocket string of length 1220 [2016-05-10 12:06:18] DEBUG[12370] res_http_websocket.c: Writing websocket text frame, length 1220 [2016-05-10 12:06:18] DEBUG[19376] http.c: HTTP idle timeout or peer closed connection. [2016-05-10 12:06:18] DEBUG[19376] http.c: HTTP closing session. Top level [2016-05-10 12:06:18] DEBUG[19377] http.c: HTTP opening session. Top level [2016-05-10 12:06:23] Asterisk 13.9.0 built by root @ bsrvvoce02 on a x86_64 running Linux on 2016-05-10 06:50:21 UTC