[Feb 9 23:44:02] DEBUG[26634] chan_sip.c: = Looking for Call ID: 57b06c66-fa0e4334@192.168.0.4 (Checking From) --From tag 69ebfdec2ab461co0 --To-tag [Feb 9 23:44:02] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:02] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5360 [Feb 9 23:44:02] DEBUG[26634] chan_sip.c: = Looking for Call ID: 586eaabf-15dcf0b0@192.168.0.4 (Checking From) --From tag f1d4a1ce8a654ceco1 --To-tag [Feb 9 23:44:02] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:02] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5361 [Feb 9 23:44:04] DEBUG[26634] chan_sip.c: = Looking for Call ID: 173284a7-f5449fa0@10.2.20.149 (Checking From) --From tag 544e2e979b137e70o2 --To-tag [Feb 9 23:44:04] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:04] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.2.20.149:5062 [Feb 9 23:44:05] DEBUG[26634] chan_sip.c: = Looking for Call ID: 7cf01bff-7c482f51@79.187.161.94 (Checking From) --From tag 8f80d072f55b1e9o0 --To-tag [Feb 9 23:44:05] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:05] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 79.187.161.94:5060 [Feb 9 23:44:06] DEBUG[26634] chan_sip.c: = Looking for Call ID: 82508f59-95fdc533@192.168.0.4 (Checking From) --From tag af97b181ce60c92bo0 --To-tag [Feb 9 23:44:06] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:06] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5360 [Feb 9 23:44:06] DEBUG[26634] chan_sip.c: = Looking for Call ID: f4c97922-94ec3dff@192.168.0.4 (Checking From) --From tag fddafed15f4d5c1bo1 --To-tag [Feb 9 23:44:06] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:06] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5361 [Feb 9 23:44:06] DEBUG[26634] chan_sip.c: = Looking for Call ID: 7360545e-de82bc02@192.168.0.3 (Checking From) --From tag 5fe01a6e364f2d32o0 --To-tag [Feb 9 23:44:06] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:06] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5260 [Feb 9 23:44:06] DEBUG[26634] chan_sip.c: = Looking for Call ID: 1d8d8af-60f1be6@192.168.0.3 (Checking From) --From tag 1397508e65846d92o1 --To-tag [Feb 9 23:44:06] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:06] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5261 [Feb 9 23:44:08] DEBUG[26634] chan_sip.c: = Looking for Call ID: 532e133d-465972af@192.168.0.3 (Checking From) --From tag 11f390c54ab2d2c7o0 --To-tag [Feb 9 23:44:08] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:08] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5260 [Feb 9 23:44:08] DEBUG[26634] chan_sip.c: = Looking for Call ID: c4f749e5-71cd6c27@192.168.0.3 (Checking From) --From tag 2965f0d55d9d71f7o1 --To-tag [Feb 9 23:44:08] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:08] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5261 [Feb 9 23:44:08] DEBUG[26634] chan_sip.c: = Looking for Call ID: 772182a8-2a9d50b6@193.200.83.58 (Checking From) --From tag 95ed8b20cf70229eo0 --To-tag [Feb 9 23:44:08] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:08] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 193.200.83.58:5060 [Feb 9 23:44:11] DEBUG[26634] chan_sip.c: = Looking for Call ID: 878f4949-9384d34e@192.168.1.18 (Checking From) --From tag 78de1bbdef5036ao0 --To-tag [Feb 9 23:44:11] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:11] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 80.53.247.78:5060 [Feb 9 23:44:12] DEBUG[26634] chan_sip.c: = Looking for Call ID: 8ab64d22-31c579b9@192.168.0.2 (Checking From) --From tag feee259e824d1b6do0 --To-tag [Feb 9 23:44:12] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:12] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5160 [Feb 9 23:44:12] DEBUG[26634] chan_sip.c: = Looking for Call ID: c656de0e-124e3dbd@192.168.0.2 (Checking From) --From tag 58fa2c16cdb00755o1 --To-tag [Feb 9 23:44:12] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:12] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5161 [Feb 9 23:44:13] DEBUG[26634] chan_sip.c: = Looking for Call ID: b1a57cd8-3c861db7@192.168.0.2 (Checking From) --From tag 88c5d57488b23dcbo0 --To-tag [Feb 9 23:44:13] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:13] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5160 [Feb 9 23:44:13] DEBUG[26634] chan_sip.c: = Looking for Call ID: 20975a64-d64cfd9b@192.168.0.2 (Checking From) --From tag afc2b02cf0a06273o1 --To-tag [Feb 9 23:44:13] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:13] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5161 [Feb 9 23:44:14] DEBUG[26634] chan_sip.c: = Looking for Call ID: 7e90abc1-91214bd@YYY.YYY.YYY.YYY (Checking From) --From tag 31d37431c880670do0 --To-tag [Feb 9 23:44:14] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:14] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5060 [Feb 9 23:44:14] DEBUG[26634] chan_sip.c: = Looking for Call ID: eb295ff1-1c5d6e4d@YYY.YYY.YYY.YYY (Checking From) --From tag 685d6b1175b3ddado1 --To-tag [Feb 9 23:44:14] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:14] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5061 [Feb 9 23:44:16] DEBUG[26634] chan_sip.c: = Looking for Call ID: 2d959c61-af90db92@YYY.YYY.YYY.YYY (Checking From) --From tag 4bfbb20521c7223eo0 --To-tag [Feb 9 23:44:16] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:16] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5060 [Feb 9 23:44:16] DEBUG[26634] chan_sip.c: = Looking for Call ID: 8c0ebe15-6ea9056e@YYY.YYY.YYY.YYY (Checking From) --From tag 6fd41bcdcf308316o1 --To-tag [Feb 9 23:44:16] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:16] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5061 [Feb 9 23:44:17] DEBUG[26634] chan_sip.c: = Looking for Call ID: 57b06c66-fa0e4334@192.168.0.4 (Checking From) --From tag 69ebfdec2ab461co0 --To-tag [Feb 9 23:44:17] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:17] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5360 [Feb 9 23:44:17] DEBUG[26634] chan_sip.c: = Looking for Call ID: 586eaabf-15dcf0b0@192.168.0.4 (Checking From) --From tag f1d4a1ce8a654ceco1 --To-tag [Feb 9 23:44:17] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:17] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5361 [Feb 9 23:44:17] VERBOSE[13597] config.c: == Parsing '/etc/asterisk/logger.conf': [Feb 9 23:44:17] DEBUG[13597] config.c: Parsing /etc/asterisk/logger.conf [Feb 9 23:44:17] VERBOSE[13597] config.c: == Found [Feb 9 23:44:17] VERBOSE[13597] logger.c: Asterisk Queue Logger restarted [Feb 9 23:44:19] DEBUG[26634] chan_sip.c: = Looking for Call ID: 173284a7-f5449fa0@10.2.20.149 (Checking From) --From tag 544e2e979b137e70o2 --To-tag [Feb 9 23:44:19] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:19] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.2.20.149:5062 [Feb 9 23:44:20] DEBUG[26634] chan_sip.c: = Looking for Call ID: 7cf01bff-7c482f51@79.187.161.94 (Checking From) --From tag 8f80d072f55b1e9o0 --To-tag [Feb 9 23:44:20] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:20] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 79.187.161.94:5060 [Feb 9 23:44:21] DEBUG[26634] chan_sip.c: = Looking for Call ID: 82508f59-95fdc533@192.168.0.4 (Checking From) --From tag af97b181ce60c92bo0 --To-tag [Feb 9 23:44:21] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:21] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5360 [Feb 9 23:44:21] DEBUG[26634] chan_sip.c: = Looking for Call ID: f4c97922-94ec3dff@192.168.0.4 (Checking From) --From tag fddafed15f4d5c1bo1 --To-tag [Feb 9 23:44:21] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:21] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5361 [Feb 9 23:44:21] DEBUG[26634] chan_sip.c: = Looking for Call ID: 7360545e-de82bc02@192.168.0.3 (Checking From) --From tag 5fe01a6e364f2d32o0 --To-tag [Feb 9 23:44:21] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:21] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5260 [Feb 9 23:44:21] DEBUG[26634] chan_sip.c: = Looking for Call ID: 1d8d8af-60f1be6@192.168.0.3 (Checking From) --From tag 1397508e65846d92o1 --To-tag [Feb 9 23:44:21] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:21] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5261 [Feb 9 23:44:23] DEBUG[26634] chan_sip.c: = Looking for Call ID: 532e133d-465972af@192.168.0.3 (Checking From) --From tag 11f390c54ab2d2c7o0 --To-tag [Feb 9 23:44:23] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:23] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5260 [Feb 9 23:44:23] DEBUG[26634] chan_sip.c: = Looking for Call ID: c4f749e5-71cd6c27@192.168.0.3 (Checking From) --From tag 2965f0d55d9d71f7o1 --To-tag [Feb 9 23:44:23] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:23] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5261 [Feb 9 23:44:24] DEBUG[26634] chan_sip.c: = Looking for Call ID: 772182a8-2a9d50b6@193.200.83.58 (Checking From) --From tag 95ed8b20cf70229eo0 --To-tag [Feb 9 23:44:24] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:24] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 193.200.83.58:5060 [Feb 9 23:44:26] DEBUG[26634] chan_sip.c: = Looking for Call ID: 878f4949-9384d34e@192.168.1.18 (Checking From) --From tag 78de1bbdef5036ao0 --To-tag [Feb 9 23:44:26] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:26] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 80.53.247.78:5060 [Feb 9 23:44:27] DEBUG[26634] chan_sip.c: = Looking for Call ID: 8ab64d22-31c579b9@192.168.0.2 (Checking From) --From tag feee259e824d1b6do0 --To-tag [Feb 9 23:44:27] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:27] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5160 [Feb 9 23:44:27] DEBUG[26634] chan_sip.c: = Looking for Call ID: c656de0e-124e3dbd@192.168.0.2 (Checking From) --From tag 58fa2c16cdb00755o1 --To-tag [Feb 9 23:44:27] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:27] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5161 [Feb 9 23:44:29] DEBUG[26634] chan_sip.c: = Looking for Call ID: b1a57cd8-3c861db7@192.168.0.2 (Checking From) --From tag 88c5d57488b23dcbo0 --To-tag [Feb 9 23:44:29] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:29] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5160 [Feb 9 23:44:29] DEBUG[26634] chan_sip.c: = Looking for Call ID: 20975a64-d64cfd9b@192.168.0.2 (Checking From) --From tag afc2b02cf0a06273o1 --To-tag [Feb 9 23:44:29] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:29] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5161 [Feb 9 23:44:29] DEBUG[26634] chan_sip.c: = Looking for Call ID: 7e90abc1-91214bd@YYY.YYY.YYY.YYY (Checking From) --From tag 31d37431c880670do0 --To-tag [Feb 9 23:44:29] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:29] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5060 [Feb 9 23:44:29] DEBUG[26634] chan_sip.c: = Looking for Call ID: eb295ff1-1c5d6e4d@YYY.YYY.YYY.YYY (Checking From) --From tag 685d6b1175b3ddado1 --To-tag [Feb 9 23:44:29] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:29] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5061 [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: = Looking for Call ID: 720cdc1606a995bb046320215c8c0b1d@XXX.XXX.XXX.XXX (Checking From) --From tag as50500dcd --To-tag [Feb 9 23:44:30] DEBUG[26634] acl.c: For destination 'XXX.XXX.XXX.XXX', our source address is 'YYY.YYY.YYY.YYY'. [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: Setting SIP_TRANSPORT_UDP with address YYY.YYY.YYY.YYY:5060 [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: Setting NAT on UDPTL to Off [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: Allocating new SIP dialog for 720cdc1606a995bb046320215c8c0b1d@XXX.XXX.XXX.XXX - INVITE (No RTP) [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Feb 9 23:44:30] DEBUG[26634] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, timer" [Feb 9 23:44:30] DEBUG[26634] sip/reqresp_parser.c: Found SIP option: -replaces- [Feb 9 23:44:30] DEBUG[26634] sip/reqresp_parser.c: Matched SIP option: replaces [Feb 9 23:44:30] DEBUG[26634] sip/reqresp_parser.c: Found SIP option: -timer- [Feb 9 23:44:30] DEBUG[26634] sip/reqresp_parser.c: Matched SIP option: timer [Feb 9 23:44:30] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX:5060' into... [Feb 9 23:44:30] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port '5060'. [Feb 9 23:44:30] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:30] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = '667858XXX' AND host = 'dynamic' [Feb 9 23:44:30] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f638426ff00 Query: SELECT * FROM sip_conf WHERE name = '667858XXX' AND host = 'dynamic' [Feb 9 23:44:30] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:30] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:30] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = '667858XXX' [Feb 9 23:44:30] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f6384280500 Query: SELECT * FROM sip_conf WHERE name = '667858XXX' [Feb 9 23:44:30] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: Setting NAT on UDPTL to On [Feb 9 23:44:30] DEBUG[26634] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f6384372f58' [Feb 9 23:44:30] DEBUG[26634] res_rtp_asterisk.c: Allocated port 5074 for RTP instance '0x7f6384372f58' [Feb 9 23:44:30] DEBUG[26634] rtp_engine.c: RTP instance '0x7f6384372f58' is setup and ready to go [Feb 9 23:44:30] DEBUG[26634] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f6384372f58' [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: Setting NAT on RTP to On [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: Setting NAT on UDPTL to On [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: Processing session-level SDP o=root 1662354073 1662354073 IN IP4 XXX.XXX.XXX.XXX... UNSUPPORTED. [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: Processing session-level SDP s=Asterisk PBX 1.6.0.28... UNSUPPORTED. [Feb 9 23:44:30] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:30] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: Processing session-level SDP c=IN IP4 XXX.XXX.XXX.XXX... OK. [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Feb 9 23:44:30] DEBUG[26634] rtp_engine.c: Setting payload 8 based on m type on 0x7f6368b56d00 [Feb 9 23:44:30] DEBUG[26634] rtp_engine.c: Setting payload 101 based on m type on 0x7f6368b56d00 [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED. [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: Processing media-level (audio) SDP a=silenceSupp:off - - - -... UNSUPPORTED. [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Feb 9 23:44:30] DEBUG[26634] rtp_engine.c: Incorporating payload 8 on 0x7f6368b56d00 [Feb 9 23:44:30] DEBUG[26634] rtp_engine.c: Incorporating payload 101 on 0x7f6368b56d00 [Feb 9 23:44:30] DEBUG[26634] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f6384372f58' [Feb 9 23:44:30] DEBUG[26634] rtp_engine.c: Copying payload 8 from 0x7f6368b56d00 to 0x7f6384373120 [Feb 9 23:44:30] DEBUG[26634] rtp_engine.c: Copying payload 101 from 0x7f6368b56d00 to 0x7f6384373120 [Feb 9 23:44:30] DEBUG[26634] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f6384372f58' [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: We're settling with these formats: (alaw) [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: Checking SIP call limits for device 0324223197 [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: Updating call counter for incoming call [Feb 9 23:44:30] DEBUG[26625] devicestate.c: No provider found, checking channel drivers for SIP - sipZZZpl1 [Feb 9 23:44:30] DEBUG[26625] chan_sip.c: Checking device state for peer sipZZZpl1 [Feb 9 23:44:30] DEBUG[26625] devicestate.c: Changing state for SIP/sipZZZpl1 - state 2 (In use) [Feb 9 23:44:30] DEBUG[26625] devicestate.c: device 'SIP/sipZZZpl1' state '2' [Feb 9 23:44:30] DEBUG[26655] app_queue.c: Device 'SIP/sipZZZpl1' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: *** Our native formats are (alaw) [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: *** Joint capabilities are (alaw) [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: *** Our capabilities are (alaw) [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: This channel will not be able to handle video. [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: build_route: Contact hop: [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: SIP/sipZZZpl1-0000011d: New call is still down.... Trying... [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for XXX.XXX.XXX.XXX:5060 [Feb 9 23:44:30] DEBUG[26625] devicestate.c: No provider found, checking channel drivers for SIP - sipZZZpl1 [Feb 9 23:44:30] DEBUG[26625] chan_sip.c: Checking device state for peer sipZZZpl1 [Feb 9 23:44:30] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:30] DEBUG[26625] devicestate.c: Changing state for SIP/sipZZZpl1 - state 2 (In use) [Feb 9 23:44:30] DEBUG[26625] devicestate.c: device 'SIP/sipZZZpl1' state '2' [Feb 9 23:44:30] DEBUG[26655] app_queue.c: Device 'SIP/sipZZZpl1' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 9 23:44:30] DEBUG[13881] pbx.c: Launching 'Answer' [Feb 9 23:44:30] VERBOSE[13881] pbx.c: -- Executing [032XXXXXX@incoming:1] Answer("SIP/sipZZZpl1-0000011d", "") in new stack [Feb 9 23:44:30] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = '032XXXXXX032XXXXXX032XXXXXX' AND host = 'dynamic' [Feb 9 23:44:30] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2f83600 Query: SELECT * FROM sip_conf WHERE name = '032XXXXXX' AND host = 'dynamic' [Feb 9 23:44:30] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:30] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:30] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = '032XXXXXX' [Feb 9 23:44:30] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2f83600 Query: SELECT * FROM sip_conf WHERE name = '032XXXXXX' [Feb 9 23:44:30] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:30] DEBUG[13881] chan_sip.c: SIP answering channel: SIP/sipZZZpl1-0000011d [Feb 9 23:44:30] DEBUG[13881] res_rtp_asterisk.c: Setting the marker bit due to a source update [Feb 9 23:44:30] DEBUG[26625] devicestate.c: No provider found, checking channel drivers for SIP - sipZZZpl1 [Feb 9 23:44:30] DEBUG[26625] chan_sip.c: Checking device state for peer sipZZZpl1 [Feb 9 23:44:30] DEBUG[26625] devicestate.c: Changing state for SIP/sipZZZpl1 - state 2 (In use) [Feb 9 23:44:30] DEBUG[13881] chan_sip.c: Setting framing from config on incoming call [Feb 9 23:44:30] DEBUG[26625] devicestate.c: device 'SIP/sipZZZpl1' state '2' [Feb 9 23:44:30] DEBUG[26655] app_queue.c: Device 'SIP/sipZZZpl1' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 9 23:44:30] DEBUG[13881] chan_sip.c: ** Our capability: (alaw) Video flag: True Text flag: True [Feb 9 23:44:30] DEBUG[13881] chan_sip.c: ** Our prefcodec: (nothing) [Feb 9 23:44:30] DEBUG[13881] chan_sip.c: -- Done with adding codecs to SDP [Feb 9 23:44:30] DEBUG[13881] chan_sip.c: Done building SDP. Settling with this capability: (alaw) [Feb 9 23:44:30] DEBUG[13881] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for XXX.XXX.XXX.XXX:5060 [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: = Looking for Call ID: 720cdc1606a995bb046320215c8c0b1d@XXX.XXX.XXX.XXX (Checking From) --From tag as50500dcd --To-tag as568a43b8 [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Feb 9 23:44:30] DEBUG[26634] chan_sip.c: Stopping retransmission on '720cdc1606a995bb046320215c8c0b1d@XXX.XXX.XXX.XXX' of Response 102: Match Found [Feb 9 23:44:30] DEBUG[13881] pbx.c: Launching 'Goto' [Feb 9 23:44:30] VERBOSE[13881] pbx.c: -- Executing [032XXXXXX@incoming:2] Goto("SIP/sipZZZpl1-0000011d", "incoming,s,10") in new stack [Feb 9 23:44:30] VERBOSE[13881] pbx.c: -- Goto (incoming,s,10) [Feb 9 23:44:30] DEBUG[13881] pbx.c: Launching 'Set' [Feb 9 23:44:30] VERBOSE[13881] pbx.c: -- Executing [s@incoming:10] Set("SIP/sipZZZpl1-0000011d", "TRANSFER_CONTEXT=Inside") in new stack [Feb 9 23:44:30] DEBUG[13881] pbx.c: Launching 'GotoIfTime' [Feb 9 23:44:30] VERBOSE[13881] pbx.c: -- Executing [s@incoming:11] GotoIfTime("SIP/sipZZZpl1-0000011d", "07:00-23:59,mon-fri,*,*?Ivr-main,s,1") in new stack [Feb 9 23:44:30] VERBOSE[13881] pbx.c: -- Goto (Ivr-main,s,1) [Feb 9 23:44:30] DEBUG[13881] pbx.c: Launching 'Wait' [Feb 9 23:44:30] VERBOSE[13881] pbx.c: -- Executing [s@Ivr-main:1] Wait("SIP/sipZZZpl1-0000011d", "1") in new stack [Feb 9 23:44:31] DEBUG[26634] chan_sip.c: = Looking for Call ID: 2d959c61-af90db92@YYY.YYY.YYY.YYY (Checking From) --From tag 4bfbb20521c7223eo0 --To-tag [Feb 9 23:44:31] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:31] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5060 [Feb 9 23:44:31] DEBUG[26634] chan_sip.c: = Looking for Call ID: 8c0ebe15-6ea9056e@YYY.YYY.YYY.YYY (Checking From) --From tag 6fd41bcdcf308316o1 --To-tag [Feb 9 23:44:31] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:31] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5061 [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2f83600 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2eca1c0 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:31] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:31] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:31] DEBUG[26634] chan_sip.c: Allocating new SIP dialog for 431479da26cac81d7db140217219aa53@127.0.1.1 - REGISTER (No RTP) [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2f83a10 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2c063b0 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2f83a10 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2c063b0 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:31] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 3 [Feb 9 23:44:31] DEBUG[26634] acl.c: For destination 'XXX.XXX.XXX.XXX', our source address is 'YYY.YYY.YYY.YYY'. [Feb 9 23:44:31] DEBUG[26634] chan_sip.c: Setting SIP_TRANSPORT_UDP with address YYY.YYY.YYY.YYY:5060 [Feb 9 23:44:31] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 4 [Feb 9 23:44:31] DEBUG[26634] chan_sip.c: Scheduled a registration timeout for XXX.XXX.XXX.XXX id #126363 [Feb 9 23:44:31] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:31] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:31] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:31] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:31] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:31] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:31] DEBUG[26634] chan_sip.c: Initializing initreq for method REGISTER - callid 431479da26cac81d7db140217219aa53@127.0.1.1 [Feb 9 23:44:31] DEBUG[26634] chan_sip.c: REGISTER attempt 1 to 0324407451@XXX.XXX.XXX.XXX [Feb 9 23:44:31] DEBUG[26634] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for XXX.XXX.XXX.XXX:5060 [Feb 9 23:44:31] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 3 [Feb 9 23:44:31] DEBUG[13881] pbx.c: Launching 'BackGround' [Feb 9 23:44:31] VERBOSE[13881] pbx.c: -- Executing [s@Ivr-main:2] BackGround("SIP/sipZZZpl1-0000011d", "ivr/welcomedga&ivr/hours&ivr/operator&ivr/sales&ivr/accountants&ivr/technical&ivr/marketing&ivr/warehouse&ivr/thankyou") in new stack [Feb 9 23:44:31] DEBUG[13881] channel.c: Set channel SIP/sipZZZpl1-0000011d to write format slin [Feb 9 23:44:31] DEBUG[13881] res_rtp_asterisk.c: Ooh, format changed from unknown to alaw [Feb 9 23:44:31] DEBUG[13881] res_rtp_asterisk.c: Created smoother: format: alaw ms: 20 len: 160 [Feb 9 23:44:31] DEBUG[13881] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Feb 9 23:44:31] VERBOSE[13881] file.c: -- Playing 'ivr/welcomedga.slin' (language 'pl') [Feb 9 23:44:31] DEBUG[26634] chan_sip.c: = Looking for Call ID: 431479da26cac81d7db140217219aa53@127.0.1.1 (Checking To) --From tag as65ed24e9 --To-tag as6882bac8 [Feb 9 23:44:31] DEBUG[26634] chan_sip.c: Stopping retransmission on '431479da26cac81d7db140217219aa53@127.0.1.1' of Request 1512: Match Found [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2dc5a10 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2dc5a10 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:31] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:31] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:31] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:31] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:31] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:31] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:31] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:31] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:31] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:31] DEBUG[26634] chan_sip.c: Initializing already initialized SIP dialog 431479da26cac81d7db140217219aa53@127.0.1.1 (presumably reinvite) [Feb 9 23:44:31] DEBUG[26634] chan_sip.c: REGISTER attempt 2 to 0324407451@XXX.XXX.XXX.XXX [Feb 9 23:44:31] DEBUG[26634] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for XXX.XXX.XXX.XXX:5060 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: = Looking for Call ID: 431479da26cac81d7db140217219aa53@127.0.1.1 (Checking To) --From tag as526955f8 --To-tag as6882bac8 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Stopping retransmission on '431479da26cac81d7db140217219aa53@127.0.1.1' of Request 1513: Match Found [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Registration successful [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Cancelling timeout 126363 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 2 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 1 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 2 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2dc5a10 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2dc5a10 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Allocating new SIP dialog for 417845b34c7e798f50c27b9f75590999@127.0.1.1 - REGISTER (No RTP) [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2f61800 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2f61800 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2f61800 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2f61800 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 3 [Feb 9 23:44:32] DEBUG[26634] acl.c: For destination 'XXX.XXX.XXX.XXX', our source address is 'YYY.YYY.YYY.YYY'. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Setting SIP_TRANSPORT_UDP with address YYY.YYY.YYY.YYY:5060 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 4 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Scheduled a registration timeout for XXX.XXX.XXX.XXX id #126368 [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Initializing initreq for method REGISTER - callid 417845b34c7e798f50c27b9f75590999@127.0.1.1 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: REGISTER attempt 1 to 0324223197@XXX.XXX.XXX.XXX [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for XXX.XXX.XXX.XXX:5060 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 3 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: = Looking for Call ID: 417845b34c7e798f50c27b9f75590999@127.0.1.1 (Checking To) --From tag as3626a6bd --To-tag as29a8c376 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Stopping retransmission on '417845b34c7e798f50c27b9f75590999@127.0.1.1' of Request 1512: Match Found [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f638426ff00 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f6384280500 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Initializing already initialized SIP dialog 417845b34c7e798f50c27b9f75590999@127.0.1.1 (presumably reinvite) [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: REGISTER attempt 2 to 0324223197@XXX.XXX.XXX.XXX [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for XXX.XXX.XXX.XXX:5060 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: = Looking for Call ID: 417845b34c7e798f50c27b9f75590999@127.0.1.1 (Checking To) --From tag as049444f3 --To-tag as29a8c376 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Stopping retransmission on '417845b34c7e798f50c27b9f75590999@127.0.1.1' of Request 1513: Match Found [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Registration successful [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Cancelling timeout 126368 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 2 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 1 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 2 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: = Looking for Call ID: 57b06c66-fa0e4334@192.168.0.4 (Checking From) --From tag 69ebfdec2ab461co0 --To-tag [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5360 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: = Looking for Call ID: 586eaabf-15dcf0b0@192.168.0.4 (Checking From) --From tag f1d4a1ce8a654ceco1 --To-tag [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5361 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f638426ff00 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f6384280500 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Allocating new SIP dialog for 47549f0100758ef67284ee453373a936@127.0.1.1 - REGISTER (No RTP) [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f6384280500 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f6384280500 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f6384280500 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f6384280500 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 3 [Feb 9 23:44:32] DEBUG[26634] acl.c: For destination 'XXX.XXX.XXX.XXX', our source address is 'YYY.YYY.YYY.YYY'. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Setting SIP_TRANSPORT_UDP with address YYY.YYY.YYY.YYY:5060 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 4 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Scheduled a registration timeout for XXX.XXX.XXX.XXX id #126375 [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Initializing initreq for method REGISTER - callid 47549f0100758ef67284ee453373a936@127.0.1.1 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: REGISTER attempt 1 to 0324239625@XXX.XXX.XXX.XXX [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for XXX.XXX.XXX.XXX:5060 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 3 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f6384280500 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f6384280500 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Allocating new SIP dialog for 7f25a07002d1c2dd1e46c0c4492b6846@127.0.1.1 - REGISTER (No RTP) [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2f18110 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f638426a740 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f6384238d40 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2f83740 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 3 [Feb 9 23:44:32] DEBUG[26634] acl.c: For destination 'XXX.XXX.XXX.XXX', our source address is 'YYY.YYY.YYY.YYY'. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Setting SIP_TRANSPORT_UDP with address YYY.YYY.YYY.YYY:5060 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 4 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Scheduled a registration timeout for XXX.XXX.XXX.XXX id #126377 [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Initializing initreq for method REGISTER - callid 7f25a07002d1c2dd1e46c0c4492b6846@127.0.1.1 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: REGISTER attempt 1 to 032XXXXXX@XXX.XXX.XXX.XXX [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for XXX.XXX.XXX.XXX:5060 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 3 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2f79da0 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f6384307db0 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Allocating new SIP dialog for 7b3301eb113b64a0313340347a209d3b@127.0.1.1 - REGISTER (No RTP) [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f63842fd7a0 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f638425d5f0 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2f61800 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f6384338510 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 3 [Feb 9 23:44:32] DEBUG[26634] acl.c: For destination 'XXX.XXX.XXX.XXX', our source address is 'YYY.YYY.YYY.YYY'. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Setting SIP_TRANSPORT_UDP with address YYY.YYY.YYY.YYY:5060 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 4 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Scheduled a registration timeout for XXX.XXX.XXX.XXX id #126379 [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Initializing initreq for method REGISTER - callid 7b3301eb113b64a0313340347a209d3b@127.0.1.1 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: REGISTER attempt 1 to 0324212515@XXX.XXX.XXX.XXX [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for XXX.XXX.XXX.XXX:5060 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 3 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f63842aae30 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f63842d52e0 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Allocating new SIP dialog for 41932455282eba974c519ea87a5e4cf3@127.0.1.1 - REGISTER (No RTP) [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f6384238d40 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f6384307db0 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f63842fd7a0 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2f61800 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 3 [Feb 9 23:44:32] DEBUG[26634] acl.c: For destination 'XXX.XXX.XXX.XXX', our source address is 'YYY.YYY.YYY.YYY'. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Setting SIP_TRANSPORT_UDP with address YYY.YYY.YYY.YYY:5060 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 4 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Scheduled a registration timeout for XXX.XXX.XXX.XXX id #126381 [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Initializing initreq for method REGISTER - callid 41932455282eba974c519ea87a5e4cf3@127.0.1.1 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: REGISTER attempt 1 to 0324239622@XXX.XXX.XXX.XXX [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for XXX.XXX.XXX.XXX:5060 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 3 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: = Looking for Call ID: 47549f0100758ef67284ee453373a936@127.0.1.1 (Checking To) --From tag as7c26ecf1 --To-tag as0e7f1bfb [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Stopping retransmission on '47549f0100758ef67284ee453373a936@127.0.1.1' of Request 1512: Match Found [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2f7a5a0 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f638425d5f0 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Initializing already initialized SIP dialog 47549f0100758ef67284ee453373a936@127.0.1.1 (presumably reinvite) [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: REGISTER attempt 2 to 0324239625@XXX.XXX.XXX.XXX [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for XXX.XXX.XXX.XXX:5060 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: = Looking for Call ID: 7f25a07002d1c2dd1e46c0c4492b6846@127.0.1.1 (Checking To) --From tag as6d0e586f --To-tag as63ca1a71 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Stopping retransmission on '7f25a07002d1c2dd1e46c0c4492b6846@127.0.1.1' of Request 1513: Match Found [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2f7a5a0 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2f7a5a0 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Initializing already initialized SIP dialog 7f25a07002d1c2dd1e46c0c4492b6846@127.0.1.1 (presumably reinvite) [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: REGISTER attempt 2 to 032XXXXXX@XXX.XXX.XXX.XXX [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for XXX.XXX.XXX.XXX:5060 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: = Looking for Call ID: 7b3301eb113b64a0313340347a209d3b@127.0.1.1 (Checking To) --From tag as68180048 --To-tag as5b1527f4 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Stopping retransmission on '7b3301eb113b64a0313340347a209d3b@127.0.1.1' of Request 1513: Match Found [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2f180b0 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f6384338510 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Initializing already initialized SIP dialog 7b3301eb113b64a0313340347a209d3b@127.0.1.1 (presumably reinvite) [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: REGISTER attempt 2 to 0324212515@XXX.XXX.XXX.XXX [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for XXX.XXX.XXX.XXX:5060 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: = Looking for Call ID: 41932455282eba974c519ea87a5e4cf3@127.0.1.1 (Checking To) --From tag as015b6be1 --To-tag as4634868a [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Stopping retransmission on '41932455282eba974c519ea87a5e4cf3@127.0.1.1' of Request 1514: Match Found [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2f61800 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' AND host = 'dynamic' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: PostgreSQL RealTime: Result=0x7f63842aae30 Query: SELECT * FROM sip_conf WHERE name = 'XXX.XXX.XXX.XXX' [Feb 9 23:44:32] DEBUG[26634] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table sip_conf@asterisk. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX' into... [Feb 9 23:44:32] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port ''. [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Initializing already initialized SIP dialog 41932455282eba974c519ea87a5e4cf3@127.0.1.1 (presumably reinvite) [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: REGISTER attempt 2 to 0324239622@XXX.XXX.XXX.XXX [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for XXX.XXX.XXX.XXX:5060 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: = Looking for Call ID: 47549f0100758ef67284ee453373a936@127.0.1.1 (Checking To) --From tag as2a71ef48 --To-tag as0e7f1bfb [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Stopping retransmission on '47549f0100758ef67284ee453373a936@127.0.1.1' of Request 1513: Match Found [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Registration successful [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Cancelling timeout 126375 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 2 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 1 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 2 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: = Looking for Call ID: 7f25a07002d1c2dd1e46c0c4492b6846@127.0.1.1 (Checking To) --From tag as1c47d3b9 --To-tag as63ca1a71 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Stopping retransmission on '7f25a07002d1c2dd1e46c0c4492b6846@127.0.1.1' of Request 1514: Match Found [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Registration successful [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Cancelling timeout 126377 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 2 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 1 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 2 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: = Looking for Call ID: 7b3301eb113b64a0313340347a209d3b@127.0.1.1 (Checking To) --From tag as6cde500b --To-tag as5b1527f4 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Stopping retransmission on '7b3301eb113b64a0313340347a209d3b@127.0.1.1' of Request 1514: Match Found [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Registration successful [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Cancelling timeout 126379 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 2 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 1 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 2 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: = Looking for Call ID: 41932455282eba974c519ea87a5e4cf3@127.0.1.1 (Checking To) --From tag as72fc8e6f --To-tag as4634868a [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Stopping retransmission on '41932455282eba974c519ea87a5e4cf3@127.0.1.1' of Request 1515: Match Found [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Registration successful [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: Cancelling timeout 126381 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 2 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 1 [Feb 9 23:44:32] DEBUG[26634] chan_sip.c: SIP Registry XXX.XXX.XXX.XXX: refcount now 2 [Feb 9 23:44:34] DEBUG[26634] chan_sip.c: = Looking for Call ID: 173284a7-f5449fa0@10.2.20.149 (Checking From) --From tag 544e2e979b137e70o2 --To-tag [Feb 9 23:44:34] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:34] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.2.20.149:5062 [Feb 9 23:44:34] DEBUG[26634] chan_sip.c: = Looking for Call ID: 720cdc1606a995bb046320215c8c0b1d@XXX.XXX.XXX.XXX (Checking From) --From tag as50500dcd --To-tag as568a43b8 [Feb 9 23:44:34] DEBUG[26634] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Feb 9 23:44:34] DEBUG[26634] netsock2.c: Splitting 'XXX.XXX.XXX.XXX:5060' into... [Feb 9 23:44:34] DEBUG[26634] netsock2.c: ...host 'XXX.XXX.XXX.XXX' and port '5060'. [Feb 9 23:44:34] DEBUG[26634] chan_sip.c: Setting SIP_ALREADYGONE on dialog 720cdc1606a995bb046320215c8c0b1d@XXX.XXX.XXX.XXX [Feb 9 23:44:34] DEBUG[26634] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f6384372f58' [Feb 9 23:44:34] DEBUG[26634] chan_sip.c: Received bye, issuing owner hangup [Feb 9 23:44:34] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for XXX.XXX.XXX.XXX:5060 [Feb 9 23:44:34] DEBUG[13881] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 9 23:44:34] DEBUG[13881] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Feb 9 23:44:34] DEBUG[13881] channel.c: Set channel SIP/sipZZZpl1-0000011d to write format alaw [Feb 9 23:44:34] DEBUG[13881] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:34] ERROR[13881] res_config_pgsql.c: PostgreSQL RealTime: Failed to query 'extensions_conf@asterisk'. [Feb 9 23:44:34] ERROR[13881] res_config_pgsql.c: PostgreSQL RealTime: Query Failed: SELECT * FROM extensions_conf WHERE exten LIKE 'ÿ%' AND context = 'Ivr-main' AND priority = '1' [Feb 9 23:44:34] ERROR[13881] res_config_pgsql.c: PostgreSQL RealTime: Query Failed because: ERROR: invalid byte sequence for encoding "UTF8": 0xff (PGRES_FATAL_ERROR) [Feb 9 23:44:34] DEBUG[13881] res_config_pgsql.c: PostgreSQL query attempt 1 [Feb 9 23:44:34] DEBUG[13881] res_config_pgsql.c: PostgreSQL query successful: SELECT * FROM extensions_conf WHERE exten LIKE '\_%' AND context = 'Ivr-main' AND priority = '1' ORDER BY exten [Feb 9 23:44:34] DEBUG[13881] res_config_pgsql.c: PostgreSQL RealTime: Result=0x2fffe00 Query: SELECT * FROM extensions_conf WHERE exten LIKE '\_%' AND context = 'Ivr-main' AND priority = '1' ORDER BY exten [Feb 9 23:44:34] DEBUG[13881] res_config_pgsql.c: PostgreSQL RealTime: Found 2 rows. [Feb 9 23:44:34] DEBUG[13881] pbx.c: Spawn extension (Ivr-main,s,2) exited non-zero on 'SIP/sipZZZpl1-0000011d' [Feb 9 23:44:34] VERBOSE[13881] pbx.c: == Spawn extension (Ivr-main, s, 2) exited non-zero on 'SIP/sipZZZpl1-0000011d' [Feb 9 23:44:34] DEBUG[13881] channel.c: Soft-Hanging up channel 'SIP/sipZZZpl1-0000011d' [Feb 9 23:44:34] DEBUG[13881] pbx.c: Launching 'Hangup' [Feb 9 23:44:34] VERBOSE[13881] pbx.c: -- Executing [h@Ivr-main:1] Hangup("SIP/sipZZZpl1-0000011d", "") in new stack [Feb 9 23:44:34] DEBUG[13881] pbx.c: Spawn extension (Ivr-main,h,1) exited non-zero on 'SIP/sipZZZpl1-0000011d' [Feb 9 23:44:34] VERBOSE[13881] pbx.c: == Spawn extension (Ivr-main, h, 1) exited non-zero on 'SIP/sipZZZpl1-0000011d' [Feb 9 23:44:34] DEBUG[13881] channel.c: Hanging up channel 'SIP/sipZZZpl1-0000011d' [Feb 9 23:44:34] DEBUG[13881] chan_sip.c: Hanging up zombie call. Be scared. [Feb 9 23:44:34] DEBUG[13881] chan_sip.c: Updating call counter for incoming call [Feb 9 23:44:34] DEBUG[26625] devicestate.c: No provider found, checking channel drivers for SIP - sipZZZpl1 [Feb 9 23:44:34] DEBUG[26625] chan_sip.c: Checking device state for peer sipZZZpl1 [Feb 9 23:44:34] DEBUG[26625] devicestate.c: Changing state for SIP/sipZZZpl1 - state 1 (Not in use) [Feb 9 23:44:34] DEBUG[26625] devicestate.c: device 'SIP/sipZZZpl1' state '1' [Feb 9 23:44:34] DEBUG[26655] app_queue.c: Device 'SIP/sipZZZpl1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 9 23:44:34] DEBUG[13881] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f6384372f58' [Feb 9 23:44:34] DEBUG[13881] pbx.c: Function result is '2012-02-09 23:44:30' [Feb 9 23:44:34] DEBUG[13881] pbx.c: Function result is '"667858XXX" <667858XXX>' [Feb 9 23:44:34] DEBUG[13881] pbx.c: Function result is 'Ivr-main' [Feb 9 23:44:34] DEBUG[13881] pbx.c: Function result is 'SIP/sipZZZpl1-0000011d' [Feb 9 23:44:34] DEBUG[13881] pbx.c: Function result is '(null)' [Feb 9 23:44:34] DEBUG[13881] pbx.c: Function result is 'BackGround' [Feb 9 23:44:34] DEBUG[13881] pbx.c: Function result is 'ivr/welcomedga&ivr/hours&ivr/operator&ivr/sales&ivr/accountants&ivr/technical&i' [Feb 9 23:44:34] DEBUG[13881] pbx.c: Function result is '4' [Feb 9 23:44:34] DEBUG[13881] pbx.c: Function result is '4' [Feb 9 23:44:34] DEBUG[13881] pbx.c: Function result is 'ANSWERED' [Feb 9 23:44:34] DEBUG[13881] pbx.c: Function result is 'DOCUMENTATION' [Feb 9 23:44:34] DEBUG[13881] pbx.c: Function result is '(null)' [Feb 9 23:44:34] DEBUG[13881] pbx.c: Function result is '1328827470.290' [Feb 9 23:44:34] DEBUG[13881] pbx.c: Function result is '(null)' [Feb 9 23:44:34] DEBUG[13881] pbx.c: Function result is '(null)' [Feb 9 23:44:34] DEBUG[13881] cdr_sqlite3_custom.c: About to log: INSERT INTO cdr (calldate,clid,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield,test) VALUES ('2012-02-09 23:44:30','"667858XXX" <667858XXX>','Ivr-main','SIP/sipZZZpl1-0000011d','','BackGround','ivr/welcomedga&ivr/hours&ivr/operator&ivr/sales&ivr/accountants&ivr/technical&i','4','4','ANSWERED','DOCUMENTATION','','1328827470.290','','') [Feb 9 23:44:34] VERBOSE[13881] cdr_pgsql.c: > [INSERT INTO cdr ("calldate","clid","src","dst","dcontext","channel","lastapp","lastdata","duration","billsec","disposition","amaflags","uniqueid") VALUES ('2012-02-09 23:44:30','"667858XXX" <667858XXX>','667858XXX','s','Ivr-main','SIP/sipZZZpl1-0000011d','BackGround','ivr/welcomedga&ivr/hours&ivr/operator&ivr/sales&ivr/accountants&ivr/technical&i',4,4,'ANSWERED',3,'1328827470.290')] [Feb 9 23:44:34] DEBUG[13881] cdr_pgsql.c: inserting a CDR record. [Feb 9 23:44:34] DEBUG[26625] devicestate.c: No provider found, checking channel drivers for SIP - sipZZZpl1 [Feb 9 23:44:34] DEBUG[26625] chan_sip.c: Checking device state for peer sipZZZpl1 [Feb 9 23:44:34] DEBUG[26625] devicestate.c: Changing state for SIP/sipZZZpl1 - state 1 (Not in use) [Feb 9 23:44:34] DEBUG[26625] devicestate.c: device 'SIP/sipZZZpl1' state '1' [Feb 9 23:44:34] DEBUG[26655] app_queue.c: Device 'SIP/sipZZZpl1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 9 23:44:35] DEBUG[26634] chan_sip.c: = Looking for Call ID: 7cf01bff-7c482f51@79.187.161.94 (Checking From) --From tag 8f80d072f55b1e9o0 --To-tag [Feb 9 23:44:35] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:35] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 79.187.161.94:5060 [Feb 9 23:44:36] DEBUG[26634] chan_sip.c: = Looking for Call ID: 82508f59-95fdc533@192.168.0.4 (Checking From) --From tag af97b181ce60c92bo0 --To-tag [Feb 9 23:44:36] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:36] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5360 [Feb 9 23:44:36] DEBUG[26634] chan_sip.c: = Looking for Call ID: f4c97922-94ec3dff@192.168.0.4 (Checking From) --From tag fddafed15f4d5c1bo1 --To-tag [Feb 9 23:44:36] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:36] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5361 [Feb 9 23:44:36] DEBUG[26634] chan_sip.c: = Looking for Call ID: 7360545e-de82bc02@192.168.0.3 (Checking From) --From tag 5fe01a6e364f2d32o0 --To-tag [Feb 9 23:44:36] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:36] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5260 [Feb 9 23:44:36] DEBUG[26634] chan_sip.c: = Looking for Call ID: 1d8d8af-60f1be6@192.168.0.3 (Checking From) --From tag 1397508e65846d92o1 --To-tag [Feb 9 23:44:36] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:36] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5261 [Feb 9 23:44:38] DEBUG[26634] chan_sip.c: = Looking for Call ID: 532e133d-465972af@192.168.0.3 (Checking From) --From tag 11f390c54ab2d2c7o0 --To-tag [Feb 9 23:44:38] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:38] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5260 [Feb 9 23:44:38] DEBUG[26634] chan_sip.c: = Looking for Call ID: c4f749e5-71cd6c27@192.168.0.3 (Checking From) --From tag 2965f0d55d9d71f7o1 --To-tag [Feb 9 23:44:38] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:38] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5261 [Feb 9 23:44:39] DEBUG[26634] chan_sip.c: = Looking for Call ID: 772182a8-2a9d50b6@193.200.83.58 (Checking From) --From tag 95ed8b20cf70229eo0 --To-tag [Feb 9 23:44:39] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:39] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 193.200.83.58:5060 [Feb 9 23:44:42] DEBUG[26634] chan_sip.c: = Looking for Call ID: 878f4949-9384d34e@192.168.1.18 (Checking From) --From tag 78de1bbdef5036ao0 --To-tag [Feb 9 23:44:42] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:42] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 80.53.247.78:5060 [Feb 9 23:44:42] DEBUG[26634] chan_sip.c: = Looking for Call ID: 8ab64d22-31c579b9@192.168.0.2 (Checking From) --From tag feee259e824d1b6do0 --To-tag [Feb 9 23:44:42] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:42] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5160 [Feb 9 23:44:42] DEBUG[26634] chan_sip.c: = Looking for Call ID: c656de0e-124e3dbd@192.168.0.2 (Checking From) --From tag 58fa2c16cdb00755o1 --To-tag [Feb 9 23:44:42] DEBUG[26634] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Feb 9 23:44:42] DEBUG[26634] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for YYY.YYY.YYY.YYY:5161