[Jan 16 11:04:19] Asterisk 14.2.1 built by root @ maxvoip on a x86_64 running Linux on 2017-01-05 09:22:40 UTC [Jan 16 11:04:19] VERBOSE[12904] config.c: Parsing '/etc/asterisk/logger.conf': Found [Jan 16 11:04:19] VERBOSE[12904] logger.c: Asterisk Queue Logger restarted [Jan 16 11:04:24] DEBUG[12871] chan_iax2.c: schedule decrement of callno used for 192.168.5.16 in 60 seconds [Jan 16 11:04:25] DEBUG[12824] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 16 11:04:25] DEBUG[12823] threadpool.c: Destroying worker thread 0 [Jan 16 11:04:34] DEBUG[12873] chan_iax2.c: ip callno count incremented to 3 for 192.168.5.16 [Jan 16 11:04:37] DEBUG[12851] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 16 11:04:37] DEBUG[12850] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 16 11:04:37] DEBUG[12852] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 16 11:04:37] DEBUG[12845] threadpool.c: Destroying worker thread 8 [Jan 16 11:04:37] DEBUG[12845] threadpool.c: Destroying worker thread 7 [Jan 16 11:04:37] DEBUG[12845] threadpool.c: Destroying worker thread 9 [Jan 16 11:04:41] DEBUG[12854] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 16 11:04:41] DEBUG[12822] threadpool.c: Destroying worker thread 11 [Jan 16 11:04:42] DEBUG[12876] chan_iax2.c: schedule decrement of callno used for 192.168.5.16 in 60 seconds [Jan 16 11:04:43] DEBUG[12865] chan_iax2.c: ip callno count decremented to 0 for 192.168.0.137 [Jan 16 11:04:43] DEBUG[12867] chan_iax2.c: ip callno count incremented to 1 for 192.168.0.137 [Jan 16 11:04:43] DEBUG[12868] chan_iax2.c: schedule decrement of callno used for 192.168.0.137 in 60 seconds [Jan 16 11:04:43] DEBUG[12868] chan_iax2.c: Peer iax2-app-server-1: got pong, lastms 1, historicms 1, maxms 2000 [Jan 16 11:04:43] DEBUG[12879] chan_sip.c: Allocating new SIP dialog for 7efa9b12200100ab48d29763485461b7@127.0.1.1:5060 - OPTIONS (No RTP) [Jan 16 11:04:43] DEBUG[12879] acl.c: For destination '192.168.0.227', our source address is '192.168.0.98'. [Jan 16 11:04:43] DEBUG[12879] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.0.98:5060 [Jan 16 11:04:43] DEBUG[12879] chan_sip.c: SIP call-id changed from '7efa9b12200100ab48d29763485461b7@127.0.1.1:5060' to '07f4bb882659959648b703166698dea2@192.168.0.98:5060' [Jan 16 11:04:43] DEBUG[12879] chan_sip.c: Initializing initreq for method OPTIONS - callid 07f4bb882659959648b703166698dea2@192.168.0.98:5060 [Jan 16 11:04:43] DEBUG[12879] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.0.227:59318 [Jan 16 11:04:44] DEBUG[12879] chan_sip.c: Allocating new SIP dialog for 523a6c9c51b9e5355c39743d3eb75dc2@127.0.1.1:5060 - OPTIONS (No RTP) [Jan 16 11:04:44] DEBUG[12879] acl.c: For destination '192.168.0.137', our source address is '192.168.0.98'. [Jan 16 11:04:44] DEBUG[12879] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.0.98:5060 [Jan 16 11:04:44] DEBUG[12879] chan_sip.c: SIP call-id changed from '523a6c9c51b9e5355c39743d3eb75dc2@127.0.1.1:5060' to '349386fd06d367ed41e13f6e095e764d@192.168.0.98:5060' [Jan 16 11:04:44] DEBUG[12879] chan_sip.c: Initializing initreq for method OPTIONS - callid 349386fd06d367ed41e13f6e095e764d@192.168.0.98:5060 [Jan 16 11:04:44] DEBUG[12879] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.0.137:5060 [Jan 16 11:04:44] DEBUG[12879] chan_sip.c: = Looking for Call ID: 349386fd06d367ed41e13f6e095e764d@192.168.0.98:5060 (Checking To) --From tag as37e45396 --To-tag as2ca37420 [Jan 16 11:04:44] DEBUG[12879] chan_sip.c: Stopping retransmission on '349386fd06d367ed41e13f6e095e764d@192.168.0.98:5060' of Request 102: Match Found [Jan 16 11:04:44] DEBUG[12879] chan_sip.c: Destroying SIP dialog 349386fd06d367ed41e13f6e095e764d@192.168.0.98:5060 [Jan 16 11:04:44] DEBUG[12879] chan_sip.c: Allocating new SIP dialog for 04ce04a325ea737e5e9e60d8519d258a@127.0.1.1:5060 - OPTIONS (No RTP) [Jan 16 11:04:44] DEBUG[12879] acl.c: For destination '192.168.0.214', our source address is '192.168.0.98'. [Jan 16 11:04:44] DEBUG[12879] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.0.98:5060 [Jan 16 11:04:44] DEBUG[12879] chan_sip.c: SIP call-id changed from '04ce04a325ea737e5e9e60d8519d258a@127.0.1.1:5060' to '5b2a101e0a71bc8d7619d6fd15ecb5be@192.168.0.98:5060' [Jan 16 11:04:44] DEBUG[12879] chan_sip.c: Initializing initreq for method OPTIONS - callid 5b2a101e0a71bc8d7619d6fd15ecb5be@192.168.0.98:5060 [Jan 16 11:04:44] DEBUG[12879] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.0.214:5062 [Jan 16 11:04:44] DEBUG[12879] chan_sip.c: = Looking for Call ID: 5b2a101e0a71bc8d7619d6fd15ecb5be@192.168.0.98:5060 (Checking To) --From tag as6500f8fd --To-tag 976744017 [Jan 16 11:04:44] DEBUG[12879] chan_sip.c: Stopping retransmission on '5b2a101e0a71bc8d7619d6fd15ecb5be@192.168.0.98:5060' of Request 102: Match Found [Jan 16 11:04:44] DEBUG[12879] chan_sip.c: Destroying SIP dialog 5b2a101e0a71bc8d7619d6fd15ecb5be@192.168.0.98:5060 [Jan 16 11:04:44] DEBUG[12879] chan_sip.c: = Looking for Call ID: 07f4bb882659959648b703166698dea2@192.168.0.98:5060 (Checking To) --From tag as3c29c9c0 --To-tag f2fb0530 [Jan 16 11:04:44] DEBUG[12879] chan_sip.c: Stopping retransmission on '07f4bb882659959648b703166698dea2@192.168.0.98:5060' of Request 102: Match Found [Jan 16 11:04:44] DEBUG[12879] chan_sip.c: Destroying SIP dialog 07f4bb882659959648b703166698dea2@192.168.0.98:5060 [Jan 16 11:04:44] DEBUG[12853] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 16 11:04:44] DEBUG[12822] threadpool.c: Destroying worker thread 10 [Jan 16 11:04:44] DEBUG[12887] res_pjsip_registrar_expire.c: Woke up at 1484561084 Interval: 30 [Jan 16 11:04:44] DEBUG[12887] res_pjsip_registrar_expire.c: Expiring 0 contacts [Jan 16 11:04:46] DEBUG[12849] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 16 11:04:46] DEBUG[12845] threadpool.c: Destroying worker thread 6 [Jan 16 11:04:50] DEBUG[12848] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 16 11:04:50] DEBUG[12845] threadpool.c: Destroying worker thread 5 [Jan 16 11:04:52] DEBUG[12905] http.c: HTTP opening session. Top level [Jan 16 11:04:52] DEBUG[12905] http.c: HTTP Request URI is /ari/asterisk/info?api_key=ariuser:aripass [Jan 16 11:04:52] DEBUG[12905] http.c: match request [ari/asterisk/info] with handler [httpstatus] len 10 [Jan 16 11:04:52] DEBUG[12905] http.c: match request [ari/asterisk/info] with handler [phoneprov] len 9 [Jan 16 11:04:52] DEBUG[12905] http.c: match request [ari/asterisk/info] with handler [static] len 6 [Jan 16 11:04:52] DEBUG[12905] http.c: match request [ari/asterisk/info] with handler [ari] len 3 [Jan 16 11:04:52] DEBUG[12905] http.c: Match made with [ari] [Jan 16 11:04:52] DEBUG[12905] res_ari.c: Finding handler for asterisk [Jan 16 11:04:52] DEBUG[12905] res_ari.c: Checking bridges [Jan 16 11:04:52] DEBUG[12905] res_ari.c: Checking channels [Jan 16 11:04:52] DEBUG[12905] res_ari.c: Checking asterisk [Jan 16 11:04:52] DEBUG[12905] res_ari.c: Got it! [Jan 16 11:04:52] DEBUG[12905] res_ari.c: Finding handler for info [Jan 16 11:04:52] DEBUG[12905] res_ari.c: Checking config [Jan 16 11:04:52] DEBUG[12905] res_ari.c: Checking info [Jan 16 11:04:52] DEBUG[12905] res_ari.c: Got it! [Jan 16 11:04:52] DEBUG[12905] res_ari.c: Examining ARI response: 200 OK Content-type: application/json {"build":{"machine":"x86_64","os":"Linux","date":"2017-01-05 09:22:40 UTC","options":"LOADABLE_MODULES, OPTIONAL_API","kernel":"3.16.0-4-amd64","user":"root"},"system":{"version":"14.2.1","entity_id":"00:0f:1f:fb:4a:01"},"config":{"name":"","setid":{"user":"","group":""},"default_language":"en"},"status":{"last_reload_time":"2017-01-16T11:04:19.996+0100","startup_time":"2017-01-16T11:03:34.439+0100"}} [Jan 16 11:04:52] DEBUG[12905] http.c: HTTP closing session. status_code:200 [Jan 16 11:04:52] DEBUG[12873] chan_iax2.c: ip callno count incremented to 4 for 192.168.5.16 [Jan 16 11:04:52] DEBUG[12907] http.c: HTTP opening session. Top level [Jan 16 11:04:52] DEBUG[12907] http.c: HTTP Request URI is /ari/events?api_key=ariuser:aripass&app=AriStart&subscribeAll=true [Jan 16 11:04:52] DEBUG[12907] http.c: match request [ari/events] with handler [httpstatus] len 10 [Jan 16 11:04:52] DEBUG[12907] http.c: match request [ari/events] with handler [phoneprov] len 9 [Jan 16 11:04:52] DEBUG[12907] http.c: match request [ari/events] with handler [static] len 6 [Jan 16 11:04:52] DEBUG[12907] http.c: match request [ari/events] with handler [ari] len 3 [Jan 16 11:04:52] DEBUG[12907] http.c: Match made with [ari] [Jan 16 11:04:52] DEBUG[12907] res_ari.c: Finding handler for events [Jan 16 11:04:52] DEBUG[12907] res_ari.c: Checking bridges [Jan 16 11:04:52] DEBUG[12907] res_ari.c: Checking channels [Jan 16 11:04:52] DEBUG[12907] res_ari.c: Checking asterisk [Jan 16 11:04:52] DEBUG[12907] res_ari.c: Checking endpoints [Jan 16 11:04:52] DEBUG[12907] res_ari.c: Checking sounds [Jan 16 11:04:52] DEBUG[12907] res_ari.c: Checking deviceStates [Jan 16 11:04:52] DEBUG[12907] res_ari.c: Checking events [Jan 16 11:04:52] DEBUG[12907] res_ari.c: Got it! [Jan 16 11:04:52] DEBUG[12907] ari/resource_events.c: /events WebSocket attempted [Jan 16 11:04:52] VERBOSE[12907] stasis/app.c: Creating Stasis app 'AriStart' [Jan 16 11:04:52] DEBUG[12907] res_stasis_device_state.c: Subscribing to device __AST_DEVICE_STATE_ALL_TOPIC [Jan 16 11:04:52] DEBUG[12823] threadpool.c: Increasing threadpool stasis-core's size by 1 [Jan 16 11:04:52] DEBUG[12907] stasis/app.c: Channel 'ALL' is 1 interested in AriStart [Jan 16 11:04:52] DEBUG[12907] stasis/app.c: Bridge 'ALL' is 1 interested in AriStart [Jan 16 11:04:52] DEBUG[12910] http.c: HTTP opening session. Top level [Jan 16 11:04:52] DEBUG[12907] stasis/messaging.c: App 'AriStart' subscribed to messages from endpoint '-- ALL --' [Jan 16 11:04:52] DEBUG[12907] stasis/app.c: Endpoint 'ALL' is 1 interested in AriStart [Jan 16 11:04:52] VERBOSE[12907] res_http_websocket.c: WebSocket connection from '192.168.0.67:59737' for protocol '' accepted using version '13' [Jan 16 11:04:52] DEBUG[12907] ari/resource_events.c: /events WebSocket established [Jan 16 11:04:52] DEBUG[12910] http.c: HTTP Request URI is /ari/channels?api_key=ariuser:aripass [Jan 16 11:04:52] DEBUG[12910] http.c: match request [ari/channels] with handler [httpstatus] len 10 [Jan 16 11:04:52] DEBUG[12910] http.c: match request [ari/channels] with handler [phoneprov] len 9 [Jan 16 11:04:52] DEBUG[12910] http.c: match request [ari/channels] with handler [static] len 6 [Jan 16 11:04:52] DEBUG[12910] http.c: match request [ari/channels] with handler [ari] len 3 [Jan 16 11:04:52] DEBUG[12910] http.c: Match made with [ari] [Jan 16 11:04:52] DEBUG[12910] res_ari.c: Finding handler for channels [Jan 16 11:04:52] DEBUG[12910] res_ari.c: Checking bridges [Jan 16 11:04:52] DEBUG[12910] res_ari.c: Checking channels [Jan 16 11:04:52] DEBUG[12910] res_ari.c: Got it! [Jan 16 11:04:52] DEBUG[12910] res_ari.c: Examining ARI response: 200 OK Content-type: application/json [] [Jan 16 11:04:52] DEBUG[12910] http.c: HTTP closing session. status_code:200 [Jan 16 11:04:52] DEBUG[12913] http.c: HTTP opening session. Top level [Jan 16 11:04:52] DEBUG[12913] http.c: HTTP Request URI is /ari/applications?api_key=ariuser:aripass [Jan 16 11:04:52] DEBUG[12913] http.c: match request [ari/applications] with handler [httpstatus] len 10 [Jan 16 11:04:52] DEBUG[12913] http.c: match request [ari/applications] with handler [phoneprov] len 9 [Jan 16 11:04:52] DEBUG[12913] http.c: match request [ari/applications] with handler [static] len 6 [Jan 16 11:04:52] DEBUG[12913] http.c: match request [ari/applications] with handler [ari] len 3 [Jan 16 11:04:52] DEBUG[12913] http.c: Match made with [ari] [Jan 16 11:04:52] DEBUG[12913] res_ari.c: Finding handler for applications [Jan 16 11:04:52] DEBUG[12913] res_ari.c: Checking bridges [Jan 16 11:04:52] DEBUG[12913] res_ari.c: Checking channels [Jan 16 11:04:52] DEBUG[12913] res_ari.c: Checking asterisk [Jan 16 11:04:52] DEBUG[12913] res_ari.c: Checking endpoints [Jan 16 11:04:52] DEBUG[12913] res_ari.c: Checking sounds [Jan 16 11:04:52] DEBUG[12913] res_ari.c: Checking deviceStates [Jan 16 11:04:52] DEBUG[12913] res_ari.c: Checking events [Jan 16 11:04:52] DEBUG[12913] res_ari.c: Checking applications [Jan 16 11:04:52] DEBUG[12913] res_ari.c: Got it! [Jan 16 11:04:52] DEBUG[12913] res_ari.c: Examining ARI response: 200 OK Content-type: application/json [{"name":"AriStart","channel_ids":["__AST_CHANNEL_ALL_TOPIC"],"bridge_ids":["__AST_BRIDGE_ALL_TOPIC"],"endpoint_ids":["__AST_ENDPOINT_ALL_TOPIC"],"device_names":["__AST_DEVICE_STATE_ALL_TOPIC"]}] [Jan 16 11:04:52] DEBUG[12913] http.c: HTTP closing session. status_code:200 [Jan 16 11:04:52] DEBUG[12914] http.c: HTTP opening session. Top level [Jan 16 11:04:52] DEBUG[12914] http.c: HTTP Request URI is /ari/applications?api_key=ariuser:aripass [Jan 16 11:04:52] DEBUG[12914] http.c: match request [ari/applications] with handler [httpstatus] len 10 [Jan 16 11:04:52] DEBUG[12914] http.c: match request [ari/applications] with handler [phoneprov] len 9 [Jan 16 11:04:52] DEBUG[12914] http.c: match request [ari/applications] with handler [static] len 6 [Jan 16 11:04:52] DEBUG[12914] http.c: match request [ari/applications] with handler [ari] len 3 [Jan 16 11:04:52] DEBUG[12914] http.c: Match made with [ari] [Jan 16 11:04:52] DEBUG[12914] res_ari.c: Finding handler for applications [Jan 16 11:04:52] DEBUG[12914] res_ari.c: Checking bridges [Jan 16 11:04:52] DEBUG[12914] res_ari.c: Checking channels [Jan 16 11:04:52] DEBUG[12914] res_ari.c: Checking asterisk [Jan 16 11:04:52] DEBUG[12914] res_ari.c: Checking endpoints [Jan 16 11:04:52] DEBUG[12914] res_ari.c: Checking sounds [Jan 16 11:04:52] DEBUG[12914] res_ari.c: Checking deviceStates [Jan 16 11:04:52] DEBUG[12914] res_ari.c: Checking events [Jan 16 11:04:52] DEBUG[12914] res_ari.c: Checking applications [Jan 16 11:04:52] DEBUG[12914] res_ari.c: Got it! [Jan 16 11:04:52] DEBUG[12914] res_ari.c: Examining ARI response: 200 OK Content-type: application/json [{"name":"AriStart","channel_ids":["__AST_CHANNEL_ALL_TOPIC"],"bridge_ids":["__AST_BRIDGE_ALL_TOPIC"],"endpoint_ids":["__AST_ENDPOINT_ALL_TOPIC"],"device_names":["__AST_DEVICE_STATE_ALL_TOPIC"]}] [Jan 16 11:04:52] DEBUG[12914] http.c: HTTP closing session. status_code:200 [Jan 16 11:05:00] DEBUG[12876] chan_iax2.c: schedule decrement of callno used for 192.168.5.16 in 60 seconds [Jan 16 11:05:02] DEBUG[12915] http.c: HTTP opening session. Top level [Jan 16 11:05:02] DEBUG[12915] http.c: HTTP Request URI is /ari/applications/AriStart?api_key=ariuser:aripass [Jan 16 11:05:02] DEBUG[12915] http.c: match request [ari/applications/AriStart] with handler [httpstatus] len 10 [Jan 16 11:05:02] DEBUG[12915] http.c: match request [ari/applications/AriStart] with handler [phoneprov] len 9 [Jan 16 11:05:02] DEBUG[12915] http.c: match request [ari/applications/AriStart] with handler [static] len 6 [Jan 16 11:05:02] DEBUG[12915] http.c: match request [ari/applications/AriStart] with handler [ari] len 3 [Jan 16 11:05:02] DEBUG[12915] http.c: Match made with [ari] [Jan 16 11:05:02] DEBUG[12915] res_ari.c: Finding handler for applications [Jan 16 11:05:02] DEBUG[12915] res_ari.c: Checking bridges [Jan 16 11:05:02] DEBUG[12915] res_ari.c: Checking channels [Jan 16 11:05:02] DEBUG[12915] res_ari.c: Checking asterisk [Jan 16 11:05:02] DEBUG[12915] res_ari.c: Checking endpoints [Jan 16 11:05:02] DEBUG[12915] res_ari.c: Checking sounds [Jan 16 11:05:02] DEBUG[12915] res_ari.c: Checking deviceStates [Jan 16 11:05:02] DEBUG[12915] res_ari.c: Checking events [Jan 16 11:05:02] DEBUG[12915] res_ari.c: Checking applications [Jan 16 11:05:02] DEBUG[12915] res_ari.c: Got it! [Jan 16 11:05:02] DEBUG[12915] res_ari.c: Finding handler for AriStart [Jan 16 11:05:02] DEBUG[12915] res_ari.c: Checking applicationName [Jan 16 11:05:02] DEBUG[12915] res_ari.c: Got it! [Jan 16 11:05:02] DEBUG[12915] res_ari.c: Examining ARI response: 200 OK Content-type: application/json {"name":"AriStart","channel_ids":["__AST_CHANNEL_ALL_TOPIC"],"bridge_ids":["__AST_BRIDGE_ALL_TOPIC"],"endpoint_ids":["__AST_ENDPOINT_ALL_TOPIC"],"device_names":["__AST_DEVICE_STATE_ALL_TOPIC"]} [Jan 16 11:05:02] DEBUG[12915] http.c: HTTP closing session. status_code:200 [Jan 16 11:05:05] DEBUG[12865] chan_iax2.c: ip callno count decremented to 3 for 192.168.5.16 [Jan 16 11:05:09] DEBUG[12879] chan_sip.c: = Looking for Call ID: 1593618112 (Checking From) --From tag 891428290 --To-tag [Jan 16 11:05:09] DEBUG[12879] acl.c: For destination '192.168.0.214', our source address is '192.168.0.98'. [Jan 16 11:05:09] DEBUG[12879] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.0.98:5060 [Jan 16 11:05:09] DEBUG[12879] netsock2.c: Splitting '192.168.0.214:5062' into... [Jan 16 11:05:09] DEBUG[12879] netsock2.c: ...host '192.168.0.214' and port '5062'. [Jan 16 11:05:09] DEBUG[12879] chan_sip.c: Allocating new SIP dialog for 1593618112 - INVITE (No RTP) [Jan 16 11:05:09] DEBUG[12879][C-00000001] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 16 11:05:09] DEBUG[12879][C-00000001] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces" [Jan 16 11:05:09] DEBUG[12879][C-00000001] sip/reqresp_parser.c: Found SIP option: -replaces- [Jan 16 11:05:09] DEBUG[12879][C-00000001] sip/reqresp_parser.c: Matched SIP option: replaces [Jan 16 11:05:09] DEBUG[12879][C-00000001] netsock2.c: Splitting '192.168.0.214:5062' into... [Jan 16 11:05:09] DEBUG[12879][C-00000001] netsock2.c: ...host '192.168.0.214' and port '5062'. [Jan 16 11:05:09] DEBUG[12879][C-00000001] netsock2.c: Splitting '192.168.0.98' into... [Jan 16 11:05:09] DEBUG[12879][C-00000001] netsock2.c: ...host '192.168.0.98' and port ''. [Jan 16 11:05:09] DEBUG[12879][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.0.214:5062 [Jan 16 11:05:09] DEBUG[12879] chan_sip.c: = Looking for Call ID: 1593618112 (Checking From) --From tag 891428290 --To-tag as3a2d3cb1 [Jan 16 11:05:09] DEBUG[12879][C-00000001] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 16 11:05:09] DEBUG[12879][C-00000001] chan_sip.c: Stopping retransmission on '1593618112' of Response 1: Match Found [Jan 16 11:05:10] DEBUG[12879] chan_sip.c: = Looking for Call ID: 1593618112 (Checking From) --From tag 891428290 --To-tag [Jan 16 11:05:10] DEBUG[12879] netsock2.c: Splitting '192.168.0.98' into... [Jan 16 11:05:10] DEBUG[12879] netsock2.c: ...host '192.168.0.98' and port ''. [Jan 16 11:05:10] DEBUG[12879] netsock2.c: Splitting '192.168.0.98' into... [Jan 16 11:05:10] DEBUG[12879] netsock2.c: ...host '192.168.0.98' and port ''. [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 16 11:05:10] DEBUG[12879][C-00000001] netsock2.c: Splitting '192.168.0.214:5062' into... [Jan 16 11:05:10] DEBUG[12879][C-00000001] netsock2.c: ...host '192.168.0.214' and port '5062'. [Jan 16 11:05:10] DEBUG[12879][C-00000001] netsock2.c: Splitting '192.168.0.98' into... [Jan 16 11:05:10] DEBUG[12879][C-00000001] netsock2.c: ...host '192.168.0.98' and port ''. [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fd2540036b8' [Jan 16 11:05:10] DEBUG[12879][C-00000001] res_rtp_asterisk.c: Allocated port 25762 for RTP instance '0x7fd2540036b8' [Jan 16 11:05:10] DEBUG[12879][C-00000001] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:25762 (25762) for RTP instance '0x7fd2540036b8' [Jan 16 11:05:10] DEBUG[12879][C-00000001] netsock2.c: Splitting '192.168.0.98' into... [Jan 16 11:05:10] DEBUG[12879][C-00000001] netsock2.c: ...host '192.168.0.98' and port ''. [Jan 16 11:05:10] DEBUG[12879][C-00000001] netsock2.c: Splitting '192.168.0.98' into... [Jan 16 11:05:10] DEBUG[12879][C-00000001] netsock2.c: ...host '192.168.0.98' and port ''. [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: RTP instance '0x7fd2540036b8' is setup and ready to go [Jan 16 11:05:10] DEBUG[12879][C-00000001] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Jan 16 11:05:10] DEBUG[12879][C-00000001] netsock2.c: Splitting 'maxvoip' into... [Jan 16 11:05:10] DEBUG[12879][C-00000001] netsock2.c: ...host 'maxvoip' and port ''. [Jan 16 11:05:10] DEBUG[12879][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fd2540036b8' [Jan 16 11:05:10] VERBOSE[12879][C-00000001] netsock2.c: Using SIP RTP CoS mark 5 [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: Setting NAT on RTP to On [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: Processing session-level SDP o=- 20115 20115 IN IP4 192.168.0.214... OK. [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: Processing session-level SDP s=SDP data... UNSUPPORTED OR FAILED. [Jan 16 11:05:10] DEBUG[12879][C-00000001] netsock2.c: Splitting '192.168.0.214' into... [Jan 16 11:05:10] DEBUG[12879][C-00000001] netsock2.c: ...host '192.168.0.214' and port ''. [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.0.214... OK. [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Setting tx payload type 9 based on m type on 0x7fd1f567e3f0 [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7fd1f567e3f0 [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7fd1f567e3f0 [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Setting tx payload type 4 based on m type on 0x7fd1f567e3f0 [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Setting tx payload type 112 based on m type on 0x7fd1f567e3f0 [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7fd1f567e3f0 [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7fd1f567e3f0 [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... OK. [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:4 G723/8000... OK. [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Unsetting payload 112 on 0x7fd1f567e3f0 [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:112 G726-16/8000... UNSUPPORTED OR FAILED. [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Crossover copying tx to rx payload mapping 0 (0x7fd2540088f0) from 0x7fd1f567e3f0 to 0x7fd1f567e3f0 [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Crossover copying tx to rx payload mapping 4 (0x7fd25400cdb0) from 0x7fd1f567e3f0 to 0x7fd1f567e3f0 [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Crossover copying tx to rx payload mapping 8 (0x7fd254003060) from 0x7fd1f567e3f0 to 0x7fd1f567e3f0 [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Crossover copying tx to rx payload mapping 9 (0x7fd254008840) from 0x7fd1f567e3f0 to 0x7fd1f567e3f0 [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Crossover copying tx to rx payload mapping 18 (0x7fd25400ce00) from 0x7fd1f567e3f0 to 0x7fd1f567e3f0 [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Crossover copying tx to rx payload mapping 101 (0x2b9ffc0) from 0x7fd1f567e3f0 to 0x7fd1f567e3f0 [Jan 16 11:05:10] DEBUG[12879][C-00000001] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Jan 16 11:05:10] DEBUG[12879][C-00000001] acl.c: For destination '192.168.0.214', our source address is '192.168.0.98'. [Jan 16 11:05:10] DEBUG[12879][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fd2540036b8' [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Copying rx payload mapping 0 (0x7fd2540088f0) from 0x7fd1f567e3f0 to 0x7fd254003880 [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Copying rx payload mapping 4 (0x7fd25400cdb0) from 0x7fd1f567e3f0 to 0x7fd254003880 [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Copying rx payload mapping 8 (0x7fd254003060) from 0x7fd1f567e3f0 to 0x7fd254003880 [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Copying rx payload mapping 9 (0x7fd254008840) from 0x7fd1f567e3f0 to 0x7fd254003880 [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Copying rx payload mapping 18 (0x7fd25400ce00) from 0x7fd1f567e3f0 to 0x7fd254003880 [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Copying rx payload mapping 101 (0x2b9ffc0) from 0x7fd1f567e3f0 to 0x7fd254003880 [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Copying tx payload mapping 0 (0x7fd2540088f0) from 0x7fd1f567e3f0 to 0x7fd254003880 [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Copying tx payload mapping 4 (0x7fd25400cdb0) from 0x7fd1f567e3f0 to 0x7fd254003880 [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Copying tx payload mapping 8 (0x7fd254003060) from 0x7fd1f567e3f0 to 0x7fd254003880 [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Copying tx payload mapping 9 (0x7fd254008840) from 0x7fd1f567e3f0 to 0x7fd254003880 [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Copying tx payload mapping 18 (0x7fd25400ce00) from 0x7fd1f567e3f0 to 0x7fd254003880 [Jan 16 11:05:10] DEBUG[12879][C-00000001] rtp_engine.c: Copying tx payload mapping 101 (0x2b9ffc0) from 0x7fd1f567e3f0 to 0x7fd254003880 [Jan 16 11:05:10] DEBUG[12879][C-00000001] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fd2540036b8' [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: We're settling with these formats: (ulaw) [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: Checking SIP call limits for device telefon [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: Updating call counter for incoming call [Jan 16 11:05:10] DEBUG[12879][C-00000001] netsock2.c: Splitting '192.168.0.98' into... [Jan 16 11:05:10] DEBUG[12879][C-00000001] netsock2.c: ...host '192.168.0.98' and port ''. [Jan 16 11:05:10] DEBUG[12879][C-00000001] netsock2.c: Splitting '192.168.0.98' into... [Jan 16 11:05:10] DEBUG[12879][C-00000001] netsock2.c: ...host '192.168.0.98' and port ''. [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: *** Our native formats are (ulaw) [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: *** Joint capabilities are (ulaw) [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: *** Our capabilities are (ulaw) [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: This channel will not be able to handle video. [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 432 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 432 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 492 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 492 [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: SIP/telefon-00000000: New call is still down.... Trying... [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 477 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 477 [Jan 16 11:05:10] DEBUG[12879][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.0.214:5062 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 475 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 475 [Jan 16 11:05:10] DEBUG[12834] devicestate.c: No provider found, checking channel drivers for SIP - telefon [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 436 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 436 [Jan 16 11:05:10] DEBUG[12834] chan_sip.c: Checking device state for peer telefon [Jan 16 11:05:10] DEBUG[12834] devicestate.c: Changing state for SIP/telefon - state 1 (Not in use) [Jan 16 11:05:10] DEBUG[12823] threadpool.c: Increasing threadpool stasis-core's size by 1 [Jan 16 11:05:10] DEBUG[12917][C-00000001] pbx.c: Launching 'Stasis' [Jan 16 11:05:10] VERBOSE[12917][C-00000001] pbx.c: Executing [104@from-sip:1] Stasis("SIP/telefon-00000000", "AriStart") in new stack [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 488 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 488 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 468 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 468 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 439 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 439 [Jan 16 11:05:10] DEBUG[12918] http.c: HTTP opening session. Top level [Jan 16 11:05:10] DEBUG[12918] http.c: HTTP Request URI is /ari/channels/1484561110.0/ring?api_key=ariuser:aripass [Jan 16 11:05:10] DEBUG[12918] http.c: match request [ari/channels/1484561110.0/ring] with handler [httpstatus] len 10 [Jan 16 11:05:10] DEBUG[12918] http.c: match request [ari/channels/1484561110.0/ring] with handler [phoneprov] len 9 [Jan 16 11:05:10] DEBUG[12918] http.c: match request [ari/channels/1484561110.0/ring] with handler [static] len 6 [Jan 16 11:05:10] DEBUG[12918] http.c: match request [ari/channels/1484561110.0/ring] with handler [ari] len 3 [Jan 16 11:05:10] DEBUG[12918] http.c: Match made with [ari] [Jan 16 11:05:10] DEBUG[12918] res_ari.c: Finding handler for channels [Jan 16 11:05:10] DEBUG[12918] res_ari.c: Checking bridges [Jan 16 11:05:10] DEBUG[12918] res_ari.c: Checking channels [Jan 16 11:05:10] DEBUG[12918] res_ari.c: Got it! [Jan 16 11:05:10] DEBUG[12918] res_ari.c: Finding handler for 1484561110.0 [Jan 16 11:05:10] DEBUG[12918] res_ari.c: Checking create [Jan 16 11:05:10] DEBUG[12918] res_ari.c: Checking channelId [Jan 16 11:05:10] DEBUG[12918] res_ari.c: Got it! [Jan 16 11:05:10] DEBUG[12918] res_ari.c: Finding handler for ring [Jan 16 11:05:10] DEBUG[12918] res_ari.c: Checking continue [Jan 16 11:05:10] DEBUG[12918] res_ari.c: Checking redirect [Jan 16 11:05:10] DEBUG[12918] res_ari.c: Checking answer [Jan 16 11:05:10] DEBUG[12918] res_ari.c: Checking ring [Jan 16 11:05:10] DEBUG[12918] res_ari.c: Got it! [Jan 16 11:05:10] DEBUG[12918] res_ari.c: Examining ARI response: 204 No Content [Jan 16 11:05:10] DEBUG[12918] http.c: HTTP closing session. status_code:204 [Jan 16 11:05:10] DEBUG[12919] http.c: HTTP opening session. Top level [Jan 16 11:05:10] DEBUG[12919] http.c: HTTP Request URI is /ari/bridges?api_key=ariuser:aripass&type=mixing&bridgeId=C-1-31&name=CONF-1484561110.0 [Jan 16 11:05:10] DEBUG[12919] http.c: match request [ari/bridges] with handler [httpstatus] len 10 [Jan 16 11:05:10] DEBUG[12919] http.c: match request [ari/bridges] with handler [phoneprov] len 9 [Jan 16 11:05:10] DEBUG[12919] http.c: match request [ari/bridges] with handler [static] len 6 [Jan 16 11:05:10] DEBUG[12919] http.c: match request [ari/bridges] with handler [ari] len 3 [Jan 16 11:05:10] DEBUG[12919] http.c: Match made with [ari] [Jan 16 11:05:10] DEBUG[12919] res_ari.c: Finding handler for bridges [Jan 16 11:05:10] DEBUG[12919] res_ari.c: Checking bridges [Jan 16 11:05:10] DEBUG[12919] res_ari.c: Got it! [Jan 16 11:05:10] DEBUG[12919] dahdi/bridge_native_dahdi.c: Bridge C-1-31: Cannot use native DAHDI. Must have two channels. [Jan 16 11:05:10] DEBUG[12919] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Jan 16 11:05:10] DEBUG[12919] bridge_native_rtp.c: Bridge 'C-1-31' can not use native RTP bridge as two channels are required [Jan 16 11:05:10] DEBUG[12919] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jan 16 11:05:10] DEBUG[12919] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jan 16 11:05:10] DEBUG[12919] bridge.c: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping. [Jan 16 11:05:10] DEBUG[12919] bridge.c: Chose bridge technology simple_bridge [Jan 16 11:05:10] DEBUG[12919] bridge.c: Bridge C-1-31: calling simple_bridge technology constructor [Jan 16 11:05:10] DEBUG[12919] bridge.c: Bridge C-1-31: calling simple_bridge technology start [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 307 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 307 [Jan 16 11:05:10] DEBUG[12919] res_ari.c: Examining ARI response: 200 OK Content-type: application/json {"channels":[],"id":"C-1-31","video_mode":"talker","technology":"simple_bridge","bridge_class":"stasis","bridge_type":"mixing","creator":"Stasis","name":"CONF-1484561110.0"} [Jan 16 11:05:10] DEBUG[12919] http.c: HTTP closing session. status_code:200 [Jan 16 11:05:10] DEBUG[12920] http.c: HTTP opening session. Top level [Jan 16 11:05:10] DEBUG[12920] http.c: HTTP Request URI is /ari/bridges/C-1-31/addChannel?api_key=ariuser:aripass&channel=1484561110.0 [Jan 16 11:05:10] DEBUG[12920] http.c: match request [ari/bridges/C-1-31/addChannel] with handler [httpstatus] len 10 [Jan 16 11:05:10] DEBUG[12920] http.c: match request [ari/bridges/C-1-31/addChannel] with handler [phoneprov] len 9 [Jan 16 11:05:10] DEBUG[12920] http.c: match request [ari/bridges/C-1-31/addChannel] with handler [static] len 6 [Jan 16 11:05:10] DEBUG[12920] http.c: match request [ari/bridges/C-1-31/addChannel] with handler [ari] len 3 [Jan 16 11:05:10] DEBUG[12920] http.c: Match made with [ari] [Jan 16 11:05:10] DEBUG[12920] res_ari.c: Finding handler for bridges [Jan 16 11:05:10] DEBUG[12920] res_ari.c: Checking bridges [Jan 16 11:05:10] DEBUG[12920] res_ari.c: Got it! [Jan 16 11:05:10] DEBUG[12920] res_ari.c: Finding handler for C-1-31 [Jan 16 11:05:10] DEBUG[12920] res_ari.c: Checking bridgeId [Jan 16 11:05:10] DEBUG[12920] res_ari.c: Got it! [Jan 16 11:05:10] DEBUG[12920] res_ari.c: Finding handler for addChannel [Jan 16 11:05:10] DEBUG[12920] res_ari.c: Checking addChannel [Jan 16 11:05:10] DEBUG[12920] res_ari.c: Got it! [Jan 16 11:05:10] DEBUG[12920] stasis/control.c: 1484561110.0: Sending channel add_to_bridge command [Jan 16 11:05:10] DEBUG[12917][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for 192.168.0.214:5062 [Jan 16 11:05:10] DEBUG[12917][C-00000001] bridge_roles.c: Roles did not exist on channel SIP/telefon-00000000 [Jan 16 11:05:10] DEBUG[12917][C-00000001] stasis/control.c: 1484561110.0: Adding to bridge C-1-31 [Jan 16 11:05:10] DEBUG[12921][C-00000001] bridge_channel.c: Bridge C-1-31: 0x7fd258001f18(SIP/telefon-00000000) is joining [Jan 16 11:05:10] DEBUG[12921][C-00000001] bridge_channel.c: Bridge C-1-31: pushing 0x7fd258001f18(SIP/telefon-00000000) [Jan 16 11:05:10] VERBOSE[12921][C-00000001] bridge_channel.c: Channel SIP/telefon-00000000 joined 'simple_bridge' stasis-bridge [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 635 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 635 [Jan 16 11:05:10] DEBUG[12921][C-00000001] dahdi/bridge_native_dahdi.c: Bridge C-1-31: Cannot use native DAHDI. Must have two channels. [Jan 16 11:05:10] DEBUG[12921][C-00000001] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Jan 16 11:05:10] DEBUG[12921][C-00000001] bridge_native_rtp.c: Bridge 'C-1-31' can not use native RTP bridge as two channels are required [Jan 16 11:05:10] DEBUG[12921][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jan 16 11:05:10] DEBUG[12921][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jan 16 11:05:10] DEBUG[12921][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jan 16 11:05:10] DEBUG[12921][C-00000001] bridge.c: Chose bridge technology simple_bridge [Jan 16 11:05:10] DEBUG[12921][C-00000001] bridge.c: Bridge C-1-31 is already using the new technology. [Jan 16 11:05:10] DEBUG[12921][C-00000001] bridge.c: Bridge C-1-31: 0x7fd258001f18(SIP/telefon-00000000) is joining simple_bridge technology [Jan 16 11:05:10] DEBUG[12921][C-00000001] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [Jan 16 11:05:10] DEBUG[12920] res_ari.c: Examining ARI response: 204 No Content [Jan 16 11:05:10] DEBUG[12920] http.c: HTTP closing session. status_code:204 [Jan 16 11:05:10] DEBUG[12922] http.c: HTTP opening session. Top level [Jan 16 11:05:10] DEBUG[12922] http.c: HTTP Request URI is /ari/channels/1484561110.0?api_key=ariuser:aripass [Jan 16 11:05:10] DEBUG[12922] http.c: match request [ari/channels/1484561110.0] with handler [httpstatus] len 10 [Jan 16 11:05:10] DEBUG[12922] http.c: match request [ari/channels/1484561110.0] with handler [phoneprov] len 9 [Jan 16 11:05:10] DEBUG[12922] http.c: match request [ari/channels/1484561110.0] with handler [static] len 6 [Jan 16 11:05:10] DEBUG[12922] http.c: match request [ari/channels/1484561110.0] with handler [ari] len 3 [Jan 16 11:05:10] DEBUG[12922] http.c: Match made with [ari] [Jan 16 11:05:10] DEBUG[12922] res_ari.c: Finding handler for channels [Jan 16 11:05:10] DEBUG[12922] res_ari.c: Checking bridges [Jan 16 11:05:10] DEBUG[12922] res_ari.c: Checking channels [Jan 16 11:05:10] DEBUG[12922] res_ari.c: Got it! [Jan 16 11:05:10] DEBUG[12922] res_ari.c: Finding handler for 1484561110.0 [Jan 16 11:05:10] DEBUG[12922] res_ari.c: Checking create [Jan 16 11:05:10] DEBUG[12922] res_ari.c: Checking channelId [Jan 16 11:05:10] DEBUG[12922] res_ari.c: Got it! [Jan 16 11:05:10] DEBUG[12922] res_ari.c: Examining ARI response: 200 OK Content-type: application/json {"language":"en","id":"1484561110.0","dialplan":{"context":"from-sip","exten":"104","priority":1},"connected":{"name":"","number":""},"name":"SIP/telefon-00000000","state":"Ring","caller":{"name":"telefon desk","number":"telefon"},"creationtime":"2017-01-16T11:05:10.051+0100","accountcode":""} [Jan 16 11:05:10] DEBUG[12922] http.c: HTTP closing session. status_code:200 [Jan 16 11:05:10] DEBUG[12923] http.c: HTTP opening session. Top level [Jan 16 11:05:10] DEBUG[12923] http.c: HTTP Request URI is /ari/channels/create?api_key=ariuser:aripass&endpoint=DAHDI%2Fr1%2F42999104&app=AriStart&originator=1484561110.0 [Jan 16 11:05:10] DEBUG[12923] http.c: match request [ari/channels/create] with handler [httpstatus] len 10 [Jan 16 11:05:10] DEBUG[12923] http.c: match request [ari/channels/create] with handler [phoneprov] len 9 [Jan 16 11:05:10] DEBUG[12923] http.c: match request [ari/channels/create] with handler [static] len 6 [Jan 16 11:05:10] DEBUG[12923] http.c: match request [ari/channels/create] with handler [ari] len 3 [Jan 16 11:05:10] DEBUG[12923] http.c: Match made with [ari] [Jan 16 11:05:10] DEBUG[12923] res_ari.c: Finding handler for channels [Jan 16 11:05:10] DEBUG[12923] res_ari.c: Checking bridges [Jan 16 11:05:10] DEBUG[12923] res_ari.c: Checking channels [Jan 16 11:05:10] DEBUG[12923] res_ari.c: Got it! [Jan 16 11:05:10] DEBUG[12923] res_ari.c: Finding handler for create [Jan 16 11:05:10] DEBUG[12923] res_ari.c: Checking create [Jan 16 11:05:10] DEBUG[12923] res_ari.c: Got it! [Jan 16 11:05:10] DEBUG[12923] res_stasis.c: AriStart: Subscribing to 1484561110.0 [Jan 16 11:05:10] DEBUG[12923][C-00000002] chan_dahdi.c: Using channel 1 [Jan 16 11:05:10] DEBUG[12923][C-00000002] sig_pri.c: sig_pri_request 1 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 412 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 412 [Jan 16 11:05:10] DEBUG[12923][C-00000002] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Jan 16 11:05:10] DEBUG[12923][C-00000002] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Jan 16 11:05:10] DEBUG[12834] devicestate.c: No provider found, checking channel drivers for DAHDI - i1/42999104 [Jan 16 11:05:10] DEBUG[12834] devicestate.c: Changing state for DAHDI/i1/42999104 - state 2 (In use) [Jan 16 11:05:10] DEBUG[12901] app_queue.c: Device 'DAHDI/i1/42999104' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 460 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 460 [Jan 16 11:05:10] DEBUG[12923] channel_internal_api.c: Channel Call ID changing from [C-00000002] to [C-00000001] [Jan 16 11:05:10] DEBUG[12923] res_stasis.c: AriStart: Subscribing to 1484561110.1 [Jan 16 11:05:10] DEBUG[12911] res_http_websocket.c: Writing websocket string of length 191 [Jan 16 11:05:10] DEBUG[12911] res_http_websocket.c: Writing websocket text frame, length 191 [Jan 16 11:05:10] DEBUG[12923] res_ari.c: Examining ARI response: 200 OK Content-type: application/json {"language":"en","id":"1484561110.1","dialplan":{"context":"from-pstn","exten":"s","priority":1},"connected":{"name":"","number":""},"name":"DAHDI/i1/42999104-1","state":"Rsrvd","caller":{"name":"","number":""},"creationtime":"2017-01-16T11:05:10.535+0100","accountcode":""} [Jan 16 11:05:10] DEBUG[12923] http.c: HTTP closing session. status_code:200 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 468 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 468 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 448 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 448 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 419 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 419 [Jan 16 11:05:10] DEBUG[12925] http.c: HTTP opening session. Top level [Jan 16 11:05:10] DEBUG[12925] http.c: HTTP Request URI is /ari/channels/1484561110.0/variable?api_key=ariuser:aripass&variable=CALLERID%28all%29&value=%3C98765%3E [Jan 16 11:05:10] DEBUG[12925] http.c: match request [ari/channels/1484561110.0/variable] with handler [httpstatus] len 10 [Jan 16 11:05:10] DEBUG[12925] http.c: match request [ari/channels/1484561110.0/variable] with handler [phoneprov] len 9 [Jan 16 11:05:10] DEBUG[12925] http.c: match request [ari/channels/1484561110.0/variable] with handler [static] len 6 [Jan 16 11:05:10] DEBUG[12925] http.c: match request [ari/channels/1484561110.0/variable] with handler [ari] len 3 [Jan 16 11:05:10] DEBUG[12925] http.c: Match made with [ari] [Jan 16 11:05:10] DEBUG[12925] res_ari.c: Finding handler for channels [Jan 16 11:05:10] DEBUG[12925] res_ari.c: Checking bridges [Jan 16 11:05:10] DEBUG[12925] res_ari.c: Checking channels [Jan 16 11:05:10] DEBUG[12925] res_ari.c: Got it! [Jan 16 11:05:10] DEBUG[12925] res_ari.c: Finding handler for 1484561110.0 [Jan 16 11:05:10] DEBUG[12925] res_ari.c: Checking create [Jan 16 11:05:10] DEBUG[12925] res_ari.c: Checking channelId [Jan 16 11:05:10] DEBUG[12925] res_ari.c: Got it! [Jan 16 11:05:10] DEBUG[12925] res_ari.c: Finding handler for variable [Jan 16 11:05:10] DEBUG[12925] res_ari.c: Checking continue [Jan 16 11:05:10] DEBUG[12925] res_ari.c: Checking redirect [Jan 16 11:05:10] DEBUG[12925] res_ari.c: Checking answer [Jan 16 11:05:10] DEBUG[12925] res_ari.c: Checking ring [Jan 16 11:05:10] DEBUG[12925] res_ari.c: Checking dtmf [Jan 16 11:05:10] DEBUG[12925] res_ari.c: Checking mute [Jan 16 11:05:10] DEBUG[12925] res_ari.c: Checking hold [Jan 16 11:05:10] DEBUG[12925] res_ari.c: Checking moh [Jan 16 11:05:10] DEBUG[12925] res_ari.c: Checking silence [Jan 16 11:05:10] DEBUG[12925] res_ari.c: Checking play [Jan 16 11:05:10] DEBUG[12925] res_ari.c: Checking record [Jan 16 11:05:10] DEBUG[12925] res_ari.c: Checking variable [Jan 16 11:05:10] DEBUG[12925] res_ari.c: Got it! [Jan 16 11:05:10] DEBUG[12925] res_ari.c: Examining ARI response: 204 No Content [Jan 16 11:05:10] DEBUG[12925] http.c: HTTP closing session. status_code:204 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 506 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 506 [Jan 16 11:05:10] DEBUG[12926] http.c: HTTP opening session. Top level [Jan 16 11:05:10] DEBUG[12926] http.c: HTTP Request URI is /ari/bridges/C-1-31/addChannel?api_key=ariuser:aripass&channel=1484561110.1 [Jan 16 11:05:10] DEBUG[12926] http.c: match request [ari/bridges/C-1-31/addChannel] with handler [httpstatus] len 10 [Jan 16 11:05:10] DEBUG[12926] http.c: match request [ari/bridges/C-1-31/addChannel] with handler [phoneprov] len 9 [Jan 16 11:05:10] DEBUG[12926] http.c: match request [ari/bridges/C-1-31/addChannel] with handler [static] len 6 [Jan 16 11:05:10] DEBUG[12926] http.c: match request [ari/bridges/C-1-31/addChannel] with handler [ari] len 3 [Jan 16 11:05:10] DEBUG[12926] http.c: Match made with [ari] [Jan 16 11:05:10] DEBUG[12926] res_ari.c: Finding handler for bridges [Jan 16 11:05:10] DEBUG[12926] res_ari.c: Checking bridges [Jan 16 11:05:10] DEBUG[12926] res_ari.c: Got it! [Jan 16 11:05:10] DEBUG[12926] res_ari.c: Finding handler for C-1-31 [Jan 16 11:05:10] DEBUG[12926] res_ari.c: Checking bridgeId [Jan 16 11:05:10] DEBUG[12926] res_ari.c: Got it! [Jan 16 11:05:10] DEBUG[12926] res_ari.c: Finding handler for addChannel [Jan 16 11:05:10] DEBUG[12926] res_ari.c: Checking addChannel [Jan 16 11:05:10] DEBUG[12926] res_ari.c: Got it! [Jan 16 11:05:10] DEBUG[12926] stasis/control.c: 1484561110.1: Sending channel add_to_bridge command [Jan 16 11:05:10] DEBUG[12924] bridge_roles.c: Roles did not exist on channel DAHDI/i1/42999104-1 [Jan 16 11:05:10] DEBUG[12924] stasis/control.c: 1484561110.1: Adding to bridge C-1-31 [Jan 16 11:05:10] DEBUG[12927] bridge_channel.c: Bridge C-1-31: 0x7fd24c005478(DAHDI/i1/42999104-1) is joining [Jan 16 11:05:10] DEBUG[12927] bridge_channel.c: Bridge C-1-31: pushing 0x7fd24c005478(DAHDI/i1/42999104-1) [Jan 16 11:05:10] VERBOSE[12927] bridge_channel.c: Channel DAHDI/i1/42999104-1 joined 'simple_bridge' stasis-bridge [Jan 16 11:05:10] DEBUG[12838] cdr.c: Finalized CDR for DAHDI/i1/42999104-1 - start 1484561110.535605 answer 0.000000 end 1484561110.557220 dispo FAILED [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 630 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 630 [Jan 16 11:05:10] DEBUG[12927] dahdi/bridge_native_dahdi.c: Channel 'SIP/telefon-00000000' is not DAHDI. [Jan 16 11:05:10] DEBUG[12927] dahdi/bridge_native_dahdi.c: Bridge C-1-31: Cannot use native DAHDI. Channel 'SIP/telefon-00000000' not compatible. [Jan 16 11:05:10] DEBUG[12927] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Jan 16 11:05:10] DEBUG[12927] bridge_native_rtp.c: Bridge 'C-1-31' can not use native RTP bridge as it was forbidden while getting details [Jan 16 11:05:10] DEBUG[12927] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jan 16 11:05:10] DEBUG[12927] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jan 16 11:05:10] DEBUG[12927] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jan 16 11:05:10] DEBUG[12927] bridge.c: Chose bridge technology simple_bridge [Jan 16 11:05:10] DEBUG[12927] bridge.c: Bridge C-1-31 is already using the new technology. [Jan 16 11:05:10] DEBUG[12927] bridge.c: Bridge C-1-31: 0x7fd24c005478(DAHDI/i1/42999104-1) is joining simple_bridge technology [Jan 16 11:05:10] DEBUG[12927] channel.c: Channel SIP/telefon-00000000 setting write format path: alaw -> ulaw [Jan 16 11:05:10] DEBUG[12927] channel.c: Channel DAHDI/i1/42999104-1 setting write format path: ulaw -> alaw [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 471 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 471 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 466 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 466 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 461 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 461 [Jan 16 11:05:10] DEBUG[12927] chan_dahdi.c: Requested indication 26 on channel DAHDI/i1/42999104-1 [Jan 16 11:05:10] DEBUG[12927] chan_dahdi.c: Requested indication 22 on channel DAHDI/i1/42999104-1 [Jan 16 11:05:10] DEBUG[12927] sig_pri.c: Received AST_CONTROL_CONNECTED_LINE on DAHDI/i1/42999104-1 [Jan 16 11:05:10] DEBUG[12921][C-00000001] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 423 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 423 [Jan 16 11:05:10] DEBUG[12926] res_ari.c: Examining ARI response: 204 No Content [Jan 16 11:05:10] DEBUG[12926] http.c: HTTP closing session. status_code:204 [Jan 16 11:05:10] DEBUG[12921][C-00000001] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 16 11:05:10] DEBUG[12921][C-00000001] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 16 11:05:10] DEBUG[12921][C-00000001] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 16 11:05:10] DEBUG[12921][C-00000001] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 16 11:05:10] DEBUG[12921][C-00000001] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 16 11:05:10] DEBUG[12928] http.c: HTTP opening session. Top level [Jan 16 11:05:10] DEBUG[12928] http.c: HTTP Request URI is /ari/channels/1484561110.1/dial?api_key=ariuser:aripass&caller=1484561110.0&timeout=20 [Jan 16 11:05:10] DEBUG[12928] http.c: match request [ari/channels/1484561110.1/dial] with handler [httpstatus] len 10 [Jan 16 11:05:10] DEBUG[12928] http.c: match request [ari/channels/1484561110.1/dial] with handler [phoneprov] len 9 [Jan 16 11:05:10] DEBUG[12928] http.c: match request [ari/channels/1484561110.1/dial] with handler [static] len 6 [Jan 16 11:05:10] DEBUG[12928] http.c: match request [ari/channels/1484561110.1/dial] with handler [ari] len 3 [Jan 16 11:05:10] DEBUG[12928] http.c: Match made with [ari] [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Finding handler for channels [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Checking bridges [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Checking channels [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Got it! [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Finding handler for 1484561110.1 [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Checking create [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Checking channelId [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Got it! [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Finding handler for dial [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Checking continue [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Checking redirect [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Checking answer [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Checking ring [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Checking dtmf [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Checking mute [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Checking hold [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Checking moh [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Checking silence [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Checking play [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Checking record [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Checking variable [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Checking snoop [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Checking dial [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Got it! [Jan 16 11:05:10] DEBUG[12924] bridge.c: Putting interval hook 0x7fd24c0016e0 with interval 19999 in the heap on features 0x7fd24c0020b0 [Jan 16 11:05:10] DEBUG[12924] sig_pri.c: CALLER NAME: NUM: 98765 [Jan 16 11:05:10] DEBUG[12924] sig_pri.c: prioffset: 1 mastertrunkgroup: 0 logicalspan: 0 result: 1 [Jan 16 11:05:10] VERBOSE[12924] sig_pri.c: Requested transfer capability: 0x00 - SPEECH [Jan 16 11:05:10] DEBUG[12834] devicestate.c: No provider found, checking channel drivers for DAHDI - i1/42999104 [Jan 16 11:05:10] DEBUG[12834] devicestate.c: Changing state for DAHDI/i1/42999104 - state 2 (In use) [Jan 16 11:05:10] DEBUG[12901] app_queue.c: Device 'DAHDI/i1/42999104' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 423 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 423 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 462 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 462 [Jan 16 11:05:10] DEBUG[12911] res_http_websocket.c: Writing websocket string of length 191 [Jan 16 11:05:10] DEBUG[12911] res_http_websocket.c: Writing websocket text frame, length 191 [Jan 16 11:05:10] DEBUG[12928] res_ari.c: Examining ARI response: 204 No Content [Jan 16 11:05:10] DEBUG[12928] http.c: HTTP closing session. status_code:204 [Jan 16 11:05:10] DEBUG[12868] chan_iax2.c: ip callno count incremented to 4 for 192.168.5.16 [Jan 16 11:05:10] DEBUG[12883][C-00000001] sig_pri.c: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/1 span 1 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 461 [Jan 16 11:05:10] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 461 [Jan 16 11:05:10] DEBUG[12921][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.0.214:5062 [Jan 16 11:05:11] DEBUG[12883][C-00000001] chan_dahdi.c: Enabled echo cancellation on channel 1 [Jan 16 11:05:11] DEBUG[12834] devicestate.c: No provider found, checking channel drivers for DAHDI - i1/42999104 [Jan 16 11:05:11] DEBUG[12834] devicestate.c: Changing state for DAHDI/i1/42999104 - state 6 (Ringing) [Jan 16 11:05:11] DEBUG[12911] res_http_websocket.c: Writing websocket string of length 193 [Jan 16 11:05:11] DEBUG[12911] res_http_websocket.c: Writing websocket text frame, length 193 [Jan 16 11:05:11] DEBUG[12901] app_queue.c: Device 'DAHDI/i1/42999104' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jan 16 11:05:11] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 423 [Jan 16 11:05:11] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 423 [Jan 16 11:05:11] DEBUG[12921][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for 192.168.0.214:5062 [Jan 16 11:05:11] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 458 [Jan 16 11:05:11] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 458 [Jan 16 11:05:12] DEBUG[12929] http.c: HTTP opening session. Top level [Jan 16 11:05:12] DEBUG[12929] http.c: HTTP Request URI is /ari/applications/AriStart?api_key=ariuser:aripass [Jan 16 11:05:12] DEBUG[12929] http.c: match request [ari/applications/AriStart] with handler [httpstatus] len 10 [Jan 16 11:05:12] DEBUG[12929] http.c: match request [ari/applications/AriStart] with handler [phoneprov] len 9 [Jan 16 11:05:12] DEBUG[12929] http.c: match request [ari/applications/AriStart] with handler [static] len 6 [Jan 16 11:05:12] DEBUG[12929] http.c: match request [ari/applications/AriStart] with handler [ari] len 3 [Jan 16 11:05:12] DEBUG[12929] http.c: Match made with [ari] [Jan 16 11:05:12] DEBUG[12929] res_ari.c: Finding handler for applications [Jan 16 11:05:12] DEBUG[12929] res_ari.c: Checking bridges [Jan 16 11:05:12] DEBUG[12929] res_ari.c: Checking channels [Jan 16 11:05:12] DEBUG[12929] res_ari.c: Checking asterisk [Jan 16 11:05:12] DEBUG[12929] res_ari.c: Checking endpoints [Jan 16 11:05:12] DEBUG[12929] res_ari.c: Checking sounds [Jan 16 11:05:12] DEBUG[12929] res_ari.c: Checking deviceStates [Jan 16 11:05:12] DEBUG[12929] res_ari.c: Checking events [Jan 16 11:05:12] DEBUG[12929] res_ari.c: Checking applications [Jan 16 11:05:12] DEBUG[12929] res_ari.c: Got it! [Jan 16 11:05:12] DEBUG[12929] res_ari.c: Finding handler for AriStart [Jan 16 11:05:12] DEBUG[12929] res_ari.c: Checking applicationName [Jan 16 11:05:12] DEBUG[12929] res_ari.c: Got it! [Jan 16 11:05:12] DEBUG[12929] res_ari.c: Examining ARI response: 200 OK Content-type: application/json {"name":"AriStart","channel_ids":["__AST_CHANNEL_ALL_TOPIC"],"bridge_ids":["__AST_BRIDGE_ALL_TOPIC"],"endpoint_ids":["__AST_ENDPOINT_ALL_TOPIC"],"device_names":["__AST_DEVICE_STATE_ALL_TOPIC"]} [Jan 16 11:05:12] DEBUG[12929] http.c: HTTP closing session. status_code:200 [Jan 16 11:05:14] DEBUG[12887] res_pjsip_registrar_expire.c: Woke up at 1484561114 Interval: 30 [Jan 16 11:05:14] DEBUG[12887] res_pjsip_registrar_expire.c: Expiring 0 contacts [Jan 16 11:05:14] DEBUG[12883][C-00000001] chan_dahdi.c: Echo cancellation already on [Jan 16 11:05:14] DEBUG[12834] devicestate.c: No provider found, checking channel drivers for DAHDI - i1/42999104 [Jan 16 11:05:14] DEBUG[12834] devicestate.c: Changing state for DAHDI/i1/42999104 - state 2 (In use) [Jan 16 11:05:14] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 418 [Jan 16 11:05:14] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 418 [Jan 16 11:05:14] DEBUG[12921][C-00000001] chan_sip.c: SIP answering channel: SIP/telefon-00000000 [Jan 16 11:05:14] DEBUG[12921][C-00000001] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 16 11:05:14] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 452 [Jan 16 11:05:14] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 452 [Jan 16 11:05:14] DEBUG[12921][C-00000001] chan_sip.c: ** Our capability: (ulaw) Video flag: True Text flag: True [Jan 16 11:05:14] DEBUG[12921][C-00000001] chan_sip.c: ** Our prefcodec: (nothing) [Jan 16 11:05:14] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 420 [Jan 16 11:05:14] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 420 [Jan 16 11:05:14] DEBUG[12921][C-00000001] chan_sip.c: -- Done with adding codecs to SDP [Jan 16 11:05:14] DEBUG[12921][C-00000001] chan_sip.c: Setting framing on incoming call: 0 [Jan 16 11:05:14] DEBUG[12921][C-00000001] chan_sip.c: Done building SDP. Settling with this capability: (ulaw) [Jan 16 11:05:14] DEBUG[12921][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.0.214:5062 [Jan 16 11:05:14] DEBUG[12834] devicestate.c: No provider found, checking channel drivers for SIP - telefon [Jan 16 11:05:14] DEBUG[12834] chan_sip.c: Checking device state for peer telefon [Jan 16 11:05:14] DEBUG[12834] devicestate.c: Changing state for SIP/telefon - state 1 (Not in use) [Jan 16 11:05:14] DEBUG[12901] app_queue.c: Device 'DAHDI/i1/42999104' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 16 11:05:14] DEBUG[12911] res_http_websocket.c: Writing websocket string of length 191 [Jan 16 11:05:14] DEBUG[12911] res_http_websocket.c: Writing websocket text frame, length 191 [Jan 16 11:05:14] DEBUG[12930] http.c: HTTP opening session. Top level [Jan 16 11:05:14] DEBUG[12930] http.c: HTTP Request URI is /ari/channels/1484561110.0/answer?api_key=ariuser:aripass [Jan 16 11:05:14] DEBUG[12930] http.c: match request [ari/channels/1484561110.0/answer] with handler [httpstatus] len 10 [Jan 16 11:05:14] DEBUG[12930] http.c: match request [ari/channels/1484561110.0/answer] with handler [phoneprov] len 9 [Jan 16 11:05:14] DEBUG[12930] http.c: match request [ari/channels/1484561110.0/answer] with handler [static] len 6 [Jan 16 11:05:14] DEBUG[12930] http.c: match request [ari/channels/1484561110.0/answer] with handler [ari] len 3 [Jan 16 11:05:14] DEBUG[12930] http.c: Match made with [ari] [Jan 16 11:05:14] DEBUG[12930] res_ari.c: Finding handler for channels [Jan 16 11:05:14] DEBUG[12930] res_ari.c: Checking bridges [Jan 16 11:05:14] DEBUG[12930] res_ari.c: Checking channels [Jan 16 11:05:14] DEBUG[12930] res_ari.c: Got it! [Jan 16 11:05:14] DEBUG[12930] res_ari.c: Finding handler for 1484561110.0 [Jan 16 11:05:14] DEBUG[12930] res_ari.c: Checking create [Jan 16 11:05:14] DEBUG[12930] res_ari.c: Checking channelId [Jan 16 11:05:14] DEBUG[12930] res_ari.c: Got it! [Jan 16 11:05:14] DEBUG[12930] res_ari.c: Finding handler for answer [Jan 16 11:05:14] DEBUG[12930] res_ari.c: Checking continue [Jan 16 11:05:14] DEBUG[12930] res_ari.c: Checking redirect [Jan 16 11:05:14] DEBUG[12930] res_ari.c: Checking answer [Jan 16 11:05:14] DEBUG[12930] res_ari.c: Got it! [Jan 16 11:05:14] DEBUG[12930] res_stasis_answer.c: 1484561110.0: Sending answer command [Jan 16 11:05:14] DEBUG[12917][C-00000001] res_stasis_answer.c: 1484561110.0: Answering [Jan 16 11:05:14] DEBUG[12930] res_ari.c: Examining ARI response: 204 No Content [Jan 16 11:05:14] DEBUG[12930] http.c: HTTP closing session. status_code:204 [Jan 16 11:05:14] DEBUG[12879] chan_sip.c: = Looking for Call ID: 1593618112 (Checking From) --From tag 891428290 --To-tag as3ad49d08 [Jan 16 11:05:14] DEBUG[12879][C-00000001] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 16 11:05:14] DEBUG[12879][C-00000001] chan_sip.c: Stopping retransmission on '1593618112' of Response 2: Match Found [Jan 16 11:05:15] DEBUG[12921][C-00000001] res_rtp_asterisk.c: 0x7fd254008b00 -- Probation learning mode pass with source address 192.168.0.214:11790 [Jan 16 11:05:15] VERBOSE[12921][C-00000001] res_rtp_asterisk.c: 0x7fd254008b00 -- Probation passed - setting RTP source address to 192.168.0.214:11790 [Jan 16 11:05:15] DEBUG[12921][C-00000001] res_rtp_asterisk.c: Ooh, format changed from none to ulaw [Jan 16 11:05:17] DEBUG[12847] netsock2.c: Splitting '192.168.0.137:5061' into... [Jan 16 11:05:17] DEBUG[12847] netsock2.c: ...host '192.168.0.137' and port '5061'. [Jan 16 11:05:17] DEBUG[12847] netsock2.c: Splitting '192.168.0.98:5061' into... [Jan 16 11:05:17] DEBUG[12847] netsock2.c: ...host '192.168.0.98' and port '5061'. [Jan 16 11:05:17] DEBUG[12847] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg OPTIONS/cseq=54969 (rdata0x7fd22c001e68) [Jan 16 11:05:17] DEBUG[12847] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000035 to use for Request msg OPTIONS/cseq=54969 (rdata0x7fd22c001e68) [Jan 16 11:05:17] DEBUG[12845] threadpool.c: Increasing threadpool SIP's size by 5 [Jan 16 11:05:17] DEBUG[12931] netsock2.c: Splitting '192.168.0.137' into... [Jan 16 11:05:17] DEBUG[12931] netsock2.c: ...host '192.168.0.137' and port ''. [Jan 16 11:05:17] DEBUG[12931] res_pjsip_endpoint_identifier_ip.c: Source address 192.168.0.137:5061 matches identify 'pjsip-app-server-1' [Jan 16 11:05:17] DEBUG[12931] res_pjsip_endpoint_identifier_ip.c: Retrieved endpoint pjsip-app-server-1 [Jan 16 11:05:17] DEBUG[12931] netsock2.c: Splitting '192.168.0.98:5061' into... [Jan 16 11:05:17] DEBUG[12931] netsock2.c: ...host '192.168.0.98' and port '5061'. [Jan 16 11:05:17] DEBUG[12931] netsock2.c: Splitting '192.168.0.137:5061' into... [Jan 16 11:05:17] DEBUG[12931] netsock2.c: ...host '192.168.0.137' and port '5061'. [Jan 16 11:05:19] DEBUG[12871] chan_iax2.c: schedule decrement of callno used for 192.168.5.16 in 60 seconds [Jan 16 11:05:20] DEBUG[12890] netsock2.c: Splitting '192.168.0.98:25763' into... [Jan 16 11:05:20] DEBUG[12890] netsock2.c: ...host '192.168.0.98' and port '25763'. [Jan 16 11:05:20] DEBUG[12890] netsock2.c: Splitting '192.168.0.214:11791' into... [Jan 16 11:05:20] DEBUG[12890] netsock2.c: ...host '192.168.0.214' and port '11791'. [Jan 16 11:05:22] DEBUG[12936] http.c: HTTP opening session. Top level [Jan 16 11:05:22] DEBUG[12936] http.c: HTTP Request URI is /ari/applications/AriStart?api_key=ariuser:aripass [Jan 16 11:05:22] DEBUG[12936] http.c: match request [ari/applications/AriStart] with handler [httpstatus] len 10 [Jan 16 11:05:22] DEBUG[12936] http.c: match request [ari/applications/AriStart] with handler [phoneprov] len 9 [Jan 16 11:05:22] DEBUG[12936] http.c: match request [ari/applications/AriStart] with handler [static] len 6 [Jan 16 11:05:22] DEBUG[12936] http.c: match request [ari/applications/AriStart] with handler [ari] len 3 [Jan 16 11:05:22] DEBUG[12936] http.c: Match made with [ari] [Jan 16 11:05:22] DEBUG[12936] res_ari.c: Finding handler for applications [Jan 16 11:05:22] DEBUG[12936] res_ari.c: Checking bridges [Jan 16 11:05:22] DEBUG[12936] res_ari.c: Checking channels [Jan 16 11:05:22] DEBUG[12936] res_ari.c: Checking asterisk [Jan 16 11:05:22] DEBUG[12936] res_ari.c: Checking endpoints [Jan 16 11:05:22] DEBUG[12936] res_ari.c: Checking sounds [Jan 16 11:05:22] DEBUG[12936] res_ari.c: Checking deviceStates [Jan 16 11:05:22] DEBUG[12936] res_ari.c: Checking events [Jan 16 11:05:22] DEBUG[12936] res_ari.c: Checking applications [Jan 16 11:05:22] DEBUG[12936] res_ari.c: Got it! [Jan 16 11:05:22] DEBUG[12936] res_ari.c: Finding handler for AriStart [Jan 16 11:05:22] DEBUG[12936] res_ari.c: Checking applicationName [Jan 16 11:05:22] DEBUG[12936] res_ari.c: Got it! [Jan 16 11:05:22] DEBUG[12936] res_ari.c: Examining ARI response: 200 OK Content-type: application/json {"name":"AriStart","channel_ids":["__AST_CHANNEL_ALL_TOPIC"],"bridge_ids":["__AST_BRIDGE_ALL_TOPIC"],"endpoint_ids":["__AST_ENDPOINT_ALL_TOPIC"],"device_names":["__AST_DEVICE_STATE_ALL_TOPIC"]} [Jan 16 11:05:22] DEBUG[12936] http.c: HTTP closing session. status_code:200 [Jan 16 11:05:24] DEBUG[12865] chan_iax2.c: ip callno count decremented to 3 for 192.168.5.16 [Jan 16 11:05:25] DEBUG[12890] netsock2.c: Splitting '192.168.0.98:25763' into... [Jan 16 11:05:25] DEBUG[12890] netsock2.c: ...host '192.168.0.98' and port '25763'. [Jan 16 11:05:25] DEBUG[12890] netsock2.c: Splitting '192.168.0.214:11791' into... [Jan 16 11:05:25] DEBUG[12890] netsock2.c: ...host '192.168.0.214' and port '11791'. [Jan 16 11:05:29] DEBUG[12873] chan_iax2.c: ip callno count incremented to 4 for 192.168.5.16 [Jan 16 11:05:30] DEBUG[12890] netsock2.c: Splitting '192.168.0.98:25763' into... [Jan 16 11:05:30] DEBUG[12890] netsock2.c: ...host '192.168.0.98' and port '25763'. [Jan 16 11:05:30] DEBUG[12890] netsock2.c: Splitting '192.168.0.214:11791' into... [Jan 16 11:05:30] DEBUG[12890] netsock2.c: ...host '192.168.0.214' and port '11791'. [Jan 16 11:05:30] DEBUG[12927] bridge_channel.c: Executing hook 0x7fd24c0016e0 on 0x7fd24c005478(DAHDI/i1/42999104-1) [Jan 16 11:05:30] DEBUG[12927] bridge_channel.c: Removed interval hook 0x7fd24c0016e0 from 0x7fd24c005478(DAHDI/i1/42999104-1) [Jan 16 11:05:32] DEBUG[12937] http.c: HTTP opening session. Top level [Jan 16 11:05:32] DEBUG[12937] http.c: HTTP Request URI is /ari/applications/AriStart?api_key=ariuser:aripass [Jan 16 11:05:32] DEBUG[12937] http.c: match request [ari/applications/AriStart] with handler [httpstatus] len 10 [Jan 16 11:05:32] DEBUG[12937] http.c: match request [ari/applications/AriStart] with handler [phoneprov] len 9 [Jan 16 11:05:32] DEBUG[12937] http.c: match request [ari/applications/AriStart] with handler [static] len 6 [Jan 16 11:05:32] DEBUG[12937] http.c: match request [ari/applications/AriStart] with handler [ari] len 3 [Jan 16 11:05:32] DEBUG[12937] http.c: Match made with [ari] [Jan 16 11:05:32] DEBUG[12937] res_ari.c: Finding handler for applications [Jan 16 11:05:32] DEBUG[12937] res_ari.c: Checking bridges [Jan 16 11:05:32] DEBUG[12937] res_ari.c: Checking channels [Jan 16 11:05:32] DEBUG[12937] res_ari.c: Checking asterisk [Jan 16 11:05:32] DEBUG[12937] res_ari.c: Checking endpoints [Jan 16 11:05:32] DEBUG[12937] res_ari.c: Checking sounds [Jan 16 11:05:32] DEBUG[12937] res_ari.c: Checking deviceStates [Jan 16 11:05:32] DEBUG[12937] res_ari.c: Checking events [Jan 16 11:05:32] DEBUG[12937] res_ari.c: Checking applications [Jan 16 11:05:32] DEBUG[12937] res_ari.c: Got it! [Jan 16 11:05:32] DEBUG[12937] res_ari.c: Finding handler for AriStart [Jan 16 11:05:32] DEBUG[12937] res_ari.c: Checking applicationName [Jan 16 11:05:32] DEBUG[12937] res_ari.c: Got it! [Jan 16 11:05:32] DEBUG[12937] res_ari.c: Examining ARI response: 200 OK Content-type: application/json {"name":"AriStart","channel_ids":["__AST_CHANNEL_ALL_TOPIC"],"bridge_ids":["__AST_BRIDGE_ALL_TOPIC"],"endpoint_ids":["__AST_ENDPOINT_ALL_TOPIC"],"device_names":["__AST_DEVICE_STATE_ALL_TOPIC"]} [Jan 16 11:05:32] DEBUG[12937] http.c: HTTP closing session. status_code:200 [Jan 16 11:05:34] DEBUG[12916] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 16 11:05:34] DEBUG[12911] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 16 11:05:34] DEBUG[12823] threadpool.c: Destroying worker thread 13 [Jan 16 11:05:34] DEBUG[12823] threadpool.c: Destroying worker thread 12 [Jan 16 11:05:35] DEBUG[12890] netsock2.c: Splitting '192.168.0.98:25763' into... [Jan 16 11:05:35] DEBUG[12890] netsock2.c: ...host '192.168.0.98' and port '25763'. [Jan 16 11:05:35] DEBUG[12890] netsock2.c: Splitting '192.168.0.214:11791' into... [Jan 16 11:05:35] DEBUG[12890] netsock2.c: ...host '192.168.0.214' and port '11791'. [Jan 16 11:05:36] VERBOSE[12883][C-00000001] sig_pri.c: Span 1: Channel 0/1 got hangup request, cause 16 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 420 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 420 [Jan 16 11:05:36] DEBUG[12927] bridge_channel.c: Setting 0x7fd24c005478(DAHDI/i1/42999104-1) state from:0 to:1 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 448 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 448 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 453 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 453 [Jan 16 11:05:36] DEBUG[12927] bridge_channel.c: Bridge C-1-31: pulling 0x7fd24c005478(DAHDI/i1/42999104-1) [Jan 16 11:05:36] VERBOSE[12927] bridge_channel.c: Channel DAHDI/i1/42999104-1 left 'simple_bridge' stasis-bridge [Jan 16 11:05:36] DEBUG[12927] bridge_channel.c: Bridge C-1-31: 0x7fd24c005478(DAHDI/i1/42999104-1) is leaving simple_bridge technology [Jan 16 11:05:36] DEBUG[12838] cdr.c: Finalized CDR for SIP/telefon-00000000 - start 1484561110.051400 answer 1484561114.906919 end 1484561136.813184 dispo ANSWERED [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 614 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 614 [Jan 16 11:05:36] DEBUG[12927] dahdi/bridge_native_dahdi.c: Bridge C-1-31: Cannot use native DAHDI. Must have two channels. [Jan 16 11:05:36] DEBUG[12927] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Jan 16 11:05:36] DEBUG[12927] bridge_native_rtp.c: Bridge 'C-1-31' can not use native RTP bridge as two channels are required [Jan 16 11:05:36] DEBUG[12927] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jan 16 11:05:36] DEBUG[12927] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jan 16 11:05:36] DEBUG[12927] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jan 16 11:05:36] DEBUG[12927] bridge.c: Chose bridge technology simple_bridge [Jan 16 11:05:36] DEBUG[12927] bridge.c: Bridge C-1-31 is already using the new technology. [Jan 16 11:05:36] DEBUG[12927] bridge_channel.c: Bridge is returning 0x7fd24c005478(DAHDI/i1/42999104-1) to write format alaw [Jan 16 11:05:36] DEBUG[12927] channel.c: Channel DAHDI/i1/42999104-1 setting write format path: alaw -> alaw [Jan 16 11:05:36] DEBUG[12927] stasis/control.c: 1484561110.1, C-1-31: Channel leaving bridge [Jan 16 11:05:36] DEBUG[12927] stasis/app.c: App 'AriStart' not subscribed to bridge 'C-1-31' [Jan 16 11:05:36] DEBUG[12927] stasis/control.c: reason: Channel was departed from bridge [Jan 16 11:05:36] DEBUG[12924] stasis/control.c: 1484561110.1: Channel departing bridge [Jan 16 11:05:36] DEBUG[12924] bridge.c: Waiting for 0x7fd24c005478(DAHDI/i1/42999104-1) bridge thread to die. [Jan 16 11:05:36] DEBUG[12924] stasis/app.c: App 'AriStart' not subscribed to channel '1484561110.1' [Jan 16 11:05:36] DEBUG[12924] channel.c: Hanging up channel 'DAHDI/i1/42999104-1' [Jan 16 11:05:36] DEBUG[12924] chan_dahdi.c: dahdi_hangup(DAHDI/i1/42999104-1) [Jan 16 11:05:36] DEBUG[12924] chan_dahdi.c: Set option AUDIO MODE, value: ON(1) on DAHDI/i1/42999104-1 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 409 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 409 [Jan 16 11:05:36] DEBUG[12924] sig_pri.c: sig_pri_hangup 1 [Jan 16 11:05:36] DEBUG[12924] sig_pri.c: Channel 'DAHDI/i1/42999104-1' MOH-Event: SIG_PRI_MOH_EVENT_RESET in state SIG_PRI_MOH_STATE_IDLE [Jan 16 11:05:36] DEBUG[12924] sig_pri.c: Channel 'DAHDI/i1/42999104-1' MOH-Next-State: $ [Jan 16 11:05:36] DEBUG[12924] sig_pri.c: Not yet hungup... Calling hangup with cause 16, and clearing call [Jan 16 11:05:36] DEBUG[12924] chan_dahdi.c: Disabled echo cancellation on channel 1 [Jan 16 11:05:36] DEBUG[12924] chan_dahdi.c: Set option TDD MODE, value: OFF(0) on DAHDI/i1/42999104-1 [Jan 16 11:05:36] DEBUG[12924] chan_dahdi.c: Updated conferencing on 1, with 0 conference users [Jan 16 11:05:36] DEBUG[12924] chan_dahdi.c: Set option AUDIO MODE, value: OFF(0) on DAHDI/i1/42999104-1 [Jan 16 11:05:36] VERBOSE[12924] chan_dahdi.c: Hungup 'DAHDI/i1/42999104-1' [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 457 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 457 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 457 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 457 [Jan 16 11:05:36] DEBUG[12834] devicestate.c: No provider found, checking channel drivers for DAHDI - i1/42999104 [Jan 16 11:05:36] DEBUG[12909] stasis/app.c: App 'AriStart' not subscribed to channel '1484561110.1' [Jan 16 11:05:36] DEBUG[12834] devicestate.c: Changing state for DAHDI/i1/42999104 - state 0 (Unknown) [Jan 16 11:05:36] DEBUG[12838] cdr.c: Finalized CDR for DAHDI/i1/42999104-1 - start 1484561110.671972 answer 1484561114.905818 end 1484561136.814926 dispo ANSWERED [Jan 16 11:05:36] DEBUG[12838] cdr.c: CDR for DAHDI/i1/42999104-1 is dialed and has no Party B; discarding [Jan 16 11:05:36] DEBUG[12838] cdr.c: CDR for DAHDI/i1/42999104-1 is dialed and has no Party B; discarding [Jan 16 11:05:36] DEBUG[12901] app_queue.c: Device 'DAHDI/i1/42999104' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jan 16 11:05:36] DEBUG[12823] threadpool.c: Increasing threadpool stasis-core's size by 1 [Jan 16 11:05:36] DEBUG[12938] res_http_websocket.c: Writing websocket string of length 193 [Jan 16 11:05:36] DEBUG[12938] res_http_websocket.c: Writing websocket text frame, length 193 [Jan 16 11:05:36] DEBUG[12939] http.c: HTTP opening session. Top level [Jan 16 11:05:36] DEBUG[12939] http.c: HTTP Request URI is /ari/channels/1484561110.0?api_key=ariuser:aripass&reason=normal [Jan 16 11:05:36] DEBUG[12939] http.c: match request [ari/channels/1484561110.0] with handler [httpstatus] len 10 [Jan 16 11:05:36] DEBUG[12939] http.c: match request [ari/channels/1484561110.0] with handler [phoneprov] len 9 [Jan 16 11:05:36] DEBUG[12939] http.c: match request [ari/channels/1484561110.0] with handler [static] len 6 [Jan 16 11:05:36] DEBUG[12939] http.c: match request [ari/channels/1484561110.0] with handler [ari] len 3 [Jan 16 11:05:36] DEBUG[12939] http.c: Match made with [ari] [Jan 16 11:05:36] DEBUG[12939] res_ari.c: Finding handler for channels [Jan 16 11:05:36] DEBUG[12939] res_ari.c: Checking bridges [Jan 16 11:05:36] DEBUG[12939] res_ari.c: Checking channels [Jan 16 11:05:36] DEBUG[12939] res_ari.c: Got it! [Jan 16 11:05:36] DEBUG[12939] res_ari.c: Finding handler for 1484561110.0 [Jan 16 11:05:36] DEBUG[12939] res_ari.c: Checking create [Jan 16 11:05:36] DEBUG[12939] res_ari.c: Checking channelId [Jan 16 11:05:36] DEBUG[12939] res_ari.c: Got it! [Jan 16 11:05:36] DEBUG[12939] channel.c: Soft-Hanging (0x20) up channel 'SIP/telefon-00000000' [Jan 16 11:05:36] DEBUG[12939] res_ari.c: Examining ARI response: 204 No Content [Jan 16 11:05:36] DEBUG[12939] http.c: HTTP closing session. status_code:204 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 445 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 445 [Jan 16 11:05:36] DEBUG[12921][C-00000001] bridge_channel.c: Setting 0x7fd258001f18(SIP/telefon-00000000) state from:0 to:1 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 450 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 450 [Jan 16 11:05:36] DEBUG[12921][C-00000001] bridge_channel.c: Bridge C-1-31: pulling 0x7fd258001f18(SIP/telefon-00000000) [Jan 16 11:05:36] VERBOSE[12921][C-00000001] bridge_channel.c: Channel SIP/telefon-00000000 left 'simple_bridge' stasis-bridge [Jan 16 11:05:36] DEBUG[12921][C-00000001] bridge_channel.c: Bridge C-1-31: 0x7fd258001f18(SIP/telefon-00000000) is leaving simple_bridge technology [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 602 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 602 [Jan 16 11:05:36] DEBUG[12921][C-00000001] dahdi/bridge_native_dahdi.c: Bridge C-1-31: Cannot use native DAHDI. Must have two channels. [Jan 16 11:05:36] DEBUG[12921][C-00000001] bridge.c: Bridge technology native_dahdi is not compatible with properties of existing bridge. [Jan 16 11:05:36] DEBUG[12921][C-00000001] bridge_native_rtp.c: Bridge 'C-1-31' can not use native RTP bridge as two channels are required [Jan 16 11:05:36] DEBUG[12921][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jan 16 11:05:36] DEBUG[12921][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jan 16 11:05:36] DEBUG[12921][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jan 16 11:05:36] DEBUG[12921][C-00000001] bridge.c: Chose bridge technology simple_bridge [Jan 16 11:05:36] DEBUG[12921][C-00000001] bridge.c: Bridge C-1-31 is already using the new technology. [Jan 16 11:05:36] DEBUG[12921][C-00000001] bridge_channel.c: Bridge is returning 0x7fd258001f18(SIP/telefon-00000000) to write format ulaw [Jan 16 11:05:36] DEBUG[12921][C-00000001] channel.c: Channel SIP/telefon-00000000 setting write format path: ulaw -> ulaw [Jan 16 11:05:36] DEBUG[12921][C-00000001] stasis/control.c: 1484561110.0, C-1-31: Channel leaving bridge [Jan 16 11:05:36] DEBUG[12921][C-00000001] stasis/app.c: App 'AriStart' not subscribed to bridge 'C-1-31' [Jan 16 11:05:36] DEBUG[12921][C-00000001] stasis/control.c: reason: Channel was departed from bridge [Jan 16 11:05:36] DEBUG[12917][C-00000001] stasis/control.c: 1484561110.0: Channel departing bridge [Jan 16 11:05:36] DEBUG[12917][C-00000001] bridge.c: Waiting for 0x7fd258001f18(SIP/telefon-00000000) bridge thread to die. [Jan 16 11:05:36] DEBUG[12917][C-00000001] stasis/app.c: App 'AriStart' not subscribed to channel '1484561110.0' [Jan 16 11:05:36] DEBUG[12917][C-00000001] pbx.c: Extension 104, priority 1 returned normally even though call was hung up [Jan 16 11:05:36] DEBUG[12917][C-00000001] channel.c: Soft-Hanging (0x10) up channel 'SIP/telefon-00000000' [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 411 [Jan 16 11:05:36] DEBUG[12917][C-00000001] channel.c: Soft-Hanging (0x80) up channel 'SIP/telefon-00000000' [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 411 [Jan 16 11:05:36] DEBUG[12917][C-00000001] pbx.c: Launching 'Stasis' [Jan 16 11:05:36] VERBOSE[12917][C-00000001] pbx.c: Executing [h@from-sip:1] Stasis("SIP/telefon-00000000", "AriStart") in new stack [Jan 16 11:05:36] DEBUG[12917][C-00000001] stasis/app.c: App 'AriStart' not subscribed to channel '1484561110.0' [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 459 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 459 [Jan 16 11:05:36] DEBUG[12917][C-00000001] channel.c: Hanging up channel 'SIP/telefon-00000000' [Jan 16 11:05:36] DEBUG[12917][C-00000001] chan_sip.c: Hangup call SIP/telefon-00000000, SIP callid 1593618112 [Jan 16 11:05:36] DEBUG[12917][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fd2540036b8' [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 445 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 445 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 470 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 470 [Jan 16 11:05:36] DEBUG[12917][C-00000001] chan_sip.c: Trying to put 'BYE sip:tel' onto UDP socket destined for 192.168.0.214:5062 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 450 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 450 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 421 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 421 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 409 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 409 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 457 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 457 [Jan 16 11:05:36] DEBUG[12834] devicestate.c: No provider found, checking channel drivers for SIP - telefon [Jan 16 11:05:36] DEBUG[12834] chan_sip.c: Checking device state for peer telefon [Jan 16 11:05:36] DEBUG[12834] devicestate.c: Changing state for SIP/telefon - state 1 (Not in use) [Jan 16 11:05:36] DEBUG[12823] threadpool.c: Increasing threadpool stasis-core's size by 1 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 565 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 565 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 655 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 655 [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(clid)})' (from 'CSV_QUOTE(${CDR(clid)})},${CSV_QUOTE(${CDR(src)})},${CSV_QUOTE(${CDR(dst)})},${CSV_QUOTE(${CDR(dcontext)})},${CSV_QUOTE(${CDR(channel)})},${CSV_QUOTE(${CDR(dstchannel)})},${CSV_QUOTE(${CDR(lastapp)})},${CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(start)})},${CSV_QUOTE(${CDR(answer)})},${CSV_QUOTE(${CDR(end)})},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)} ' len 23) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CDR(clid)' (from 'CDR(clid)})' len 9) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CDR(clid) result is '"" <98765>' [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 637 [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CSV_QUOTE("" <98765>) result is '""""" <98765>"' [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 637 [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(src)})' (from 'CSV_QUOTE(${CDR(src)})},${CSV_QUOTE(${CDR(dst)})},${CSV_QUOTE(${CDR(dcontext)})},${CSV_QUOTE(${CDR(channel)})},${CSV_QUOTE(${CDR(dstchannel)})},${CSV_QUOTE(${CDR(lastapp)})},${CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(start)})},${CSV_QUOTE(${CDR(answer)})},${CSV_QUOTE(${CDR(end)})},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)} ' len 22) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CDR(src)' (from 'CDR(src)})' len 8) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CDR(src) result is '98765' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CSV_QUOTE(98765) result is '"98765"' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(dst)})' (from 'CSV_QUOTE(${CDR(dst)})},${CSV_QUOTE(${CDR(dcontext)})},${CSV_QUOTE(${CDR(channel)})},${CSV_QUOTE(${CDR(dstchannel)})},${CSV_QUOTE(${CDR(lastapp)})},${CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(start)})},${CSV_QUOTE(${CDR(answer)})},${CSV_QUOTE(${CDR(end)})},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)} ' len 22) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CDR(dst)' (from 'CDR(dst)})' len 8) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CDR(dst) result is '104' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CSV_QUOTE(104) result is '"104"' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(dcontext)})' (from 'CSV_QUOTE(${CDR(dcontext)})},${CSV_QUOTE(${CDR(channel)})},${CSV_QUOTE(${CDR(dstchannel)})},${CSV_QUOTE(${CDR(lastapp)})},${CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(start)})},${CSV_QUOTE(${CDR(answer)})},${CSV_QUOTE(${CDR(end)})},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)} ' len 27) [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 518 [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CDR(dcontext)' (from 'CDR(dcontext)})' len 13) [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 518 [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CDR(dcontext) result is 'from-sip' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CSV_QUOTE(from-sip) result is '"from-sip"' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(channel)})' (from 'CSV_QUOTE(${CDR(channel)})},${CSV_QUOTE(${CDR(dstchannel)})},${CSV_QUOTE(${CDR(lastapp)})},${CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(start)})},${CSV_QUOTE(${CDR(answer)})},${CSV_QUOTE(${CDR(end)})},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)} ' len 26) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CDR(channel)' (from 'CDR(channel)})' len 12) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CDR(channel) result is 'SIP/telefon-00000000' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CSV_QUOTE(SIP/telefon-00000000) result is '"SIP/telefon-00000000"' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(dstchannel)})' (from 'CSV_QUOTE(${CDR(dstchannel)})},${CSV_QUOTE(${CDR(lastapp)})},${CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(start)})},${CSV_QUOTE(${CDR(answer)})},${CSV_QUOTE(${CDR(end)})},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)} ' len 29) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CDR(dstchannel)' (from 'CDR(dstchannel)})' len 15) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CDR(dstchannel) result is 'DAHDI/i1/42999104-1' [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 565 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 565 [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CSV_QUOTE(DAHDI/i1/42999104-1) result is '"DAHDI/i1/42999104-1"' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(lastapp)})' (from 'CSV_QUOTE(${CDR(lastapp)})},${CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(start)})},${CSV_QUOTE(${CDR(answer)})},${CSV_QUOTE(${CDR(end)})},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)} ' len 26) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CDR(lastapp)' (from 'CDR(lastapp)})' len 12) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CDR(lastapp) result is 'Stasis' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CSV_QUOTE(Stasis) result is '"Stasis"' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(lastdata)})' (from 'CSV_QUOTE(${CDR(lastdata)})},${CSV_QUOTE(${CDR(start)})},${CSV_QUOTE(${CDR(answer)})},${CSV_QUOTE(${CDR(end)})},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)} ' len 27) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CDR(lastdata)' (from 'CDR(lastdata)})' len 13) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CDR(lastdata) result is 'AriStart' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CSV_QUOTE(AriStart) result is '"AriStart"' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(start)})' (from 'CSV_QUOTE(${CDR(start)})},${CSV_QUOTE(${CDR(answer)})},${CSV_QUOTE(${CDR(end)})},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)} ' len 24) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CDR(start)' (from 'CDR(start)})' len 10) [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket string of length 457 [Jan 16 11:05:36] DEBUG[12909] res_http_websocket.c: Writing websocket text frame, length 457 [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CDR(start) result is '2017-01-16 11:05:10' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CSV_QUOTE(2017-01-16 11:05:10) result is '"2017-01-16 11:05:10"' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(answer)})' (from 'CSV_QUOTE(${CDR(answer)})},${CSV_QUOTE(${CDR(end)})},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)} ' len 25) [Jan 16 11:05:36] DEBUG[12909] stasis/app.c: App 'AriStart' not subscribed to channel '1484561110.0' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CDR(answer)' (from 'CDR(answer)})' len 11) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CDR(answer) result is '2017-01-16 11:05:14' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CSV_QUOTE(2017-01-16 11:05:14) result is '"2017-01-16 11:05:14"' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(end)})' (from 'CSV_QUOTE(${CDR(end)})},${CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)} ' len 22) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CDR(end)' (from 'CDR(end)})' len 8) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CDR(end) result is '2017-01-16 11:05:36' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CSV_QUOTE(2017-01-16 11:05:36) result is '"2017-01-16 11:05:36"' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(duration,f)})' (from 'CSV_QUOTE(${CDR(duration,f)})},${CSV_QUOTE(${CDR(billsec,f)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)} ' len 29) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CDR(duration,f)' (from 'CDR(duration,f)})' len 15) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CDR(duration,f) result is '26.761784' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CSV_QUOTE(26.761784) result is '"26.761784"' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(billsec,f)})' (from 'CSV_QUOTE(${CDR(billsec,f)})},${CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)} ' len 28) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CDR(billsec,f)' (from 'CDR(billsec,f)})' len 14) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CDR(billsec,f) result is '21.906265' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CSV_QUOTE(21.906265) result is '"21.906265"' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(disposition)})' (from 'CSV_QUOTE(${CDR(disposition)})},${CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)} ' len 30) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CDR(disposition)' (from 'CDR(disposition)})' len 16) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CDR(disposition) result is 'ANSWERED' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CSV_QUOTE(ANSWERED) result is '"ANSWERED"' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(amaflags)})' (from 'CSV_QUOTE(${CDR(amaflags)})},${CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)} ' len 27) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CDR(amaflags)' (from 'CDR(amaflags)})' len 13) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CDR(amaflags) result is 'DOCUMENTATION' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CSV_QUOTE(DOCUMENTATION) result is '"DOCUMENTATION"' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(accountcode)})' (from 'CSV_QUOTE(${CDR(accountcode)})},${CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)} ' len 30) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CDR(accountcode)' (from 'CDR(accountcode)})' len 16) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CDR(accountcode) result is '' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CSV_QUOTE() result is '""' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(uniqueid)})' (from 'CSV_QUOTE(${CDR(uniqueid)})},${CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)} ' len 27) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CDR(uniqueid)' (from 'CDR(uniqueid)})' len 13) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CDR(uniqueid) result is '1484561110.0' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CSV_QUOTE(1484561110.0) result is '"1484561110.0"' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CSV_QUOTE(${CDR(userfield)})' (from 'CSV_QUOTE(${CDR(userfield)})},${CDR(sequence)} ' len 28) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CDR(userfield)' (from 'CDR(userfield)})' len 14) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CDR(userfield) result is '' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CSV_QUOTE() result is '""' [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Evaluating 'CDR(sequence)' (from 'CDR(sequence)} ' len 13) [Jan 16 11:05:36] DEBUG[12838] pbx_variables.c: Function CDR(sequence) result is '0' [Jan 16 11:05:36] DEBUG[12838] res_config_sqlite.c: About to query table structure: SELECT sql FROM sqlite_master WHERE type='table' AND tbl_name='ast_cdr' [Jan 16 11:05:36] DEBUG[12838] res_config_sqlite.c: Found field: id INTEGER [Jan 16 11:05:36] DEBUG[12838] res_config_sqlite.c: Found field: clid VARCHAR(80) NOT NULL DEFAULT '' [Jan 16 11:05:36] DEBUG[12838] res_config_sqlite.c: Found field: src VARCHAR(80) NOT NULL DEFAULT '' [Jan 16 11:05:36] DEBUG[12838] res_config_sqlite.c: Found field: dst VARCHAR(80) NOT NULL DEFAULT '' [Jan 16 11:05:36] DEBUG[12838] res_config_sqlite.c: Found field: dcontext VARCHAR(80) NOT NULL DEFAULT '' [Jan 16 11:05:36] DEBUG[12838] res_config_sqlite.c: Found field: channel VARCHAR(80) NOT NULL DEFAULT '' [Jan 16 11:05:36] DEBUG[12838] res_config_sqlite.c: Found field: dstchannel VARCHAR(80) NOT NULL DEFAULT '' [Jan 16 11:05:36] DEBUG[12838] res_config_sqlite.c: Found field: lastapp VARCHAR(80) NOT NULL DEFAULT '' [Jan 16 11:05:36] DEBUG[12838] res_config_sqlite.c: Found field: lastdata VARCHAR(80) NOT NULL DEFAULT '' [Jan 16 11:05:36] DEBUG[12838] res_config_sqlite.c: Found field: start DATETIME NOT NULL DEFAULT '0000-00-00 00:00:00' [Jan 16 11:05:36] DEBUG[12838] res_config_sqlite.c: Found field: answer DATETIME NOT NULL DEFAULT '0000-00-00 00:00:00' [Jan 16 11:05:36] DEBUG[12838] res_config_sqlite.c: Found field: end DATETIME NOT NULL DEFAULT '0000-00-00 00:00:00' [Jan 16 11:05:36] DEBUG[12838] res_config_sqlite.c: Found field: duration INT(11) NOT NULL DEFAULT 0 [Jan 16 11:05:36] DEBUG[12838] res_config_sqlite.c: Found field: billsec INT(11) NOT NULL DEFAULT 0 [Jan 16 11:05:36] DEBUG[12838] res_config_sqlite.c: Found field: disposition VARCHAR(45) NOT NULL DEFAULT '' [Jan 16 11:05:36] DEBUG[12838] res_config_sqlite.c: Found field: amaflags INT(11) NOT NULL DEFAULT 0 [Jan 16 11:05:36] DEBUG[12838] res_config_sqlite.c: Found field: accountcode VARCHAR(20) NOT NULL DEFAULT '' [Jan 16 11:05:36] DEBUG[12838] res_config_sqlite.c: Found field: uniqueid VARCHAR(32) NOT NULL DEFAULT '' [Jan 16 11:05:36] DEBUG[12838] res_config_sqlite.c: Found field: userfield VARCHAR(255) NOT NULL DEFAULT '' [Jan 16 11:05:36] DEBUG[12838] res_config_sqlite.c: Found field: PRIMARY KEY (id) [Jan 16 11:05:36] DEBUG[12838] res_config_sqlite.c: SQL query: INSERT INTO ast_cdr (clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,start,answer,end,duration,billsec,disposition,amaflags,uniqueid) VALUES ('"" <98765>','98765','104','from-sip','SIP/telefon-00000000','DAHDI/i1/42999104-1','Stasis','AriStart','2017-01-16 11:05:10','2017-01-16 11:05:14','2017-01-16 11:05:36','26','21','ANSWERED','DOCUMENTATION','1484561110.0') [Jan 16 11:05:36] DEBUG[12879] chan_sip.c: = Looking for Call ID: 1593618112 (Checking To) --From tag as3ad49d08 --To-tag 891428290 [Jan 16 11:05:36] DEBUG[12879][C-00000001] chan_sip.c: Stopping retransmission on '1593618112' of Request 102: Match Found [Jan 16 11:05:36] DEBUG[12879] chan_sip.c: Destroying SIP dialog 1593618112 [Jan 16 11:05:36] DEBUG[12879] rtp_engine.c: Destroyed RTP instance '0x7fd2540036b8' [Jan 16 11:05:36] DEBUG[12941] http.c: HTTP opening session. Top level [Jan 16 11:05:36] DEBUG[12941] http.c: HTTP Request URI is /ari/channels/1484561110.1?api_key=ariuser:aripass [Jan 16 11:05:36] DEBUG[12941] http.c: match request [ari/channels/1484561110.1] with handler [httpstatus] len 10 [Jan 16 11:05:36] DEBUG[12941] http.c: match request [ari/channels/1484561110.1] with handler [phoneprov] len 9 [Jan 16 11:05:36] DEBUG[12941] http.c: match request [ari/channels/1484561110.1] with handler [static] len 6 [Jan 16 11:05:36] DEBUG[12941] http.c: match request [ari/channels/1484561110.1] with handler [ari] len 3 [Jan 16 11:05:36] DEBUG[12941] http.c: Match made with [ari] [Jan 16 11:05:36] DEBUG[12941] res_ari.c: Finding handler for channels [Jan 16 11:05:36] DEBUG[12941] res_ari.c: Checking bridges [Jan 16 11:05:36] DEBUG[12941] res_ari.c: Checking channels [Jan 16 11:05:36] DEBUG[12941] res_ari.c: Got it! [Jan 16 11:05:36] DEBUG[12941] res_ari.c: Finding handler for 1484561110.1 [Jan 16 11:05:36] DEBUG[12941] res_ari.c: Checking create [Jan 16 11:05:36] DEBUG[12941] res_ari.c: Checking channelId [Jan 16 11:05:36] DEBUG[12941] res_ari.c: Got it! [Jan 16 11:05:36] DEBUG[12941] res_ari.c: Examining ARI response: 404 Not Found Content-type: application/json {"message":"Channel not found"} [Jan 16 11:05:36] DEBUG[12941] http.c: HTTP closing session. status_code:404 [Jan 16 11:05:37] DEBUG[12942] http.c: HTTP opening session. Top level [Jan 16 11:05:37] DEBUG[12942] http.c: HTTP Request URI is /ari/bridges/C-1-31?api_key=ariuser:aripass [Jan 16 11:05:37] DEBUG[12942] http.c: match request [ari/bridges/C-1-31] with handler [httpstatus] len 10 [Jan 16 11:05:37] DEBUG[12942] http.c: match request [ari/bridges/C-1-31] with handler [phoneprov] len 9 [Jan 16 11:05:37] DEBUG[12942] http.c: match request [ari/bridges/C-1-31] with handler [static] len 6 [Jan 16 11:05:37] DEBUG[12942] http.c: match request [ari/bridges/C-1-31] with handler [ari] len 3 [Jan 16 11:05:37] DEBUG[12942] http.c: Match made with [ari] [Jan 16 11:05:37] DEBUG[12942] res_ari.c: Finding handler for bridges [Jan 16 11:05:37] DEBUG[12942] res_ari.c: Checking bridges [Jan 16 11:05:37] DEBUG[12942] res_ari.c: Got it! [Jan 16 11:05:37] DEBUG[12942] res_ari.c: Finding handler for C-1-31 [Jan 16 11:05:37] DEBUG[12942] res_ari.c: Checking bridgeId [Jan 16 11:05:37] DEBUG[12942] res_ari.c: Got it! [Jan 16 11:05:37] DEBUG[12942] res_ari.c: Examining ARI response: 200 OK Content-type: application/json {"channels":[],"id":"C-1-31","video_mode":"talker","technology":"simple_bridge","bridge_class":"stasis","bridge_type":"mixing","creator":"Stasis","name":"CONF-1484561110.0"} [Jan 16 11:05:37] DEBUG[12942] http.c: HTTP closing session. status_code:200 [Jan 16 11:05:37] DEBUG[12943] http.c: HTTP opening session. Top level [Jan 16 11:05:37] DEBUG[12943] http.c: HTTP Request URI is /ari/bridges/C-1-31?api_key=ariuser:aripass [Jan 16 11:05:37] DEBUG[12943] http.c: match request [ari/bridges/C-1-31] with handler [httpstatus] len 10 [Jan 16 11:05:37] DEBUG[12943] http.c: match request [ari/bridges/C-1-31] with handler [phoneprov] len 9 [Jan 16 11:05:37] DEBUG[12943] http.c: match request [ari/bridges/C-1-31] with handler [static] len 6 [Jan 16 11:05:37] DEBUG[12943] http.c: match request [ari/bridges/C-1-31] with handler [ari] len 3 [Jan 16 11:05:37] DEBUG[12943] http.c: Match made with [ari] [Jan 16 11:05:37] DEBUG[12943] res_ari.c: Finding handler for bridges [Jan 16 11:05:37] DEBUG[12943] res_ari.c: Checking bridges [Jan 16 11:05:37] DEBUG[12943] res_ari.c: Got it! [Jan 16 11:05:37] DEBUG[12943] res_ari.c: Finding handler for C-1-31 [Jan 16 11:05:37] DEBUG[12943] res_ari.c: Checking bridgeId [Jan 16 11:05:37] DEBUG[12943] res_ari.c: Got it! [Jan 16 11:05:37] DEBUG[12943] bridge.c: Bridge C-1-31: telling all channels to leave the party [Jan 16 11:05:37] DEBUG[12943] bridge.c: Bridge C-1-31: dissolving bridge with cause 16(Normal Clearing) [Jan 16 11:05:37] DEBUG[12943] bridge.c: Bridge C-1-31: queueing action type:13 sub:1001 [Jan 16 11:05:37] DEBUG[12943] res_ari.c: Examining ARI response: 204 No Content [Jan 16 11:05:37] DEBUG[12943] http.c: HTTP closing session. status_code:204 [Jan 16 11:05:37] DEBUG[12944] http.c: HTTP opening session. Top level [Jan 16 11:05:37] DEBUG[12944] http.c: HTTP Request URI is /ari/bridges/C-1-31?api_key=ariuser:aripass [Jan 16 11:05:37] DEBUG[12944] http.c: match request [ari/bridges/C-1-31] with handler [httpstatus] len 10 [Jan 16 11:05:37] DEBUG[12944] http.c: match request [ari/bridges/C-1-31] with handler [phoneprov] len 9 [Jan 16 11:05:37] DEBUG[12944] http.c: match request [ari/bridges/C-1-31] with handler [static] len 6 [Jan 16 11:05:37] DEBUG[12944] http.c: match request [ari/bridges/C-1-31] with handler [ari] len 3 [Jan 16 11:05:37] DEBUG[12944] http.c: Match made with [ari] [Jan 16 11:05:37] DEBUG[12944] res_ari.c: Finding handler for bridges [Jan 16 11:05:37] DEBUG[12944] res_ari.c: Checking bridges [Jan 16 11:05:37] DEBUG[12944] res_ari.c: Got it! [Jan 16 11:05:37] DEBUG[12944] res_ari.c: Finding handler for C-1-31 [Jan 16 11:05:37] DEBUG[12944] res_ari.c: Checking bridgeId [Jan 16 11:05:37] DEBUG[12944] res_ari.c: Got it! [Jan 16 11:05:37] DEBUG[12944] res_ari.c: Examining ARI response: 200 OK Content-type: application/json {"channels":[],"id":"C-1-31","video_mode":"talker","technology":"simple_bridge","bridge_class":"stasis","bridge_type":"mixing","creator":"Stasis","name":"CONF-1484561110.0"} [Jan 16 11:05:37] DEBUG[12944] http.c: HTTP closing session. status_code:200 [Jan 16 11:05:37] DEBUG[12876] chan_iax2.c: schedule decrement of callno used for 192.168.5.16 in 60 seconds [Jan 16 11:05:42] DEBUG[12865] chan_iax2.c: ip callno count decremented to 3 for 192.168.5.16 [Jan 16 11:05:42] DEBUG[12945] http.c: HTTP opening session. Top level [Jan 16 11:05:42] DEBUG[12945] http.c: HTTP Request URI is /ari/applications/AriStart?api_key=ariuser:aripass [Jan 16 11:05:42] DEBUG[12945] http.c: match request [ari/applications/AriStart] with handler [httpstatus] len 10 [Jan 16 11:05:42] DEBUG[12945] http.c: match request [ari/applications/AriStart] with handler [phoneprov] len 9 [Jan 16 11:05:42] DEBUG[12945] http.c: match request [ari/applications/AriStart] with handler [static] len 6 [Jan 16 11:05:42] DEBUG[12945] http.c: match request [ari/applications/AriStart] with handler [ari] len 3 [Jan 16 11:05:42] DEBUG[12945] http.c: Match made with [ari] [Jan 16 11:05:42] DEBUG[12945] res_ari.c: Finding handler for applications [Jan 16 11:05:42] DEBUG[12945] res_ari.c: Checking bridges [Jan 16 11:05:42] DEBUG[12945] res_ari.c: Checking channels [Jan 16 11:05:42] DEBUG[12945] res_ari.c: Checking asterisk [Jan 16 11:05:42] DEBUG[12945] res_ari.c: Checking endpoints [Jan 16 11:05:42] DEBUG[12945] res_ari.c: Checking sounds [Jan 16 11:05:42] DEBUG[12945] res_ari.c: Checking deviceStates [Jan 16 11:05:42] DEBUG[12945] res_ari.c: Checking events [Jan 16 11:05:42] DEBUG[12945] res_ari.c: Checking applications [Jan 16 11:05:42] DEBUG[12945] res_ari.c: Got it! [Jan 16 11:05:42] DEBUG[12945] res_ari.c: Finding handler for AriStart [Jan 16 11:05:42] DEBUG[12945] res_ari.c: Checking applicationName [Jan 16 11:05:42] DEBUG[12945] res_ari.c: Got it! [Jan 16 11:05:42] DEBUG[12945] res_ari.c: Examining ARI response: 200 OK Content-type: application/json {"name":"AriStart","channel_ids":["__AST_CHANNEL_ALL_TOPIC"],"bridge_ids":["__AST_BRIDGE_ALL_TOPIC"],"endpoint_ids":["__AST_ENDPOINT_ALL_TOPIC"],"device_names":["__AST_DEVICE_STATE_ALL_TOPIC"]} [Jan 16 11:05:42] DEBUG[12945] http.c: HTTP closing session. status_code:200 [Jan 16 11:05:43] DEBUG[12865] chan_iax2.c: ip callno count decremented to 0 for 192.168.0.137 [Jan 16 11:05:43] DEBUG[12867] chan_iax2.c: ip callno count incremented to 1 for 192.168.0.137 [Jan 16 11:05:43] DEBUG[12868] chan_iax2.c: schedule decrement of callno used for 192.168.0.137 in 60 seconds [Jan 16 11:05:43] DEBUG[12868] chan_iax2.c: Peer iax2-app-server-1: got pong, lastms 3, historicms 2, maxms 2000 [Jan 16 11:05:44] DEBUG[12879] chan_sip.c: Allocating new SIP dialog for 5a90f551223ddce143b81a4c142b32e2@127.0.1.1:5060 - OPTIONS (No RTP) [Jan 16 11:05:44] DEBUG[12879] acl.c: For destination '192.168.0.137', our source address is '192.168.0.98'. [Jan 16 11:05:44] DEBUG[12879] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.0.98:5060 [Jan 16 11:05:44] DEBUG[12879] chan_sip.c: SIP call-id changed from '5a90f551223ddce143b81a4c142b32e2@127.0.1.1:5060' to '504960a32294e0d17168c36553835e2a@192.168.0.98:5060' [Jan 16 11:05:44] DEBUG[12879] chan_sip.c: Initializing initreq for method OPTIONS - callid 504960a32294e0d17168c36553835e2a@192.168.0.98:5060 [Jan 16 11:05:44] DEBUG[12879] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.0.137:5060 [Jan 16 11:05:44] DEBUG[12879] chan_sip.c: = Looking for Call ID: 504960a32294e0d17168c36553835e2a@192.168.0.98:5060 (Checking To) --From tag as5ca77886 --To-tag as1f425725 [Jan 16 11:05:44] DEBUG[12879] chan_sip.c: Stopping retransmission on '504960a32294e0d17168c36553835e2a@192.168.0.98:5060' of Request 102: Match Found [Jan 16 11:05:44] DEBUG[12879] chan_sip.c: Destroying SIP dialog 504960a32294e0d17168c36553835e2a@192.168.0.98:5060 [Jan 16 11:05:44] DEBUG[12879] chan_sip.c: Allocating new SIP dialog for 4581776b3f0d425739a81f1f0d0a9406@127.0.1.1:5060 - OPTIONS (No RTP) [Jan 16 11:05:44] DEBUG[12879] acl.c: For destination '192.168.0.214', our source address is '192.168.0.98'. [Jan 16 11:05:44] DEBUG[12879] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.0.98:5060 [Jan 16 11:05:44] DEBUG[12879] chan_sip.c: SIP call-id changed from '4581776b3f0d425739a81f1f0d0a9406@127.0.1.1:5060' to '1a14f2fd1c5fe2911faaa3fd3e944816@192.168.0.98:5060' [Jan 16 11:05:44] DEBUG[12879] chan_sip.c: Initializing initreq for method OPTIONS - callid 1a14f2fd1c5fe2911faaa3fd3e944816@192.168.0.98:5060 [Jan 16 11:05:44] DEBUG[12879] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.0.214:5062 [Jan 16 11:05:44] DEBUG[12879] chan_sip.c: = Looking for Call ID: 1a14f2fd1c5fe2911faaa3fd3e944816@192.168.0.98:5060 (Checking To) --From tag as7614bb34 --To-tag 140895131 [Jan 16 11:05:44] DEBUG[12879] chan_sip.c: Stopping retransmission on '1a14f2fd1c5fe2911faaa3fd3e944816@192.168.0.98:5060' of Request 102: Match Found [Jan 16 11:05:44] DEBUG[12879] chan_sip.c: Destroying SIP dialog 1a14f2fd1c5fe2911faaa3fd3e944816@192.168.0.98:5060 [Jan 16 11:05:44] DEBUG[12879] chan_sip.c: Allocating new SIP dialog for 4799e709086d8ed351e41ca206e372d4@127.0.1.1:5060 - OPTIONS (No RTP) [Jan 16 11:05:44] DEBUG[12879] acl.c: For destination '192.168.0.227', our source address is '192.168.0.98'. [Jan 16 11:05:44] DEBUG[12879] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.0.98:5060 [Jan 16 11:05:44] DEBUG[12879] chan_sip.c: SIP call-id changed from '4799e709086d8ed351e41ca206e372d4@127.0.1.1:5060' to '3bdc3440546dee3c693ce749795e1ef6@192.168.0.98:5060' [Jan 16 11:05:44] DEBUG[12879] chan_sip.c: Initializing initreq for method OPTIONS - callid 3bdc3440546dee3c693ce749795e1ef6@192.168.0.98:5060 [Jan 16 11:05:44] DEBUG[12879] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.0.227:59318 [Jan 16 11:05:44] DEBUG[12879] chan_sip.c: = Looking for Call ID: 3bdc3440546dee3c693ce749795e1ef6@192.168.0.98:5060 (Checking To) --From tag as07a3a585 --To-tag afef8443 [Jan 16 11:05:44] DEBUG[12879] chan_sip.c: Stopping retransmission on '3bdc3440546dee3c693ce749795e1ef6@192.168.0.98:5060' of Request 102: Match Found [Jan 16 11:05:44] DEBUG[12879] chan_sip.c: Destroying SIP dialog 3bdc3440546dee3c693ce749795e1ef6@192.168.0.98:5060 [Jan 16 11:05:44] DEBUG[12887] res_pjsip_registrar_expire.c: Woke up at 1484561144 Interval: 30 [Jan 16 11:05:44] DEBUG[12887] res_pjsip_registrar_expire.c: Expiring 0 contacts [Jan 16 11:05:47] DEBUG[12871] chan_iax2.c: ip callno count incremented to 4 for 192.168.5.16 [Jan 16 11:05:50] DEBUG[12907] ari/ari_websockets.c: WebSocket closed [Jan 16 11:05:50] VERBOSE[12907] stasis/app.c: Deactivating Stasis app 'AriStart' [Jan 16 11:05:50] VERBOSE[12907] res_http_websocket.c: WebSocket connection from '192.168.0.67:59737' closed [Jan 16 11:05:55] DEBUG[12876] chan_iax2.c: schedule decrement of callno used for 192.168.5.16 in 60 seconds [Jan 16 11:05:56] DEBUG[12940] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 16 11:05:56] DEBUG[12938] threadpool.c: Worker thread idle timeout reached. Dying. [Jan 16 11:05:56] DEBUG[12823] threadpool.c: Destroying worker thread 20 [Jan 16 11:05:56] DEBUG[12823] threadpool.c: Destroying worker thread 19 [Jan 16 11:06:00] DEBUG[12865] chan_iax2.c: ip callno count decremented to 3 for 192.168.5.16 [Jan 16 11:06:05] DEBUG[12868] chan_iax2.c: ip callno count incremented to 4 for 192.168.5.16 [Jan 16 11:06:14] DEBUG[12871] chan_iax2.c: schedule decrement of callno used for 192.168.5.16 in 60 seconds [Jan 16 11:06:14] DEBUG[12887] res_pjsip_registrar_expire.c: Woke up at 1484561174 Interval: 30 [Jan 16 11:06:14] DEBUG[12887] res_pjsip_registrar_expire.c: Expiring 0 contacts