[Dec 25 14:05:02] DEBUG[22673]: acl.c:992 ast_ouraddrfor: For destination '192.168.0.33', our source address is '185.88.6.121'. [Dec 25 14:05:02] DEBUG[22673]: chan_sip.c:3908 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 185.88.6.121:5060 [Dec 25 14:05:02] DEBUG[22673]: chan_sip.c:9014 __sip_alloc: Allocating new SIP dialog for lqhcmdvcmbrowdtaijdweosfmbvptfjgcpkwybekhsxlrjkgco - INVITE (No RTP) [Dec 25 14:05:02] DEBUG[22673][C-00000000]: res_odbc.c:982 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f0c60001038 from class 'pbxconf1' [Dec 25 14:05:02] DEBUG[22673][C-00000000]: res_config_odbc.c:117 custom_prepare: Skip: 0; SQL: SELECT * FROM sip_users WHERE name = ? AND host = ? [Dec 25 14:05:02] DEBUG[22673][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 1 ('name') = '321' [Dec 25 14:05:02] DEBUG[22673][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 2 ('host') = 'dynamic' [Dec 25 14:05:02] DEBUG[22673][C-00000000]: res_odbc.c:825 ast_odbc_release_obj: Releasing ODBC handle 0x7f0c60001038 into pool [Dec 25 14:05:02] DEBUG[22673][C-00000000]: res_odbc.c:982 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f0c60001038 from class 'pbxconf1' [Dec 25 14:05:02] DEBUG[22673][C-00000000]: res_config_odbc.c:117 custom_prepare: Skip: 0; SQL: SELECT * FROM sip_users WHERE name = ? [Dec 25 14:05:02] DEBUG[22673][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 1 ('name') = '321' [Dec 25 14:05:02] DEBUG[22673][C-00000000]: res_odbc.c:825 ast_odbc_release_obj: Releasing ODBC handle 0x7f0c60001038 into pool [Dec 25 14:05:02] DEBUG[22673][C-00000000]: stasis.c:460 stasis_topic_create: Topic 'endpoint:SIP/321': 0x7f0c90006628 created [Dec 25 14:05:02] DEBUG[22673][C-00000000]: stasis.c:460 stasis_topic_create: Topic 'cache:10/endpoint:SIP/321': 0x7f0c90004828 created [Dec 25 14:05:02] DEBUG[22644]: threadpool.c:536 grow: Increasing threadpool stasis/pool's size by 1 [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:31969 build_peer: Not an IPv4 nor IPv6 address, cannot get port. [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:31972 build_peer: Not an IPv4 nor IPv6 address, cannot set port. [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:5662 realtime_peer: -REALTIME- loading peer from database to memory. Name: 321. Peer objects: 0 [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:3751 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.0.33:10033 [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:4535 __sip_ack: Stopping retransmission on 'lqhcmdvcmbrowdtaijdweosfmbvptfjgcpkwybekhsxlrjkgco' of Response 1: Match Found [Dec 25 14:05:02] DEBUG[22673][C-00000000]: rtp_engine.c:459 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f0c900308f8' [Dec 25 14:05:02] DEBUG[22673][C-00000000]: res_rtp_asterisk.c:3202 ast_rtp_new: Allocated port 16972 for RTP instance '0x7f0c900308f8' [Dec 25 14:05:02] DEBUG[22673][C-00000000]: rtp_engine.c:476 ast_rtp_instance_new: RTP instance '0x7f0c900308f8' is setup and ready to go [Dec 25 14:05:02] DEBUG[22673][C-00000000]: acl.c:830 resolve_first: Multiple addresses. Using the first only [Dec 25 14:05:02] DEBUG[22673][C-00000000]: res_rtp_asterisk.c:5987 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f0c900308f8' == Using SIP RTP CoS mark 5 [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:5797 do_setnat: Setting NAT on RTP to On [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:10337 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:10337 process_sdp: Processing session-level SDP o=- 18540999 18541000 IN IP4 192.168.0.33... OK. [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:10337 process_sdp: Processing session-level SDP s=Netsipp-v1.0.3.2 call v1.9.2... UNSUPPORTED OR FAILED. [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:10337 process_sdp: Processing session-level SDP c=IN IP4 192.168.0.33... OK. [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:10337 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Dec 25 14:05:02] DEBUG[22673][C-00000000]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7f0cac0c7140 [Dec 25 14:05:02] DEBUG[22673][C-00000000]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7f0cac0c7140 [Dec 25 14:05:02] DEBUG[22673][C-00000000]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 9 based on m type on 0x7f0cac0c7140 [Dec 25 14:05:02] DEBUG[22673][C-00000000]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 18 based on m type on 0x7f0cac0c7140 [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=fmtp:9 bitrate=64000... OK. [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=fmtp:18 annexb=no... OK. [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK. [Dec 25 14:05:02] DEBUG[22673][C-00000000]: acl.c:992 ast_ouraddrfor: For destination '192.168.0.33', our source address is '185.88.6.121'. [Dec 25 14:05:02] DEBUG[22673][C-00000000]: res_rtp_asterisk.c:6052 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f0c900308f8' [Dec 25 14:05:02] DEBUG[22673][C-00000000]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 0 (0x7f0c90020fc0) from 0x7f0cac0c7140 to 0x7f0c90030ac0 [Dec 25 14:05:02] DEBUG[22673][C-00000000]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7f0c9001e810) from 0x7f0cac0c7140 to 0x7f0c90030ac0 [Dec 25 14:05:02] DEBUG[22673][C-00000000]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 9 (0x7f0c90006590) from 0x7f0cac0c7140 to 0x7f0c90030ac0 [Dec 25 14:05:02] DEBUG[22673][C-00000000]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 18 (0x7f0c9001f4d0) from 0x7f0cac0c7140 to 0x7f0c90030ac0 [Dec 25 14:05:02] DEBUG[22673][C-00000000]: res_rtp_asterisk.c:5886 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f0c900308f8' [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:11098 process_sdp: We're settling with these formats: (g729|ulaw|alaw) [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:26424 handle_request_invite: Checking SIP call limits for device 321 [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:6766 update_call_counter: Updating call counter for incoming call [Dec 25 14:05:02] DEBUG[22673][C-00000000]: stasis.c:460 stasis_topic_create: Topic 'channel:1577271902.0': 0x7f0c900208b8 created [Dec 25 14:05:02] DEBUG[22656]: chan_sip.c:30388 sip_devicestate: Checking device state for peer 321 [Dec 25 14:05:02] DEBUG[22673][C-00000000]: stasis.c:460 stasis_topic_create: Topic 'cache:11/channel:1577271902.0': 0x7f0c90020968 created [Dec 25 14:05:02] DEBUG[22656]: devicestate.c:474 do_state_change: Changing state for SIP/321 - state 2 (In use) [Dec 25 14:05:02] DEBUG[22656]: stasis.c:460 stasis_topic_create: Topic 'devicestate:all/SIP/321': 0x7f0d00001438 created [Dec 25 14:05:02] DEBUG[22685]: app_queue.c:2489 device_state_cb: Device 'SIP/321' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 25 14:05:02] DEBUG[22673][C-00000000]: channel.c:1005 __ast_channel_alloc_ap: Channel 0x7f0c9000b7a8 'SIP/321-00000000' allocated [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:8163 sip_new: *** Our native formats are (g729) [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:8164 sip_new: *** Joint capabilities are (g729|ulaw|alaw) [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:8165 sip_new: *** Our capabilities are (g729|ulaw|alaw) [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:8166 sip_new: *** AST_CODEC_CHOOSE formats are g729 [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:8199 sip_new: This channel will not be able to handle video. [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:26629 handle_request_invite: SIP/321-00000000: New call is still down.... Trying... [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:3751 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.0.33:10033 [Dec 25 14:05:02] DEBUG[22656]: chan_sip.c:30388 sip_devicestate: Checking device state for peer 321 [Dec 25 14:05:02] DEBUG[22656]: devicestate.c:474 do_state_change: Changing state for SIP/321 - state 2 (In use) [Dec 25 14:05:02] DEBUG[22734][C-00000000]: pbx.c:2878 pbx_extension_helper: Launching 'Queue' -- Executing [999@dahiliara:1] Queue("SIP/321-00000000", "example_queue") in new stack [Dec 25 14:05:02] DEBUG[22734][C-00000000]: app_queue.c:7951 queue_exec: queue: example_queue, options: , url: , announce: , timeout: , agi: , macro: , gosub: , rule: , position: [Dec 25 14:05:02] DEBUG[22734][C-00000000]: app_queue.c:7981 queue_exec: NO QUEUE_PRIO variable found. Using default. [Dec 25 14:05:02] DEBUG[22734][C-00000000]: app_queue.c:8033 queue_exec: queue: example_queue, expires: 0, priority: 0 [Dec 25 14:05:02] DEBUG[22734][C-00000000]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update [Dec 25 14:05:02] DEBUG[22734][C-00000000]: stasis.c:460 stasis_topic_create: Topic 'devicestate:all/Queue:example_queue': 0x7f0d20000d98 created [Dec 25 14:05:02] DEBUG[22734][C-00000000]: app_queue.c:3762 join_queue: Queue 'example_queue' Join, Channel 'SIP/321-00000000', Position '1' [Dec 25 14:05:02] DEBUG[22685]: app_queue.c:2489 device_state_cb: Device 'Queue:example_queue' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_odbc.c:982 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f0c601ac018 from class 'proxysql' [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_odbc.c:332 ast_odbc_find_table: Found id column with type 4 with len 10, octetlen 10, and numlen (0,10) [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_odbc.c:332 ast_odbc_find_table: Found time column with type 12 with len 26, octetlen 26, and numlen (0,0) [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_odbc.c:332 ast_odbc_find_table: Found callid column with type 12 with len 32, octetlen 32, and numlen (0,0) [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_odbc.c:332 ast_odbc_find_table: Found queuename column with type 12 with len 100, octetlen 100, and numlen (0,0) [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_odbc.c:332 ast_odbc_find_table: Found agent column with type 12 with len 100, octetlen 100, and numlen (0,0) [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_odbc.c:332 ast_odbc_find_table: Found event column with type 12 with len 32, octetlen 32, and numlen (0,0) [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_odbc.c:332 ast_odbc_find_table: Found data1 column with type 12 with len 100, octetlen 100, and numlen (0,0) [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_odbc.c:332 ast_odbc_find_table: Found data2 column with type 12 with len 100, octetlen 100, and numlen (0,0) [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_odbc.c:332 ast_odbc_find_table: Found data3 column with type 12 with len 100, octetlen 100, and numlen (0,0) [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_odbc.c:332 ast_odbc_find_table: Found data4 column with type 12 with len 100, octetlen 100, and numlen (0,0) [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_odbc.c:332 ast_odbc_find_table: Found data5 column with type 12 with len 100, octetlen 100, and numlen (0,0) [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_odbc.c:332 ast_odbc_find_table: Found isleme_alindi column with type 4 with len 10, octetlen 10, and numlen (0,10) [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_odbc.c:825 ast_odbc_release_obj: Releasing ODBC handle 0x7f0c601ac018 into pool [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_odbc.c:982 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f0c601ac018 from class 'proxysql' [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_config_odbc.c:117 custom_prepare: Skip: 0; SQL: INSERT INTO queue_log (time, data5, data4, data3, data2, data1, event, agent, queuename, callid) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?) [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 1 ('time') = '2019-12-25 14:05:02.381354' [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 2 ('data5') = '' [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 3 ('data4') = '' [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 4 ('data3') = '1' [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 5 ('data2') = '321' [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 6 ('data1') = '' [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 7 ('event') = 'ENTERQUEUE' [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 8 ('agent') = 'NONE' [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 9 ('queuename') = 'example_queue' [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 10 ('callid') = '1577271902.0' [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_odbc.c:825 ast_odbc_release_obj: Releasing ODBC handle 0x7f0c601ac018 into pool -- Started music on hold, class 'default', on channel 'SIP/321-00000000' [Dec 25 14:05:02] DEBUG[22734][C-00000000]: channel.c:3500 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Dec 25 14:05:02] DEBUG[22734][C-00000000]: channel.c:5076 ast_prod: Prodding channel 'SIP/321-00000000' [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_rtp_asterisk.c:3611 ast_rtp_update_source: Setting the marker bit due to a source update [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:13512 add_sdp: ** Our capability: (g729|ulaw|alaw) Video flag: True Text flag: True [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:13513 add_sdp: ** Our prefcodec: (nothing) [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:13684 add_sdp: -- Done with adding codecs to SDP [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:13709 add_sdp: Setting framing on incoming call: 20 [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:13903 add_sdp: Done building SDP. Settling with this capability: (g729|ulaw|alaw) [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:3751 __sip_xmit: Trying to put 'SIP/2.0 183' onto UDP socket destined for 192.168.0.33:10033 [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_rtp_asterisk.c:4165 ast_rtp_write: Received frame with no data for RTP instance '0x7f0c900308f8' so dropping frame [Dec 25 14:05:02] DEBUG[22734][C-00000000]: app_queue.c:5331 is_our_turn: There is 1 available member. [Dec 25 14:05:02] DEBUG[22734][C-00000000]: app_queue.c:5346 is_our_turn: It's our turn (SIP/321-00000000). [Dec 25 14:05:02] DEBUG[22734][C-00000000]: app_queue.c:6599 try_calling: SIP/321-00000000 is trying to call a queue member. [Dec 25 14:05:02] DEBUG[22734][C-00000000]: app_queue.c:4509 ring_one: (Parallel) Trying 'SIP/205' with metric 0 [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:30494 sip_request_call: Asked to create a SIP channel with formats: (g729) [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:9014 __sip_alloc: Allocating new SIP dialog for 6b98d7aa7baac71c0201b2791ae3aea2@[fe80::250:56ff:fe96:1c16]:5060 - INVITE (No RTP) [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_odbc.c:982 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f0c60001038 from class 'pbxconf1' [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_config_odbc.c:117 custom_prepare: Skip: 0; SQL: SELECT * FROM sip_users WHERE name = ? AND host = ? [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 1 ('name') = '205' [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 2 ('host') = 'dynamic' [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_odbc.c:825 ast_odbc_release_obj: Releasing ODBC handle 0x7f0c60001038 into pool [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_odbc.c:982 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f0c60001038 from class 'pbxconf1' [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_config_odbc.c:117 custom_prepare: Skip: 0; SQL: SELECT * FROM sip_users WHERE name = ? [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 1 ('name') = '205' [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_odbc.c:825 ast_odbc_release_obj: Releasing ODBC handle 0x7f0c60001038 into pool [Dec 25 14:05:02] DEBUG[22734][C-00000000]: stasis.c:460 stasis_topic_create: Topic 'endpoint:SIP/205': 0x7f0d20008078 created [Dec 25 14:05:02] DEBUG[22734][C-00000000]: stasis.c:460 stasis_topic_create: Topic 'cache:12/endpoint:SIP/205': 0x7f0d20007868 created [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:31969 build_peer: Not an IPv4 nor IPv6 address, cannot get port. [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:31972 build_peer: Not an IPv4 nor IPv6 address, cannot set port. [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:5662 realtime_peer: -REALTIME- loading peer from database to memory. Name: 205. Peer objects: 0 [Dec 25 14:05:02] DEBUG[22734][C-00000000]: rtp_engine.c:459 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f0d20008128' [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_rtp_asterisk.c:3202 ast_rtp_new: Allocated port 15858 for RTP instance '0x7f0d20008128' [Dec 25 14:05:02] DEBUG[22734][C-00000000]: rtp_engine.c:476 ast_rtp_instance_new: RTP instance '0x7f0d20008128' is setup and ready to go [Dec 25 14:05:02] DEBUG[22734][C-00000000]: acl.c:830 resolve_first: Multiple addresses. Using the first only [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_rtp_asterisk.c:5987 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f0d20008128' == Using SIP RTP CoS mark 5 [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:5797 do_setnat: Setting NAT on RTP to On [Dec 25 14:05:02] DEBUG[22734][C-00000000]: acl.c:992 ast_ouraddrfor: For destination '192.168.0.33', our source address is '185.88.6.121'. [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:3908 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 185.88.6.121:5060 [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:5797 do_setnat: Setting NAT on RTP to On [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:8799 change_callid_pvt: SIP call-id changed from '6b98d7aa7baac71c0201b2791ae3aea2@[fe80::250:56ff:fe96:1c16]:5060' to '2520f34317a5ba8d6b5ba5f32e4e6f9c@185.88.6.121:5060' [Dec 25 14:05:02] DEBUG[22734][C-00000000]: stasis.c:460 stasis_topic_create: Topic 'channel:1577271902.1': 0x7f0d200016a8 created [Dec 25 14:05:02] DEBUG[22734][C-00000000]: stasis.c:460 stasis_topic_create: Topic 'cache:13/channel:1577271902.1': 0x7f0d20004c38 created [Dec 25 14:05:02] DEBUG[22734][C-00000000]: channel.c:1005 __ast_channel_alloc_ap: Channel 0x7f0d200224e8 'SIP/205-00000001' allocated [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:8163 sip_new: *** Our native formats are (g729) [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:8164 sip_new: *** Joint capabilities are (g729) [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:8165 sip_new: *** Our capabilities are (g729|ulaw|alaw) [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:8166 sip_new: *** AST_CODEC_CHOOSE formats are g729 [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:8168 sip_new: *** Our preferred formats from the incoming channel are (g729) [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:8199 sip_new: This channel will not be able to handle video. [Dec 25 14:05:02] DEBUG[22734][C-00000000]: channel_internal_api.c:936 ast_channel_callid_set: Channel Call ID changing from [C-00000000] to [C-00000000] [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:6472 sip_call: Outgoing Call for 205 [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:6766 update_call_counter: Updating call counter for outgoing call [Dec 25 14:05:02] DEBUG[22656]: chan_sip.c:30388 sip_devicestate: Checking device state for peer 205 [Dec 25 14:05:02] DEBUG[22656]: devicestate.c:474 do_state_change: Changing state for SIP/205 - state 6 (Ringing) [Dec 25 14:05:02] DEBUG[22656]: stasis.c:460 stasis_topic_create: Topic 'devicestate:all/SIP/205': 0x7f0d00001588 created [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:13512 add_sdp: ** Our capability: (g729|ulaw|alaw) Video flag: False Text flag: False [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:13513 add_sdp: ** Our prefcodec: (g729) [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:13684 add_sdp: -- Done with adding codecs to SDP [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:13903 add_sdp: Done building SDP. Settling with this capability: (g729|ulaw|alaw) [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:3394 initialize_initreq: Initializing initreq for method INVITE - callid 2520f34317a5ba8d6b5ba5f32e4e6f9c@185.88.6.121:5060 [Dec 25 14:05:02] DEBUG[22734][C-00000000]: chan_sip.c:3751 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 192.168.0.33:4094 [Dec 25 14:05:02] DEBUG[22685]: app_queue.c:2336 pending_members_remove: Removed SIP/205 from pending_members -- Called SIP/205 [Dec 25 14:05:02] DEBUG[22685]: app_queue.c:2484 device_state_cb: Device 'SIP/205' changed to state '6' (Ringing) [Dec 25 14:05:02] DEBUG[22685]: app_queue.c:2489 device_state_cb: Device 'Queue:example_queue_avail' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. -- SIP/205-00000001 connected line has changed. Saving it until answer for SIP/321-00000000 [Dec 25 14:05:02] DEBUG[22734][C-00000000]: channel.c:5791 set_format: Channel SIP/321-00000000 setting write format path: slin -> g729 [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_musiconhold.c:383 ast_moh_files_next: SIP/321-00000000 Opened file 0 '/var/lib/asterisk/moh/macroform-the_simplicity' [Dec 25 14:05:02] DEBUG[22734][C-00000000]: res_rtp_asterisk.c:4201 ast_rtp_write: Ooh, format changed from none to g729 [Dec 25 14:05:02] DEBUG[22673][C-00000000]: chan_sip.c:4576 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '2520f34317a5ba8d6b5ba5f32e4e6f9c@185.88.6.121:5060' Request 102: Found [Dec 25 14:05:02] DEBUG[22656]: chan_sip.c:30388 sip_devicestate: Checking device state for peer 205 [Dec 25 14:05:02] DEBUG[22656]: devicestate.c:474 do_state_change: Changing state for SIP/205 - state 6 (Ringing) [Dec 25 14:05:02] DEBUG[22656]: chan_sip.c:30388 sip_devicestate: Checking device state for peer 205 [Dec 25 14:05:02] DEBUG[22656]: devicestate.c:474 do_state_change: Changing state for SIP/205 - state 6 (Ringing) [Dec 25 14:05:02] DEBUG[22685]: app_queue.c:2484 device_state_cb: Device 'SIP/205' changed to state '6' (Ringing) -- SIP/205-00000001 is ringing [Dec 25 14:05:04] DEBUG[22734][C-00000000]: res_rtp_asterisk.c:4808 ast_rtcp_interpret: Got RTCP report of 132 bytes from 192.168.0.33:16797 [Dec 25 14:05:04] DEBUG[22673][C-00000000]: chan_sip.c:4519 __sip_ack: Acked pending invite 102 [Dec 25 14:05:04] DEBUG[22673][C-00000000]: chan_sip.c:4535 __sip_ack: Stopping retransmission on '2520f34317a5ba8d6b5ba5f32e4e6f9c@185.88.6.121:5060' of Request 102: Match Found [Dec 25 14:05:04] DEBUG[22673][C-00000000]: chan_sip.c:10337 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Dec 25 14:05:04] DEBUG[22673][C-00000000]: chan_sip.c:10337 process_sdp: Processing session-level SDP o=- 0 2 IN IP4 192.168.0.33... OK. [Dec 25 14:05:04] DEBUG[22673][C-00000000]: chan_sip.c:10337 process_sdp: Processing session-level SDP s=CounterPath eyeBeam 1.5... UNSUPPORTED OR FAILED. [Dec 25 14:05:04] DEBUG[22673][C-00000000]: chan_sip.c:10337 process_sdp: Processing session-level SDP c=IN IP4 192.168.0.33... OK. [Dec 25 14:05:04] DEBUG[22673][C-00000000]: chan_sip.c:10337 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Dec 25 14:05:04] DEBUG[22673][C-00000000]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 18 based on m type on 0x7f0cac0c63a0 [Dec 25 14:05:04] DEBUG[22673][C-00000000]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7f0cac0c63a0 [Dec 25 14:05:04] DEBUG[22673][C-00000000]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7f0cac0c63a0 [Dec 25 14:05:04] DEBUG[22673][C-00000000]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7f0cac0c63a0 [Dec 25 14:05:04] DEBUG[22673][C-00000000]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=fmtp:18 annexb=no... OK. [Dec 25 14:05:04] DEBUG[22673][C-00000000]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [Dec 25 14:05:04] DEBUG[22673][C-00000000]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Dec 25 14:05:04] DEBUG[22673][C-00000000]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK. [Dec 25 14:05:04] DEBUG[22673][C-00000000]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=x-rtp-session-id:FE6DD291B34D439BA11148F9EA912A58... UNSUPPORTED OR FAILED. [Dec 25 14:05:04] DEBUG[22673][C-00000000]: acl.c:992 ast_ouraddrfor: For destination '192.168.0.33', our source address is '185.88.6.121'. [Dec 25 14:05:04] DEBUG[22673][C-00000000]: res_rtp_asterisk.c:6052 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f0d20008128' [Dec 25 14:05:04] DEBUG[22673][C-00000000]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 0 (0x20bd0f0) from 0x7f0cac0c63a0 to 0x7f0d200082f0 [Dec 25 14:05:04] DEBUG[22673][C-00000000]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x20bd210) from 0x7f0cac0c63a0 to 0x7f0d200082f0 [Dec 25 14:05:04] DEBUG[22673][C-00000000]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 18 (0x7f0c90007010) from 0x7f0cac0c63a0 to 0x7f0d200082f0 [Dec 25 14:05:04] DEBUG[22673][C-00000000]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7f0c9000b750) from 0x7f0cac0c63a0 to 0x7f0d200082f0 [Dec 25 14:05:04] DEBUG[22673][C-00000000]: res_rtp_asterisk.c:5886 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f0d20008128' [Dec 25 14:05:04] DEBUG[22673][C-00000000]: chan_sip.c:11098 process_sdp: We're settling with these formats: (g729|ulaw|alaw) [Dec 25 14:05:04] DEBUG[22673][C-00000000]: chan_sip.c:6766 update_call_counter: Updating call counter for outgoing call [Dec 25 14:05:04] DEBUG[22656]: chan_sip.c:30388 sip_devicestate: Checking device state for peer 205 [Dec 25 14:05:04] DEBUG[22656]: devicestate.c:474 do_state_change: Changing state for SIP/205 - state 2 (In use) [Dec 25 14:05:04] DEBUG[22685]: app_queue.c:2336 pending_members_remove: Removed SIP/205 from pending_members [Dec 25 14:05:04] DEBUG[22685]: app_queue.c:2484 device_state_cb: Device 'SIP/205' changed to state '2' (In use) [Dec 25 14:05:04] DEBUG[22673][C-00000000]: chan_sip.c:3751 __sip_xmit: Trying to put 'ACK sip:205' onto UDP socket destined for 192.168.0.33:4094 -- SIP/205-00000001 connected line has changed. Saving it until answer for SIP/321-00000000 -- SIP/205-00000001 answered SIP/321-00000000 [Dec 25 14:05:04] DEBUG[22656]: chan_sip.c:30388 sip_devicestate: Checking device state for peer 205 [Dec 25 14:05:04] DEBUG[22656]: devicestate.c:474 do_state_change: Changing state for SIP/205 - state 2 (In use) -- Stopped music on hold on SIP/321-00000000 [Dec 25 14:05:04] DEBUG[22734][C-00000000]: channel.c:5791 set_format: Channel SIP/321-00000000 setting write format path: g729 -> g729 [Dec 25 14:05:04] DEBUG[22734][C-00000000]: channel.c:3500 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Dec 25 14:05:04] DEBUG[22734][C-00000000]: app_queue.c:4046 leave_queue: Queue 'example_queue' Leave, Channel 'SIP/321-00000000' [Dec 25 14:05:04] DEBUG[22685]: app_queue.c:2489 device_state_cb: Device 'Queue:example_queue' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 25 14:05:04] DEBUG[22734][C-00000000]: res_odbc.c:982 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f0c601ac018 from class 'proxysql' [Dec 25 14:05:04] DEBUG[22734][C-00000000]: res_config_odbc.c:117 custom_prepare: Skip: 0; SQL: INSERT INTO queue_log (time, data5, data4, data3, data2, data1, event, agent, queuename, callid) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?) [Dec 25 14:05:04] DEBUG[22734][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 1 ('time') = '2019-12-25 14:05:04.422647' [Dec 25 14:05:04] DEBUG[22734][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 2 ('data5') = '' [Dec 25 14:05:04] DEBUG[22734][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 3 ('data4') = '' [Dec 25 14:05:04] DEBUG[22734][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 4 ('data3') = '2' [Dec 25 14:05:04] DEBUG[22734][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 5 ('data2') = '1577271902.1' [Dec 25 14:05:04] DEBUG[22734][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 6 ('data1') = '2' [Dec 25 14:05:04] DEBUG[22734][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 7 ('event') = 'CONNECT' [Dec 25 14:05:04] DEBUG[22734][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 8 ('agent') = 'SIP/205' [Dec 25 14:05:04] DEBUG[22734][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 9 ('queuename') = 'example_queue' [Dec 25 14:05:04] DEBUG[22734][C-00000000]: res_config_odbc.c:136 custom_prepare: Parameter 10 ('callid') = '1577271902.0' [Dec 25 14:05:04] DEBUG[22734][C-00000000]: res_odbc.c:825 ast_odbc_release_obj: Releasing ODBC handle 0x7f0c601ac018 into pool [Dec 25 14:05:04] DEBUG[22644]: threadpool.c:536 grow: Increasing threadpool stasis/pool's size by 1 [Dec 25 14:05:04] DEBUG[22734][C-00000000]: chan_sip.c:7411 sip_answer: SIP answering channel: SIP/321-00000000 [Dec 25 14:05:04] DEBUG[22734][C-00000000]: res_rtp_asterisk.c:3611 ast_rtp_update_source: Setting the marker bit due to a source update [Dec 25 14:05:04] DEBUG[22656]: chan_sip.c:30388 sip_devicestate: Checking device state for peer 321 [Dec 25 14:05:04] DEBUG[22656]: devicestate.c:474 do_state_change: Changing state for SIP/321 - state 2 (In use) [Dec 25 14:05:04] DEBUG[22734][C-00000000]: chan_sip.c:13512 add_sdp: ** Our capability: (g729|ulaw|alaw) Video flag: True Text flag: True [Dec 25 14:05:04] DEBUG[22734][C-00000000]: chan_sip.c:13513 add_sdp: ** Our prefcodec: (nothing) [Dec 25 14:05:04] DEBUG[22734][C-00000000]: chan_sip.c:13684 add_sdp: -- Done with adding codecs to SDP [Dec 25 14:05:04] DEBUG[22734][C-00000000]: chan_sip.c:13709 add_sdp: Setting framing on incoming call: 20 [Dec 25 14:05:04] DEBUG[22734][C-00000000]: chan_sip.c:13903 add_sdp: Done building SDP. Settling with this capability: (g729|ulaw|alaw) [Dec 25 14:05:04] DEBUG[22734][C-00000000]: chan_sip.c:3751 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.0.33:10033 [Dec 25 14:05:04] DEBUG[22734][C-00000000]: stasis.c:460 stasis_topic_create: Topic 'bridge:69d72f89-fd94-4382-978a-6ad106538c80': 0x7f0d200282b8 created [Dec 25 14:05:04] DEBUG[22734][C-00000000]: stasis.c:460 stasis_topic_create: Topic 'cache:14/bridge:69d72f89-fd94-4382-978a-6ad106538c80': 0x7f0d20026578 created [Dec 25 14:05:04] DEBUG[22734][C-00000000]: bridge_native_rtp.c:748 native_rtp_bridge_compatible: Bridge '69d72f89-fd94-4382-978a-6ad106538c80' can not use native RTP bridge as two channels are required [Dec 25 14:05:04] DEBUG[22734][C-00000000]: bridge.c:507 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Dec 25 14:05:04] DEBUG[22734][C-00000000]: bridge.c:502 find_best_technology: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping. [Dec 25 14:05:04] DEBUG[22734][C-00000000]: bridge.c:497 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Dec 25 14:05:04] DEBUG[22734][C-00000000]: bridge.c:516 find_best_technology: Chose bridge technology simple_bridge [Dec 25 14:05:04] DEBUG[22734][C-00000000]: bridge.c:795 bridge_base_init: Bridge 69d72f89-fd94-4382-978a-6ad106538c80: calling simple_bridge technology constructor [Dec 25 14:05:04] DEBUG[22734][C-00000000]: bridge.c:803 bridge_base_init: Bridge 69d72f89-fd94-4382-978a-6ad106538c80: calling simple_bridge technology start [Dec 25 14:05:04] DEBUG[22738][C-00000000]: bridge_channel.c:2686 bridge_channel_internal_join: Bridge 69d72f89-fd94-4382-978a-6ad106538c80: 0x7f0d20028368(SIP/205-00000001) is joining [Dec 25 14:05:04] DEBUG[22738][C-00000000]: bridge_channel.c:2148 bridge_channel_internal_push_full: Bridge 69d72f89-fd94-4382-978a-6ad106538c80: pushing 0x7f0d20028368(SIP/205-00000001) -- Channel SIP/205-00000001 joined 'simple_bridge' basic-bridge <69d72f89-fd94-4382-978a-6ad106538c80> [Dec 25 14:05:04] DEBUG[22738][C-00000000]: bridge_native_rtp.c:748 native_rtp_bridge_compatible: Bridge '69d72f89-fd94-4382-978a-6ad106538c80' can not use native RTP bridge as two channels are required [Dec 25 14:05:04] DEBUG[22738][C-00000000]: bridge.c:507 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Dec 25 14:05:04] DEBUG[22738][C-00000000]: bridge.c:497 find_best_technology: Bridge technology softmix does not have any capabilities we want. [Dec 25 14:05:04] DEBUG[22738][C-00000000]: bridge.c:497 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Dec 25 14:05:04] DEBUG[22738][C-00000000]: bridge.c:516 find_best_technology: Chose bridge technology simple_bridge [Dec 25 14:05:04] DEBUG[22738][C-00000000]: bridge.c:1049 smart_bridge_operation: Bridge 69d72f89-fd94-4382-978a-6ad106538c80 is already using the new technology. [Dec 25 14:05:04] DEBUG[22738][C-00000000]: bridge.c:432 bridge_channel_complete_join: Bridge 69d72f89-fd94-4382-978a-6ad106538c80: 0x7f0d20028368(SIP/205-00000001) is joining simple_bridge technology [Dec 25 14:05:04] DEBUG[22738][C-00000000]: res_rtp_asterisk.c:3625 ast_rtp_change_source: Not changing SSRC since we haven't sent any RTP yet [Dec 25 14:05:04] DEBUG[22738][C-00000000]: bridge_native_rtp.c:748 native_rtp_bridge_compatible: Bridge '69d72f89-fd94-4382-978a-6ad106538c80' can not use native RTP bridge as two channels are required [Dec 25 14:05:04] DEBUG[22738][C-00000000]: bridge.c:507 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Dec 25 14:05:04] DEBUG[22738][C-00000000]: bridge.c:497 find_best_technology: Bridge technology softmix does not have any capabilities we want. [Dec 25 14:05:04] DEBUG[22738][C-00000000]: bridge.c:497 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Dec 25 14:05:04] DEBUG[22738][C-00000000]: bridge.c:516 find_best_technology: Chose bridge technology simple_bridge [Dec 25 14:05:04] DEBUG[22738][C-00000000]: bridge.c:1049 smart_bridge_operation: Bridge 69d72f89-fd94-4382-978a-6ad106538c80 is already using the new technology. [Dec 25 14:05:04] DEBUG[22734][C-00000000]: bridge_channel.c:2686 bridge_channel_internal_join: Bridge 69d72f89-fd94-4382-978a-6ad106538c80: 0x7f0d200250b8(SIP/321-00000000) is joining [Dec 25 14:05:04] DEBUG[22734][C-00000000]: bridge_channel.c:2148 bridge_channel_internal_push_full: Bridge 69d72f89-fd94-4382-978a-6ad106538c80: pushing 0x7f0d200250b8(SIP/321-00000000) -- Channel SIP/321-00000000 joined 'simple_bridge' basic-bridge <69d72f89-fd94-4382-978a-6ad106538c80> [Dec 25 14:05:04] DEBUG[22658]: cdr.c:1473 cdr_object_finalize: Finalized CDR for SIP/205-00000001 - start 1577271902.395239 answer 1577271904.422370 end 1577271904.430165 dispo ANSWERED [Dec 25 14:05:04] DEBUG[22734][C-00000000]: bridge_native_rtp.c:626 native_rtp_bridge_compatible_check: Bridge '69d72f89-fd94-4382-978a-6ad106538c80'. Checking compatability for channels 'SIP/205-00000001' and 'SIP/321-00000000' [Dec 25 14:05:04] DEBUG[22733]: app_queue.c:5930 handle_bridge_enter: Detected entry of caller channel SIP/321-00000000 into bridge 69d72f89-fd94-4382-978a-6ad106538c80 [Dec 25 14:05:04] DEBUG[22734][C-00000000]: bridge_native_rtp.c:630 native_rtp_bridge_compatible_check: Bridge '69d72f89-fd94-4382-978a-6ad106538c80' can not use native RTP bridge as channel 'SIP/205-00000001' has features which prevent it [Dec 25 14:05:04] DEBUG[22734][C-00000000]: bridge.c:507 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Dec 25 14:05:04] DEBUG[22734][C-00000000]: bridge.c:497 find_best_technology: Bridge technology softmix does not have any capabilities we want. [Dec 25 14:05:04] DEBUG[22734][C-00000000]: bridge.c:497 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Dec 25 14:05:04] DEBUG[22734][C-00000000]: bridge.c:516 find_best_technology: Chose bridge technology simple_bridge [Dec 25 14:05:04] DEBUG[22734][C-00000000]: bridge.c:1049 smart_bridge_operation: Bridge 69d72f89-fd94-4382-978a-6ad106538c80 is already using the new technology. [Dec 25 14:05:04] DEBUG[22734][C-00000000]: bridge.c:432 bridge_channel_complete_join: Bridge 69d72f89-fd94-4382-978a-6ad106538c80: 0x7f0d200250b8(SIP/321-00000000) is joining simple_bridge technology [Dec 25 14:05:04] DEBUG[22673][C-00000000]: chan_sip.c:4535 __sip_ack: Stopping retransmission on 'lqhcmdvcmbrowdtaijdweosfmbvptfjgcpkwybekhsxlrjkgco' of Response 2: Match Found [Dec 25 14:05:04] DEBUG[22734][C-00000000]: res_rtp_asterisk.c:3632 ast_rtp_change_source: Changing ssrc from 1396119977 to 1241874156 due to a source change [Dec 25 14:05:04] DEBUG[22734][C-00000000]: bridge_native_rtp.c:626 native_rtp_bridge_compatible_check: Bridge '69d72f89-fd94-4382-978a-6ad106538c80'. Checking compatability for channels 'SIP/205-00000001' and 'SIP/321-00000000' [Dec 25 14:05:04] DEBUG[22734][C-00000000]: bridge_native_rtp.c:630 native_rtp_bridge_compatible_check: Bridge '69d72f89-fd94-4382-978a-6ad106538c80' can not use native RTP bridge as channel 'SIP/205-00000001' has features which prevent it [Dec 25 14:05:04] DEBUG[22734][C-00000000]: bridge.c:507 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Dec 25 14:05:04] DEBUG[22734][C-00000000]: bridge.c:497 find_best_technology: Bridge technology softmix does not have any capabilities we want. [Dec 25 14:05:04] DEBUG[22734][C-00000000]: bridge.c:497 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Dec 25 14:05:04] DEBUG[22734][C-00000000]: bridge.c:516 find_best_technology: Chose bridge technology simple_bridge [Dec 25 14:05:04] DEBUG[22734][C-00000000]: bridge.c:1049 smart_bridge_operation: Bridge 69d72f89-fd94-4382-978a-6ad106538c80 is already using the new technology. [Dec 25 14:05:04] DEBUG[22738][C-00000000]: res_rtp_asterisk.c:4165 ast_rtp_write: Received frame with no data for RTP instance '0x7f0d20008128' so dropping frame [Dec 25 14:05:04] DEBUG[22738][C-00000000]: res_rtp_asterisk.c:4165 ast_rtp_write: Received frame with no data for RTP instance '0x7f0d20008128' so dropping frame [Dec 25 14:05:04] DEBUG[22738][C-00000000]: chan_sip.c:8617 sip_rtp_read: Oooh, format changed to ulaw [Dec 25 14:05:04] DEBUG[22738][C-00000000]: channel.c:5791 set_format: Channel SIP/205-00000001 setting read format path: ulaw -> g729 [Dec 25 14:05:04] DEBUG[22738][C-00000000]: channel.c:5791 set_format: Channel SIP/205-00000001 setting write format path: g729 -> ulaw [Dec 25 14:05:05] DEBUG[22673]: acl.c:992 ast_ouraddrfor: For destination '192.168.0.33', our source address is '185.88.6.121'. [Dec 25 14:05:05] DEBUG[22673]: chan_sip.c:3908 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 185.88.6.121:5060 [Dec 25 14:05:05] DEBUG[22673]: chan_sip.c:9014 __sip_alloc: Allocating new SIP dialog for YjUxODc2OGQ4NTBjYTkzMGUzNWRkODM4Yjg1Y2Q0N2E. - REGISTER (No RTP) [Dec 25 14:05:05] DEBUG[22673]: chan_sip.c:3751 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.0.33:63086 [Dec 25 14:05:05] DEBUG[22673]: chan_sip.c:16939 parse_register_contact: Store REGISTER's src-IP:port for call routing. [Dec 25 14:05:05] DEBUG[22673]: chan_sip.c:17103 build_path: build_path: do not use Path headers [Dec 25 14:05:05] DEBUG[22673]: chan_sip.c:3751 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.0.33:63086 [Dec 25 14:05:05] DEBUG[22656]: chan_sip.c:30388 sip_devicestate: Checking device state for peer 103 [Dec 25 14:05:05] DEBUG[22656]: devicestate.c:474 do_state_change: Changing state for SIP/103 - state 1 (Not in use) [Dec 25 14:05:05] DEBUG[22656]: stasis.c:460 stasis_topic_create: Topic 'devicestate:all/SIP/103': 0x7f0d00001d68 created [Dec 25 14:05:05] DEBUG[22685]: app_queue.c:2489 device_state_cb: Device 'SIP/103' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 25 14:05:06] DEBUG[22673]: chan_sip.c:4359 __sip_autodestruct: Auto destroying SIP dialog 'svfldqqiionmsoslwijqbcqwgmhptnifdpkoytwpnxkxgounkw' [Dec 25 14:05:06] DEBUG[22673]: chan_sip.c:6588 sip_pvt_dtor: Destroying SIP dialog svfldqqiionmsoslwijqbcqwgmhptnifdpkoytwpnxkxgounkw -- Remote UNIX connection [Dec 25 14:05:07] DEBUG[22738][C-00000000]: res_rtp_asterisk.c:4808 ast_rtcp_interpret: Got RTCP report of 152 bytes from 192.168.0.33:16797 [Dec 25 14:05:11] DEBUG[22738][C-00000000]: res_rtp_asterisk.c:4808 ast_rtcp_interpret: Got RTCP report of 176 bytes from 192.168.0.33:16797 Tekli-Santral*CLI> queue show example_queue rules [Dec 25 14:05:14] DEBUG[22742]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update [Dec 25 14:05:14] DEBUG[22738][C-00000000]: res_rtp_asterisk.c:4808 ast_rtcp_interpret: Got RTCP report of 176 bytes from 192.168.0.33:16797 [Dec 25 14:05:15] DEBUG[22742]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update Tekli-Santral*CLI> queue show example_queue example_queue has 0 calls (max unlimited) in 'ringall' strategy (2s holdtime, 0s talktime), W:0, C:0, A:0, SL:0.0% within 0s Members: SIP/205 (ringinuse enabled) (in call) (In use) has taken no calls yet No Callers [Dec 25 14:05:15] DEBUG[22678]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update [Dec 25 14:05:15] DEBUG[22742]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update [Dec 25 14:05:16] DEBUG[22742]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update [Dec 25 14:05:16] DEBUG[22742]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update [Dec 25 14:05:18] DEBUG[22742]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update [Dec 25 14:05:18] DEBUG[22738][C-00000000]: res_rtp_asterisk.c:4808 ast_rtcp_interpret: Got RTCP report of 176 bytes from 192.168.0.33:16797 [Dec 25 14:05:18] DEBUG[22742]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update [Dec 25 14:05:21] DEBUG[22738][C-00000000]: res_rtp_asterisk.c:4808 ast_rtcp_interpret: Got RTCP report of 176 bytes from 192.168.0.33:16797 [Dec 25 14:05:24] DEBUG[22733]: threadpool.c:1169 worker_idle: Worker thread idle timeout reached. Dying. [Dec 25 14:05:24] DEBUG[22644]: threadpool.c:1028 worker_thread_destroy: Destroying worker thread 5 [Dec 25 14:05:24] DEBUG[22737]: threadpool.c:1169 worker_idle: Worker thread idle timeout reached. Dying. [Dec 25 14:05:24] DEBUG[22644]: threadpool.c:1028 worker_thread_destroy: Destroying worker thread 6 [Dec 25 14:05:24] DEBUG[22673]: acl.c:992 ast_ouraddrfor: For destination '192.168.0.33', our source address is '185.88.6.121'. [Dec 25 14:05:24] DEBUG[22673]: chan_sip.c:3908 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 185.88.6.121:5060 [Dec 25 14:05:24] DEBUG[22673]: chan_sip.c:9014 __sip_alloc: Allocating new SIP dialog for YjQ1MDBmNWMyNmE5NjI0ZjYzNDAxZjAxYWQ3YTU2YWQ. - INVITE (No RTP) [Dec 25 14:05:24] DEBUG[22673][C-00000001]: sip/reqresp_parser.c:1711 parse_sip_options: Begin: parsing SIP "Supported: replaces" [Dec 25 14:05:24] DEBUG[22673][C-00000001]: sip/reqresp_parser.c:1726 parse_sip_options: Found SIP option: -replaces- [Dec 25 14:05:24] DEBUG[22673][C-00000001]: sip/reqresp_parser.c:1734 parse_sip_options: Matched SIP option: replaces [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:3751 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.0.33:63086 [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:4535 __sip_ack: Stopping retransmission on 'YjQ1MDBmNWMyNmE5NjI0ZjYzNDAxZjAxYWQ3YTU2YWQ.' of Response 1: Match Found [Dec 25 14:05:24] DEBUG[22673][C-00000001]: rtp_engine.c:459 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f0c9001f0b8' [Dec 25 14:05:24] DEBUG[22673][C-00000001]: res_rtp_asterisk.c:3202 ast_rtp_new: Allocated port 16678 for RTP instance '0x7f0c9001f0b8' [Dec 25 14:05:24] DEBUG[22673][C-00000001]: rtp_engine.c:476 ast_rtp_instance_new: RTP instance '0x7f0c9001f0b8' is setup and ready to go [Dec 25 14:05:24] DEBUG[22673][C-00000001]: acl.c:830 resolve_first: Multiple addresses. Using the first only [Dec 25 14:05:24] DEBUG[22673][C-00000001]: res_rtp_asterisk.c:5987 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f0c9001f0b8' == Using SIP RTP CoS mark 5 [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:5797 do_setnat: Setting NAT on RTP to On [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:10337 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:10337 process_sdp: Processing session-level SDP o=3cxVCE 393410460 393842535 IN IP4 192.168.0.33... OK. [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:10337 process_sdp: Processing session-level SDP s=3cxVCE Audio Call... UNSUPPORTED OR FAILED. [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:10337 process_sdp: Processing session-level SDP c=IN IP4 192.168.0.33... OK. [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:10337 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Dec 25 14:05:24] DEBUG[22673][C-00000001]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7f0cac0c7140 [Dec 25 14:05:24] DEBUG[22673][C-00000001]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7f0cac0c7140 [Dec 25 14:05:24] DEBUG[22673][C-00000001]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 3 based on m type on 0x7f0cac0c7140 [Dec 25 14:05:24] DEBUG[22673][C-00000001]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7f0cac0c7140 [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK. [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK. [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK. [Dec 25 14:05:24] DEBUG[22673][C-00000001]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 34 based on m type on 0x7f0cac0c71b0 [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:10800 process_sdp: Processing media-level (video) SDP c=IN IP4 192.168.0.33... OK. [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:33953 process_crypto: Received offer with crypto line for media stream that is not enabled [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:10800 process_sdp: Processing media-level (video) SDP a=rtpmap:34 H263/90000... OK. [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:33953 process_crypto: Received offer with crypto line for media stream that is not enabled [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:10800 process_sdp: Processing media-level (video) SDP a=fmtp:34 QCIF=1;CIF=1;SQCIF=1;CIF4=1... OK. [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:33953 process_crypto: Received offer with crypto line for media stream that is not enabled [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:10800 process_sdp: Processing media-level (video) SDP a=sendrecv... UNSUPPORTED OR FAILED. [Dec 25 14:05:24] DEBUG[22673][C-00000001]: acl.c:992 ast_ouraddrfor: For destination '192.168.0.33', our source address is '185.88.6.121'. [Dec 25 14:05:24] DEBUG[22673][C-00000001]: res_rtp_asterisk.c:6052 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f0c9001f0b8' [Dec 25 14:05:24] DEBUG[22673][C-00000001]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 0 (0x7f0c9001eac0) from 0x7f0cac0c7140 to 0x7f0c9001f280 [Dec 25 14:05:24] DEBUG[22673][C-00000001]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 3 (0x7f0c9001eb20) from 0x7f0cac0c7140 to 0x7f0c9001f280 [Dec 25 14:05:24] DEBUG[22673][C-00000001]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7f0c9000e760) from 0x7f0cac0c7140 to 0x7f0c9001f280 [Dec 25 14:05:24] DEBUG[22673][C-00000001]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7f0c9001eb50) from 0x7f0cac0c7140 to 0x7f0c9001f280 [Dec 25 14:05:24] DEBUG[22673][C-00000001]: res_rtp_asterisk.c:5886 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f0c9001f0b8' [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:11098 process_sdp: We're settling with these formats: (ulaw|alaw) [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:26424 handle_request_invite: Checking SIP call limits for device 103 [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:6766 update_call_counter: Updating call counter for incoming call [Dec 25 14:05:24] DEBUG[22673][C-00000001]: stasis.c:460 stasis_topic_create: Topic 'channel:1577271924.2': 0x7f0c9001e618 created [Dec 25 14:05:24] DEBUG[22656]: chan_sip.c:30388 sip_devicestate: Checking device state for peer 103 [Dec 25 14:05:24] DEBUG[22656]: devicestate.c:474 do_state_change: Changing state for SIP/103 - state 2 (In use) [Dec 25 14:05:24] DEBUG[22673][C-00000001]: stasis.c:460 stasis_topic_create: Topic 'cache:15/channel:1577271924.2': 0x7f0c9000de88 created [Dec 25 14:05:24] DEBUG[22685]: app_queue.c:2489 device_state_cb: Device 'SIP/103' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 25 14:05:24] DEBUG[22673][C-00000001]: channel.c:1005 __ast_channel_alloc_ap: Channel 0x7f0c9000d058 'SIP/103-00000002' allocated [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:8163 sip_new: *** Our native formats are (ulaw) [Dec 25 14:05:24] DEBUG[22644]: threadpool.c:536 grow: Increasing threadpool stasis/pool's size by 1 [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:8164 sip_new: *** Joint capabilities are (ulaw|alaw) [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:8165 sip_new: *** Our capabilities are (ulaw|alaw|g729) [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:8166 sip_new: *** AST_CODEC_CHOOSE formats are ulaw [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:8199 sip_new: This channel will not be able to handle video. [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:26629 handle_request_invite: SIP/103-00000002: New call is still down.... Trying... [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:3751 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.0.33:63086 [Dec 25 14:05:24] DEBUG[22656]: chan_sip.c:30388 sip_devicestate: Checking device state for peer 103 [Dec 25 14:05:24] DEBUG[22656]: devicestate.c:474 do_state_change: Changing state for SIP/103 - state 2 (In use) [Dec 25 14:05:24] DEBUG[22758][C-00000001]: pbx.c:2878 pbx_extension_helper: Launching 'Queue' -- Executing [999@dahiliara:1] Queue("SIP/103-00000002", "example_queue") in new stack [Dec 25 14:05:24] DEBUG[22758][C-00000001]: app_queue.c:7951 queue_exec: queue: example_queue, options: , url: , announce: , timeout: , agi: , macro: , gosub: , rule: , position: [Dec 25 14:05:24] DEBUG[22758][C-00000001]: app_queue.c:7981 queue_exec: NO QUEUE_PRIO variable found. Using default. [Dec 25 14:05:24] DEBUG[22758][C-00000001]: app_queue.c:8033 queue_exec: queue: example_queue, expires: 0, priority: 0 [Dec 25 14:05:24] DEBUG[22758][C-00000001]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update [Dec 25 14:05:24] DEBUG[22758][C-00000001]: app_queue.c:3762 join_queue: Queue 'example_queue' Join, Channel 'SIP/103-00000002', Position '1' [Dec 25 14:05:24] DEBUG[22685]: app_queue.c:2489 device_state_cb: Device 'Queue:example_queue' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Dec 25 14:05:24] DEBUG[22758][C-00000001]: res_odbc.c:982 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f0c601ac018 from class 'proxysql' [Dec 25 14:05:24] DEBUG[22758][C-00000001]: res_config_odbc.c:117 custom_prepare: Skip: 0; SQL: INSERT INTO queue_log (time, data5, data4, data3, data2, data1, event, agent, queuename, callid) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?) [Dec 25 14:05:24] DEBUG[22758][C-00000001]: res_config_odbc.c:136 custom_prepare: Parameter 1 ('time') = '2019-12-25 14:05:24.793204' [Dec 25 14:05:24] DEBUG[22758][C-00000001]: res_config_odbc.c:136 custom_prepare: Parameter 2 ('data5') = '' [Dec 25 14:05:24] DEBUG[22758][C-00000001]: res_config_odbc.c:136 custom_prepare: Parameter 3 ('data4') = '' [Dec 25 14:05:24] DEBUG[22758][C-00000001]: res_config_odbc.c:136 custom_prepare: Parameter 4 ('data3') = '1' [Dec 25 14:05:24] DEBUG[22758][C-00000001]: res_config_odbc.c:136 custom_prepare: Parameter 5 ('data2') = '103' [Dec 25 14:05:24] DEBUG[22758][C-00000001]: res_config_odbc.c:136 custom_prepare: Parameter 6 ('data1') = '' [Dec 25 14:05:24] DEBUG[22758][C-00000001]: res_config_odbc.c:136 custom_prepare: Parameter 7 ('event') = 'ENTERQUEUE' [Dec 25 14:05:24] DEBUG[22758][C-00000001]: res_config_odbc.c:136 custom_prepare: Parameter 8 ('agent') = 'NONE' [Dec 25 14:05:24] DEBUG[22758][C-00000001]: res_config_odbc.c:136 custom_prepare: Parameter 9 ('queuename') = 'example_queue' [Dec 25 14:05:24] DEBUG[22758][C-00000001]: res_config_odbc.c:136 custom_prepare: Parameter 10 ('callid') = '1577271924.2' [Dec 25 14:05:24] DEBUG[22758][C-00000001]: res_odbc.c:825 ast_odbc_release_obj: Releasing ODBC handle 0x7f0c601ac018 into pool -- Started music on hold, class 'default', on channel 'SIP/103-00000002' [Dec 25 14:05:24] DEBUG[22758][C-00000001]: channel.c:3500 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Dec 25 14:05:24] DEBUG[22758][C-00000001]: channel.c:5076 ast_prod: Prodding channel 'SIP/103-00000002' [Dec 25 14:05:24] DEBUG[22758][C-00000001]: res_rtp_asterisk.c:3611 ast_rtp_update_source: Setting the marker bit due to a source update [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:13512 add_sdp: ** Our capability: (ulaw|alaw) Video flag: False Text flag: True [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:13513 add_sdp: ** Our prefcodec: (nothing) [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:13684 add_sdp: -- Done with adding codecs to SDP [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:13709 add_sdp: Setting framing on incoming call: 20 [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:13903 add_sdp: Done building SDP. Settling with this capability: (ulaw|alaw) [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:3751 __sip_xmit: Trying to put 'SIP/2.0 183' onto UDP socket destined for 192.168.0.33:63086 [Dec 25 14:05:24] DEBUG[22758][C-00000001]: res_rtp_asterisk.c:4165 ast_rtp_write: Received frame with no data for RTP instance '0x7f0c9001f0b8' so dropping frame [Dec 25 14:05:24] DEBUG[22758][C-00000001]: app_queue.c:5331 is_our_turn: There is 1 available member. [Dec 25 14:05:24] DEBUG[22758][C-00000001]: app_queue.c:5346 is_our_turn: It's our turn (SIP/103-00000002). [Dec 25 14:05:24] DEBUG[22758][C-00000001]: app_queue.c:6599 try_calling: SIP/103-00000002 is trying to call a queue member. [Dec 25 14:05:24] DEBUG[22758][C-00000001]: app_queue.c:4509 ring_one: (Parallel) Trying 'SIP/205' with metric 0 [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:30494 sip_request_call: Asked to create a SIP channel with formats: (ulaw) [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:9014 __sip_alloc: Allocating new SIP dialog for 69824c0238ea7f78744bee0d4abed3f9@[fe80::250:56ff:fe96:1c16]:5060 - INVITE (No RTP) [Dec 25 14:05:24] DEBUG[22758][C-00000001]: rtp_engine.c:459 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f0c601e5788' [Dec 25 14:05:24] DEBUG[22758][C-00000001]: res_rtp_asterisk.c:3202 ast_rtp_new: Allocated port 13284 for RTP instance '0x7f0c601e5788' [Dec 25 14:05:24] DEBUG[22758][C-00000001]: rtp_engine.c:476 ast_rtp_instance_new: RTP instance '0x7f0c601e5788' is setup and ready to go [Dec 25 14:05:24] DEBUG[22758][C-00000001]: acl.c:830 resolve_first: Multiple addresses. Using the first only [Dec 25 14:05:24] DEBUG[22758][C-00000001]: res_rtp_asterisk.c:5987 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f0c601e5788' == Using SIP RTP CoS mark 5 [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:5797 do_setnat: Setting NAT on RTP to On [Dec 25 14:05:24] DEBUG[22758][C-00000001]: acl.c:992 ast_ouraddrfor: For destination '192.168.0.33', our source address is '185.88.6.121'. [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:3908 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 185.88.6.121:5060 [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:5797 do_setnat: Setting NAT on RTP to On [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:8799 change_callid_pvt: SIP call-id changed from '69824c0238ea7f78744bee0d4abed3f9@[fe80::250:56ff:fe96:1c16]:5060' to '53fde56705b9dec61b7404a052f2df46@185.88.6.121:5060' [Dec 25 14:05:24] DEBUG[22758][C-00000001]: stasis.c:460 stasis_topic_create: Topic 'channel:1577271924.3': 0x7f0c602ad8a8 created [Dec 25 14:05:24] DEBUG[22758][C-00000001]: stasis.c:460 stasis_topic_create: Topic 'cache:16/channel:1577271924.3': 0x7f0c602ad938 created [Dec 25 14:05:24] DEBUG[22758][C-00000001]: channel.c:1005 __ast_channel_alloc_ap: Channel 0x7f0c602c71a8 'SIP/205-00000003' allocated [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:8163 sip_new: *** Our native formats are (ulaw) [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:8164 sip_new: *** Joint capabilities are (ulaw) [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:8165 sip_new: *** Our capabilities are (g729|ulaw|alaw) [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:8166 sip_new: *** AST_CODEC_CHOOSE formats are ulaw [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:8168 sip_new: *** Our preferred formats from the incoming channel are (ulaw) [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:8199 sip_new: This channel will not be able to handle video. [Dec 25 14:05:24] DEBUG[22758][C-00000001]: channel_internal_api.c:936 ast_channel_callid_set: Channel Call ID changing from [C-00000001] to [C-00000001] [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:6472 sip_call: Outgoing Call for 205 [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:6766 update_call_counter: Updating call counter for outgoing call [Dec 25 14:05:24] DEBUG[22656]: chan_sip.c:30388 sip_devicestate: Checking device state for peer 205 [Dec 25 14:05:24] DEBUG[22656]: devicestate.c:474 do_state_change: Changing state for SIP/205 - state 7 (Ring+Inuse) [Dec 25 14:05:24] DEBUG[22685]: app_queue.c:2336 pending_members_remove: Removed SIP/205 from pending_members [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:13512 add_sdp: ** Our capability: (ulaw|g729|alaw) Video flag: False Text flag: False [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:13513 add_sdp: ** Our prefcodec: (ulaw) [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:13684 add_sdp: -- Done with adding codecs to SDP [Dec 25 14:05:24] DEBUG[22685]: app_queue.c:2484 device_state_cb: Device 'SIP/205' changed to state '7' (Ring+Inuse) [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:13903 add_sdp: Done building SDP. Settling with this capability: (ulaw|g729|alaw) [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:3394 initialize_initreq: Initializing initreq for method INVITE - callid 53fde56705b9dec61b7404a052f2df46@185.88.6.121:5060 [Dec 25 14:05:24] DEBUG[22758][C-00000001]: chan_sip.c:3751 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 192.168.0.33:4094 -- Called SIP/205 -- SIP/205-00000003 connected line has changed. Saving it until answer for SIP/103-00000002 [Dec 25 14:05:24] DEBUG[22758][C-00000001]: channel.c:5791 set_format: Channel SIP/103-00000002 setting write format path: slin -> ulaw [Dec 25 14:05:24] DEBUG[22758][C-00000001]: res_musiconhold.c:383 ast_moh_files_next: SIP/103-00000002 Opened file 0 '/var/lib/asterisk/moh/macroform-the_simplicity' [Dec 25 14:05:24] DEBUG[22758][C-00000001]: res_rtp_asterisk.c:4201 ast_rtp_write: Ooh, format changed from none to ulaw [Dec 25 14:05:24] DEBUG[22758][C-00000001]: res_rtp_asterisk.c:4041 rtp_raw_write: Starting RTCP transmission on RTP instance '0x7f0c9001f0b8' [Dec 25 14:05:24] DEBUG[22673][C-00000001]: chan_sip.c:4576 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '53fde56705b9dec61b7404a052f2df46@185.88.6.121:5060' Request 102: Found [Dec 25 14:05:24] DEBUG[22656]: chan_sip.c:30388 sip_devicestate: Checking device state for peer 205 [Dec 25 14:05:24] DEBUG[22656]: devicestate.c:474 do_state_change: Changing state for SIP/205 - state 7 (Ring+Inuse) [Dec 25 14:05:24] DEBUG[22656]: chan_sip.c:30388 sip_devicestate: Checking device state for peer 205 [Dec 25 14:05:24] DEBUG[22656]: devicestate.c:474 do_state_change: Changing state for SIP/205 - state 7 (Ring+Inuse) -- SIP/205-00000003 is ringing [Dec 25 14:05:24] DEBUG[22685]: app_queue.c:2484 device_state_cb: Device 'SIP/205' changed to state '7' (Ring+Inuse) [Dec 25 14:05:25] DEBUG[22738][C-00000000]: res_rtp_asterisk.c:4808 ast_rtcp_interpret: Got RTCP report of 176 bytes from 192.168.0.33:16797 [Dec 25 14:05:26] DEBUG[22742]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update Tekli-Santral*CLI> queue show example_queue example_queue has 1 calls (max unlimited) in 'ringall' strategy (2s holdtime, 0s talktime), W:0, C:0, A:0, SL:0.0% within 0s Members: SIP/205 (ringinuse enabled) (in call) (Ring+Inuse) has taken no calls yet Callers: 1. SIP/103-00000002 (wait: 0:02, prio: 0) [Dec 25 14:05:26] DEBUG[22678]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update [Dec 25 14:05:27] DEBUG[22742]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update [Dec 25 14:05:27] DEBUG[22742]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update [Dec 25 14:05:27] DEBUG[22742]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update Tekli-Santral*CLI> queue show example_queue example_queue has 1 calls (max unlimited) in 'ringall' strategy (2s holdtime, 0s talktime), W:0, C:0, A:0, SL:0.0% within 0s Members: SIP/205 (ringinuse enabled) (in call) (Ring+Inuse) has taken no calls yet Callers: 1. SIP/103-00000002 (wait: 0:04, prio: 0) [Dec 25 14:05:28] DEBUG[22678]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update [Dec 25 14:05:28] DEBUG[22742]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update [Dec 25 14:05:28] DEBUG[22738][C-00000000]: res_rtp_asterisk.c:4808 ast_rtcp_interpret: Got RTCP report of 176 bytes from 192.168.0.33:16797 [Dec 25 14:05:28] DEBUG[22742]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update [Dec 25 14:05:29] DEBUG[22742]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update [Dec 25 14:05:30] DEBUG[22742]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update [Dec 25 14:05:30] DEBUG[22742]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update [Dec 25 14:05:31] DEBUG[22742]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update [Dec 25 14:05:32] DEBUG[22738][C-00000000]: res_rtp_asterisk.c:4808 ast_rtcp_interpret: Got RTCP report of 176 bytes from 192.168.0.33:16797 [Dec 25 14:05:32] DEBUG[22742]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update Tekli-Santral*CLI> reload [Dec 25 14:05:33] DEBUG[22678]: config_options.c:716 aco_process_config: acl.conf was unchanged [Dec 25 14:05:33] DEBUG[22678]: config.c:3739 ast_parse_arg: extract uint from [100] in [0, 1000] gives [100](0) [Dec 25 14:05:33] DEBUG[22678]: config.c:3739 ast_parse_arg: extract uint from [300] in [1, 86400] gives [300](0) [Dec 25 14:05:33] DEBUG[22678]: config_options.c:716 aco_process_config: cdr.conf was unchanged [Dec 25 14:05:33] NOTICE[22678]: cdr.c:4475 cdr_toggle_runtime_options: CDR simple logging enabled. [Dec 25 14:05:33] DEBUG[22678]: config_options.c:716 aco_process_config: cel.conf was unchanged -- CEL logging disabled. [Dec 25 14:05:33] DEBUG[22678]: config.c:2195 config_text_file_load: Parsing /etc/asterisk/extconfig.conf [Dec 25 14:05:33] DEBUG[22678]: config.c:2195 config_text_file_load: Parsing /etc/asterisk/realtime.conf == Binding queue_log to odbc/proxysql/queue_log == Binding sipusers to odbc/pbxconf1/sip_users == Binding sippeers to odbc/pbxconf1/sip_users == Binding sipregs to odbc/pbxconf1/sip_users == Binding voicemail to odbc/pbxconf1/voicemail_users == Binding extensions to odbc/pbxconf1/extensions == Binding extensions_realtime.include to odbc/pbxconf1/n13dialplan == Binding extensions.include to odbc/pbxconf1/n13dialplan == Binding menus.include to odbc/pbxconf1/n13dialplan == Binding schedule.include to odbc/pbxconf1/n13dialplan == Binding musiconhold to odbc/pbxconf1/musiconhold [Dec 25 14:05:33] DEBUG[22678]: config.c:3686 ast_parse_arg: extract int from [10] in [-2147483648, 2147483647] gives [10](0) [Dec 25 14:05:33] DEBUG[22678]: config.c:3686 ast_parse_arg: extract int from [1000] in [-2147483648, 2147483647] gives [1000](0) [Dec 25 14:05:33] DEBUG[22678]: config.c:3686 ast_parse_arg: extract int from [2] in [-2147483648, 2147483647] gives [2](0) [Dec 25 14:05:33] DEBUG[22678]: config.c:3686 ast_parse_arg: extract int from [1] in [-2147483648, 2147483647] gives [1](0) [Dec 25 14:05:33] DEBUG[22678]: config.c:3686 ast_parse_arg: extract int from [15] in [-2147483648, 2147483647] gives [15](0) [Dec 25 14:05:33] DEBUG[22678]: config.c:3686 ast_parse_arg: extract int from [3] in [-2147483648, 2147483647] gives [3](0) [Dec 25 14:05:33] DEBUG[22678]: config_options.c:716 aco_process_config: features.conf was unchanged [Dec 25 14:05:33] DEBUG[22678]: config.c:2195 config_text_file_load: Parsing /etc/asterisk/logger.conf [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:217 destroy_table_cache: Destroying table cache for queue_log [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:982 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f0c601ac018 from class 'proxysql' [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:332 ast_odbc_find_table: Found id column with type 4 with len 10, octetlen 10, and numlen (0,10) [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:332 ast_odbc_find_table: Found time column with type 12 with len 26, octetlen 26, and numlen (0,0) [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:332 ast_odbc_find_table: Found callid column with type 12 with len 32, octetlen 32, and numlen (0,0) [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:332 ast_odbc_find_table: Found queuename column with type 12 with len 100, octetlen 100, and numlen (0,0) [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:332 ast_odbc_find_table: Found agent column with type 12 with len 100, octetlen 100, and numlen (0,0) [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:332 ast_odbc_find_table: Found event column with type 12 with len 32, octetlen 32, and numlen (0,0) [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:332 ast_odbc_find_table: Found data1 column with type 12 with len 100, octetlen 100, and numlen (0,0) [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:332 ast_odbc_find_table: Found data2 column with type 12 with len 100, octetlen 100, and numlen (0,0) [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:332 ast_odbc_find_table: Found data3 column with type 12 with len 100, octetlen 100, and numlen (0,0) [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:332 ast_odbc_find_table: Found data4 column with type 12 with len 100, octetlen 100, and numlen (0,0) [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:332 ast_odbc_find_table: Found data5 column with type 12 with len 100, octetlen 100, and numlen (0,0) [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:332 ast_odbc_find_table: Found isleme_alindi column with type 4 with len 10, octetlen 10, and numlen (0,10) [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:825 ast_odbc_release_obj: Releasing ODBC handle 0x7f0c601ac018 into pool [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:982 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f0c601ac018 from class 'proxysql' [Dec 25 14:05:33] DEBUG[22678]: res_config_odbc.c:117 custom_prepare: Skip: 0; SQL: INSERT INTO queue_log (time, data5, data4, data3, data2, data1, event, agent, queuename, callid) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?) [Dec 25 14:05:33] DEBUG[22678]: res_config_odbc.c:136 custom_prepare: Parameter 1 ('time') = '2019-12-25 14:05:33.701167' [Dec 25 14:05:33] DEBUG[22678]: res_config_odbc.c:136 custom_prepare: Parameter 2 ('data5') = '' [Dec 25 14:05:33] DEBUG[22678]: res_config_odbc.c:136 custom_prepare: Parameter 3 ('data4') = '' [Dec 25 14:05:33] DEBUG[22678]: res_config_odbc.c:136 custom_prepare: Parameter 4 ('data3') = '' [Dec 25 14:05:33] DEBUG[22678]: res_config_odbc.c:136 custom_prepare: Parameter 5 ('data2') = '' [Dec 25 14:05:33] DEBUG[22678]: res_config_odbc.c:136 custom_prepare: Parameter 6 ('data1') = '' [Dec 25 14:05:33] DEBUG[22678]: res_config_odbc.c:136 custom_prepare: Parameter 7 ('event') = 'CONFIGRELOAD' [Dec 25 14:05:33] DEBUG[22678]: res_config_odbc.c:136 custom_prepare: Parameter 8 ('agent') = 'NONE' [Dec 25 14:05:33] DEBUG[22678]: res_config_odbc.c:136 custom_prepare: Parameter 9 ('queuename') = 'NONE' [Dec 25 14:05:33] DEBUG[22678]: res_config_odbc.c:136 custom_prepare: Parameter 10 ('callid') = 'NONE' [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:825 ast_odbc_release_obj: Releasing ODBC handle 0x7f0c601ac018 into pool Asterisk Queue Logger restarted [Dec 25 14:05:33] DEBUG[22678]: config.c:2195 config_text_file_load: Parsing /etc/asterisk/codecs.conf [Dec 25 14:05:33] DEBUG[22678]: config.c:3739 ast_parse_arg: extract uint from [4999] in [1024, 65535] gives [4999](0) [Dec 25 14:05:33] DEBUG[22678]: config.c:3739 ast_parse_arg: extract uint from [4000] in [1024, 65535] gives [4000](0) [Dec 25 14:05:33] DEBUG[22678]: config_options.c:716 aco_process_config: udptl.conf was unchanged -- Reloading module 'res_statsd.so' (Statsd client support) [Dec 25 14:05:33] DEBUG[22678]: config.c:3838 ast_parse_arg: extract addr from 127.0.0.1 gives 127.0.0.1:0(0) [Dec 25 14:05:33] DEBUG[22678]: config_options.c:716 aco_process_config: statsd.conf was unchanged -- Reloading module 'res_odbc.so' (ODBC resource) [Dec 25 14:05:33] DEBUG[22678]: config.c:2195 config_text_file_load: Parsing /etc/asterisk/res_odbc.conf [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:1044 odbc_obj_connect: Connecting pbxconf1(0x7f0c800019e8) [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:1082 odbc_obj_connect: res_odbc: Connected to pbxconf1 [pbxconf1 (0x7f0c800019e8)] [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:961 _ast_odbc_request_obj2: Created ODBC handle 0x7f0c800019e8 on class 'pbxconf1', new count is 1 [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:825 ast_odbc_release_obj: Releasing ODBC handle 0x7f0c800019e8 into pool [Dec 25 14:05:33] NOTICE[22678]: res_odbc.c:718 load_odbc_config: Registered ODBC class 'pbxconf1' dsn->[pbxconf1] [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:1044 odbc_obj_connect: Connecting pbxlogs(0x7f0c800c6128) [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:1082 odbc_obj_connect: res_odbc: Connected to pbxlogs [pbxlogs (0x7f0c800c6128)] [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:961 _ast_odbc_request_obj2: Created ODBC handle 0x7f0c800c6128 on class 'pbxlogs', new count is 1 [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:825 ast_odbc_release_obj: Releasing ODBC handle 0x7f0c800c6128 into pool [Dec 25 14:05:33] NOTICE[22678]: res_odbc.c:718 load_odbc_config: Registered ODBC class 'pbxlogs' dsn->[pbxlogs] [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:1044 odbc_obj_connect: Connecting proxysql(0x7f0c801b4cc8) [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:1082 odbc_obj_connect: res_odbc: Connected to proxysql [proxysql (0x7f0c801b4cc8)] [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:961 _ast_odbc_request_obj2: Created ODBC handle 0x7f0c801b4cc8 on class 'proxysql', new count is 1 [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:825 ast_odbc_release_obj: Releasing ODBC handle 0x7f0c801b4cc8 into pool [Dec 25 14:05:33] NOTICE[22678]: res_odbc.c:718 load_odbc_config: Registered ODBC class 'proxysql' dsn->[proxysql] [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:1021 odbc_obj_disconnect: Database handle 0x7f0c60001038 (connection 0x7f0c60005c70) deallocated [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:1021 odbc_obj_disconnect: Database handle 0x7f0c600c64b8 (connection 0x7f0c600137e0) deallocated [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:1021 odbc_obj_disconnect: Database handle 0x7f0c601ac018 (connection 0x7f0c600ff390) deallocated [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:217 destroy_table_cache: Destroying table cache for queue_log -- Reloading module 'res_crypto.so' (Cryptographic Digital Signatures) -- Reloading module 'res_stun_monitor.so' (STUN Network Monitor) -- Reloading module 'res_fax.so' (Generic FAX Applications) -- Reloading module 'res_hep.so' (HEPv3 API) [Dec 25 14:05:33] DEBUG[22678]: config.c:3739 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [Dec 25 14:05:33] DEBUG[22678]: config_options.c:716 aco_process_config: hep.conf was unchanged -- Reloading module 'res_ari.so' (Asterisk RESTful Interface) [Dec 25 14:05:33] DEBUG[22678]: config.c:3686 ast_parse_arg: extract int from [100] in [1, 2147483647] gives [100](0) [Dec 25 14:05:33] DEBUG[22678]: config.c:3686 ast_parse_arg: extract int from [100] in [1, 2147483647] gives [100](0) [Dec 25 14:05:33] DEBUG[22678]: config_options.c:716 aco_process_config: ari.conf was unchanged -- Reloading module 'res_calendar.so' (Asterisk Calendar integration) -- Reloading module 'res_parking.so' (Call Parking Resource) [Dec 25 14:05:33] DEBUG[22678]: config_options.c:716 aco_process_config: res_parking.conf was unchanged -- Reloading module 'res_config_odbc.so' (Realtime ODBC configuration) -- Reloading module 'res_config_sqlite3.so' (SQLite 3 realtime config engine) [Dec 25 14:05:33] DEBUG[22678]: res_config_sqlite3.c:1260 parse_config: res_config_sqlite3.conf was unchanged, skipping parsing -- Reloading module 'res_config_curl.so' (Realtime Curl configuration) [Dec 25 14:05:33] DEBUG[22678]: config.c:2195 config_text_file_load: Parsing /etc/asterisk/res_curl.conf [Dec 25 14:05:33] DEBUG[22678]: func_curl.c:405 acf_curlopt_write: Inserting entry 0x7f0c801dc000 with key 101 and value (nil) [Dec 25 14:05:33] DEBUG[22678]: func_curl.c:405 acf_curlopt_write: Inserting entry 0x7f0c802a5bc0 with key 59 and value 0x1f41 -- Reloading module 'res_musiconhold.so' (Music On Hold Resource) -- Reloading module 'res_rtp_asterisk.so' (Asterisk RTP Stack) -- Reloading module 'chan_sip.so' (Session Initiation Protocol (SIP)) Reloading SIP [Dec 25 14:05:33] DEBUG[22678]: db.c:394 db_get_common: Unable to find key '(bogus_peer)' in family 'SIP/Registry' [Dec 25 14:05:33] DEBUG[22678]: chan_sip.c:5237 sip_destroy_peer: Destroying SIP peer (bogus_peer) [Dec 25 14:05:33] DEBUG[22673]: config.c:2195 config_text_file_load: Parsing /etc/asterisk/sip.conf -- Reloading module 'res_adsi.so' (ADSI Resource) -- Reloading module 'app_agent_pool.so' (Call center agent pool applications) [Dec 25 14:05:33] DEBUG[22678]: config_options.c:716 aco_process_config: agents.conf was unchanged -- Reloading module 'app_confbridge.so' (Conference Bridge Application) [Dec 25 14:05:33] DEBUG[22678]: config_options.c:716 aco_process_config: confbridge.conf was unchanged -- Reloading module 'cdr_adaptive_odbc.so' (Adaptive ODBC CDR backend) [Dec 25 14:05:33] DEBUG[22678]: config.c:2195 config_text_file_load: Parsing /etc/asterisk/cdr_adaptive_odbc.conf [Dec 25 14:05:33] DEBUG[22673]: config.c:2195 config_text_file_load: Parsing /etc/asterisk/users.conf [Dec 25 14:05:33] DEBUG[22673]: chan_sip.c:32440 reload_config: Setting SIP channel User-Agent Name to NETPBX [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:982 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f0c800c6128 from class 'pbxlogs' [Dec 25 14:05:33] DEBUG[22673]: chan_sip.c:32503 reload_config: Enabling TCP socket for listening [Dec 25 14:05:33] DEBUG[22673]: config.c:3838 ast_parse_arg: extract addr from 0.0.0.0 gives 0.0.0.0:0(0) [Dec 25 14:05:33] DEBUG[22673]: chan_sip.c:32513 reload_config: Setting TCP socket address to 0.0.0.0:0 [Dec 25 14:05:33] DEBUG[22673]: config.c:3838 ast_parse_arg: extract addr from 0.0.0.0 gives 0.0.0.0:0(0) -- Found adaptive CDR table cdr@pbxlogs. [Dec 25 14:05:33] DEBUG[22673]: acl.c:830 resolve_first: Multiple addresses. Using the first only == Using SIP CoS mark 4 [Dec 25 14:05:33] DEBUG[22673]: tcptls.c:1256 ast_tcptls_server_start: Nothing changed in SIP TCP server [Dec 25 14:05:33] DEBUG[22673]: chan_sip.c:33107 reload_config: SIP TCP server started [Dec 25 14:05:33] DEBUG[22673]: chan_sip.c:31964 build_peer: Not an IPv4 nor IPv6 address, cannot get port. [Dec 25 14:05:33] DEBUG[22673]: chan_sip.c:31967 build_peer: Not an IPv4 nor IPv6 address, cannot set port. [Dec 25 14:05:33] DEBUG[22678]: res_odbc.c:825 ast_odbc_release_obj: Releasing ODBC handle 0x7f0c800c6128 into pool [Dec 25 14:05:33] DEBUG[22673]: chan_sip.c:31969 build_peer: Not an IPv4 nor IPv6 address, cannot get port. [Dec 25 14:05:33] DEBUG[22673]: chan_sip.c:31972 build_peer: Not an IPv4 nor IPv6 address, cannot set port. -- Reloading module 'app_voicemail.so' (Comedian Mail (Voicemail System)) [Dec 25 14:05:33] DEBUG[22673]: db.c:394 db_get_common: Unable to find key '101' in family 'SIP/Registry' -- Reloading module 'app_alarmreceiver.so' (Alarm Receiver for Asterisk) [Dec 25 14:05:33] DEBUG[22673]: chan_sip.c:31964 build_peer: Not an IPv4 nor IPv6 address, cannot get port. [Dec 25 14:05:33] DEBUG[22673]: chan_sip.c:31967 build_peer: Not an IPv4 nor IPv6 address, cannot set port. [Dec 25 14:05:33] DEBUG[22673]: chan_sip.c:31969 build_peer: Not an IPv4 nor IPv6 address, cannot get port. [Dec 25 14:05:33] DEBUG[22673]: chan_sip.c:31972 build_peer: Not an IPv4 nor IPv6 address, cannot set port. -- Reloading module 'app_followme.so' (Find-Me/Follow-Me Application) [Dec 25 14:05:33] DEBUG[22673]: db.c:394 db_get_common: Unable to find key '102' in family 'SIP/Registry' -- Reloading module 'func_odbc.so' (ODBC lookups) [Dec 25 14:05:33] DEBUG[22673]: chan_sip.c:31964 build_peer: Not an IPv4 nor IPv6 address, cannot get port. [Dec 25 14:05:33] DEBUG[22673]: chan_sip.c:31967 build_peer: Not an IPv4 nor IPv6 address, cannot set port. [Dec 25 14:05:33] DEBUG[22673]: chan_sip.c:31969 build_peer: Not an IPv4 nor IPv6 address, cannot get port. -- Reloading module 'pbx_config.so' (Text Extension Configuration) [Dec 25 14:05:33] DEBUG[22673]: chan_sip.c:31972 build_peer: Not an IPv4 nor IPv6 address, cannot set port. [Dec 25 14:05:33] DEBUG[22673]: chan_sip.c:16669 reg_source_db: SIP Seeding peer from astdb: '103' at 103@192.168.0.33 for 600 [Dec 25 14:05:33] DEBUG[22678]: config.c:2195 config_text_file_load: Parsing /etc/asterisk/extensions.conf [Dec 25 14:05:33] DEBUG[22673]: db.c:394 db_get_common: Unable to find key '103' in family 'SIP/RegistryPath' [Dec 25 14:05:33] DEBUG[22678]: pbx.c:6172 ast_context_find_or_create: Registered extension context 'dahiliara'; registrar: pbx_config [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '999' priority 1 to dahiliara (0x7f0c80020390) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '101' priority 1 to dahiliara (0x7f0c80020390) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '102' priority 1 to dahiliara (0x7f0c80020390) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '_0850X.' priority 1 to dahiliara (0x7f0c80020390) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:6172 ast_context_find_or_create: Registered extension context 'hint'; registrar: pbx_config [Dec 25 14:05:33] DEBUG[22678]: chan_sip.c:30388 sip_devicestate: Checking device state for peer 101 [Dec 25 14:05:33] DEBUG[22678]: pbx.c:3966 ast_add_hint: HINTS: Adding hint 101: SIP/101 [Dec 25 14:05:33] DEBUG[22673]: res_odbc.c:982 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f0c800019e8 from class 'pbxconf1' [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '101' priority -1 to hint (0x7f0c801e4630) [Dec 25 14:05:33] DEBUG[22678]: chan_sip.c:30388 sip_devicestate: Checking device state for peer 102 [Dec 25 14:05:33] DEBUG[22678]: pbx.c:3966 ast_add_hint: HINTS: Adding hint 102: SIP/102 [Dec 25 14:05:33] DEBUG[22673]: res_config_odbc.c:117 custom_prepare: Skip: 0; SQL: SELECT * FROM sip_users WHERE name LIKE ? ESCAPE '\\' AND callbackextension LIKE ? ESCAPE '\\' ORDER BY name [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '102' priority -1 to hint (0x7f0c801e4630) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:3966 ast_add_hint: HINTS: Adding hint 103: SIP/103 [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '103' priority -1 to hint (0x7f0c801e4630) [Dec 25 14:05:33] DEBUG[22678]: config.c:2195 config_text_file_load: Parsing /etc/asterisk/users.conf [Dec 25 14:05:33] DEBUG[22678]: pbx.c:6172 ast_context_find_or_create: Registered extension context 'parkedcalls'; registrar: res_parking/default [Dec 25 14:05:33] DEBUG[22678]: pbx.c:6199 context_merge_incls_swits_igps_other_registrars: merging incls/swits/igpats from old(parkedcalls) to new(parkedcalls) context, registrar = pbx_config [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '720' priority 1 to parkedcalls (0x7f0c800017a0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '719' priority 1 to parkedcalls (0x7f0c800017a0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '718' priority 1 to parkedcalls (0x7f0c800017a0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '717' priority 1 to parkedcalls (0x7f0c800017a0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '716' priority 1 to parkedcalls (0x7f0c800017a0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '715' priority 1 to parkedcalls (0x7f0c800017a0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '714' priority 1 to parkedcalls (0x7f0c800017a0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '713' priority 1 to parkedcalls (0x7f0c800017a0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '712' priority 1 to parkedcalls (0x7f0c800017a0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '711' priority 1 to parkedcalls (0x7f0c800017a0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '710' priority 1 to parkedcalls (0x7f0c800017a0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '709' priority 1 to parkedcalls (0x7f0c800017a0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '708' priority 1 to parkedcalls (0x7f0c800017a0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '707' priority 1 to parkedcalls (0x7f0c800017a0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '706' priority 1 to parkedcalls (0x7f0c800017a0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '705' priority 1 to parkedcalls (0x7f0c800017a0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '704' priority 1 to parkedcalls (0x7f0c800017a0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '703' priority 1 to parkedcalls (0x7f0c800017a0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '702' priority 1 to parkedcalls (0x7f0c800017a0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '701' priority 1 to parkedcalls (0x7f0c800017a0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7452 ast_add_extension2_lockopt: Added extension '700' priority 1 to parkedcalls (0x7f0c800017a0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:6172 ast_context_find_or_create: Registered extension context '__func_periodic_hook_context__'; registrar: func_periodic_hook [Dec 25 14:05:33] DEBUG[22678]: pbx.c:6199 context_merge_incls_swits_igps_other_registrars: merging incls/swits/igpats from old(__func_periodic_hook_context__) to new(__func_periodic_hook_context__) context, registrar = pbx_config [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7449 ast_add_extension2_lockopt: Added extension 'beep' priority 2 (CID match '') to __func_periodic_hook_context__ (0x7f0c801e47b0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7449 ast_add_extension2_lockopt: Added extension 'beep' priority 1 (CID match '') to __func_periodic_hook_context__ (0x7f0c801e47b0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7449 ast_add_extension2_lockopt: Added extension 'hook' priority 6 (CID match '') to __func_periodic_hook_context__ (0x7f0c801e47b0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7449 ast_add_extension2_lockopt: Added extension 'hook' priority 5 (CID match '') to __func_periodic_hook_context__ (0x7f0c801e47b0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7449 ast_add_extension2_lockopt: Added extension 'hook' priority 4 (CID match '') to __func_periodic_hook_context__ (0x7f0c801e47b0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7449 ast_add_extension2_lockopt: Added extension 'hook' priority 3 (CID match '') to __func_periodic_hook_context__ (0x7f0c801e47b0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7449 ast_add_extension2_lockopt: Added extension 'hook' priority 2 (CID match '') to __func_periodic_hook_context__ (0x7f0c801e47b0) [Dec 25 14:05:33] DEBUG[22678]: pbx.c:7449 ast_add_extension2_lockopt: Added extension 'hook' priority 1 (CID match '') to __func_periodic_hook_context__ (0x7f0c801e47b0) -- Time to scan old dialplan and merge leftovers back into the new: 0.000328 sec -- Time to restore hints and swap in new dialplan: 0.000004 sec -- Time to delete the old dialplan: 0.000079 sec -- Total time merge_contexts_delete: 0.000411 sec -- pbx_config successfully loaded 4 contexts (enable debug for details). -- Reloading module 'res_clialiases.so' (CLI Aliases) -- Reloading module 'app_minivm.so' (Mini VoiceMail (A minimal Voicemail e-mail System)) -- Reloading module 'app_playback.so' (Sound File Playback Application) -- Reloading module 'app_amd.so' (Answering Machine Detection Application) -- Reloading module 'app_queue.so' (True Call Queueing) [Dec 25 14:05:33] NOTICE[22678]: app_queue.c:8743 reload_queue_rules: queuerules.conf has not changed since it was last loaded. Not taking any action. [Dec 25 14:05:33] DEBUG[22673]: res_config_odbc.c:136 custom_prepare: Parameter 1 ('name LIKE') = '%' [Dec 25 14:05:33] DEBUG[22673]: res_config_odbc.c:136 custom_prepare: Parameter 2 ('callbackextension LIKE') = '%' [Dec 25 14:05:33] DEBUG[22673]: res_odbc.c:825 ast_odbc_release_obj: Releasing ODBC handle 0x7f0c800019e8 into pool [Dec 25 14:05:33] DEBUG[22673]: config.c:2195 config_text_file_load: Parsing /etc/asterisk/sip_notify.conf [Dec 25 14:05:33] DEBUG[22673]: sched.c:714 ast_sched_dump: Asterisk Schedule Dump (6 in Q, 66 Total, 4 Cache, 10 high-water) [Dec 25 14:05:33] DEBUG[22673]: sched.c:721 ast_sched_dump: ============================================================= [Dec 25 14:05:33] DEBUG[22673]: sched.c:722 ast_sched_dump: |ID Callback Data Time (sec:ms) | [Dec 25 14:05:33] DEBUG[22673]: sched.c:723 ast_sched_dump: +-----+-----------------+-----------------+-----------------+ [Dec 25 14:05:33] DEBUG[22673]: sched.c:730 ast_sched_dump: |0012 | 0x7f0cd5010390 | 0x7f0d20008128 | 000000 : 803666 | [Dec 25 14:05:33] DEBUG[22673]: sched.c:730 ast_sched_dump: |0013 | 0x7f0cd5010390 | 0x7f0c900308f8 | 000003 : 438794 | [Dec 25 14:05:33] DEBUG[22673]: sched.c:730 ast_sched_dump: |0002 | 0x7f0cd5010390 | 0x7f0c9001f0b8 | 000000 : 861933 | [Dec 25 14:05:33] DEBUG[22673]: sched.c:730 ast_sched_dump: |0004 | 0x7f0cbe18ee50 | 0x7f0c9000ea48 | 000003 : 471635 | [Dec 25 14:05:33] DEBUG[22673]: sched.c:730 ast_sched_dump: |0005 | 0x7f0cbe163ac0 | 0x7f0c90001968 | 000050 : 844816 | [Dec 25 14:05:33] DEBUG[22673]: sched.c:730 ast_sched_dump: |0011 | 0x7f0cbe12f830 | 0x2573448 | 000609 : 996943 | [Dec 25 14:05:33] DEBUG[22673]: sched.c:738 ast_sched_dump: ============================================================= [Dec 25 14:05:34] DEBUG[22673]: acl.c:992 ast_ouraddrfor: For destination '192.168.0.33', our source address is '185.88.6.121'. [Dec 25 14:05:34] DEBUG[22673]: chan_sip.c:3908 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 185.88.6.121:5060 [Dec 25 14:05:34] DEBUG[22673]: chan_sip.c:9014 __sip_alloc: Allocating new SIP dialog for fpiantghidedlclsddqrqrqsfvxugactjqoggmjqrxfrjhlmbg - OPTIONS (No RTP) [Dec 25 14:05:34] DEBUG[22673]: chan_sip.c:3751 __sip_xmit: Trying to put 'SIP/2.0 404' onto UDP socket destined for 192.168.0.33:10033 [Dec 25 14:05:35] DEBUG[22738][C-00000000]: res_rtp_asterisk.c:4808 ast_rtcp_interpret: Got RTCP report of 176 bytes from 192.168.0.33:16797 Tekli-Santral*CLI> queue show example_queue example_queue has 1 calls (max unlimited) in 'ringall' strategy (2s holdtime, 0s talktime), W:0, C:0, A:0, SL:0.0% within 0s Members: SIP/205 (ringinuse enabled) (in call) (Ring+Inuse) has taken no calls yet Callers: 1. SIP/103-00000002 (wait: 0:12, prio: 0) [Dec 25 14:05:36] DEBUG[22678]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update [Dec 25 14:05:36] DEBUG[22742]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update [Dec 25 14:05:36] DEBUG[22742]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update [Dec 25 14:05:37] DEBUG[22673]: chan_sip.c:4359 __sip_autodestruct: Auto destroying SIP dialog 'YjUxODc2OGQ4NTBjYTkzMGUzNWRkODM4Yjg1Y2Q0N2E.' [Dec 25 14:05:37] DEBUG[22673]: chan_sip.c:6588 sip_pvt_dtor: Destroying SIP dialog YjUxODc2OGQ4NTBjYTkzMGUzNWRkODM4Yjg1Y2Q0N2E. [Dec 25 14:05:37] DEBUG[22742]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update [Dec 25 14:05:39] DEBUG[22738][C-00000000]: res_rtp_asterisk.c:4808 ast_rtcp_interpret: Got RTCP report of 176 bytes from 192.168.0.33:16797 [Dec 25 14:05:39] DEBUG[22673][C-00000001]: chan_sip.c:3407 sip_alreadygone: Setting SIP_ALREADYGONE on dialog YjQ1MDBmNWMyNmE5NjI0ZjYzNDAxZjAxYWQ3YTU2YWQ. [Dec 25 14:05:39] DEBUG[22673][C-00000001]: chan_sip.c:6766 update_call_counter: Updating call counter for incoming call [Dec 25 14:05:39] DEBUG[22673][C-00000001]: chan_sip.c:3751 __sip_xmit: Trying to put 'SIP/2.0 487' onto UDP socket destined for 192.168.0.33:63086 [Dec 25 14:05:39] DEBUG[22656]: chan_sip.c:30388 sip_devicestate: Checking device state for peer 103 [Dec 25 14:05:39] DEBUG[22673][C-00000001]: chan_sip.c:3751 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.0.33:63086 [Dec 25 14:05:39] DEBUG[22656]: devicestate.c:474 do_state_change: Changing state for SIP/103 - state 1 (Not in use) [Dec 25 14:05:39] DEBUG[22685]: app_queue.c:2489 device_state_cb: Device 'SIP/103' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. -- Stopped music on hold on SIP/103-00000002 [Dec 25 14:05:39] DEBUG[22758][C-00000001]: channel.c:5791 set_format: Channel SIP/103-00000002 setting write format path: ulaw -> ulaw [Dec 25 14:05:39] DEBUG[22758][C-00000001]: channel.c:3500 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Dec 25 14:05:39] DEBUG[22658]: cdr.c:1473 cdr_object_finalize: Finalized CDR for SIP/103-00000002 - start 1577271924.791476 answer 0.000000 end 1577271939.629382 dispo NO ANSWER [Dec 25 14:05:39] DEBUG[22758][C-00000001]: app_queue.c:6696 try_calling: SIP/103-00000002: Nobody answered. [Dec 25 14:05:39] DEBUG[22758][C-00000001]: channel.c:2683 ast_hangup: Channel 0x7f0c602c71a8 'SIP/205-00000003' hanging up. Refs: 2 [Dec 25 14:05:39] DEBUG[22673][C-00000001]: chan_sip.c:4535 __sip_ack: Stopping retransmission on 'YjQ1MDBmNWMyNmE5NjI0ZjYzNDAxZjAxYWQ3YTU2YWQ.' of Response 2: Match Found [Dec 25 14:05:39] DEBUG[22758][C-00000001]: chan_sip.c:7153 sip_hangup: Hangup call SIP/205-00000003, SIP callid 53fde56705b9dec61b7404a052f2df46@185.88.6.121:5060 [Dec 25 14:05:39] DEBUG[22758][C-00000001]: chan_sip.c:6766 update_call_counter: Updating call counter for outgoing call [Dec 25 14:05:39] DEBUG[22758][C-00000001]: chan_sip.c:4576 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '53fde56705b9dec61b7404a052f2df46@185.88.6.121:5060' Request 102: Found [Dec 25 14:05:39] DEBUG[22656]: chan_sip.c:30388 sip_devicestate: Checking device state for peer 205 [Dec 25 14:05:39] DEBUG[22758][C-00000001]: chan_sip.c:3751 __sip_xmit: Trying to put 'CANCEL sip:' onto UDP socket destined for 192.168.0.33:4094 [Dec 25 14:05:39] DEBUG[22758][C-00000001]: channel.c:2235 ast_channel_destructor: Channel 0x7f0c602c71a8 'SIP/205-00000003' destroying [Dec 25 14:05:39] DEBUG[22658]: cdr.c:1473 cdr_object_finalize: Finalized CDR for SIP/205-00000003 - start 1577271924.801666 answer 0.000000 end 1577271939.629832 dispo NO ANSWER [Dec 25 14:05:39] DEBUG[22658]: cdr.c:1306 cdr_object_create_public_records: CDR for SIP/205-00000003 is dialed and has no Party B; discarding [Dec 25 14:05:39] DEBUG[22758][C-00000001]: stasis.c:405 topic_dtor: Topic 'cache:16/channel:1577271924.3': 0x7f0c602ad938 destroyed [Dec 25 14:05:39] DEBUG[22758][C-00000001]: stasis.c:405 topic_dtor: Topic 'channel:1577271924.3': 0x7f0c602ad8a8 destroyed [Dec 25 14:05:39] DEBUG[22656]: res_odbc.c:982 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f0c800019e8 from class 'pbxconf1' [Dec 25 14:05:39] DEBUG[22644]: threadpool.c:536 grow: Increasing threadpool stasis/pool's size by 1 [Dec 25 14:05:39] DEBUG[22656]: res_config_odbc.c:117 custom_prepare: Skip: 0; SQL: SELECT * FROM sip_users WHERE name = ? AND host = ? [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_odbc.c:982 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f0c801b4cc8 from class 'proxysql' [Dec 25 14:05:39] DEBUG[22656]: res_config_odbc.c:136 custom_prepare: Parameter 1 ('name') = '205' [Dec 25 14:05:39] DEBUG[22656]: res_config_odbc.c:136 custom_prepare: Parameter 2 ('host') = 'dynamic' [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_odbc.c:332 ast_odbc_find_table: Found id column with type 4 with len 10, octetlen 10, and numlen (0,10) [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_odbc.c:332 ast_odbc_find_table: Found time column with type 12 with len 26, octetlen 26, and numlen (0,0) [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_odbc.c:332 ast_odbc_find_table: Found callid column with type 12 with len 32, octetlen 32, and numlen (0,0) [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_odbc.c:332 ast_odbc_find_table: Found queuename column with type 12 with len 100, octetlen 100, and numlen (0,0) [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_odbc.c:332 ast_odbc_find_table: Found agent column with type 12 with len 100, octetlen 100, and numlen (0,0) [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_odbc.c:332 ast_odbc_find_table: Found event column with type 12 with len 32, octetlen 32, and numlen (0,0) [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_odbc.c:332 ast_odbc_find_table: Found data1 column with type 12 with len 100, octetlen 100, and numlen (0,0) [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_odbc.c:332 ast_odbc_find_table: Found data2 column with type 12 with len 100, octetlen 100, and numlen (0,0) [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_odbc.c:332 ast_odbc_find_table: Found data3 column with type 12 with len 100, octetlen 100, and numlen (0,0) [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_odbc.c:332 ast_odbc_find_table: Found data4 column with type 12 with len 100, octetlen 100, and numlen (0,0) [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_odbc.c:332 ast_odbc_find_table: Found data5 column with type 12 with len 100, octetlen 100, and numlen (0,0) [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_odbc.c:332 ast_odbc_find_table: Found isleme_alindi column with type 4 with len 10, octetlen 10, and numlen (0,10) [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_odbc.c:825 ast_odbc_release_obj: Releasing ODBC handle 0x7f0c801b4cc8 into pool [Dec 25 14:05:39] DEBUG[22656]: res_odbc.c:825 ast_odbc_release_obj: Releasing ODBC handle 0x7f0c800019e8 into pool [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_odbc.c:982 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f0c801b4cc8 from class 'proxysql' [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_config_odbc.c:117 custom_prepare: Skip: 0; SQL: INSERT INTO queue_log (time, data5, data4, data3, data2, data1, event, agent, queuename, callid) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?) [Dec 25 14:05:39] DEBUG[22656]: res_odbc.c:982 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f0c800019e8 from class 'pbxconf1' [Dec 25 14:05:39] DEBUG[22656]: res_config_odbc.c:117 custom_prepare: Skip: 0; SQL: SELECT * FROM sip_users WHERE name = ? [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_config_odbc.c:136 custom_prepare: Parameter 1 ('time') = '2019-12-25 14:05:39.629983' [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_config_odbc.c:136 custom_prepare: Parameter 2 ('data5') = '' [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_config_odbc.c:136 custom_prepare: Parameter 3 ('data4') = '' [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_config_odbc.c:136 custom_prepare: Parameter 4 ('data3') = '15' [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_config_odbc.c:136 custom_prepare: Parameter 5 ('data2') = '1' [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_config_odbc.c:136 custom_prepare: Parameter 6 ('data1') = '1' [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_config_odbc.c:136 custom_prepare: Parameter 7 ('event') = 'ABANDON' [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_config_odbc.c:136 custom_prepare: Parameter 8 ('agent') = 'NONE' [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_config_odbc.c:136 custom_prepare: Parameter 9 ('queuename') = 'example_queue' [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_config_odbc.c:136 custom_prepare: Parameter 10 ('callid') = '1577271924.2' [Dec 25 14:05:39] DEBUG[22656]: res_config_odbc.c:136 custom_prepare: Parameter 1 ('name') = '205' [Dec 25 14:05:39] DEBUG[22656]: res_odbc.c:825 ast_odbc_release_obj: Releasing ODBC handle 0x7f0c800019e8 into pool [Dec 25 14:05:39] DEBUG[22656]: stasis.c:460 stasis_topic_create: Topic 'endpoint:SIP/205': 0x7f0d0000d2f8 created [Dec 25 14:05:39] DEBUG[22656]: stasis.c:460 stasis_topic_create: Topic 'cache:17/endpoint:SIP/205': 0x7f0d0000ce18 created [Dec 25 14:05:39] DEBUG[22656]: chan_sip.c:31969 build_peer: Not an IPv4 nor IPv6 address, cannot get port. [Dec 25 14:05:39] DEBUG[22656]: chan_sip.c:31972 build_peer: Not an IPv4 nor IPv6 address, cannot set port. [Dec 25 14:05:39] DEBUG[22656]: chan_sip.c:5662 realtime_peer: -REALTIME- loading peer from database to memory. Name: 205. Peer objects: 0 [Dec 25 14:05:39] DEBUG[22656]: chan_sip.c:5237 sip_destroy_peer: Destroying SIP peer 205 [Dec 25 14:05:39] DEBUG[22656]: devicestate.c:474 do_state_change: Changing state for SIP/205 - state 1 (Not in use) [Dec 25 14:05:39] DEBUG[22656]: chan_sip.c:30388 sip_devicestate: Checking device state for peer 205 [Dec 25 14:05:39] DEBUG[22685]: app_queue.c:2336 pending_members_remove: Removed SIP/205 from pending_members [Dec 25 14:05:39] DEBUG[22685]: app_queue.c:2336 pending_members_remove: Removed SIP/205 from pending_members [Dec 25 14:05:39] DEBUG[22757]: stasis.c:405 topic_dtor: Topic 'cache:17/endpoint:SIP/205': 0x7f0d0000ce18 destroyed [Dec 25 14:05:39] DEBUG[22757]: stasis.c:405 topic_dtor: Topic 'endpoint:SIP/205': 0x7f0d0000d2f8 destroyed [Dec 25 14:05:39] DEBUG[22656]: res_odbc.c:982 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f0c800019e8 from class 'pbxconf1' [Dec 25 14:05:39] DEBUG[22656]: res_config_odbc.c:117 custom_prepare: Skip: 0; SQL: SELECT * FROM sip_users WHERE name = ? AND host = ? [Dec 25 14:05:39] DEBUG[22685]: app_queue.c:2484 device_state_cb: Device 'SIP/205' changed to state '1' (Not in use) [Dec 25 14:05:39] DEBUG[22685]: app_queue.c:2489 device_state_cb: Device 'Queue:example_queue_avail' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 25 14:05:39] DEBUG[22656]: res_config_odbc.c:136 custom_prepare: Parameter 1 ('name') = '205' [Dec 25 14:05:39] DEBUG[22656]: res_config_odbc.c:136 custom_prepare: Parameter 2 ('host') = 'dynamic' [Dec 25 14:05:39] DEBUG[22656]: res_odbc.c:825 ast_odbc_release_obj: Releasing ODBC handle 0x7f0c800019e8 into pool [Dec 25 14:05:39] DEBUG[22758][C-00000001]: res_odbc.c:825 ast_odbc_release_obj: Releasing ODBC handle 0x7f0c801b4cc8 into pool [Dec 25 14:05:39] DEBUG[22656]: res_odbc.c:982 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f0c800019e8 from class 'pbxconf1' [Dec 25 14:05:39] DEBUG[22656]: res_config_odbc.c:117 custom_prepare: Skip: 0; SQL: SELECT * FROM sip_users WHERE name = ? [Dec 25 14:05:39] DEBUG[22758][C-00000001]: app_queue.c:4046 leave_queue: Queue 'example_queue' Leave, Channel 'SIP/103-00000002' [Dec 25 14:05:39] DEBUG[22758][C-00000001]: pbx.c:4369 __ast_pbx_run: Spawn extension (dahiliara,999,1) exited non-zero on 'SIP/103-00000002' == Spawn extension (dahiliara, 999, 1) exited non-zero on 'SIP/103-00000002' [Dec 25 14:05:39] DEBUG[22758][C-00000001]: channel.c:2592 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'SIP/103-00000002' [Dec 25 14:05:39] DEBUG[22758][C-00000001]: channel.c:2683 ast_hangup: Channel 0x7f0c9000d058 'SIP/103-00000002' hanging up. Refs: 2 [Dec 25 14:05:39] DEBUG[22758][C-00000001]: chan_sip.c:7153 sip_hangup: Hangup call SIP/103-00000002, SIP callid YjQ1MDBmNWMyNmE5NjI0ZjYzNDAxZjAxYWQ3YTU2YWQ. [Dec 25 14:05:39] DEBUG[22758][C-00000001]: channel.c:2235 ast_channel_destructor: Channel 0x7f0c9000d058 'SIP/103-00000002' destroying [Dec 25 14:05:39] DEBUG[22685]: app_queue.c:2489 device_state_cb: Device 'Queue:example_queue' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 25 14:05:39] DEBUG[22658]: res_odbc.c:982 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f0c800c6128 from class 'pbxlogs' [Dec 25 14:05:39] DEBUG[22658]: cdr_adaptive_odbc.c:741 odbc_log: Executing [INSERT INTO cdr (start,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,uniqueid,linkedid,sequence) VALUES ({ ts '2019-12-25 14:05:24' },'"103" <103>','103','999','dahiliara','SIP/103-00000002','SIP/205-00000003','Queue','example_queue',14,0,'NO ANSWER',3,'1577271924.2','1577271924.2',2)] [Dec 25 14:05:39] DEBUG[22656]: res_config_odbc.c:136 custom_prepare: Parameter 1 ('name') = '205' [Dec 25 14:05:39] DEBUG[22758][C-00000001]: stasis.c:405 topic_dtor: Topic 'cache:15/channel:1577271924.2': 0x7f0c9000de88 destroyed [Dec 25 14:05:39] DEBUG[22758][C-00000001]: stasis.c:405 topic_dtor: Topic 'channel:1577271924.2': 0x7f0c9001e618 destroyed [Dec 25 14:05:39] DEBUG[22656]: res_odbc.c:825 ast_odbc_release_obj: Releasing ODBC handle 0x7f0c800019e8 into pool [Dec 25 14:05:39] DEBUG[22656]: stasis.c:460 stasis_topic_create: Topic 'endpoint:SIP/205': 0x7f0d0002b4e8 created [Dec 25 14:05:39] DEBUG[22658]: res_odbc.c:825 ast_odbc_release_obj: Releasing ODBC handle 0x7f0c800c6128 into pool [Dec 25 14:05:39] DEBUG[22656]: stasis.c:460 stasis_topic_create: Topic 'cache:18/endpoint:SIP/205': 0x7f0d000014c8 created [Dec 25 14:05:39] DEBUG[22656]: chan_sip.c:31969 build_peer: Not an IPv4 nor IPv6 address, cannot get port. [Dec 25 14:05:39] DEBUG[22656]: chan_sip.c:31972 build_peer: Not an IPv4 nor IPv6 address, cannot set port. [Dec 25 14:05:39] DEBUG[22656]: chan_sip.c:5662 realtime_peer: -REALTIME- loading peer from database to memory. Name: 205. Peer objects: 0 [Dec 25 14:05:39] DEBUG[22656]: chan_sip.c:5237 sip_destroy_peer: Destroying SIP peer 205 [Dec 25 14:05:39] DEBUG[22656]: devicestate.c:474 do_state_change: Changing state for SIP/205 - state 1 (Not in use) [Dec 25 14:05:39] DEBUG[22656]: chan_sip.c:30388 sip_devicestate: Checking device state for peer 103 [Dec 25 14:05:39] DEBUG[22656]: devicestate.c:474 do_state_change: Changing state for SIP/103 - state 1 (Not in use) [Dec 25 14:05:39] DEBUG[22757]: stasis.c:405 topic_dtor: Topic 'cache:18/endpoint:SIP/205': 0x7f0d000014c8 destroyed [Dec 25 14:05:39] DEBUG[22757]: stasis.c:405 topic_dtor: Topic 'endpoint:SIP/205': 0x7f0d0002b4e8 destroyed [Dec 25 14:05:39] DEBUG[22673][C-00000001]: chan_sip.c:4519 __sip_ack: Acked pending invite 102 [Dec 25 14:05:39] DEBUG[22673][C-00000001]: chan_sip.c:4535 __sip_ack: Stopping retransmission on '53fde56705b9dec61b7404a052f2df46@185.88.6.121:5060' of Request 102: Match Found [Dec 25 14:05:39] DEBUG[22673][C-00000001]: chan_sip.c:4535 __sip_ack: Stopping retransmission on '53fde56705b9dec61b7404a052f2df46@185.88.6.121:5060' of Request 102: Match Found [Dec 25 14:05:39] DEBUG[22673][C-00000001]: chan_sip.c:3751 __sip_xmit: Trying to put 'ACK sip:205' onto UDP socket destined for 192.168.0.33:4094 [Dec 25 14:05:39] DEBUG[22673][C-00000001]: chan_sip.c:6766 update_call_counter: Updating call counter for outgoing call [Dec 25 14:05:39] DEBUG[22673]: chan_sip.c:6588 sip_pvt_dtor: Destroying SIP dialog YjQ1MDBmNWMyNmE5NjI0ZjYzNDAxZjAxYWQ3YTU2YWQ. [Dec 25 14:05:39] DEBUG[22656]: chan_sip.c:30388 sip_devicestate: Checking device state for peer 205 [Dec 25 14:05:39] DEBUG[22673]: rtp_engine.c:402 instance_destructor: Destroyed RTP instance '0x7f0c9001f0b8' [Dec 25 14:05:39] DEBUG[22656]: res_odbc.c:982 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f0c800019e8 from class 'pbxconf1' [Dec 25 14:05:39] DEBUG[22656]: res_config_odbc.c:117 custom_prepare: Skip: 0; SQL: SELECT * FROM sip_users WHERE name = ? AND host = ? [Dec 25 14:05:39] DEBUG[22656]: res_config_odbc.c:136 custom_prepare: Parameter 1 ('name') = '205' [Dec 25 14:05:39] DEBUG[22656]: res_config_odbc.c:136 custom_prepare: Parameter 2 ('host') = 'dynamic' [Dec 25 14:05:39] DEBUG[22656]: res_odbc.c:825 ast_odbc_release_obj: Releasing ODBC handle 0x7f0c800019e8 into pool [Dec 25 14:05:39] DEBUG[22656]: res_odbc.c:982 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f0c800019e8 from class 'pbxconf1' [Dec 25 14:05:39] DEBUG[22656]: res_config_odbc.c:117 custom_prepare: Skip: 0; SQL: SELECT * FROM sip_users WHERE name = ? [Dec 25 14:05:39] DEBUG[22656]: res_config_odbc.c:136 custom_prepare: Parameter 1 ('name') = '205' [Dec 25 14:05:39] DEBUG[22656]: res_odbc.c:825 ast_odbc_release_obj: Releasing ODBC handle 0x7f0c800019e8 into pool [Dec 25 14:05:39] DEBUG[22656]: stasis.c:460 stasis_topic_create: Topic 'endpoint:SIP/205': 0x7f0d00000c98 created [Dec 25 14:05:39] DEBUG[22656]: stasis.c:460 stasis_topic_create: Topic 'cache:19/endpoint:SIP/205': 0x7f0d00002958 created [Dec 25 14:05:39] DEBUG[22656]: chan_sip.c:31969 build_peer: Not an IPv4 nor IPv6 address, cannot get port. [Dec 25 14:05:39] DEBUG[22656]: chan_sip.c:31972 build_peer: Not an IPv4 nor IPv6 address, cannot set port. [Dec 25 14:05:39] DEBUG[22656]: chan_sip.c:5662 realtime_peer: -REALTIME- loading peer from database to memory. Name: 205. Peer objects: 0 [Dec 25 14:05:39] DEBUG[22656]: chan_sip.c:5237 sip_destroy_peer: Destroying SIP peer 205 [Dec 25 14:05:39] DEBUG[22656]: devicestate.c:474 do_state_change: Changing state for SIP/205 - state 1 (Not in use) [Dec 25 14:05:39] DEBUG[22757]: stasis.c:405 topic_dtor: Topic 'cache:19/endpoint:SIP/205': 0x7f0d00002958 destroyed [Dec 25 14:05:39] DEBUG[22757]: stasis.c:405 topic_dtor: Topic 'endpoint:SIP/205': 0x7f0d00000c98 destroyed Tekli-Santral*CLI> queue show example_queue example_queue has 0 calls (max unlimited) in 'ringall' strategy (2s holdtime, 35s talktime), W:0, C:1, A:1, SL:0.0% within 0s Members: SIP/205 (ringinuse enabled) (Not in use) has taken 1 calls (last was 2 secs ago) No Callers [Dec 25 14:05:41] DEBUG[22678]: app_queue.c:3647 update_realtime_members: Queue example_queue has no realtime members defined. No need for update [Dec 25 14:05:41] DEBUG[22673]: acl.c:992 ast_ouraddrfor: For destination '192.168.0.33', our source address is '185.88.6.121'. [Dec 25 14:05:41] DEBUG[22673]: chan_sip.c:3908 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 185.88.6.121:5060 [Dec 25 14:05:41] DEBUG[22673]: chan_sip.c:9014 __sip_alloc: Allocating new SIP dialog for MWEyMjhjNzEyOTNiNDNkMTk2ZWMzMzExZDk4NjNjYjA. - INVITE (No RTP) [Dec 25 14:05:41] DEBUG[22673][C-00000002]: sip/reqresp_parser.c:1711 parse_sip_options: Begin: parsing SIP "Supported: replaces" [Dec 25 14:05:41] DEBUG[22673][C-00000002]: sip/reqresp_parser.c:1726 parse_sip_options: Found SIP option: -replaces- [Dec 25 14:05:41] DEBUG[22673][C-00000002]: sip/reqresp_parser.c:1734 parse_sip_options: Matched SIP option: replaces [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:3751 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.0.33:63086 [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:4535 __sip_ack: Stopping retransmission on 'MWEyMjhjNzEyOTNiNDNkMTk2ZWMzMzExZDk4NjNjYjA.' of Response 1: Match Found [Dec 25 14:05:41] DEBUG[22673][C-00000002]: rtp_engine.c:459 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f0c9001b9e8' [Dec 25 14:05:41] DEBUG[22673][C-00000002]: res_rtp_asterisk.c:3202 ast_rtp_new: Allocated port 15270 for RTP instance '0x7f0c9001b9e8' [Dec 25 14:05:41] DEBUG[22673][C-00000002]: rtp_engine.c:476 ast_rtp_instance_new: RTP instance '0x7f0c9001b9e8' is setup and ready to go [Dec 25 14:05:41] DEBUG[22673][C-00000002]: acl.c:830 resolve_first: Multiple addresses. Using the first only [Dec 25 14:05:41] DEBUG[22673][C-00000002]: res_rtp_asterisk.c:5987 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f0c9001b9e8' == Using SIP RTP CoS mark 5 [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:5797 do_setnat: Setting NAT on RTP to On [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:10337 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:10337 process_sdp: Processing session-level SDP o=3cxVCE 208013250 253084845 IN IP4 192.168.0.33... OK. [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:10337 process_sdp: Processing session-level SDP s=3cxVCE Audio Call... UNSUPPORTED OR FAILED. [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:10337 process_sdp: Processing session-level SDP c=IN IP4 192.168.0.33... OK. [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:10337 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Dec 25 14:05:41] DEBUG[22673][C-00000002]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7f0cac0c7140 [Dec 25 14:05:41] DEBUG[22673][C-00000002]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7f0cac0c7140 [Dec 25 14:05:41] DEBUG[22673][C-00000002]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 3 based on m type on 0x7f0cac0c7140 [Dec 25 14:05:41] DEBUG[22673][C-00000002]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7f0cac0c7140 [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK. [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK. [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:10800 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK. [Dec 25 14:05:41] DEBUG[22673][C-00000002]: rtp_engine.c:764 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 34 based on m type on 0x7f0cac0c71b0 [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:10800 process_sdp: Processing media-level (video) SDP c=IN IP4 192.168.0.33... OK. [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:33953 process_crypto: Received offer with crypto line for media stream that is not enabled [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:10800 process_sdp: Processing media-level (video) SDP a=rtpmap:34 H263/90000... OK. [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:33953 process_crypto: Received offer with crypto line for media stream that is not enabled [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:10800 process_sdp: Processing media-level (video) SDP a=fmtp:34 QCIF=1;CIF=1;SQCIF=1;CIF4=1... OK. [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:33953 process_crypto: Received offer with crypto line for media stream that is not enabled [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:10800 process_sdp: Processing media-level (video) SDP a=sendrecv... UNSUPPORTED OR FAILED. [Dec 25 14:05:41] DEBUG[22673][C-00000002]: acl.c:992 ast_ouraddrfor: For destination '192.168.0.33', our source address is '185.88.6.121'. [Dec 25 14:05:41] DEBUG[22673][C-00000002]: res_rtp_asterisk.c:6052 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f0c9001b9e8' [Dec 25 14:05:41] DEBUG[22673][C-00000002]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 0 (0x7f0c9001c8e0) from 0x7f0cac0c7140 to 0x7f0c9001bbb0 [Dec 25 14:05:41] DEBUG[22673][C-00000002]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 3 (0x7f0c90002e50) from 0x7f0cac0c7140 to 0x7f0c9001bbb0 [Dec 25 14:05:41] DEBUG[22673][C-00000002]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x7f0c9001c910) from 0x7f0cac0c7140 to 0x7f0c9001bbb0 [Dec 25 14:05:41] DEBUG[22673][C-00000002]: rtp_engine.c:730 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7f0c9001c8b0) from 0x7f0cac0c7140 to 0x7f0c9001bbb0 [Dec 25 14:05:41] DEBUG[22673][C-00000002]: res_rtp_asterisk.c:5886 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f0c9001b9e8' [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:11098 process_sdp: We're settling with these formats: (ulaw|alaw) [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:26424 handle_request_invite: Checking SIP call limits for device 103 [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:6766 update_call_counter: Updating call counter for incoming call [Dec 25 14:05:41] DEBUG[22656]: chan_sip.c:30388 sip_devicestate: Checking device state for peer 103 [Dec 25 14:05:41] DEBUG[22656]: devicestate.c:474 do_state_change: Changing state for SIP/103 - state 2 (In use) [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:3751 __sip_xmit: Trying to put 'SIP/2.0 404' onto UDP socket destined for 192.168.0.33:63086 [Dec 25 14:05:41] NOTICE[22673][C-00000002]: chan_sip.c:26471 handle_request_invite: Call from '103' (192.168.0.33:63086) to extension '205' rejected because extension not found in context 'dahiliara'. [Dec 25 14:05:41] DEBUG[22685]: app_queue.c:2489 device_state_cb: Device 'SIP/103' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:6766 update_call_counter: Updating call counter for incoming call [Dec 25 14:05:41] DEBUG[22656]: chan_sip.c:30388 sip_devicestate: Checking device state for peer 103 [Dec 25 14:05:41] DEBUG[22656]: devicestate.c:474 do_state_change: Changing state for SIP/103 - state 1 (Not in use) [Dec 25 14:05:41] DEBUG[22685]: app_queue.c:2489 device_state_cb: Device 'SIP/103' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 25 14:05:41] DEBUG[22673][C-00000002]: chan_sip.c:4535 __sip_ack: Stopping retransmission on 'MWEyMjhjNzEyOTNiNDNkMTk2ZWMzMzExZDk4NjNjYjA.' of Response 2: Match Found [Dec 25 14:05:42] DEBUG[22738][C-00000000]: res_rtp_asterisk.c:4808 ast_rtcp_interpret: Got RTCP report of 176 bytes from 192.168.0.33:16797