[Jan 30 16:44:03] Asterisk 11.7.0 built by sickpig @ suino on a x86_64 running Linux on 2014-01-30 15:09:43 UTC [Jan 30 16:44:03] DEBUG[6406] config.c: Parsing /etc/asterisk/logger.conf [Jan 30 16:44:03] VERBOSE[6406] config.c: == Parsing '/etc/asterisk/logger.conf': Found [Jan 30 16:44:03] VERBOSE[6406] logger.c: Asterisk Queue Logger restarted [Jan 30 16:44:22] DEBUG[6275] chan_sip.c: Allocating new SIP dialog for 6500f811498bd2486d877a70184e1d83@192.168.1.50:5060 - OPTIONS (No RTP) [Jan 30 16:44:22] DEBUG[6275] acl.c: For destination '80.xxx.xxx.xxx', our source address is '192.168.1.50'. [Jan 30 16:44:22] DEBUG[6275] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.1.50:5060 [Jan 30 16:44:22] DEBUG[6275] chan_sip.c: SIP call-id changed from '6500f811498bd2486d877a70184e1d83@192.168.1.50:5060' to '0801ab7573c8e59f707df6522c1d312b@192.168.1.50:5060' [Jan 30 16:44:22] DEBUG[6275] chan_sip.c: Initializing initreq for method OPTIONS - callid 0801ab7573c8e59f707df6522c1d312b@192.168.1.50:5060 [Jan 30 16:44:22] DEBUG[6275] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 80.xxx.xxx.xxx:5060 [Jan 30 16:44:22] DEBUG[6275] chan_sip.c: = Looking for Call ID: 0801ab7573c8e59f707df6522c1d312b@192.168.1.50:5060 (Checking To) --From tag as71049670 --To-tag as0d07e517 [Jan 30 16:44:22] DEBUG[6275] chan_sip.c: Stopping retransmission on '0801ab7573c8e59f707df6522c1d312b@192.168.1.50:5060' of Request 102: Match Found [Jan 30 16:44:22] DEBUG[6275] chan_sip.c: Destroying SIP dialog 0801ab7573c8e59f707df6522c1d312b@192.168.1.50:5060 [Jan 30 16:44:22] DEBUG[6279] chan_iax2.c: ip callno count decremented to 0 for 80.xxx.xxx.xxx [Jan 30 16:44:22] DEBUG[6282] chan_iax2.c: ip callno count incremented to 1 for 80.xxx.xxx.xxx [Jan 30 16:44:22] DEBUG[6283] chan_iax2.c: schedule decrement of callno used for 80.xxx.xxx.xxx in 60 seconds [Jan 30 16:44:22] DEBUG[6283] chan_iax2.c: Peer beffect-iax: got pong, lastms 42, historicms 42, maxms 500 [Jan 30 16:44:26] DEBUG[6431] http.c: HTTP Request URI is /ws [Jan 30 16:44:26] DEBUG[6431] http.c: match request [ws] with handler [httpstatus] len 0 [Jan 30 16:44:26] DEBUG[6431] http.c: match request [ws] with handler [phoneprov] len 10 [Jan 30 16:44:26] DEBUG[6431] http.c: match request [ws] with handler [static] len 9 [Jan 30 16:44:26] DEBUG[6431] http.c: match request [ws] with handler [ws] len 6 [Jan 30 16:44:26] VERBOSE[6431] res_http_websocket.c: == WebSocket connection from '192.168.1.50:50062' for protocol 'sip' accepted using version '13' [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: = Looking for Call ID: o5bihi5mtffe0pkmbk0pvh (Checking From) --From tag kephilbn83 --To-tag [Jan 30 16:44:26] DEBUG[6431] acl.c: For destination '192.168.1.50', our source address is '192.168.1.50'. [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: Setting SIP_TRANSPORT_WS with address 192.168.1.50:5060 [Jan 30 16:44:26] DEBUG[6431] netsock2.c: Splitting '192.0.2.233' into... [Jan 30 16:44:26] DEBUG[6431] netsock2.c: ...host '192.0.2.233' and port ''. [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: NAT detected for 192.0.2.233 / 192.168.1.50 [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: Allocating new SIP dialog for o5bihi5mtffe0pkmbk0pvh - REGISTER (No RTP) [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jan 30 16:44:26] DEBUG[6431] netsock2.c: Splitting '192.0.2.233' into... [Jan 30 16:44:26] DEBUG[6431] netsock2.c: ...host '192.0.2.233' and port ''. [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: NAT detected for 192.0.2.233 / 192.168.1.50 [Jan 30 16:44:26] DEBUG[6431] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:26] DEBUG[6431] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:26] DEBUG[6431] res_config_pgsql.c: PostgreSQL query attempt 1 [Jan 30 16:44:26] DEBUG[6431] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM voip.sip_users WHERE name = 'webrtc_form_demetra_10_326_1391096474' AND host = 'dynamic' [Jan 30 16:44:26] DEBUG[6431] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f81c000eb30 Query: SELECT * FROM voip.sip_users WHERE name = 'webrtc_form_demetra_10_326_1391096474' AND host = 'dynamic' [Jan 30 16:44:26] DEBUG[6431] res_config_pgsql.c: PostgreSQL RealTime: Found 1 rows. [Jan 30 16:44:26] DEBUG[6431] netsock2.c: Splitting '0.0.0.0' into... [Jan 30 16:44:26] DEBUG[6431] netsock2.c: ...host '0.0.0.0' and port ''. [Jan 30 16:44:26] DEBUG[6431] netsock2.c: Splitting '0.0.0.0' into... [Jan 30 16:44:26] DEBUG[6431] netsock2.c: ...host '0.0.0.0' and port ''. [Jan 30 16:44:26] DEBUG[6431] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 1 appended to ACL [Jan 30 16:44:26] DEBUG[6431] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:26] DEBUG[6431] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port. [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port. [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: Allocating new SIP dialog for 1e88f4fe503b88c871ccd627196334bd@192.168.1.50:5060 - OPTIONS (No RTP) [Jan 30 16:44:26] DEBUG[6431] acl.c: For destination '192.168.1.50', our source address is '192.168.1.50'. [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.1.50:5060 [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: SIP call-id changed from '1e88f4fe503b88c871ccd627196334bd@192.168.1.50:5060' to '474d7cea43a1ef7f37d6d59a62f0a3ce@192.168.1.50:5060' [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: Initializing initreq for method OPTIONS - callid 474d7cea43a1ef7f37d6d59a62f0a3ce@192.168.1.50:5060 [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.1.50:49948 [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: -REALTIME- loading peer from database to memory. Name: webrtc_form_demetra_10_326_1391096474. Peer objects: 0 [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: Trying to put 'SIP/2.0 401' onto WS socket destined for 192.168.1.50:50062 [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: = Looking for Call ID: o5bihi5mtffe0pkmbk0pvh (Checking From) --From tag kephilbn83 --To-tag [Jan 30 16:44:26] DEBUG[6431] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:26] DEBUG[6431] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:26] DEBUG[6431] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:26] DEBUG[6431] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jan 30 16:44:26] DEBUG[6431] netsock2.c: Splitting '192.0.2.233' into... [Jan 30 16:44:26] DEBUG[6431] netsock2.c: ...host '192.0.2.233' and port ''. [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: NAT detected for 192.0.2.233 / 192.168.1.50 [Jan 30 16:44:26] DEBUG[6431] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:26] DEBUG[6431] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: peer 'webrtc_form_demetra_10_326_1391096474' has contacted us over WS even though we prefer UDP. [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: Store REGISTER's src-IP:port for call routing. [Jan 30 16:44:26] VERBOSE[6431] chan_sip.c: -- Registered SIP 'webrtc_form_demetra_10_326_1391096474' at 192.168.1.50:50062 [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: Destroying SIP dialog 474d7cea43a1ef7f37d6d59a62f0a3ce@192.168.1.50:5060 [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: Allocating new SIP dialog for 0ad7a7fe4e9816444373b9ae067a1e17@192.168.1.50:5060 - OPTIONS (No RTP) [Jan 30 16:44:26] DEBUG[6431] acl.c: For destination '192.168.1.50', our source address is '192.168.1.50'. [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: Setting SIP_TRANSPORT_WS with address 192.168.1.50:5060 [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: SIP call-id changed from '0ad7a7fe4e9816444373b9ae067a1e17@192.168.1.50:5060' to '015c390b13969e1109b3a4375b92b901@192.168.1.50:5060' [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: Initializing initreq for method OPTIONS - callid 015c390b13969e1109b3a4375b92b901@192.168.1.50:5060 [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: Trying to put 'OPTIONS sip' onto WS socket destined for 192.168.1.50:50062 [Jan 30 16:44:26] DEBUG[6431] res_config_pgsql.c: Found table in cache; now locking [Jan 30 16:44:26] DEBUG[6431] res_config_pgsql.c: Lock cached table; now returning [Jan 30 16:44:26] DEBUG[6431] res_config_pgsql.c: PostgreSQL RealTime: Update SQL: UPDATE voip.sip_users SET ipaddr = '192.168.1.50', port = '50062', regseconds = '1391097266', username = 'webrtc_form_demetra_10_326_1391096474', useragent = 'JsSIP 0.3.7', lastms = '56', fullcontact = 'sip:d3nn8pd1@192.0.2.233^3Btransport=ws' WHERE name = 'webrtc_form_demetra_10_326_1391096474' [Jan 30 16:44:26] DEBUG[6431] res_config_pgsql.c: PostgreSQL query attempt 1 [Jan 30 16:44:26] DEBUG[6431] res_config_pgsql.c: PostgreSQL query successful: UPDATE voip.sip_users SET ipaddr = '192.168.1.50', port = '50062', regseconds = '1391097266', username = 'webrtc_form_demetra_10_326_1391096474', useragent = 'JsSIP 0.3.7', lastms = '56', fullcontact = 'sip:d3nn8pd1@192.0.2.233^3Btransport=ws' WHERE name = 'webrtc_form_demetra_10_326_1391096474' [Jan 30 16:44:26] DEBUG[6431] res_config_pgsql.c: PostgreSQL RealTime: Updated 1 rows on table: voip.sip_users [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: Trying to put 'SIP/2.0 200' onto WS socket destined for 192.168.1.50:50062 [Jan 30 16:44:26] DEBUG[6263] devicestate.c: No provider found, checking channel drivers for SIP - webrtc_form_demetra_10_326_1391096474 [Jan 30 16:44:26] DEBUG[6263] chan_sip.c: Checking device state for peer webrtc_form_demetra_10_326_1391096474 [Jan 30 16:44:26] DEBUG[6263] devicestate.c: Changing state for SIP/webrtc_form_demetra_10_326_1391096474 - state 1 (Not in use) [Jan 30 16:44:26] DEBUG[6263] devicestate.c: device 'SIP/webrtc_form_demetra_10_326_1391096474' state '1' [Jan 30 16:44:26] DEBUG[6301] app_queue.c: Device 'SIP/webrtc_form_demetra_10_326_1391096474' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 30 16:44:26] DEBUG[6431] chan_sip.c: = Looking for Call ID: 015c390b13969e1109b3a4375b92b901@192.168.1.50:5060 (Checking To) --From tag as012734cc --To-tag n3g15ti9b5 [Jan 30 16:44:27] DEBUG[6275] chan_sip.c: Destroying SIP dialog 015c390b13969e1109b3a4375b92b901@192.168.1.50:5060 [Jan 30 16:44:28] DEBUG[6431] chan_sip.c: = Looking for Call ID: o5bihi5mtffe0pkmbk0pvh (Checking From) --From tag b1brv672mp --To-tag [Jan 30 16:44:28] DEBUG[6431] acl.c: For destination '192.168.1.50', our source address is '192.168.1.50'. [Jan 30 16:44:28] DEBUG[6431] chan_sip.c: Setting SIP_TRANSPORT_WS with address 192.168.1.50:5060 [Jan 30 16:44:28] DEBUG[6431] netsock2.c: Splitting '192.0.2.233' into... [Jan 30 16:44:28] DEBUG[6431] netsock2.c: ...host '192.0.2.233' and port ''. [Jan 30 16:44:28] DEBUG[6431] chan_sip.c: NAT detected for 192.0.2.233 / 192.168.1.50 [Jan 30 16:44:28] DEBUG[6431] chan_sip.c: Allocating new SIP dialog for o5bihi5mtffe0pkmbk0pvh - REGISTER (No RTP) [Jan 30 16:44:28] DEBUG[6431] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jan 30 16:44:28] DEBUG[6431] netsock2.c: Splitting '192.0.2.233' into... [Jan 30 16:44:28] DEBUG[6431] netsock2.c: ...host '192.0.2.233' and port ''. [Jan 30 16:44:28] DEBUG[6431] chan_sip.c: NAT detected for 192.0.2.233 / 192.168.1.50 [Jan 30 16:44:28] DEBUG[6431] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:28] DEBUG[6431] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:28] DEBUG[6431] chan_sip.c: Trying to put 'SIP/2.0 401' onto WS socket destined for 192.168.1.50:50062 [Jan 30 16:44:28] VERBOSE[6431] res_http_websocket.c: == WebSocket connection from '192.168.1.50:50062' closed [Jan 30 16:44:33] DEBUG[6460] http.c: HTTP Request URI is /ws [Jan 30 16:44:33] DEBUG[6460] http.c: match request [ws] with handler [httpstatus] len 0 [Jan 30 16:44:33] DEBUG[6460] http.c: match request [ws] with handler [phoneprov] len 10 [Jan 30 16:44:33] DEBUG[6460] http.c: match request [ws] with handler [static] len 9 [Jan 30 16:44:33] DEBUG[6460] http.c: match request [ws] with handler [ws] len 6 [Jan 30 16:44:33] VERBOSE[6460] res_http_websocket.c: == WebSocket connection from '192.168.1.50:50082' for protocol 'sip' accepted using version '13' [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: = Looking for Call ID: qioasfuo0k7jgm9sr3ls7a (Checking From) --From tag o0fpbh6m8f --To-tag [Jan 30 16:44:33] DEBUG[6460] acl.c: For destination '192.168.1.50', our source address is '192.168.1.50'. [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: Setting SIP_TRANSPORT_WS with address 192.168.1.50:5060 [Jan 30 16:44:33] DEBUG[6460] netsock2.c: Splitting '192.0.2.47' into... [Jan 30 16:44:33] DEBUG[6460] netsock2.c: ...host '192.0.2.47' and port ''. [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: NAT detected for 192.0.2.47 / 192.168.1.50 [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: Allocating new SIP dialog for qioasfuo0k7jgm9sr3ls7a - REGISTER (No RTP) [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jan 30 16:44:33] DEBUG[6460] netsock2.c: Splitting '192.0.2.47' into... [Jan 30 16:44:33] DEBUG[6460] netsock2.c: ...host '192.0.2.47' and port ''. [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: NAT detected for 192.0.2.47 / 192.168.1.50 [Jan 30 16:44:33] DEBUG[6460] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:33] DEBUG[6460] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:33] DEBUG[6460] res_config_pgsql.c: PostgreSQL query attempt 1 [Jan 30 16:44:33] DEBUG[6460] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM voip.sip_users WHERE name = 'webrtc_form_demetra_10_326_1391096671' AND host = 'dynamic' [Jan 30 16:44:33] DEBUG[6460] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f81c002e790 Query: SELECT * FROM voip.sip_users WHERE name = 'webrtc_form_demetra_10_326_1391096671' AND host = 'dynamic' [Jan 30 16:44:33] DEBUG[6460] res_config_pgsql.c: PostgreSQL RealTime: Found 1 rows. [Jan 30 16:44:33] DEBUG[6460] netsock2.c: Splitting '0.0.0.0' into... [Jan 30 16:44:33] DEBUG[6460] netsock2.c: ...host '0.0.0.0' and port ''. [Jan 30 16:44:33] DEBUG[6460] netsock2.c: Splitting '0.0.0.0' into... [Jan 30 16:44:33] DEBUG[6460] netsock2.c: ...host '0.0.0.0' and port ''. [Jan 30 16:44:33] DEBUG[6460] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 1 appended to ACL [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port. [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port. [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port. [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port. [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port. [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: Bah, we're expired (1391096673/0/1391096673)! [Jan 30 16:44:33] DEBUG[6460] db.c: Unable to find key 'webrtc_form_demetra_10_326_1391096671' in family 'SIP/Registry' [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: -REALTIME- loading peer from database to memory. Name: webrtc_form_demetra_10_326_1391096671. Peer objects: 0 [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: Trying to put 'SIP/2.0 401' onto WS socket destined for 192.168.1.50:50082 [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: = Looking for Call ID: qioasfuo0k7jgm9sr3ls7a (Checking From) --From tag o0fpbh6m8f --To-tag [Jan 30 16:44:33] DEBUG[6460] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:33] DEBUG[6460] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:33] DEBUG[6460] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:33] DEBUG[6460] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jan 30 16:44:33] DEBUG[6460] netsock2.c: Splitting '192.0.2.47' into... [Jan 30 16:44:33] DEBUG[6460] netsock2.c: ...host '192.0.2.47' and port ''. [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: NAT detected for 192.0.2.47 / 192.168.1.50 [Jan 30 16:44:33] DEBUG[6460] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:33] DEBUG[6460] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: peer 'webrtc_form_demetra_10_326_1391096671' has contacted us over WS even though we prefer UDP. [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: Store REGISTER's src-IP:port for call routing. [Jan 30 16:44:33] VERBOSE[6460] chan_sip.c: -- Registered SIP 'webrtc_form_demetra_10_326_1391096671' at 192.168.1.50:50082 [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: Allocating new SIP dialog for 00b4bcb1538f1a0a079f9402523b9513@192.168.1.50:5060 - OPTIONS (No RTP) [Jan 30 16:44:33] DEBUG[6460] acl.c: For destination '192.168.1.50', our source address is '192.168.1.50'. [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: Setting SIP_TRANSPORT_WS with address 192.168.1.50:5060 [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: SIP call-id changed from '00b4bcb1538f1a0a079f9402523b9513@192.168.1.50:5060' to '0cbbfaee7f327e666cebf92b39ffcd1f@192.168.1.50:5060' [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: Initializing initreq for method OPTIONS - callid 0cbbfaee7f327e666cebf92b39ffcd1f@192.168.1.50:5060 [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: Trying to put 'OPTIONS sip' onto WS socket destined for 192.168.1.50:50082 [Jan 30 16:44:33] DEBUG[6460] res_config_pgsql.c: Found table in cache; now locking [Jan 30 16:44:33] DEBUG[6460] res_config_pgsql.c: Lock cached table; now returning [Jan 30 16:44:33] DEBUG[6460] res_config_pgsql.c: PostgreSQL RealTime: Update SQL: UPDATE voip.sip_users SET ipaddr = '192.168.1.50', port = '50082', regseconds = '1391097273', username = 'webrtc_form_demetra_10_326_1391096671', useragent = 'JsSIP 0.3.7', lastms = '-1', fullcontact = 'sip:bjpfe1sm@192.0.2.47^3Btransport=ws' WHERE name = 'webrtc_form_demetra_10_326_1391096671' [Jan 30 16:44:33] DEBUG[6460] res_config_pgsql.c: PostgreSQL query attempt 1 [Jan 30 16:44:33] DEBUG[6460] res_config_pgsql.c: PostgreSQL query successful: UPDATE voip.sip_users SET ipaddr = '192.168.1.50', port = '50082', regseconds = '1391097273', username = 'webrtc_form_demetra_10_326_1391096671', useragent = 'JsSIP 0.3.7', lastms = '-1', fullcontact = 'sip:bjpfe1sm@192.0.2.47^3Btransport=ws' WHERE name = 'webrtc_form_demetra_10_326_1391096671' [Jan 30 16:44:33] DEBUG[6460] res_config_pgsql.c: PostgreSQL RealTime: Updated 1 rows on table: voip.sip_users [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: Trying to put 'SIP/2.0 200' onto WS socket destined for 192.168.1.50:50082 [Jan 30 16:44:33] DEBUG[6263] devicestate.c: No provider found, checking channel drivers for SIP - webrtc_form_demetra_10_326_1391096671 [Jan 30 16:44:33] DEBUG[6263] chan_sip.c: Checking device state for peer webrtc_form_demetra_10_326_1391096671 [Jan 30 16:44:33] DEBUG[6263] devicestate.c: Changing state for SIP/webrtc_form_demetra_10_326_1391096671 - state 5 (Unavailable) [Jan 30 16:44:33] DEBUG[6263] devicestate.c: device 'SIP/webrtc_form_demetra_10_326_1391096671' state '5' [Jan 30 16:44:33] DEBUG[6301] app_queue.c: Device 'SIP/webrtc_form_demetra_10_326_1391096671' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: = Looking for Call ID: 0cbbfaee7f327e666cebf92b39ffcd1f@192.168.1.50:5060 (Checking To) --From tag as6bf1bd67 --To-tag 73fplgibgf [Jan 30 16:44:33] NOTICE[6460] chan_sip.c: Peer 'webrtc_form_demetra_10_326_1391096671' is now Reachable. (53ms / 2000ms) [Jan 30 16:44:33] DEBUG[6263] devicestate.c: No provider found, checking channel drivers for SIP - webrtc_form_demetra_10_326_1391096671 [Jan 30 16:44:33] DEBUG[6263] chan_sip.c: Checking device state for peer webrtc_form_demetra_10_326_1391096671 [Jan 30 16:44:33] DEBUG[6263] devicestate.c: Changing state for SIP/webrtc_form_demetra_10_326_1391096671 - state 1 (Not in use) [Jan 30 16:44:33] DEBUG[6263] devicestate.c: device 'SIP/webrtc_form_demetra_10_326_1391096671' state '1' [Jan 30 16:44:33] DEBUG[6301] app_queue.c: Device 'SIP/webrtc_form_demetra_10_326_1391096671' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 30 16:44:33] DEBUG[6460] res_config_pgsql.c: Found table in cache; now locking [Jan 30 16:44:33] DEBUG[6460] res_config_pgsql.c: Lock cached table; now returning [Jan 30 16:44:33] DEBUG[6460] res_config_pgsql.c: PostgreSQL RealTime: Update SQL: UPDATE voip.sip_users SET lastms = '53' WHERE name = 'webrtc_form_demetra_10_326_1391096671' [Jan 30 16:44:33] DEBUG[6460] res_config_pgsql.c: PostgreSQL query attempt 1 [Jan 30 16:44:33] DEBUG[6460] res_config_pgsql.c: PostgreSQL query successful: UPDATE voip.sip_users SET lastms = '53' WHERE name = 'webrtc_form_demetra_10_326_1391096671' [Jan 30 16:44:33] DEBUG[6460] res_config_pgsql.c: PostgreSQL RealTime: Updated 1 rows on table: voip.sip_users [Jan 30 16:44:33] DEBUG[6462] manager.c: Running action 'Login' [Jan 30 16:44:33] VERBOSE[6462] manager.c: == Manager 'supervisor' logged on from 192.168.1.50 [Jan 30 16:44:33] DEBUG[6462] manager.c: Running action 'Originate' [Jan 30 16:44:33] DEBUG[6462] manager.c: Running action 'Logoff' [Jan 30 16:44:33] VERBOSE[6462] manager.c: == Manager 'supervisor' logged off from 192.168.1.50 [Jan 30 16:44:33] DEBUG[6463][C-00000000] chan_sip.c: Asked to create a SIP channel with formats: (slin) [Jan 30 16:44:33] DEBUG[6463][C-00000000] chan_sip.c: Allocating new SIP dialog for 2396d93a6e836f0639ca08a274a1c92c@192.168.1.50:5060 - INVITE (No RTP) [Jan 30 16:44:33] DEBUG[6463][C-00000000] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f81bc010698' [Jan 30 16:44:33] DEBUG[6463][C-00000000] res_rtp_asterisk.c: Allocated port 10274 for RTP instance '0x7f81bc010698' [Jan 30 16:44:33] DEBUG[6463][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:33] DEBUG[6463][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:33] DEBUG[6463][C-00000000] netsock2.c: Splitting '78.zzz.zzz.zzz' into... [Jan 30 16:44:33] DEBUG[6463][C-00000000] netsock2.c: ...host '78.zzz.zzz.zzz' and port ''. [Jan 30 16:44:33] DEBUG[6463][C-00000000] rtp_engine.c: RTP instance '0x7f81bc010698' is setup and ready to go [Jan 30 16:44:33] DEBUG[6463][C-00000000] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f81bc010698' [Jan 30 16:44:33] DEBUG[6463][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:33] DEBUG[6463][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:33] DEBUG[6463][C-00000000] netsock2.c: Splitting '78.zzz.zzz.zzz' into... [Jan 30 16:44:33] DEBUG[6463][C-00000000] netsock2.c: ...host '78.zzz.zzz.zzz' and port ''. [Jan 30 16:44:33] VERBOSE[6463][C-00000000] netsock2.c: == Using SIP RTP CoS mark 5 [Jan 30 16:44:33] DEBUG[6463][C-00000000] chan_sip.c: Setting NAT on RTP to Off [Jan 30 16:44:33] DEBUG[6463][C-00000000] acl.c: For destination '192.168.1.50', our source address is '192.168.1.50'. [Jan 30 16:44:33] DEBUG[6463][C-00000000] chan_sip.c: Setting SIP_TRANSPORT_WS with address 192.168.1.50:5060 [Jan 30 16:44:33] DEBUG[6463][C-00000000] netsock2.c: Splitting '192.0.2.47' into... [Jan 30 16:44:33] DEBUG[6463][C-00000000] netsock2.c: ...host '192.0.2.47' and port ''. [Jan 30 16:44:33] DEBUG[6463][C-00000000] chan_sip.c: NAT detected for 192.0.2.47 / 192.168.1.50 [Jan 30 16:44:33] DEBUG[6463][C-00000000] chan_sip.c: Setting NAT on RTP to Off [Jan 30 16:44:33] DEBUG[6463][C-00000000] chan_sip.c: SIP call-id changed from '2396d93a6e836f0639ca08a274a1c92c@192.168.1.50:5060' to '492b844645f010f36fc25e100357dfd2@192.168.1.50:5060' [Jan 30 16:44:33] DEBUG[6463][C-00000000] chan_sip.c: *** Our native formats are (ulaw) [Jan 30 16:44:33] DEBUG[6463][C-00000000] chan_sip.c: *** Joint capabilities are (nothing) [Jan 30 16:44:33] DEBUG[6463][C-00000000] chan_sip.c: *** Our capabilities are (ulaw|alaw) [Jan 30 16:44:33] DEBUG[6463][C-00000000] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Jan 30 16:44:33] DEBUG[6463][C-00000000] chan_sip.c: *** Our preferred formats from the incoming channel are (slin) [Jan 30 16:44:33] DEBUG[6463][C-00000000] chan_sip.c: This channel will not be able to handle video. [Jan 30 16:44:33] DEBUG[6463][C-00000000] chan_sip.c: Outgoing Call for webrtc_form_demetra_10_326_1391096671 [Jan 30 16:44:33] DEBUG[6463][C-00000000] chan_sip.c: Updating call counter for outgoing call [Jan 30 16:44:33] DEBUG[6275] chan_sip.c: Destroying SIP dialog 0cbbfaee7f327e666cebf92b39ffcd1f@192.168.1.50:5060 [Jan 30 16:44:33] DEBUG[6463][C-00000000] chan_sip.c: ** Our capability: (ulaw|alaw) Video flag: False Text flag: False [Jan 30 16:44:33] DEBUG[6463][C-00000000] chan_sip.c: ** Our prefcodec: (slin) [Jan 30 16:44:33] DEBUG[6463][C-00000000] sip/sdp_crypto.c: local_key64 G/87QLKiC0uOEPqiMB13C/0pvoprtD2YXiVAehp0 len 40 [Jan 30 16:44:33] DEBUG[6463][C-00000000] sip/sdp_crypto.c: Crypto line: a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:G/87QLKiC0uOEPqiMB13C/0pvoprtD2YXiVAehp0 [Jan 30 16:44:33] DEBUG[6463][C-00000000] chan_sip.c: -- Done with adding codecs to SDP [Jan 30 16:44:33] DEBUG[6463][C-00000000] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|alaw) [Jan 30 16:44:33] DEBUG[6463][C-00000000] chan_sip.c: Initializing initreq for method INVITE - callid 492b844645f010f36fc25e100357dfd2@192.168.1.50:5060 [Jan 30 16:44:33] DEBUG[6463][C-00000000] chan_sip.c: Trying to put 'INVITE sip:' onto WS socket destined for 192.168.1.50:50082 [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: = Looking for Call ID: 492b844645f010f36fc25e100357dfd2@192.168.1.50:5060 (Checking To) --From tag as24dc56c6 --To-tag [Jan 30 16:44:33] DEBUG[6460][C-00000000] chan_sip.c: SIP response 100 to standard invite [Jan 30 16:44:33] DEBUG[6460] chan_sip.c: = Looking for Call ID: 492b844645f010f36fc25e100357dfd2@192.168.1.50:5060 (Checking To) --From tag as24dc56c6 --To-tag nkqsjeh35r [Jan 30 16:44:33] DEBUG[6460][C-00000000] chan_sip.c: SIP response 180 to standard invite [Jan 30 16:44:33] DEBUG[6460][C-00000000] chan_sip.c: build_route: Contact hop: [Jan 30 16:44:33] DEBUG[6263] devicestate.c: No provider found, checking channel drivers for SIP - webrtc_form_demetra_10_326_1391096671 [Jan 30 16:44:33] DEBUG[6263] chan_sip.c: Checking device state for peer webrtc_form_demetra_10_326_1391096671 [Jan 30 16:44:33] DEBUG[6263] devicestate.c: Changing state for SIP/webrtc_form_demetra_10_326_1391096671 - state 1 (Not in use) [Jan 30 16:44:33] DEBUG[6263] devicestate.c: device 'SIP/webrtc_form_demetra_10_326_1391096671' state '1' [Jan 30 16:44:33] DEBUG[6301] app_queue.c: Device 'SIP/webrtc_form_demetra_10_326_1391096671' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 30 16:44:34] DEBUG[6460] chan_sip.c: = Looking for Call ID: 492b844645f010f36fc25e100357dfd2@192.168.1.50:5060 (Checking To) --From tag as24dc56c6 --To-tag nkqsjeh35r [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: SIP response 200 to standard invite [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing session-level SDP o=- 3922340859551709219 2 IN IP4 127.0.0.1... OK. [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED OR FAILED. [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing session-level SDP a=msid-semantic: WMS NYdcd2u8T2omehzDKc838Kx1phMwxXWFNaL8... UNSUPPORTED OR FAILED. [Jan 30 16:44:34] DEBUG[6460][C-00000000] rtp_engine.c: Setting payload 0 based on m type on 0x7f81ab6b9990 [Jan 30 16:44:34] DEBUG[6460][C-00000000] rtp_engine.c: Setting payload 8 based on m type on 0x7f81ab6b9990 [Jan 30 16:44:34] DEBUG[6460][C-00000000] rtp_engine.c: Setting payload 101 based on m type on 0x7f81ab6b9990 [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: Splitting '78.zzz.zzz.zzz' into... [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: ...host '78.zzz.zzz.zzz' and port ''. [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 78.zzz.zzz.zzz... OK. [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtcp:58986 IN IP4 78.zzz.zzz.zzz... UNSUPPORTED OR FAILED. [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: Splitting '0' into... [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: ...host '0' and port ''. [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=candidate:109713448 1 udp 2113937151 192.168.1.50 56813 typ host generation 0... OK. [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: Splitting '0' into... [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: ...host '0' and port ''. [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=candidate:109713448 2 udp 2113937150 192.168.1.50 58986 typ host generation 0... OK. [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: Splitting '78.zzz.zzz.zzz' into... [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: ...host '78.zzz.zzz.zzz' and port ''. [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=candidate:4036649468 1 udp 1845501695 78.zzz.zzz.zzz 56813 typ srflx raddr 192.168.1.50 rport 56813 generation 0... OK. [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: Splitting '78.zzz.zzz.zzz' into... [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: ...host '78.zzz.zzz.zzz' and port ''. [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=candidate:4036649468 2 udp 1845501694 78.zzz.zzz.zzz 58986 typ srflx raddr 192.168.1.50 rport 58986 generation 0... OK. [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: Splitting '0' into... [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: ...host '0' and port ''. [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=candidate:1208607960 1 tcp 1509957375 192.168.1.50 0 typ host generation 0... OK. [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: Splitting '0' into... [Jan 30 16:44:34] DEBUG[6460][C-00000000] netsock2.c: ...host '0' and port ''. [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=candidate:1208607960 2 tcp 1509957374 192.168.1.50 0 typ host generation 0... OK. [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=ice-ufrag:j3wbh5Zft9xmj3/Z... OK. [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=ice-pwd:coku0UTV7Mq07DZ587Z4JHhc... OK. [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=mid:audio... UNSUPPORTED OR FAILED. [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jan 30 16:44:34] DEBUG[6460][C-00000000] res_srtp.c: Adding new policy for SSRC 1532408738 [Jan 30 16:44:34] DEBUG[6460][C-00000000] sip/sdp_crypto.c: SRTP policy activated [Jan 30 16:44:34] DEBUG[6460][C-00000000] sip/sdp_crypto.c: Accepting crypto tag 1 [Jan 30 16:44:34] DEBUG[6460][C-00000000] sip/sdp_crypto.c: Crypto line: a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:G/87QLKiC0uOEPqiMB13C/0pvoprtD2YXiVAehp0 [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:w/LrXWDM6x9cq48/3okklrjaiysG+pEOzKZYxMx4... OK. [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=ssrc:1419044636 cname:cMwG2nPHv+Cr4FPU... UNSUPPORTED OR FAILED. [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=ssrc:1419044636 msid:NYdcd2u8T2omehzDKc838Kx1phMwxXWFNaL8 NYdcd2u8T2omehzDKc838Kx1phMwxXWFNaL8a0... UNSUPPORTED OR FAILED. [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=ssrc:1419044636 mslabel:NYdcd2u8T2omehzDKc838Kx1phMwxXWFNaL8... UNSUPPORTED OR FAILED. [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=ssrc:1419044636 label:NYdcd2u8T2omehzDKc838Kx1phMwxXWFNaL8a0... UNSUPPORTED OR FAILED. [Jan 30 16:44:34] DEBUG[6460][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f81bc010698' [Jan 30 16:44:34] DEBUG[6460][C-00000000] rtp_engine.c: Copying payload 0 from 0x7f81ab6b9990 to 0x7f81bc010860 [Jan 30 16:44:34] DEBUG[6460][C-00000000] rtp_engine.c: Copying payload 8 from 0x7f81ab6b9990 to 0x7f81bc010860 [Jan 30 16:44:34] DEBUG[6460][C-00000000] rtp_engine.c: Copying payload 101 from 0x7f81ab6b9990 to 0x7f81bc010860 [Jan 30 16:44:34] DEBUG[6460][C-00000000] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f81bc010698' [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: We're settling with these formats: (ulaw|alaw) [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: We have an owner, now see if we need to change this call [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Updating call counter for outgoing call [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: build_route: Contact hop: [Jan 30 16:44:34] DEBUG[6460][C-00000000] chan_sip.c: Trying to put 'ACK sip:bjp' onto WS socket destined for 192.168.1.50:50082 [Jan 30 16:44:34] DEBUG[6263] devicestate.c: No provider found, checking channel drivers for SIP - webrtc_form_demetra_10_326_1391096671 [Jan 30 16:44:34] DEBUG[6263] chan_sip.c: Checking device state for peer webrtc_form_demetra_10_326_1391096671 [Jan 30 16:44:34] DEBUG[6263] devicestate.c: Changing state for SIP/webrtc_form_demetra_10_326_1391096671 - state 1 (Not in use) [Jan 30 16:44:34] DEBUG[6263] devicestate.c: device 'SIP/webrtc_form_demetra_10_326_1391096671' state '1' [Jan 30 16:44:34] DEBUG[6301] app_queue.c: Device 'SIP/webrtc_form_demetra_10_326_1391096671' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Evaluating 'EXTEN:1' (from 'EXTEN:1}' len 7) [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Result of 'EXTEN' is '93289738232_6305022' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Function result is '6305022' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Launching 'Set' [Jan 30 16:44:34] VERBOSE[6464][C-00000000] pbx.c: -- Executing [93289738232_6305022@iaxtest:1] Set("SIP/webrtc_form_demetra_10_326_1391096671-00000000", "__session=6305022") in new stack [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Evaluating 'EXTEN:1' (from 'EXTEN:1}' len 7) [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Result of 'EXTEN' is '93289738232_6305022' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Function result is '3289738232' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Launching 'Set' [Jan 30 16:44:34] VERBOSE[6464][C-00000000] pbx.c: -- Executing [93289738232_6305022@iaxtest:2] Set("SIP/webrtc_form_demetra_10_326_1391096671-00000000", "__numero=3289738232") in new stack [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Result of 'EXTEN' is '93289738232_6305022' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Launching 'Set' [Jan 30 16:44:34] VERBOSE[6464][C-00000000] pbx.c: -- Executing [93289738232_6305022@iaxtest:3] Set("SIP/webrtc_form_demetra_10_326_1391096671-00000000", "__prefix=9") in new stack [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Result of 'EXTEN' is '93289738232_6305022' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Launching 'Macro' [Jan 30 16:44:34] VERBOSE[6464][C-00000000] pbx.c: -- Executing [93289738232_6305022@iaxtest:4] Macro("SIP/webrtc_form_demetra_10_326_1391096671-00000000", "choose-provider,9") in new stack [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Result of 'ARG1' is '9' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Launching 'NoOp' [Jan 30 16:44:34] VERBOSE[6464][C-00000000] pbx.c: -- Executing [s@macro-choose-provider:1] NoOp("SIP/webrtc_form_demetra_10_326_1391096671-00000000", "9") in new stack [Jan 30 16:44:34] DEBUG[6464][C-00000000] app_macro.c: Executed application: NoOp [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Result of 'ARG1' is '9' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Expression result is '1' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Result of 'VOIP_PROVIDER' is 'SIP/beffect-sip' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Function result is 'SIP/beffect-sip' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Launching 'Set' [Jan 30 16:44:34] VERBOSE[6464][C-00000000] pbx.c: -- Executing [s@macro-choose-provider:2] Set("SIP/webrtc_form_demetra_10_326_1391096671-00000000", "__PROVIDER=SIP/beffect-sip") in new stack [Jan 30 16:44:34] DEBUG[6464][C-00000000] app_macro.c: Executed application: Set [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Result of 'ARG1' is '9' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Expression result is '0' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Result of 'VOIP_PROVIDER2' is 'IAX2/beffect-iax' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Result of 'PROVIDER' is 'SIP/beffect-sip' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Function result is 'SIP/beffect-sip' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Launching 'Set' [Jan 30 16:44:34] VERBOSE[6464][C-00000000] pbx.c: -- Executing [s@macro-choose-provider:3] Set("SIP/webrtc_form_demetra_10_326_1391096671-00000000", "__PROVIDER=SIP/beffect-sip") in new stack [Jan 30 16:44:34] DEBUG[6464][C-00000000] app_macro.c: Executed application: Set [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Result of 'PROVIDER' is 'SIP/beffect-sip' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Launching 'NoOp' [Jan 30 16:44:34] VERBOSE[6464][C-00000000] pbx.c: -- Executing [93289738232_6305022@iaxtest:5] NoOp("SIP/webrtc_form_demetra_10_326_1391096671-00000000", "SIP/beffect-sip") in new stack [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Evaluating 'PROVIDER' (from 'PROVIDER}' len 8) [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Result of 'PROVIDER' is 'SIP/beffect-sip' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Function result is 'beffect-sip' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Launching 'Set' [Jan 30 16:44:34] VERBOSE[6464][C-00000000] pbx.c: -- Executing [93289738232_6305022@iaxtest:6] Set("SIP/webrtc_form_demetra_10_326_1391096671-00000000", "PROV_NOCHAN=beffect-sip") in new stack [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Evaluating 'PROVIDER' (from 'PROVIDER}' len 8) [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Result of 'PROVIDER' is 'SIP/beffect-sip' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Function result is 'SIP' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Launching 'Set' [Jan 30 16:44:34] VERBOSE[6464][C-00000000] pbx.c: -- Executing [93289738232_6305022@iaxtest:7] Set("SIP/webrtc_form_demetra_10_326_1391096671-00000000", "PROV_CHAN=SIP") in new stack [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Result of 'PROV_CHAN' is 'SIP' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Expression result is '0' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Launching 'GotoIf' [Jan 30 16:44:34] VERBOSE[6464][C-00000000] pbx.c: -- Executing [93289738232_6305022@iaxtest:8] GotoIf("SIP/webrtc_form_demetra_10_326_1391096671-00000000", "0?diax:dsip") in new stack [Jan 30 16:44:34] VERBOSE[6464][C-00000000] pbx.c: -- Goto (iaxtest,93289738232_6305022,11) [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Result of 'PROV_NOCHAN' is 'beffect-sip' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Evaluating 'SIPPEER(beffect-sip,status)' (from 'SIPPEER(beffect-sip,status)}' len 27) [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Function result is 'OK (40 ms)' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Function result is 'OK' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Expression result is '0' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Launching 'GotoIf' [Jan 30 16:44:34] VERBOSE[6464][C-00000000] pbx.c: -- Executing [93289738232_6305022@iaxtest:11] GotoIf("SIP/webrtc_form_demetra_10_326_1391096671-00000000", "0?stop-call,s,1") in new stack [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Not taking any branch [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Launching 'Goto' [Jan 30 16:44:34] VERBOSE[6464][C-00000000] pbx.c: -- Executing [93289738232_6305022@iaxtest:12] Goto("SIP/webrtc_form_demetra_10_326_1391096671-00000000", "goon") in new stack [Jan 30 16:44:34] VERBOSE[6464][C-00000000] pbx.c: -- Goto (iaxtest,93289738232_6305022,13) [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Launching 'SendText' [Jan 30 16:44:34] VERBOSE[6464][C-00000000] pbx.c: -- Executing [93289738232_6305022@iaxtest:13] SendText("SIP/webrtc_form_demetra_10_326_1391096671-00000000", "VOIP") in new stack [Jan 30 16:44:34] DEBUG[6464][C-00000000] chan_sip.c: Trying to put 'MESSAGE sip' onto WS socket destined for 192.168.1.50:50082 [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Result of 'session' is '6305022' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Launching 'Set' [Jan 30 16:44:34] VERBOSE[6464][C-00000000] pbx.c: -- Executing [93289738232_6305022@iaxtest:14] Set("SIP/webrtc_form_demetra_10_326_1391096671-00000000", "CHANNEL(userfield)=6305022") in new stack [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Result of 'PROVIDER' is 'SIP/beffect-sip' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Result of 'numero' is '3289738232' [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx.c: Launching 'Dial' [Jan 30 16:44:34] VERBOSE[6464][C-00000000] pbx.c: -- Executing [93289738232_6305022@iaxtest:15] Dial("SIP/webrtc_form_demetra_10_326_1391096671-00000000", "SIP/beffect-sip/3289738232,30,areG(mix_me^s^1)") in new stack [Jan 30 16:44:34] DEBUG[6464][C-00000000] chan_sip.c: Asked to create a SIP channel with formats: (ulaw) [Jan 30 16:44:34] DEBUG[6464][C-00000000] chan_sip.c: Allocating new SIP dialog for 7f5013460c66997b0c0a6ec82b341060@192.168.1.50:5060 - INVITE (No RTP) [Jan 30 16:44:34] DEBUG[6464][C-00000000] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f81bc031588' [Jan 30 16:44:34] DEBUG[6464][C-00000000] res_rtp_asterisk.c: Allocated port 15980 for RTP instance '0x7f81bc031588' [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: Splitting '78.zzz.zzz.zzz' into... [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: ...host '78.zzz.zzz.zzz' and port ''. [Jan 30 16:44:34] DEBUG[6464][C-00000000] rtp_engine.c: RTP instance '0x7f81bc031588' is setup and ready to go [Jan 30 16:44:34] DEBUG[6464][C-00000000] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f81bc031588' [Jan 30 16:44:34] VERBOSE[6464][C-00000000] netsock2.c: == Using SIP RTP CoS mark 5 [Jan 30 16:44:34] DEBUG[6464][C-00000000] chan_sip.c: Setting NAT on RTP to On [Jan 30 16:44:34] DEBUG[6464][C-00000000] acl.c: For destination '80.xxx.xxx.xxx', our source address is '192.168.1.50'. [Jan 30 16:44:34] DEBUG[6464][C-00000000] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.1.50:5060 [Jan 30 16:44:34] DEBUG[6464][C-00000000] chan_sip.c: Setting NAT on RTP to On [Jan 30 16:44:34] DEBUG[6464][C-00000000] chan_sip.c: SIP call-id changed from '7f5013460c66997b0c0a6ec82b341060@192.168.1.50:5060' to '7ff9c1805400555b71d4d4ac3ff6f309@192.168.1.50:5060' [Jan 30 16:44:34] DEBUG[6464][C-00000000] chan_sip.c: *** Our native formats are (gsm) [Jan 30 16:44:34] DEBUG[6464][C-00000000] chan_sip.c: *** Joint capabilities are (nothing) [Jan 30 16:44:34] DEBUG[6464][C-00000000] chan_sip.c: *** Our capabilities are (gsm) [Jan 30 16:44:34] DEBUG[6464][C-00000000] chan_sip.c: *** AST_CODEC_CHOOSE formats are gsm [Jan 30 16:44:34] DEBUG[6464][C-00000000] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) [Jan 30 16:44:34] DEBUG[6464][C-00000000] chan_sip.c: This channel will not be able to handle video. [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx_lua.c: Looking up @public:1 [Jan 30 16:44:34] DEBUG[6464][C-00000000] pbx_lua.c: Looking up @demo:1 [Jan 30 16:44:34] DEBUG[6464][C-00000000] channel_internal_api.c: Channel Call ID changing from [C-00000000] to [C-00000000] [Jan 30 16:44:34] DEBUG[6464][C-00000000] channel.c: Not copying variable DIALEDTIME. [Jan 30 16:44:34] DEBUG[6464][C-00000000] channel.c: Not copying variable ANSWEREDTIME. [Jan 30 16:44:34] DEBUG[6464][C-00000000] channel.c: Not copying variable DIALEDPEERNAME. [Jan 30 16:44:34] DEBUG[6464][C-00000000] channel.c: Not copying variable DIALEDPEERNUMBER. [Jan 30 16:44:34] DEBUG[6464][C-00000000] channel.c: Not copying variable DIALSTATUS. [Jan 30 16:44:34] DEBUG[6464][C-00000000] channel.c: Not copying variable SENDTEXTSTATUS. [Jan 30 16:44:34] DEBUG[6464][C-00000000] channel.c: Not copying variable PROV_CHAN. [Jan 30 16:44:34] DEBUG[6464][C-00000000] channel.c: Not copying variable PROV_NOCHAN. [Jan 30 16:44:34] DEBUG[6464][C-00000000] channel.c: Not copying variable MACRO_DEPTH. [Jan 30 16:44:34] DEBUG[6464][C-00000000] channel.c: Copying hard-transferable variable PROVIDER. [Jan 30 16:44:34] DEBUG[6464][C-00000000] channel.c: Copying hard-transferable variable prefix. [Jan 30 16:44:34] DEBUG[6464][C-00000000] channel.c: Copying hard-transferable variable numero. [Jan 30 16:44:34] DEBUG[6464][C-00000000] channel.c: Copying hard-transferable variable session. [Jan 30 16:44:34] DEBUG[6464][C-00000000] channel.c: Not copying variable SIPCALLID. [Jan 30 16:44:34] DEBUG[6464][C-00000000] chan_sip.c: Outgoing Call for 3289738232 [Jan 30 16:44:34] DEBUG[6464][C-00000000] chan_sip.c: Updating call counter for outgoing call [Jan 30 16:44:34] DEBUG[6464][C-00000000] chan_sip.c: ** Our capability: (gsm) Video flag: False Text flag: False [Jan 30 16:44:34] DEBUG[6464][C-00000000] chan_sip.c: ** Our prefcodec: (ulaw) [Jan 30 16:44:34] DEBUG[6464][C-00000000] chan_sip.c: -- Done with adding codecs to SDP [Jan 30 16:44:34] DEBUG[6464][C-00000000] chan_sip.c: Done building SDP. Settling with this capability: (gsm) [Jan 30 16:44:34] DEBUG[6464][C-00000000] chan_sip.c: Initializing initreq for method INVITE - callid 7ff9c1805400555b71d4d4ac3ff6f309@192.168.1.50:5060 [Jan 30 16:44:34] DEBUG[6464][C-00000000] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 80.xxx.xxx.xxx:5060 [Jan 30 16:44:34] VERBOSE[6464][C-00000000] app_dial.c: -- Called SIP/beffect-sip/3289738232 [Jan 30 16:44:34] DEBUG[6464][C-00000000] channel.c: Driver for channel 'SIP/webrtc_form_demetra_10_326_1391096671-00000000' does not support indication 3, emulating it [Jan 30 16:44:34] DEBUG[6464][C-00000000] channel.c: Set channel SIP/webrtc_form_demetra_10_326_1391096671-00000000 to write format slin [Jan 30 16:44:34] DEBUG[6464][C-00000000] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 30 16:44:34] DEBUG[6460] chan_sip.c: = Looking for Call ID: 492b844645f010f36fc25e100357dfd2@192.168.1.50:5060 (Checking To) --From tag as24dc56c6 --To-tag nkqsjeh35r [Jan 30 16:44:34] DEBUG[6464][C-00000000] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [Jan 30 16:44:34] DEBUG[6464][C-00000000] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [Jan 30 16:44:34] DEBUG[6464][C-00000000] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7f81bc010698' [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] VERBOSE[6464][C-00000000] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.50:56813 (via ICE) (type 00, seq 017842, ts 000160, len 4294967284) [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] VERBOSE[6464][C-00000000] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.50:56813 (via ICE) (type 00, seq 017843, ts 000320, len 4294967284) [Jan 30 16:44:34] DEBUG[6275] chan_sip.c: = Looking for Call ID: 7ff9c1805400555b71d4d4ac3ff6f309@192.168.1.50:5060 (Checking To) --From tag as08276227 --To-tag as45deda7b [Jan 30 16:44:34] DEBUG[6275][C-00000000] chan_sip.c: Acked pending invite 102 [Jan 30 16:44:34] DEBUG[6275][C-00000000] chan_sip.c: Stopping retransmission on '7ff9c1805400555b71d4d4ac3ff6f309@192.168.1.50:5060' of Request 102: Match Found [Jan 30 16:44:34] DEBUG[6275][C-00000000] chan_sip.c: SIP response 401 to standard invite [Jan 30 16:44:34] DEBUG[6275][C-00000000] chan_sip.c: Trying to put 'ACK sip:328' onto UDP socket destined for 80.xxx.xxx.xxx:5060 [Jan 30 16:44:34] DEBUG[6275][C-00000000] chan_sip.c: Auth attempt 1 on INVITE [Jan 30 16:44:34] DEBUG[6275][C-00000000] chan_sip.c: ** Our capability: (gsm) Video flag: False Text flag: False [Jan 30 16:44:34] DEBUG[6275][C-00000000] chan_sip.c: ** Our prefcodec: (ulaw) [Jan 30 16:44:34] DEBUG[6275][C-00000000] chan_sip.c: -- Done with adding codecs to SDP [Jan 30 16:44:34] DEBUG[6275][C-00000000] chan_sip.c: Done building SDP. Settling with this capability: (gsm) [Jan 30 16:44:34] DEBUG[6275][C-00000000] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 80.xxx.xxx.xxx:5060 [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] VERBOSE[6464][C-00000000] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.50:56813 (via ICE) (type 00, seq 017844, ts 000480, len 4294967284) [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] VERBOSE[6464][C-00000000] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.50:56813 (via ICE) (type 00, seq 017845, ts 000640, len 4294967284) [Jan 30 16:44:34] DEBUG[6275] chan_sip.c: = Looking for Call ID: 7ff9c1805400555b71d4d4ac3ff6f309@192.168.1.50:5060 (Checking To) --From tag as08276227 --To-tag [Jan 30 16:44:34] DEBUG[6275][C-00000000] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '7ff9c1805400555b71d4d4ac3ff6f309@192.168.1.50:5060' Request 103: Found [Jan 30 16:44:34] DEBUG[6275][C-00000000] chan_sip.c: SIP response 100 to standard invite [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] VERBOSE[6464][C-00000000] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.50:56813 (via ICE) (type 00, seq 017846, ts 000800, len 4294967284) [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] VERBOSE[6464][C-00000000] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.50:56813 (via ICE) (type 00, seq 017847, ts 000960, len 4294967284) [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] VERBOSE[6464][C-00000000] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.50:56813 (via ICE) (type 00, seq 017848, ts 001120, len 4294967284) [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] VERBOSE[6464][C-00000000] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.50:56813 (via ICE) (type 00, seq 017849, ts 001280, len 4294967284) [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] VERBOSE[6464][C-00000000] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.50:56813 (via ICE) (type 00, seq 017850, ts 001440, len 4294967284) [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] VERBOSE[6464][C-00000000] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.50:56813 (via ICE) (type 00, seq 017851, ts 001600, len 4294967284) [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] VERBOSE[6464][C-00000000] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.50:56813 (via ICE) (type 00, seq 017852, ts 001760, len 4294967284) [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] VERBOSE[6464][C-00000000] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.50:56813 (via ICE) (type 00, seq 017853, ts 001920, len 4294967284) [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] VERBOSE[6464][C-00000000] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.50:56813 (via ICE) (type 00, seq 017854, ts 002080, len 4294967284) [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] VERBOSE[6464][C-00000000] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.50:56813 (via ICE) (type 00, seq 017855, ts 002240, len 4294967284) [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] VERBOSE[6464][C-00000000] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.50:56813 (via ICE) (type 00, seq 017856, ts 002400, len 4294967284) [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] VERBOSE[6464][C-00000000] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.50:56813 (via ICE) (type 00, seq 017857, ts 002560, len 4294967284) [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] VERBOSE[6464][C-00000000] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.50:56813 (via ICE) (type 00, seq 017858, ts 002720, len 4294967284) [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] VERBOSE[6464][C-00000000] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.50:56813 (via ICE) (type 00, seq 017859, ts 002880, len 4294967284) [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] VERBOSE[6464][C-00000000] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.50:56813 (via ICE) (type 00, seq 017860, ts 003040, len 4294967284) [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: Splitting '192.168.1.50' into... [Jan 30 16:44:34] DEBUG[6464][C-00000000] netsock2.c: ...host '192.168.1.50' and port ''. [Jan 30 16:44:34] VERBOSE[6464][C-00000000] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.50:56813 (via ICE) (type 00, seq 017861, ts 003200, len 4294967284)