Script started on Sun 31 Dec 2006 12:05:48 AM EST root@avalon:/tmp# asterixk k sk -n -vvvvc Asterisk SVN-branch-1.4-r49066, Copyright (C) 1999 - 2006 Digium, Inc. and others. Created by Mark Spencer Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details. This is free software, with components licensed under the GNU General Public License version 2 and other licenses; you are welcome to redistribute it under certain conditions. Type 'core show license' for details. ========================================================================= == Parsing '/etc/asterisk/asterisk.conf': Found == Parsing '/etc/asterisk/extconfig.conf': Found == Parsing '/etc/asterisk/logger.conf': Found Asterisk Event Logger Started /var/log/asterisk/event_log Asterisk Dynamic Loader Starting: == Parsing '/etc/asterisk/modules.conf': Found == Parsing '/etc/asterisk/http.conf': Found == Manager registered action Ping == Manager registered action Events == Manager registered action Logoff == Manager registered action Hangup == Manager registered action Status == Manager registered action Setvar == Manager registered action Getvar == Manager registered action GetConfig == Manager registered action UpdateConfig == Manager registered action Redirect == Manager registered action Originate == Manager registered action Command == Manager registered action ExtensionState == Manager registered action AbsoluteTimeout == Manager registered action MailboxStatus == Manager registered action MailboxCount == Manager registered action ListCommands == Manager registered action UserEvent == Manager registered action WaitEvent == Parsing '/etc/asterisk/manager.conf': Found Asterisk Management interface listening on port 5038 [Dec 31 00:05:57] NOTICE[17413]: cdr.c:1092 do_reload: CDR simple logging enabled. == Parsing '/etc/asterisk/rtp.conf': Found == RTP Allocating from port range 10000 -> 12000 == UDPTL allocating from port range 4500 -> 4999 Asterisk PBX Core Initializing Registering builtin applications: [Answer] == Registered application 'Answer' [BackGround] == Registered application 'BackGround' [Busy] == Registered application 'Busy' [Congestion] == Registered application 'Congestion' [Goto] == Registered application 'Goto' [GotoIf] == Registered application 'GotoIf' [GotoIfTime] == Registered application 'GotoIfTime' [ExecIfTime] == Registered application 'ExecIfTime' [Hangup] == Registered application 'Hangup' [NoOp] == Registered application 'NoOp' [Progress] == Registered application 'Progress' [ResetCDR] == Registered application 'ResetCDR' [Ringing] == Registered application 'Ringing' [SayNumber] == Registered application 'SayNumber' [SayDigits] == Registered application 'SayDigits' [SayAlpha] == Registered application 'SayAlpha' [SayPhonetic] == Registered application 'SayPhonetic' [SetAMAFlags] == Registered application 'SetAMAFlags' [SetGlobalVar] == Registered application 'SetGlobalVar' [Set] == Registered application 'Set' [ImportVar] == Registered application 'ImportVar' [Wait] == Registered application 'Wait' [WaitExten] == Registered application 'WaitExten' == Manager registered action DBGet == Manager registered action DBPut == Parsing '/etc/asterisk/enum.conf': Found Asterisk Dynamic Loader Starting: == Parsing '/etc/asterisk/modules.conf': Found [Dec 31 00:05:57] NOTICE[17413]: loader.c:792 load_modules: 151 modules will be loaded. == Registered application 'MusicOnHold' == Registered application 'WaitMusicOnHold' == Registered application 'SetMusicOnHold' == Registered application 'StartMusicOnHold' == Registered application 'StopMusicOnHold' == Parsing '/etc/asterisk/musiconhold.conf': Found res_musiconhold.so => (Music On Hold Resource) == Parsing '/etc/asterisk/indications.conf': Found -- Registered indication country 'cl' -- Registered indication country 'tw' -- Registered indication country 'us' -- Registered indication country 'au' -- Registered indication country 'fr' -- Registered indication country 'de' -- Registered indication country 'nl' -- Registered indication country 'uk' -- Registered indication country 'fi' -- Registered indication country 'no' -- Registered indication country 'br' -- Registered indication country 'za' -- Registered indication country 'it' -- Registered indication country 'us-o' -- Registered indication country 'gr' -- Registered indication country 'ru' -- Registered indication country 'nz' -- Setting default indication country to 'us' == Registered application 'PlayTones' == Registered application 'StopPlayTones' res_indications.so => (Indications Resource) == Registered application 'Monitor' == Registered application 'StopMonitor' == Registered application 'ChangeMonitor' == Registered application 'PauseMonitor' == Registered application 'UnpauseMonitor' == Manager registered action Monitor == Manager registered action StopMonitor == Manager registered action ChangeMonitor == Manager registered action PauseMonitor == Manager registered action UnpauseMonitor res_monitor.so => (Call Monitoring Resource) == Parsing '/etc/asterisk/adsi.conf': Found res_adsi.so => (ADSI Resource (not optional)) == Parsing '/etc/asterisk/features.conf': Found -- Registered extension context 'parkedcalls' -- Added extension '6070' priority 1 to parkedcalls == Registered application 'ParkedCall' == Registered application 'Park' == Manager registered action ParkedCalls == Manager registered action Park res_features.so => (Call Features Resource) -- Loaded PUBLIC key 'iaxtel' -- Loaded PUBLIC key 'freeworlddialup' res_crypto.so => (Cryptographic Digital Signatures) [Dec 31 00:05:57] NOTICE[17413]: res_smdi.c:539 smdi_load: Unable to load config smdi.conf: SMDI disabled [Dec 31 00:05:57] WARNING[17413]: res_smdi.c:722 load_module: No SMDI interfaces are available to listen on, not starting SDMI listener. res_speech.so => (Generic Speech Recognition API) [Dec 31 00:05:57] WARNING[17413]: res_jabber.c:2265 aji_load_config: No such configuration file jabber.conf [Dec 31 00:05:57] ERROR[17413]: res_jabber.c:2362 aji_reload: JABBER: Failed to load config. == Registered application 'DeadAGI' == Registered application 'EAGI' == Registered application 'AGI' res_agi.so => (Asterisk Gateway Interface (AGI)) == Parsing '/etc/asterisk/sip.conf': Found [Dec 31 00:05:57] DEBUG[17413]: acl.c:199 ast_append_ha: 172.31.3.0/24/24 appended to acl for peer [Dec 31 00:05:57] DEBUG[17413]: acl.c:199 ast_append_ha: 192.168.0.0/24/24 appended to acl for peer [Dec 31 00:05:57] DEBUG[17413]: acl.c:199 ast_append_ha: 192.168.42.0/24/24 appended to acl for peer [Dec 31 00:05:57] DEBUG[17413]: acl.c:199 ast_append_ha: 192.168.10.0/24/24 appended to acl for peer -- SIP Seeding peer from astdb: 'sipura1' at sipura1@172.31.3.7:5060 for 3600 -- SIP Seeding peer from astdb: 'sipura2' at sipura2@172.31.3.7:5061 for 3600 [Dec 31 00:05:57] DEBUG[17413]: db.c:197 ast_db_get: Unable to find key 'nivex' in family 'SIP/Registry' -- SIP Seeding peer from astdb: 'cisco' at cisco@172.31.3.8:5060 for 3600 -- SIP Seeding peer from astdb: 'cmpalmer' at cmpalmer@192.168.10.14:5060 for 300 == SIP Listening on 0.0.0.0:5060 == Using SIP TOS: CS3 == Registered channel type 'SIP' (Session Initiation Protocol (SIP)) == Registered application 'SIPDtmfMode' == Registered application 'SIPAddHeader' == Registered custom function SIP_HEADER == Registered custom function SIPPEER == Registered custom function SIPCHANINFO == Registered custom function CHECKSIPDOMAIN == Manager registered action SIPpeers == Manager registered action SIPshowpeer chan_sip.so => (Session Initiation Protocol (SIP)) == Registered channel type 'Agent' (Call Agent Proxy Channel) == Parsing '/etc/asterisk/agents.conf': Found == Registered application 'AgentLogin' == Registered application 'AgentCallbackLogin' == Registered application 'AgentMonitorOutgoing' == Manager registered action Agents == Manager registered action AgentLogoff == Manager registered action AgentCallbackLogin == Registered custom function AGENT chan_agent.so => (Agent Proxy Channel) == Parsing '/etc/asterisk/mgcp.conf': Found == MGCP Listening on 0.0.0.0:2727 == Using TOS bits 0 == Registered channel type 'MGCP' (Media Gateway Control Protocol (MGCP)) chan_mgcp.so => (Media Gateway Control Protocol (MGCP)) == Registered custom function IAXPEER [Dec 31 00:05:57] WARNING[17413]: cli.c:1605 __ast_cli_register: Command 'iax2 show cache' already registered (or something close enough) [Dec 31 00:05:57] WARNING[17413]: cli.c:1605 __ast_cli_register: Command 'iax2 show channels' already registered (or something close enough) [Dec 31 00:05:57] WARNING[17413]: cli.c:1605 __ast_cli_register: Command 'iax2 show firmware' already registered (or something close enough) [Dec 31 00:05:57] WARNING[17413]: cli.c:1605 __ast_cli_register: Command 'iax2 show netstats' already registered (or something close enough) [Dec 31 00:05:57] WARNING[17413]: cli.c:1605 __ast_cli_register: Command 'iax2 show peers' already registered (or something close enough) [Dec 31 00:05:57] WARNING[17413]: cli.c:1605 __ast_cli_register: Command 'iax2 show registry' already registered (or something close enough) [Dec 31 00:05:57] WARNING[17413]: cli.c:1605 __ast_cli_register: Command 'iax2 show stats' already registered (or something close enough) [Dec 31 00:05:57] WARNING[17413]: cli.c:1605 __ast_cli_register: Command 'iax2 show threads' already registered (or something close enough) [Dec 31 00:05:57] WARNING[17413]: cli.c:1605 __ast_cli_register: Command 'iax2 show users' already registered (or something close enough) == Registered application 'IAX2Provision' == Manager registered action IAXpeers == Manager registered action IAXnetstats == Parsing '/etc/asterisk/iax.conf': Found > doing dnsmgr_lookup for 'iax.fwdnet.net' == Using TOS bits 184 == Binding IAX2 to default address 0.0.0.0:4569 > doing dnsmgr_lookup for 'iax2.fwdnet.net' > doing dnsmgr_lookup for 'iaxtel.com' > doing dnsmgr_lookup for '216.207.245.47' [Dec 31 00:05:57] DEBUG[17413]: db.c:197 ast_db_get: Unable to find key 'skywash' in family 'IAX/Registry' [Dec 31 00:05:57] DEBUG[17413]: db.c:197 ast_db_get: Unable to find key 'nivex' in family 'IAX/Registry' -- Seeding 'mattopia' at 68.107.194.220:3073 for 60 [Dec 31 00:05:57] DEBUG[17413]: db.c:197 ast_db_get: Unable to find key 'airthom' in family 'IAX/Registry' == Registered channel type 'IAX2' (Inter Asterisk eXchange Driver (Ver 2)) == 10 helper threaads started == IAX Ready and Listening == Loaded firmware 'iaxy.bin' == Parsing '/etc/asterisk/iaxprov.conf': Found -- Loaded provisioning template 'default' chan_iax2.so => (Inter Asterisk eXchange (Ver 2)) == Registered channel type 'Local' (Local Proxy Channel Driver) chan_local.so => (Local Proxy Channel) == Parsing '/etc/asterisk/skinny.conf': Found -- Setting mailbox '6001' on desk@6008 -- Added device 'desk' == Skinny listening on 172.31.3.2:2000 == Registered channel type 'Skinny' (Skinny Client Control Protocol (Skinny)) == Registered channel type 'Feature' (Feature Proxy Channel Driver) chan_features.so => (Feature Proxy Channel) == Parsing '/etc/asterisk/phone.conf': Found == Registered channel type 'Phone' (Standard Linux Telephony API Driver) chan_phone.so => (Linux Telephony API Support) == Parsing '/etc/asterisk/alsa.conf': Found [Dec 31 00:05:57] DEBUG[17413]: chan_alsa.c:370 alsa_card_init: Opening device hw:0,0 in read mode [Dec 31 00:05:57] ERROR[17413]: chan_alsa.c:385 alsa_card_init: set_channels failed: Invalid argument [Dec 31 00:05:57] DEBUG[17413]: chan_alsa.c:397 alsa_card_init: Period size is 0 [Dec 31 00:05:57] DEBUG[17413]: chan_alsa.c:404 alsa_card_init: Buffer size is set to 0 frames [Dec 31 00:05:57] DEBUG[17413]: chan_alsa.c:467 alsa_card_init: Acquired fd 19 from the poll descriptor [Dec 31 00:05:57] DEBUG[17413]: chan_alsa.c:370 alsa_card_init: -- Message count requested for mailbox 6013 but voicemail not loaded. Opening device hw:0,0 in write mode [Dec 31 00:05:57] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 192.168.10.14 with 172.31.3.0 [Dec 31 00:05:57] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 192.168.10.14 with 192.168.0.0 [Dec 31 00:05:57] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 192.168.10.14 with 192.168.42.0 [Dec 31 00:05:57] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 192.168.10.14 with 192.168.10.0 [Dec 31 00:05:57] ERROR[17413]: chan_alsa.c:385 alsa_card_init: set_channels failed: Invalid argument [Dec 31 00:05:57] DEBUG[17413]: chan_alsa.c:397 alsa_card_init: Period size is 0 [Dec 31 00:05:57] DEBUG[17413]: chan_alsa.c:404 alsa_card_init: Buffer size is set to 0 frames [Dec 31 00:05:57] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.8 with 172.31.3.0 [Dec 31 00:05:57] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.8 with 192.168.0.0 [Dec 31 00:05:57] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.8 with 192.168.42.0 [Dec 31 00:05:57] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.8 with 192.168.10.0 [Dec 31 00:05:57] DEBUG[17413]: chan_alsa.c:467 alsa_card_init: Acquired fd 20 from the poll descriptor == Registered channel type 'Console' (ALSA Console Channel Driver) chan_alsa.so => (ALSA Console Channel Driver) == Registered application 'ZapSendKeypadFacility' == Parsing '/etc/asterisk/zapata.conf': Found -- Automatically generated pseudo channel == Registered channel type 'Zap' (Zapata Telephony Driver w/PRI) == Manager registered action ZapTransfer == Manager registered action ZapHangup == Manager registered action ZapDialOffhook == Manager registered action ZapDNDon == Manager registered action ZapDNDoff == Manager registered action ZapShowChannels == Manager registered action ZapRestart chan_zap.so => (Zapata Telephony) == Parsing '/etc/asterisk/extensions.conf': Found == Parsing '/etc/asterisk/macro-trilug.conf': Found == Parsing '/etc/asterisk/extensions-demo.conf': Found == Setting global variable 'CONSOLE' to 'Console/dsp' == Setting global variable 'TRUNK' to 'Zap/g2' == Setting global variable 'FWDNUM' to '64357' == Setting global variable 'FWDCID' to '"Kevin Otte" <64357>' == Setting global variable 'SIPCID' to '"Kevin Otte" <17472444317>' == Setting global variable 'IAXCID' to '"Kevin Otte" <17007495718>' == Setting global variable 'PTNCID' to '"Nivex Networks" <3602267116>' -- Registered extension context 'macro-trilug' -- Added extension 's' priority 1 to macro-trilug -- Added extension 's' priority 2 to macro-trilug -- Added extension 's' priority 3 to macro-trilug -- Added extension 's' priority 10 to macro-trilug -- Added extension 's' priority 11 to macro-trilug -- Added extension 's' priority 20 to macro-trilug -- Added extension 's' priority 21 to macro-trilug -- Added extension 's' priority 30 to macro-trilug -- Added extension 's' priority 31 to macro-trilug -- Registered extension context 'demo' -- Added extension 's' priority 1 to demo -- Added extension 's' priority 2 to demo -- Added extension 's' priority 3 to demo -- Added extension 's' priority 4 to demo -- Added extension 's' priority 5 to demo -- Added extension 's' priority 6 to demo -- Added extension '2' priority 1 to demo -- Added extension '2' priority 2 to demo -- Added extension '1000' priority 1 to demo -- Added extension '#' priority 1 to demo -- Added extension '#' priority 2 to demo -- Added extension 't' priority 1 to demo -- Added extension 'i' priority 1 to demo -- Added extension '500' priority 1 to demo -- Added extension '500' priority 2 to demo -- Added extension '500' priority 3 to demo -- Added extension '500' priority 4 to demo -- Added extension '600' priority 1 to demo -- Added extension '600' priority 2 to demo -- Added extension '600' priority 3 to demo -- Added extension '600' priority 4 to demo -- Registered extension context 'trunktollfree' -- Added extension '_1800NXXXXXX' priority 1 to trunktollfree -- Added extension '_1800NXXXXXX' priority 2 to trunktollfree -- Added extension '_1888NXXXXXX' priority 1 to trunktollfree -- Added extension '_1888NXXXXXX' priority 2 to trunktollfree -- Added extension '_1877NXXXXXX' priority 1 to trunktollfree -- Added extension '_1877NXXXXXX' priority 2 to trunktollfree -- Added extension '_1866NXXXXXX' priority 1 to trunktollfree -- Added extension '_1866NXXXXXX' priority 2 to trunktollfree -- Registered extension context 'macro-stdexten' -- Added extension 's' priority 1 to macro-stdexten -- Added extension 's' priority 2 to macro-stdexten -- Added extension 's' priority 3 to macro-stdexten -- Added extension 's' priority 4 to macro-stdexten -- Added extension 's-NOANSWER' priority 1 to macro-stdexten -- Added extension 's-NOANSWER' priority 2 to macro-stdexten -- Added extension 's-BUSY' priority 1 to macro-stdexten -- Added extension 's-BUSY' priority 2 to macro-stdexten -- Added extension 's-CHANUNAVAIL' priority 1 to macro-stdexten -- Added extension 's-CHANUNAVAIL' priority 2 to macro-stdexten -- Added extension 's-.' priority 1 to macro-stdexten -- Added extension 'a' priority 1 to macro-stdexten -- Registered extension context 'local' -- Including context 'trunktollfree' in context 'local' -- Including context 'parkedcalls' in context 'local' -- Including context 'default' in context 'local' -- Added extension '_1747X.' priority 1 to local -- Added extension '_1747X.' priority 2 to local -- Added extension '_1222X.' priority 1 to local -- Added extension '_1222X.' priority 2 to local -- Added extension '_001.' priority 1 to local -- Added extension '_001.' priority 2 to local -- Added extension '_011.' priority 1 to local -- Added extension '_011.' priority 2 to local -- Added extension '_1858534.' priority 1 to local -- Added extension '_1393X.' priority 1 to local -- Added extension '_1393X.' priority 2 to local -- Added extension '_9.' priority 1 to local -- Added extension '_9.' priority 2 to local -- Added extension '1000' priority 1 to local -- Added extension '6011' priority 1 to local -- Added extension '6012' priority 1 to local -- Added extension '6013' priority 1 to local -- Added extension '6021' priority 1 to local -- Added extension '6022' priority 1 to local -- Added extension '6023' priority 1 to local -- Added extension '6024' priority 1 to local -- Added extension '6025' priority 1 to local -- Added extension '6026' priority 1 to local -- Added extension '6026' priority 2 to local -- Added extension '6026' priority 3 to local -- Added extension '6026' priority 4 to local -- Added extension '_7X.' priority 1 to local -- Added extension '_5XXX' priority 1 to local -- Added extension '_5XXX' priority 2 to local -- Added extension 't' priority 1 to local -- Registered extension context 'default' -- Added extension '64357' priority 1 to default -- Added extension 's' priority 1 to default -- Added extension 's' priority 2 to default -- Added extension 's' priority 3 to default -- Added extension 's' priority 4 to default -- Added extension 's' priority 5 to default -- Added extension 's' priority 6 to default -- Added extension 'i' priority 1 to default -- Added extension 't' priority 1 to default -- Added extension 't' priority 2 to default -- Added extension '6040' priority 1 to default -- Added extension '6040' priority 2 to default -- Added extension '6040' priority 3 to default -- Added extension '6041' priority 1 to default -- Added extension '6041' priority 2 to default -- Added extension '6041' priority 3 to default -- Added extension '6042' priority 1 to default -- Added extension '6042' priority 2 to default -- Added extension '6042' priority 3 to default -- Added extension '6042' priority 4 to default -- Added extension '6042' priority 5 to default -- Added extension '6050' priority 1 to default -- Added extension '6050' priority 2 to default -- Added extension '6050' priority 3 to default -- Added extension '6050' priority 4 to default -- Added extension '6051' priority 1 to default -- Added extension '6051' priority 2 to default -- Added extension '6000' priority 1 to default -- Added extension '6001' priority 1 to default -- Added extension '6002' priority 1 to default -- Added extension '6003' priority 1 to default -- Added extension '6005' priority 1 to default -- Added extension '6007' priority 1 to default -- Added extension '6009' priority 1 to default -- Added extension '6010' priority 1 to default -- Added extension '6010' priority 2 to default -- Added extension '6010' priority 3 to default -- Added extension '_657X' priority 1 to default -- Added extension '_65XX' priority 1 to default -- Registered extension context 'guestin' -- Added extension '_6XXX' priority 1 to guestin -- Added extension '_6XXX' priority 2 to guestin -- Added extension 's' priority 1 to guestin -- Added extension 's' priority 2 to guestin [Dec 31 00:05:57] DEBUG[17413]: pbx.c:3898 ast_merge_contexts_and_delete: must remove any reg pbx_config [Dec 31 00:05:57] DEBUG[17413]: pbx.c:5231 __ast_context_destroy: check ctx parkedcalls res_features pbx_config.so => (Text Extension Configuration) pbx_spool.so => (Outgoing Spool Support) [Dec 31 00:05:57] ERROR[17413]: pbx_dundi.c:4321 set_config: Unable to load config dundi.conf pbx_loopback.so => (Loopback Switch) pbx_realtime.so => (Realtime Switch) [Dec 31 00:05:57] NOTICE[17413]: pbx_ael.c:3874 pbx_load_module: Starting AEL load process. [Dec 31 00:05:57] NOTICE[17413]: pbx_ael.c:3881 pbx_load_module: AEL load process: calculated config file name '/etc/asterisk/extensions.ael'. [Dec 31 00:05:57] NOTICE[17413]: pbx_ael.c:3884 pbx_load_module: File /etc/asterisk/extensions.ael not found; AEL declining load == Registered application 'Dial' == Registered application 'RetryDial' app_dial.so => (Dialing Application) == Registered application 'Playback' app_playback.so => (Sound File Playback Application) == Registered application 'VoiceMail' == Registered application 'VoiceMailMain' == Registered application 'MailboxExists' == Registered application 'VMAuthenticate' == Parsing '/etc/asterisk/voicemail.conf': Found [Dec 31 00:05:57] DEBUG[17413]: app_voicemail.c:7250 load_config: VM Review Option disabled globally [Dec 31 00:05:57] DEBUG[17413]: app_voicemail.c:7257 load_config: VM Temperary Greeting Reminder Option disabled globally [Dec 31 00:05:57] DEBUG[17413]: app_voicemail.c:7265 load_config: VM Operator break disabled globally [Dec 31 00:05:57] DEBUG[17413]: app_voicemail.c:7271 load_config: VM CID Info before msg disabled globally [Dec 31 00:05:57] DEBUG[17413]: app_voicemail.c:7283 load_config: ENVELOPE before msg enabled globally [Dec 31 00:05:57] DEBUG[17413]: app_voicemail.c:7289 load_config: Duration info before msg enabled globally [Dec 31 00:05:57] DEBUG[17413]: app_voicemail.c:7304 load_config: We are not going to skip to the next msg after save/delete app_voicemail.so => (Comedian Mail (Voicemail System)) == Registered application 'Directory' app_directory.so => (Extension Directory) == Registered application 'MP3Player' app_mp3.so => (Silly MP3 Application) == Registered application 'TrySystem' == Registered application 'System' app_system.so => (Generic System() application) == Registered application 'Echo' app_echo.so => (Simple Echo Application) == Registered application 'Record' app_record.so => (Trivial Record Application) == Registered application 'SendImage' app_image.so => (Image Transmission Application) == Registered application 'SendURL' app_url.so => (Send URL Applications) == Registered application 'DISA' app_disa.so => (DISA (Direct Inward System Access) Application) == Registered application 'ADSIProg' app_adsiprog.so => (Asterisk ADSI Programming Application) == Registered application 'GetCPEID' app_getcpeid.so => (Get ADSI CPE ID) == Registered application 'Milliwatt' app_milliwatt.so => (Digital Milliwatt (mu-law) Test Application) == Registered application 'Zapateller' app_zapateller.so => (Block Telemarketers with Special Information Tone) == Registered application 'SetCallerPres' == Registered application 'SetCallerID' app_setcallerid.so => (Set CallerID Application) == Parsing '/etc/asterisk/festival.conf': Found == Registered application 'Festival' app_festival.so => (Simple Festival Interface) == Parsing '/etc/asterisk/queues.conf': Found == Registered application 'Queue' == Registered application 'AddQueueMember' == Registered application 'RemoveQueueMember' == Registered application 'PauseQueueMember' == Registered application 'UnpauseQueueMember' == Registered application 'QueueLog' == Manager registered action Queues == Manager registered action QueueStatus == Manager registered action QueueAdd == Manager registered action QueueRemove == Manager registered action QueuePause == Registered custom function QUEUEAGENTCOUNT == Registered custom function QUEUE_MEMBER_COUNT == Registered custom function QUEUE_MEMBER_LIST == Registered custom function QUEUE_WAITING_COUNT app_queue.so => (True Call Queueing) == Manager registered action PlayDTMF == Registered application 'SendDTMF' app_senddtmf.so => (Send DTMF digits Application) == Registered application 'ParkAndAnnounce' app_parkandannounce.so => (Call Parking and Announce Application) == Registered file format mp3, extension(s) mp3 format_mp3.so => (MP3 format [Any rate but 8000hz mono is optimal]) == Registered application 'LookupCIDName' app_lookupcidname.so => (Look up CallerID Name from local database) == Registered application 'MacroExit' == Registered application 'MacroIf' == Registered application 'MacroExclusive' == Registered application 'Macro' app_macro.so => (Extension Macros) == Registered application 'Authenticate' app_authenticate.so => (Authentication Application) == Registered application 'SoftHangup' app_softhangup.so => (Hangs up the requested channel) == Registered custom function BLACKLIST == Registered application 'LookupBlacklist' [Dec 31 00:05:57] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 198.65.166.131 with 172.31.3.0 [Dec 31 00:05:57] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 198.65.166.131 with 192.168.0.0 [Dec 31 00:05:57] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 198.65.166.131 with 192.168.42.0 [Dec 31 00:05:57] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 198.65.166.131 with 192.168.10.0 [Dec 31 00:05:57] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.2 with 172.31.3.0 [Dec 31 00:05:57] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.2 with 192.168.0.0 [Dec 31 00:05:57] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.2 with 192.168.42.0 [Dec 31 00:05:57] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.2 with 192.168.10.0 app_lookupblacklist.so => (Look up Caller*ID name/number from blacklist database) == Registered application 'WaitForRing' app_waitforring.so => (Waits until first ring after time) == Registered application 'PrivacyManager' app_privacy.so => (Require phone number to be entered, if no CallerID sent) == Registered application 'DBdel' == Registered application 'DBdeltree' app_db.so => (Database Access Functions) == Registered application 'ChanIsAvail' app_chanisavail.so => (Check channel availability) res_clioriginate.so => (Call origination from the CLI) == Registered application 'Transfer' app_transfer.so => (Transfer) res_convert.so => (File format conversion CLI command) == Registered application 'NoCDR' app_cdr.so => (Tell Asterisk to not maintain a CDR for the current call) == Registered custom function VMCOUNT == Registered application 'HasVoicemail' == Registered application 'HasNewVoicemail' app_hasnewvoicemail.so => (Indicator for whether a voice mailbox has messages in a given folder.) == Registered application 'SayUnixTime' == Registered application 'DateTime' app_sayunixtime.so => (Say time) == Registered application 'Read' app_read.so => (Read Variable Application) == Registered application 'SetCDRUserField' == Registered application 'AppendCDRUserField' == Manager registered action SetCDRUserField app_setcdruserfield.so => (CDR user field apps) == Registered application 'Random' app_random.so => (Random goto) == Registered application 'ICES' app_ices.so => (Encode and Stream via icecast and ices) [Dec 31 00:05:57] ERROR[17413]: app_amd.c:329 load_config: Configuration file amd.conf missing. == Registered application 'AMD' app_amd.so => (Answering Machine Detection Application) == Registered application 'NBScat' app_nbscat.so => (Silly NBS Stream Application) == Registered application 'SendText' app_sendtext.so => (Send Text Applications) == Registered application 'Exec' == Registered application 'TryExec' == Registered application 'ExecIf' app_exec.so => (Executes dialplan applications) == Parsing '/etc/asterisk/alarmreceiver.conf': Found == Registered application 'AlarmReceiver' app_alarmreceiver.so => (Alarm Receiver for Asterisk) == Registered application 'ControlPlayback' app_controlplayback.so => (Control Playback Application) == Registered application 'BackgroundDetect' app_talkdetect.so => (Playback with Talk Detection) == Registered application 'ChanSpy' == Registered application 'ExtenSpy' app_chanspy.so => (Listen to the audio of an active channel) == Registered application 'UserEvent' app_userevent.so => (Custom User Event Application) == Registered application 'Log' == Registered application 'Verbose' app_verbose.so => (Send verbose output) == Registered application 'TestClient' == Registered application 'TestServer' app_test.so => (Interface Test Application) == Registered application 'ForkCDR' app_forkcdr.so => (Fork The CDR into 2 separate entities) == Registered application 'Flash' app_flash.so => (Flash channel application) -- Registered IAX2 to '192.246.69.186', who sees us as 24.225.95.148:4569 with no messages waiting == Registered application 'RealTimeUpdate' == Registered application 'RealTime' app_realtime.so => (Realtime Data Lookup/Rewrite) == Registered application 'DumpChan' app_dumpchan.so => (Dump Info About The Calling Channel) == Registered application 'WaitForSilence' app_waitforsilence.so => (Wait For Silence) == Registered application 'While' == Registered application 'EndWhile' == Registered application 'ExitWhile' == Registered application 'ContinueWhile' app_while.so => (While Loops and Conditional Execution) == Registered application 'ChannelRedirect' app_channelredirect.so => (Channel Redirect) == Registered application 'ReadFile' app_readfile.so => (Stores output of file into a variable) == Registered application 'Dictate' app_dictate.so => (Virtual Dictation Machine) == Registered application 'SetTransferCapability' app_settransfercapability.so => (Set ISDN Transfer Capability) == Registered application 'ExternalIVR' app_externalivr.so => (External IVR Interface Application) [Dec 31 00:05:57] WARNING[17413]: app_followme.c:297 reload_followme: No follow me config file (followme.conf), so no follow me == Registered application 'Pickup' app_directed_pickup.so => (Directed Call Pickup Application) == Registered application 'MixMonitor' == Registered application 'StopMixMonitor' app_mixmonitor.so => (Mixed Audio Monitoring Application) == Registered application 'StackPop' == Registered application 'Return' == Registered application 'GosubIf' == Registered application 'Gosub' app_stack.so => (Stack Routines) == Registered application 'ZapRAS' app_zapras.so => (Zap RAS Application) == Manager registered action MeetmeMute == Manager registered action MeetmeUnmute == Registered application 'MeetMeAdmin' == Registered application 'MeetMeCount' == Registered application 'MeetMe' == Registered application 'SLAStation' == Registered application 'SLATrunk' == Parsing '/etc/asterisk/meetme.conf': Found app_meetme.so => (MeetMe conference bridge) == Registered application 'Page' app_page.so => (Page Multiple Phones) == Registered application 'ZapBarge' app_zapbarge.so => (Barge in on Zap channel application) == Registered application 'ZapScan' app_zapscan.so => (Scan Zap channels application) == Registered application 'SMS' app_sms.so => (SMS/PSTN handler) == Registered application 'SpeechCreate' == Registered application 'SpeechLoadGrammar' == Registered application 'SpeechUnloadGrammar' == Registered application 'SpeechActivateGrammar' == Registered application 'SpeechDeactivateGrammar' == Registered application 'SpeechStart' == Registered application 'SpeechBackground' == Registered application 'SpeechDestroy' == Registered application 'SpeechProcessingSound' == Registered custom function SPEECH == Registered custom function SPEECH_SCORE == Registered custom function SPEECH_TEXT == Registered custom function SPEECH_GRAMMAR == Registered custom function SPEECH_ENGINE app_speech_utils.so => (Dialplan Speech Applications) == Registered translator 'speextolin' from format speex to slin, cost 3 == Registered translator 'lintospeex' from format slin to speex, cost 58 codec_speex.so => (Speex Coder/Decoder) == Registered translator 'ilbctolin' from format ilbc to slin, cost 8 == Registered translator 'lintoilbc' from format slin to ilbc, cost 46 codec_ilbc.so => (iLBC Coder/Decoder) [Dec 31 00:05:57] WARNING[17413]: translate.c:675 __ast_register_translator: plc_samples 160 format 6 == Registered translator 'gsmtolin' from format gsm to slin, cost 2 == Registered translator 'lintogsm' from format slin to gsm, cost 6 codec_gsm.so => (GSM Coder/Decoder) [Dec 31 00:05:57] WARNING[17413]: translate.c:675 __ast_register_translator: plc_samples 180 format 6 == Registered translator 'lpc10tolin' from format lpc10 to slin, cost 6 == Registered translator 'lintolpc10' from format slin to lpc10, cost 8 codec_lpc10.so => (LPC10 2.4kbps Coder/Decoder) [Dec 31 00:05:57] WARNING[17413]: translate.c:675 __ast_register_translator: plc_samples 160 format 6 == Registered translator 'adpcmtolin' from format adpcm to slin, cost 1 == Registered translator 'lintoadpcm' from format slin to adpcm, cost 1 codec_adpcm.so => (Adaptive Differential PCM Coder/Decoder) [Dec 31 00:05:57] WARNING[17413]: translate.c:675 __ast_register_translator: plc_samples 160 format 6 == Registered translator 'ulawtolin' from format ulaw to slin, cost 1 == Registered translator 'lintoulaw' from format slin to ulaw, cost 1 codec_ulaw.so => (mu-Law Coder/Decoder) [Dec 31 00:05:57] WARNING[17413]: translate.c:675 __ast_register_translator: plc_samples 160 format 6 == Registered translator 'alawtolin' from format alaw to slin, cost 1 == Registered translator 'lintoalaw' from format slin to alaw, cost 1 codec_alaw.so => (A-law Coder/Decoder) == Registered translator 'alawtoulaw' from format alaw to ulaw, cost 1 == Registered translator 'ulawtoalaw' from format ulaw to alaw, cost 1 codec_a_mu.so => (A-law and Mulaw direct Coder/Decoder) [Dec 31 00:05:57] WARNING[17413]: translate.c:675 __ast_register_translator: plc_samples 160 format 6 == Registered translator 'g726tolin' from format g726 to slin, cost 5 == Registered translator 'lintog726' from format slin to g726, cost 5 [Dec 31 00:05:57] WARNING[17413]: translate.c:675 __ast_register_translator: plc_samples 160 format 6 == Registered translator 'g726aal2tolin' from format g726aal2 to slin, cost 5 == Registered translator 'lintog726aal2' from format slin to g726aal2, cost 5 == Registered translator 'g726aal2tog726' from format g726aal2 to g726, cost 1 == Registered translator 'g726tog726aal2' from format g726 to g726aal2, cost 1 codec_g726.so => (ITU G.726-32kbps G726 Transcoder) == Registered file format gsm, extension(s) gsm format_gsm.so => (Raw GSM data) == Registered file format wav, extension(s) wav format_wav.so => (Microsoft WAV format (8000Hz Signed Linear)) == Registered file format wav49, extension(s) WAV|wav49 format_wav_gsm.so => (Microsoft WAV format (Proprietary GSM)) == Registered file format vox, extension(s) vox format_vox.so => (Dialogic VOX (ADPCM) File Format) == Registered file format pcm, extension(s) pcm|ulaw|ul|mu == Registered file format alaw, extension(s) alaw|al == Registered file format au, extension(s) au == Registered file format g722, extension(s) g722 format_pcm.so => (Raw/Sun uLaw/ALaw 8KHz Audio support (PCM,PCMA,AU) and G.722 16Khz Audio Support) == Registered file format g729, extension(s) g729 format_g729.so => (Raw G729 data) == Registered application 'Morsecode' app_morsecode.so => (Morse code) == Registered file format h263, extension(s) h263 format_h263.so => (Raw H.263 data) == Registered file format g726-40, extension(s) g726-40 == Registered file format g726-32, extension(s) g726-32 == Registered file format g726-24, extension(s) g726-24 == Registered file format g726-16, extension(s) g726-16 format_g726.so => (Raw G.726 (16/24/32/40kbps) data) == Registered file format iLBC, extension(s) ilbc format_ilbc.so => (Raw iLBC data) == Registered file format sln, extension(s) sln|raw format_sln.so => (Raw Signed Linear Audio support (SLN)) == No hardware transcoders found. codec_zap.so => (Generic Zaptel Transcoder Codec Translator) == Registered format 'jpg' (JPEG (Joint Picture Experts Group)) format_jpeg.so => (JPEG (Joint Picture Experts Group) Image Format) == Registered file format g723sf, extension(s) g723|g723sf format_g723.so => (G.723.1 Simple Timestamp File Format) [Dec 31 00:05:57] WARNING[17413]: cdr_csv.c:110 load_config: unable to load config: cdr.conf == Parsing '/etc/asterisk/cdr_manager.conf': Found [Dec 31 00:05:57] WARNING[17413]: cdr_custom.c:98 load_config: Failed to load configuration file. Module not activated. == Registered file format h264, extension(s) h264 format_h264.so => (Raw H.264 data) == Registered custom function CALLERID func_callerid.so => (Caller ID related dialplan function) == Registered custom function ENUMLOOKUP == Registered custom function TXTCIDNAME func_enum.so => (ENUM related dialplan functions) == Registered custom function URIDECODE == Registered custom function URIENCODE func_uri.so => (URI encode/decode dialplan functions) == Registered file format ogg_vorbis, extension(s) ogg format_ogg_vorbis.so => (OGG/Vorbis audio) cdr_sqlite.so => (SQLite CDR Backend) == Registered custom function BASE64_ENCODE == Registered custom function BASE64_DECODE func_base64.so => (base64 encode/decode dialplan functions) == Registered custom function CDR func_cdr.so => (CDR dialplan function) == Registered custom function CHANNEL func_channel.so => (Channel information dialplan function) == Registered custom function CURL func_curl.so => (Load external URL) == Registered custom function CUT == Registered custom function SORT func_cut.so => (Cut out information from a string) == Registered custom function DB == Registered custom function DB_EXISTS == Registered custom function DB_DELETE func_db.so => (Database (astdb) related dialplan functions) == Registered custom function ENV == Registered custom function STAT func_env.so => (Environment/filesystem dialplan functions) == Registered custom function GLOBAL func_global.so => (Global variable dialplan functions) == Registered custom function GROUP_COUNT == Registered custom function GROUP_MATCH_COUNT == Registered custom function GROUP_LIST == Registered custom function GROUP func_groupcount.so => (Channel group dialplan functions) == Registered custom function LANGUAGE func_language.so => (Channel language dialplan function) == Registered custom function ISNULL == Registered custom function SET == Registered custom function EXISTS == Registered custom function IF == Registered custom function IFTIME func_logic.so => (Logical dialplan functions) == Registered custom function MATH func_math.so => (Mathematical dialplan function) == Registered custom function MD5 == Registered custom function CHECK_MD5 func_md5.so => (MD5 digest dialplan functions) == Registered custom function MUSICCLASS func_moh.so => (Music-on-hold dialplan function) == Registered custom function RAND func_rand.so => (Random number dialplan function) == Registered custom function REALTIME func_realtime.so => (Read/Write values from a RealTime repository) == Registered custom function SHA1 func_sha1.so => (SHA-1 computation dialplan function) == Registered custom function FIELDQTY == Registered custom function FILTER == Registered custom function REGEX == Registered custom function ARRAY == Registered custom function QUOTE == Registered custom function LEN == Registered custom function STRFTIME == Registered custom function STRPTIME == Registered custom function EVAL == Registered custom function KEYPADHASH == Registered custom function SPRINTF func_strings.so => (String handling dialplan functions) == Registered custom function TIMEOUT func_timeout.so => (Channel timeout dialplan functions) [Dec 31 00:05:58] ERROR[17413]: chan_gtalk.c:1778 load_module: Unable to read config file gtalk.conf. Not loading module. chan_gtalk.so => (Gtalk Channel Driver) Asterisk Ready. *CLI> [Dec 31 00:05:58] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 198.65.166.131 with 172.31.3.0 [Dec 31 00:05:58] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 198.65.166.131 with 192.168.0.0 [Dec 31 00:05:58] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 198.65.166.131 with 192.168.42.0 [Dec 31 00:05:58] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 198.65.166.131 with 192.168.10.0 [Dec 31 00:05:58] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.2 with 172.31.3.0 [Dec 31 00:05:58] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.2 with 192.168.0.0 [Dec 31 00:05:58] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.2 with 192.168.42.0 [Dec 31 00:05:58] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.2 with 192.168.10.0 [Dec 31 00:05:58] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 192.168.10.14 with 172.31.3.0 [Dec 31 00:05:58] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 192.168.10.14 with 192.168.0.0 [Dec 31 00:05:58] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 192.168.10.14 with 192.168.42.0 [Dec 31 00:05:58] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 192.168.10.14 with 192.168.10.0 [Dec 31 00:05:58] NOTICE[17420]: chan_sip.c:12010 handle_response_peerpoke: Peer 'sipphone' is now Reachable. (114ms / 2000ms) -- Saved useragent "PolycomSoundPointIP-SPIP_501-UA/1.6.2.0041" for peer cmpalmer core set debug[Dec 31 00:06:00] DEBUG[17430]: chan_iax2.c:4777 raw_hangup: Raw Hangup 68.107.194.220:3073, src=0, dst=2 9 Core debug was 0 and is now 9 *CLI> [Dec 31 00:06:08] DEBUG[17420]: chan_sip.c:4264 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Dec 31 00:06:08] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 192.168.10.14 with 172.31.3.0 [Dec 31 00:06:08] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 192.168.10.14 with 192.168.0.0 [Dec 31 00:06:08] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 192.168.10.14 with 192.168.42.0 [Dec 31 00:06:08] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 192.168.10.14 with 192.168.10.0 [Dec 31 00:06:08] DEBUG[17420]: chan_sip.c:4315 find_call: = Found Their Call ID: 4e85cb54079158183573596f21bde406@172.31.3.2 Their Tag Our tag: as7f938bfe [Dec 31 00:06:08] DEBUG[17420]: chan_sip.c:2071 __sip_ack: Stopping retransmission on '4e85cb54079158183573596f21bde406@172.31.3.2' of Request 102: Match Not Found Really destroying SIP dialog '4e85cb54079158183573596f21bde406@172.31.3.2' Method: NOTIFY [Dec 31 00:06:12] DEBUG[17420]: chan_sip.c:4315 find_call: = No match Their Call ID: aa6d5277-42fbd531-10f2b9c4@192.168.10.14 Their Tag 6C71F86B-F21FB8BE Our tag: as4ae9dbec [Dec 31 00:06:12] DEBUG[17420]: chan_sip.c:4315 find_call: = No match Their Call ID: 067a92084f72311f74e6c5dc33de5161@127.0.0.1 Their Tag 21a483426c2cd5d9b85bffe6bba40a2e.0cd0 Our tag: as56f850b0 [Dec 31 00:06:12] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.8 with 172.31.3.0 [Dec 31 00:06:12] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.8 with 192.168.0.0 [Dec 31 00:06:12] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.8 with 192.168.42.0 [Dec 31 00:06:12] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.8 with 192.168.10.0 [Dec 31 00:06:12] DEBUG[17420]: chan_sip.c:2559 do_setnat: Setting NAT on RTP to Off [Dec 31 00:06:12] DEBUG[17420]: chan_sip.c:4264 sip_alloc: Allocating new SIP dialog for 003094c3-c95e0019-47a51d42-7f68c7e7@172.31.3.8 - INVITE (With RTP) [Dec 31 00:06:12] DEBUG[17420]: chan_sip.c:14462 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Dec 31 00:06:12] DEBUG[17420]: chan_sip.c:2559 do_setnat: Setting NAT on RTP to Off [Dec 31 00:06:13] DEBUG[17420]: chan_sip.c:4315 find_call: = Found Their Call ID: 003094c3-c95e0019-47a51d42-7f68c7e7@172.31.3.8 Their Tag 003094c3c95e003177dc5fad-2c667dff Our tag: as57f1c715 [Dec 31 00:06:13] DEBUG[17420]: chan_sip.c:14462 handle_request: **** Received ACK (6) - Command in SIP ACK [Dec 31 00:06:13] DEBUG[17420]: chan_sip.c:2071 __sip_ack: Stopping retransmission on '003094c3-c95e0019-47a51d42-7f68c7e7@172.31.3.8' of Response 101: Match Not Found [Dec 31 00:06:13] DEBUG[17420]: chan_sip.c:4315 find_call: = Found Their Call ID: 003094c3-c95e0019-47a51d42-7f68c7e7@172.31.3.8 Their Tag 003094c3c95e003177dc5fad-2c667dff Our tag: as57f1c715 [Dec 31 00:06:13] DEBUG[17420]: chan_sip.c:14462 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Dec 31 00:06:13] DEBUG[17420]: chan_sip.c:2559 do_setnat: Setting NAT on RTP to Off [Dec 31 00:06:13] DEBUG[17420]: chan_sip.c:5070 process_sdp: T38 state changed to 0 on channel [Dec 31 00:06:13] DEBUG[17420]: chan_sip.c:5147 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Dec 31 00:06:13] DEBUG[17420]: chan_sip.c:13246 handle_request_invite: Checking SIP call limits for device cisco [Dec 31 00:06:13] DEBUG[17420]: chan_sip.c:2978 update_call_counter: Updating call counter for incoming call [Dec 31 00:06:13] DEBUG[17420]: frame.c:1252 ast_codec_choose: Could not find preferred codec - Going for the best codec [Dec 31 00:06:13] DEBUG[17420]: chan_sip.c:3766 sip_new: *** Our native formats are 0x4 (ulaw) [Dec 31 00:06:13] DEBUG[17420]: chan_sip.c:3767 sip_new: *** Joint capabilities are 0xc (ulaw|alaw) [Dec 31 00:06:13] DEBUG[17420]: chan_sip.c:3768 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Dec 31 00:06:13] DEBUG[17420]: frame.c:1252 ast_codec_choose: Could not find preferred codec - Going for the best codec [Dec 31 00:06:13] DEBUG[17420]: chan_sip.c:3769 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Dec 31 00:06:13] DEBUG[17420]: chan_sip.c:3792 sip_new: This channel will not be able to handle video. [Dec 31 00:06:13] DEBUG[17420]: chan_sip.c:7898 build_route: build_route: Contact hop: [Dec 31 00:06:13] DEBUG[17420]: chan_sip.c:13319 handle_request_invite: SIP/cisco-081d36b8: New call is still down.... Trying... [Dec 31 00:06:13] DEBUG[17420]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/cisco-081d36b8 [Dec 31 00:06:13] DEBUG[17445]: pbx.c:1767 pbx_extension_helper: Launching 'Dial' -- Executing [6002@local:1] Dial("SIP/cisco-081d36b8", "SIP/sipura1|30") in new stack [Dec 31 00:06:13] DEBUG[17445]: chan_sip.c:15115 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Dec 31 00:06:13] DEBUG[17445]: chan_sip.c:4264 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Dec 31 00:06:13] DEBUG[17445]: chan_sip.c:2559 do_setnat: Setting NAT on RTP to Off [Dec 31 00:06:13] DEBUG[17445]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.7 with 172.31.3.0 [Dec 31 00:06:13] DEBUG[17445]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.7 with 192.168.0.0 [Dec 31 00:06:13] DEBUG[17445]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.7 with 192.168.42.0 [Dec 31 00:06:13] DEBUG[17445]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.7 with 192.168.10.0 [Dec 31 00:06:13] DEBUG[17445]: frame.c:1252 ast_codec_choose: Could not find preferred codec - Going for the best codec [Dec 31 00:06:13] DEBUG[17445]: chan_sip.c:3766 sip_new: *** Our native formats are 0x4 (ulaw) [Dec 31 00:06:13] DEBUG[17445]: chan_sip.c:3767 sip_new: *** Joint capabilities are 0x0 (nothing) [Dec 31 00:06:13] DEBUG[17445]: chan_sip.c:3768 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Dec 31 00:06:13] DEBUG[17445]: frame.c:1252 ast_codec_choose: Could not find preferred codec - Going for the best codec [Dec 31 00:06:13] DEBUG[17445]: chan_sip.c:3769 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Dec 31 00:06:13] DEBUG[17445]: chan_sip.c:3771 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Dec 31 00:06:13] DEBUG[17445]: chan_sip.c:3792 sip_new: This channel will not be able to handle video. [Dec 31 00:06:13] DEBUG[17418]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - cisco [Dec 31 00:06:13] DEBUG[17418]: chan_sip.c:15057 sip_devicestate: Checking device state for peer cisco [Dec 31 00:06:13] DEBUG[17418]: devicestate.c:287 do_state_change: Changing state for SIP/cisco - state 1 (Not in use) [Dec 31 00:06:13] DEBUG[17446]: app_queue.c:546 changethread: Device 'SIP/cisco' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 31 00:06:13] DEBUG[17445]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-local-6002-1. [Dec 31 00:06:13] DEBUG[17445]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Dec 31 00:06:13] DEBUG[17445]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Dec 31 00:06:13] DEBUG[17445]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Dec 31 00:06:13] DEBUG[17445]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPURI. [Dec 31 00:06:13] DEBUG[17445]: chan_sip.c:2812 sip_call: Outgoing Call for sipura1 [Dec 31 00:06:13] DEBUG[17445]: chan_sip.c:2978 update_call_counter: Updating call counter for outgoing call [Dec 31 00:06:13] DEBUG[17445]: chan_sip.c:2826 sip_call: Our T38 capability (0), joint T38 capability (0) [Dec 31 00:06:13] DEBUG[17445]: chan_sip.c:6125 add_sdp: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False [Dec 31 00:06:13] DEBUG[17445]: chan_sip.c:6126 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Dec 31 00:06:13] DEBUG[17445]: chan_sip.c:6143 add_sdp: This call needs video offers, but there's no video support enabled! [Dec 31 00:06:13] DEBUG[17445]: chan_sip.c:6257 add_sdp: -- Done with adding codecs to SDP [Dec 31 00:06:13] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Dec 31 00:06:13] DEBUG[17445]: chan_sip.c:6302 add_sdp: Done building SDP. Settling with this capability: 0x8000e (gsm|ulaw|alaw|h263) -- Called sipura1 [Dec 31 00:06:13] DEBUG[17420]: chan_sip.c:4315 find_call: = Found Their Call ID: 72899b496fa48669208d2b8327e567eb@172.31.3.2 Their Tag Our tag: as30c33ae9 [Dec 31 00:06:13] DEBUG[17420]: chan_sip.c:2113 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '72899b496fa48669208d2b8327e567eb@172.31.3.2' Request 102: Found [Dec 31 00:06:13] DEBUG[17420]: chan_sip.c:11538 handle_response_invite: SIP response 100 to standard invite [Dec 31 00:06:13] DEBUG[17420]: chan_sip.c:4315 find_call: = Found Their Call ID: 72899b496fa48669208d2b8327e567eb@172.31.3.2 Their Tag Our tag: as30c33ae9 [Dec 31 00:06:13] DEBUG[17420]: chan_sip.c:2113 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '72899b496fa48669208d2b8327e567eb@172.31.3.2' Request 102: Found [Dec 31 00:06:13] DEBUG[17420]: chan_sip.c:11538 handle_response_invite: SIP response 180 to standard invite [Dec 31 00:06:13] DEBUG[17420]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sipura1-081da1c0 [Dec 31 00:06:13] DEBUG[17418]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - sipura1 [Dec 31 00:06:13] DEBUG[17418]: chan_sip.c:15057 sip_devicestate: Checking device state for peer sipura1 [Dec 31 00:06:13] DEBUG[17418]: devicestate.c:287 do_state_change: Changing state for SIP/sipura1 - state 1 (Not in use) [Dec 31 00:06:13] DEBUG[17447]: app_queue.c:546 changethread: Device 'SIP/sipura1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. -- SIP/sipura1-081da1c0 is ringing [Dec 31 00:06:20] DEBUG[17420]: chan_sip.c:4315 find_call: = Found Their Call ID: 72899b496fa48669208d2b8327e567eb@172.31.3.2 Their Tag 44027a2dbb25bb79i0 Our tag: as30c33ae9 [Dec 31 00:06:20] DEBUG[17420]: chan_sip.c:2053 __sip_ack: Acked pending invite 102 [Dec 31 00:06:20] DEBUG[17420]: chan_sip.c:2071 __sip_ack: Stopping retransmission on '72899b496fa48669208d2b8327e567eb@172.31.3.2' of Request 102: Match Not Found [Dec 31 00:06:20] DEBUG[17420]: chan_sip.c:11538 handle_response_invite: SIP response 200 to standard invite [Dec 31 00:06:20] DEBUG[17420]: chan_sip.c:5070 process_sdp: T38 state changed to 0 on channel SIP/sipura1-081da1c0 [Dec 31 00:06:20] DEBUG[17420]: chan_sip.c:5147 process_sdp: We're settling with these formats: 0x4 (ulaw) [Dec 31 00:06:20] DEBUG[17420]: chan_sip.c:5154 process_sdp: We have an owner, now see if we need to change this call [Dec 31 00:06:20] DEBUG[17420]: chan_sip.c:2978 update_call_counter: Updating call counter for outgoing call [Dec 31 00:06:20] DEBUG[17420]: chan_sip.c:7898 build_route: build_route: Contact hop: Analog 1 [Dec 31 00:06:20] DEBUG[17445]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sipura1-081da1c0 -- SIP/sipura1-081da1c0 answered SIP/cisco-081d36b8 [Dec 31 00:06:20] DEBUG[17445]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/cisco-081d36b8 [Dec 31 00:06:20] DEBUG[17445]: chan_sip.c:3428 sip_answer: SIP answering channel: SIP/cisco-081d36b8 [Dec 31 00:06:20] DEBUG[17445]: chan_sip.c:6357 transmit_response_with_sdp: Setting framing from config on incoming call [Dec 31 00:06:20] DEBUG[17445]: chan_sip.c:6125 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Dec 31 00:06:20] DEBUG[17445]: chan_sip.c:6126 add_sdp: ** Our prefcodec: 0x0 (nothing) [Dec 31 00:06:20] DEBUG[17445]: chan_sip.c:6257 add_sdp: -- Done with adding codecs to SDP [Dec 31 00:06:20] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:20] DEBUG[17445]: chan_sip.c:6302 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:20] DEBUG[17418]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - sipura1 [Dec 31 00:06:20] DEBUG[17418]: chan_sip.c:15057 sip_devicestate: Checking device state for peer sipura1 [Dec 31 00:06:20] DEBUG[17418]: devicestate.c:287 do_state_change: Changing state for SIP/sipura1 - state 1 (Not in use) [Dec 31 00:06:20] DEBUG[17449]: app_queue.c:546 changethread: Device 'SIP/sipura1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 31 00:06:20] DEBUG[17418]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - cisco [Dec 31 00:06:20] DEBUG[17418]: chan_sip.c:15057 sip_devicestate: Checking device state for peer cisco [Dec 31 00:06:20] DEBUG[17418]: devicestate.c:287 do_state_change: Changing state for SIP/cisco - state 1 (Not in use) [Dec 31 00:06:20] DEBUG[17450]: app_queue.c:546 changethread: Device 'SIP/cisco' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 31 00:06:20] DEBUG[17420]: chan_sip.c:4315 find_call: = No match Their Call ID: 72899b496fa48669208d2b8327e567eb@172.31.3.2 Their Tag 44027a2dbb25bb79i0 Our tag: as30c33ae9 [Dec 31 00:06:20] DEBUG[17420]: chan_sip.c:4315 find_call: = Found Their Call ID: 003094c3-c95e0019-47a51d42-7f68c7e7@172.31.3.8 Their Tag 003094c3c95e003177dc5fad-2c667dff Our tag: as6e7a11b1 [Dec 31 00:06:20] DEBUG[17420]: chan_sip.c:14462 handle_request: **** Received ACK (6) - Command in SIP ACK [Dec 31 00:06:20] DEBUG[17420]: chan_sip.c:2071 __sip_ack: Stopping retransmission on '003094c3-c95e0019-47a51d42-7f68c7e7@172.31.3.8' of Response 102: Match Not Found [Dec 31 00:06:20] DEBUG[17431]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/mattopia [Dec 31 00:06:20] DEBUG[17418]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - mattopia [Dec 31 00:06:20] DEBUG[17418]: chan_iax2.c:9598 iax2_devicestate: Checking device state for device mattopia [Dec 31 00:06:20] DEBUG[17418]: chan_iax2.c:9606 iax2_devicestate: iax2_devicestate: Found peer. What's device state of mattopia? addr=-591238332, defaddr=0 maxms=2000, lastms=95 [Dec 31 00:06:20] DEBUG[17418]: devicestate.c:287 do_state_change: Changing state for IAX2/mattopia - state 1 (Not in use) [Dec 31 00:06:20] DEBUG[17452]: app_queue.c:546 changethread: Device 'IAX2/mattopia' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 31 00:06:24] DEBUG[17420]: chan_sip.c:4315 find_call: = Found Their Call ID: 72899b496fa48669208d2b8327e567eb@172.31.3.2 Their Tag 44027a2dbb25bb79i0 Our tag: as30c33ae9 [Dec 31 00:06:24] DEBUG[17420]: chan_sip.c:14462 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Dec 31 00:06:24] DEBUG[17420]: chan_sip.c:5070 process_sdp: T38 state changed to 0 on channel SIP/sipura1-081da1c0 [Dec 31 00:06:24] DEBUG[17420]: chan_sip.c:5147 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Dec 31 00:06:24] DEBUG[17420]: chan_sip.c:5154 process_sdp: We have an owner, now see if we need to change this call [Dec 31 00:06:24] DEBUG[17420]: chan_sip.c:13392 handle_request_invite: SIP/sipura1-081da1c0: This call is UP.... [Dec 31 00:06:24] DEBUG[17420]: chan_sip.c:6357 transmit_response_with_sdp: Setting framing from config on incoming call [Dec 31 00:06:24] DEBUG[17420]: chan_sip.c:6125 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Dec 31 00:06:24] DEBUG[17420]: chan_sip.c:6126 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Dec 31 00:06:24] DEBUG[17420]: chan_sip.c:6257 add_sdp: -- Done with adding codecs to SDP [Dec 31 00:06:24] DEBUG[17420]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Dec 31 00:06:24] DEBUG[17420]: chan_sip.c:6302 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) -- Started music on hold, class 'default', on SIP/cisco-081d36b8 [Dec 31 00:06:24] DEBUG[17445]: channel.c:1908 ast_settimeout: Scheduling timer at 160 sample intervals [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2225 __ast_read: Generator got voice, switching to phase locked mode [Dec 31 00:06:24] DEBUG[17445]: channel.c:1908 ast_settimeout: Scheduling timer at 0 sample intervals [Dec 31 00:06:24] DEBUG[17445]: channel.c:2731 set_format: Set channel SIP/cisco-081d36b8 to write format slin [Dec 31 00:06:24] DEBUG[17420]: chan_sip.c:4315 find_call: = Found Their Call ID: 72899b496fa48669208d2b8327e567eb@172.31.3.2 Their Tag 44027a2dbb25bb79i0 Our tag: as30c33ae9 [Dec 31 00:06:24] DEBUG[17420]: chan_sip.c:14462 handle_request: **** Received ACK (6) - Command in SIP ACK [Dec 31 00:06:24] DEBUG[17420]: chan_sip.c:2071 __sip_ack: Stopping retransmission on '72899b496fa48669208d2b8327e567eb@172.31.3.2' of Response 101: Match Not Found [Dec 31 00:06:24] DEBUG[17445]: res_musiconhold.c:250 ast_moh_files_next: SIP/cisco-081d36b8 Opened file 2 '/var/lib/asterisk/mohmp3/greensleeves' [Dec 31 00:06:24] DEBUG[17445]: rtp.c:2659 ast_rtp_write: Ooh, format changed from unknown to ulaw [Dec 31 00:06:24] DEBUG[17445]: rtp.c:2676 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:24] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:25] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:26] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:4315 find_call: = No match Their Call ID: 72899b496fa48669208d2b8327e567eb@172.31.3.2 Their Tag 44027a2dbb25bb79i0 Our tag: as30c33ae9 [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:4315 find_call: = No match Their Call ID: 003094c3-c95e0019-47a51d42-7f68c7e7@172.31.3.8 Their Tag 003094c3c95e003177dc5fad-2c667dff Our tag: as6e7a11b1 [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:4315 find_call: = No match Their Call ID: aa6d5277-42fbd531-10f2b9c4@192.168.10.14 Their Tag 6C71F86B-F21FB8BE Our tag: as4ae9dbec [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:4315 find_call: = No match Their Call ID: 067a92084f72311f74e6c5dc33de5161@127.0.0.1 Their Tag 21a483426c2cd5d9b85bffe6bba40a2e.0cd0 Our tag: as56f850b0 [Dec 31 00:06:27] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.7 with 172.31.3.0 [Dec 31 00:06:27] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.7 with 192.168.0.0 [Dec 31 00:06:27] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.7 with 192.168.42.0 [Dec 31 00:06:27] DEBUG[17420]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.7 with 192.168.10.0 [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:2559 do_setnat: Setting NAT on RTP to Off [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:4264 sip_alloc: Allocating new SIP dialog for d686e15b-5d69d3a6@172.31.3.7 - INVITE (With RTP) [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:14462 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:2559 do_setnat: Setting NAT on RTP to Off [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:4315 find_call: = Found Their Call ID: d686e15b-5d69d3a6@172.31.3.7 Their Tag 7cd90dd7e07b315ao0 Our tag: as5eb90992 [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:14462 handle_request: **** Received ACK (6) - Command in SIP ACK [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:2071 __sip_ack: Stopping retransmission on 'd686e15b-5d69d3a6@172.31.3.7' of Response 101: Match Not Found [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:4315 find_call: = Found Their Call ID: d686e15b-5d69d3a6@172.31.3.7 Their Tag 7cd90dd7e07b315ao0 Our tag: as5eb90992 [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:14462 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:2559 do_setnat: Setting NAT on RTP to Off [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:5070 process_sdp: T38 state changed to 0 on channel [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:5147 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:13246 handle_request_invite: Checking SIP call limits for device sipura1 [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:2978 update_call_counter: Updating call counter for incoming call [Dec 31 00:06:27] DEBUG[17420]: frame.c:1252 ast_codec_choose: Could not find preferred codec - Going for the best codec [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:3766 sip_new: *** Our native formats are 0x4 (ulaw) [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:3767 sip_new: *** Joint capabilities are 0xc (ulaw|alaw) [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:3768 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Dec 31 00:06:27] DEBUG[17420]: frame.c:1252 ast_codec_choose: Could not find preferred codec - Going for the best codec [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:3769 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:3792 sip_new: This channel will not be able to handle video. [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:7898 build_route: build_route: Contact hop: Analog 1 [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:13319 handle_request_invite: SIP/sipura1-081e6168: New call is still down.... Trying... [Dec 31 00:06:27] DEBUG[17420]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sipura1-081e6168 [Dec 31 00:06:27] DEBUG[17454]: pbx.c:1767 pbx_extension_helper: Launching 'Dial' -- Executing [6003@local:1] Dial("SIP/sipura1-081e6168", "SIP/sipura2|30") in new stack [Dec 31 00:06:27] DEBUG[17454]: chan_sip.c:15115 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Dec 31 00:06:27] DEBUG[17454]: chan_sip.c:4264 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Dec 31 00:06:27] DEBUG[17454]: chan_sip.c:2559 do_setnat: Setting NAT on RTP to Off [Dec 31 00:06:27] DEBUG[17454]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.7 with 172.31.3.0 [Dec 31 00:06:27] DEBUG[17454]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.7 with 192.168.0.0 [Dec 31 00:06:27] DEBUG[17454]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.7 with 192.168.42.0 [Dec 31 00:06:27] DEBUG[17454]: acl.c:213 ast_apply_ha: ##### Testing 172.31.3.7 with 192.168.10.0 [Dec 31 00:06:27] DEBUG[17454]: frame.c:1252 ast_codec_choose: Could not find preferred codec - Going for the best codec [Dec 31 00:06:27] DEBUG[17454]: chan_sip.c:3766 sip_new: *** Our native formats are 0x4 (ulaw) [Dec 31 00:06:27] DEBUG[17454]: chan_sip.c:3767 sip_new: *** Joint capabilities are 0x0 (nothing) [Dec 31 00:06:27] DEBUG[17454]: chan_sip.c:3768 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Dec 31 00:06:27] DEBUG[17454]: frame.c:1252 ast_codec_choose: Could not find preferred codec - Going for the best codec [Dec 31 00:06:27] DEBUG[17454]: chan_sip.c:3769 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Dec 31 00:06:27] DEBUG[17454]: chan_sip.c:3771 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Dec 31 00:06:27] DEBUG[17454]: chan_sip.c:3792 sip_new: This channel will not be able to handle video. [Dec 31 00:06:27] DEBUG[17418]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - sipura1 [Dec 31 00:06:27] DEBUG[17418]: chan_sip.c:15057 sip_devicestate: Checking device state for peer sipura1 [Dec 31 00:06:27] DEBUG[17418]: devicestate.c:287 do_state_change: Changing state for SIP/sipura1 - state 1 (Not in use) [Dec 31 00:06:27] DEBUG[17455]: app_queue.c:546 changethread: Device 'SIP/sipura1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17454]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-local-6003-1. [Dec 31 00:06:27] DEBUG[17454]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Dec 31 00:06:27] DEBUG[17454]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Dec 31 00:06:27] DEBUG[17454]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Dec 31 00:06:27] DEBUG[17454]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPURI. [Dec 31 00:06:27] DEBUG[17454]: chan_sip.c:2812 sip_call: Outgoing Call for sipura2 [Dec 31 00:06:27] DEBUG[17454]: chan_sip.c:2978 update_call_counter: Updating call counter for outgoing call [Dec 31 00:06:27] DEBUG[17454]: chan_sip.c:2826 sip_call: Our T38 capability (0), joint T38 capability (0) [Dec 31 00:06:27] DEBUG[17454]: chan_sip.c:6125 add_sdp: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False [Dec 31 00:06:27] DEBUG[17454]: chan_sip.c:6126 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Dec 31 00:06:27] DEBUG[17454]: chan_sip.c:6143 add_sdp: This call needs video offers, but there's no video support enabled! [Dec 31 00:06:27] DEBUG[17454]: chan_sip.c:6257 add_sdp: -- Done with adding codecs to SDP [Dec 31 00:06:27] DEBUG[17454]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=34) [Dec 31 00:06:27] DEBUG[17454]: chan_sip.c:6302 add_sdp: Done building SDP. Settling with this capability: 0x8000e (gsm|ulaw|alaw|h263) -- Called sipura2 [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:4315 find_call: = Found Their Call ID: 583d108640718a035dccf24412a210cd@172.31.3.2 Their Tag Our tag: as3ca4e158 [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:2113 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '583d108640718a035dccf24412a210cd@172.31.3.2' Request 102: Found [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:11538 handle_response_invite: SIP response 100 to standard invite [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:4315 find_call: = Found Their Call ID: 583d108640718a035dccf24412a210cd@172.31.3.2 Their Tag Our tag: as3ca4e158 [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:2113 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '583d108640718a035dccf24412a210cd@172.31.3.2' Request 102: Found [Dec 31 00:06:27] DEBUG[17420]: chan_sip.c:11538 handle_response_invite: SIP response 180 to standard invite [Dec 31 00:06:27] DEBUG[17420]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sipura2-081ea6f0 [Dec 31 00:06:27] DEBUG[17418]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - sipura2 [Dec 31 00:06:27] DEBUG[17418]: chan_sip.c:15057 sip_devicestate: Checking device state for peer sipura2 [Dec 31 00:06:27] DEBUG[17418]: devicestate.c:287 do_state_change: Changing state for SIP/sipura2 - state 1 (Not in use) [Dec 31 00:06:27] DEBUG[17456]: app_queue.c:546 changethread: Device 'SIP/sipura2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. -- SIP/sipura2-081ea6f0 is ringing [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:27] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:28] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17420]: chan_sip.c:1992 __sip_autodestruct: Auto destroying SIP dialog '067a92084f72311f74e6c5dc33de5161@127.0.0.1' [Dec 31 00:06:29] DEBUG[17420]: chan_sip.c:3080 sip_destroy: Destroying SIP dialog 067a92084f72311f74e6c5dc33de5161@127.0.0.1 Really destroying SIP dialog '067a92084f72311f74e6c5dc33de5161@127.0.0.1' Method: REGISTER [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:29] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17420]: chan_sip.c:1992 __sip_autodestruct: Auto destroying SIP dialog 'aa6d5277-42fbd531-10f2b9c4@192.168.10.14' [Dec 31 00:06:30] DEBUG[17420]: chan_sip.c:3080 sip_destroy: Destroying SIP dialog aa6d5277-42fbd531-10f2b9c4@192.168.10.14 Really destroying SIP dialog 'aa6d5277-42fbd531-10f2b9c4@192.168.10.14' Method: REGISTER [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17420]: chan_sip.c:4315 find_call: = Found Their Call ID: 583d108640718a035dccf24412a210cd@172.31.3.2 Their Tag f202ac1caa6e1fdfi1 Our tag: as3ca4e158 [Dec 31 00:06:30] DEBUG[17420]: chan_sip.c:2053 __sip_ack: Acked pending invite 102 [Dec 31 00:06:30] DEBUG[17420]: chan_sip.c:2071 __sip_ack: Stopping retransmission on '583d108640718a035dccf24412a210cd@172.31.3.2' of Request 102: Match Not Found [Dec 31 00:06:30] DEBUG[17420]: chan_sip.c:11538 handle_response_invite: SIP response 200 to standard invite [Dec 31 00:06:30] DEBUG[17420]: chan_sip.c:5070 process_sdp: T38 state changed to 0 on channel SIP/sipura2-081ea6f0 [Dec 31 00:06:30] DEBUG[17420]: chan_sip.c:5147 process_sdp: We're settling with these formats: 0x4 (ulaw) [Dec 31 00:06:30] DEBUG[17420]: chan_sip.c:5154 process_sdp: We have an owner, now see if we need to change this call [Dec 31 00:06:30] DEBUG[17420]: chan_sip.c:2978 update_call_counter: Updating call counter for outgoing call [Dec 31 00:06:30] DEBUG[17420]: chan_sip.c:7898 build_route: build_route: Contact hop: Analog 2 [Dec 31 00:06:30] DEBUG[17454]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sipura2-081ea6f0 -- SIP/sipura2-081ea6f0 answered SIP/sipura1-081e6168 [Dec 31 00:06:30] DEBUG[17454]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sipura1-081e6168 [Dec 31 00:06:30] DEBUG[17454]: chan_sip.c:3428 sip_answer: SIP answering channel: SIP/sipura1-081e6168 [Dec 31 00:06:30] DEBUG[17454]: chan_sip.c:6357 transmit_response_with_sdp: Setting framing from config on incoming call [Dec 31 00:06:30] DEBUG[17454]: chan_sip.c:6125 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Dec 31 00:06:30] DEBUG[17454]: chan_sip.c:6126 add_sdp: ** Our prefcodec: 0x0 (nothing) [Dec 31 00:06:30] DEBUG[17454]: chan_sip.c:6257 add_sdp: -- Done with adding codecs to SDP [Dec 31 00:06:30] DEBUG[17454]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=31) [Dec 31 00:06:30] DEBUG[17454]: chan_sip.c:6302 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) -- Packet2Packet bridging SIP/sipura1-081e6168 and SIP/sipura2-081ea6f0 [Dec 31 00:06:30] DEBUG[17418]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - sipura2 [Dec 31 00:06:30] DEBUG[17418]: chan_sip.c:15057 sip_devicestate: Checking device state for peer sipura2 [Dec 31 00:06:30] DEBUG[17418]: devicestate.c:287 do_state_change: Changing state for SIP/sipura2 - state 1 (Not in use) [Dec 31 00:06:30] DEBUG[17458]: app_queue.c:546 changethread: Device 'SIP/sipura2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 31 00:06:30] DEBUG[17418]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - sipura1 [Dec 31 00:06:30] DEBUG[17418]: chan_sip.c:15057 sip_devicestate: Checking device state for peer sipura1 [Dec 31 00:06:30] DEBUG[17418]: devicestate.c:287 do_state_change: Changing state for SIP/sipura1 - state 1 (Not in use) [Dec 31 00:06:30] DEBUG[17459]: app_queue.c:546 changethread: Device 'SIP/sipura1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17420]: chan_sip.c:4315 find_call: = No match Their Call ID: 583d108640718a035dccf24412a210cd@172.31.3.2 Their Tag f202ac1caa6e1fdfi1 Our tag: as3ca4e158 [Dec 31 00:06:30] DEBUG[17420]: chan_sip.c:4315 find_call: = Found Their Call ID: d686e15b-5d69d3a6@172.31.3.7 Their Tag 7cd90dd7e07b315ao0 Our tag: as43d983f7 [Dec 31 00:06:30] DEBUG[17420]: chan_sip.c:14462 handle_request: **** Received ACK (6) - Command in SIP ACK [Dec 31 00:06:30] DEBUG[17420]: chan_sip.c:2071 __sip_ack: Stopping retransmission on 'd686e15b-5d69d3a6@172.31.3.7' of Response 102: Match Not Found [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:30] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:31] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:32] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:33] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:34] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:34] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:34] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:34] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:34] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:34] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:34] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:34] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:34] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:34] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:34] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:34] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:34] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:34] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:34] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:34] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:34] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:34] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:34] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:34] DEBUG[17445]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Dec 31 00:06:34] DEBUG[17420]: chan_sip.c:4315 find_call: = No match Their Call ID: 583d108640718a035dccf24412a210cd@172.31.3.2 Their Tag f202ac1caa6e1fdfi1 Our tag: as3ca4e158 [Dec 31 00:06:34] DEBUG[17420]: chan_sip.c:4315 find_call: = No match Their Call ID: d686e15b-5d69d3a6@172.31.3.7 Their Tag 7cd90dd7e07b315ao0 Our tag: as43d983f7 [Dec 31 00:06:34] DEBUG[17420]: chan_sip.c:4315 find_call: = Found Their Call ID: 72899b496fa48669208d2b8327e567eb@172.31.3.2 Their Tag 44027a2dbb25bb79i0 Our tag: as30c33ae9 [Dec 31 00:06:34] DEBUG[17420]: chan_sip.c:14462 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Dec 31 00:06:34] DEBUG[17420]: chan_sip.c:5070 process_sdp: T38 state changed to 0 on channel SIP/sipura1-081da1c0 [Dec 31 00:06:34] DEBUG[17420]: chan_sip.c:5147 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Dec 31 00:06:34] DEBUG[17420]: chan_sip.c:5154 process_sdp: We have an owner, now see if we need to change this call [Dec 31 00:06:34] DEBUG[17420]: chan_sip.c:13392 handle_request_invite: SIP/sipura1-081da1c0: This call is UP.... [Dec 31 00:06:34] DEBUG[17420]: chan_sip.c:6357 transmit_response_with_sdp: Setting framing from config on incoming call [Dec 31 00:06:34] DEBUG[17420]: chan_sip.c:6125 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Dec 31 00:06:34] DEBUG[17420]: chan_sip.c:6126 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Dec 31 00:06:34] DEBUG[17420]: chan_sip.c:6257 add_sdp: -- Done with adding codecs to SDP [Dec 31 00:06:34] DEBUG[17420]: channel.c:2274 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Dec 31 00:06:34] DEBUG[17420]: chan_sip.c:6302 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) -- Stopped music on hold on SIP/cisco-081d36b8 [Dec 31 00:06:34] DEBUG[17445]: channel.c:2731 set_format: Set channel SIP/cisco-081d36b8 to write format ulaw [Dec 31 00:06:34] DEBUG[17445]: channel.c:1908 ast_settimeout: Scheduling timer at 0 sample intervals [Dec 31 00:06:34] DEBUG[17420]: chan_sip.c:4315 find_call: = No match Their Call ID: 583d108640718a035dccf24412a210cd@172.31.3.2 Their Tag f202ac1caa6e1fdfi1 Our tag: as3ca4e158 [Dec 31 00:06:34] DEBUG[17420]: chan_sip.c:4315 find_call: = No match Their Call ID: d686e15b-5d69d3a6@172.31.3.7 Their Tag 7cd90dd7e07b315ao0 Our tag: as43d983f7 [Dec 31 00:06:34] DEBUG[17420]: chan_sip.c:4315 find_call: = Found Their Call ID: 72899b496fa48669208d2b8327e567eb@172.31.3.2 Their Tag 44027a2dbb25bb79i0 Our tag: as30c33ae9 [Dec 31 00:06:34] DEBUG[17420]: chan_sip.c:14462 handle_request: **** Received ACK (6) - Command in SIP ACK [Dec 31 00:06:34] DEBUG[17420]: chan_sip.c:2071 __sip_ack: Stopping retransmission on '72899b496fa48669208d2b8327e567eb@172.31.3.2' of Response 102: Match Not Found [Dec 31 00:06:38] DEBUG[17420]: chan_sip.c:4315 find_call: = No match Their Call ID: 583d108640718a035dccf24412a210cd@172.31.3.2 Their Tag f202ac1caa6e1fdfi1 Our tag: as3ca4e158 [Dec 31 00:06:38] DEBUG[17420]: chan_sip.c:4315 find_call: = No match Their Call ID: d686e15b-5d69d3a6@172.31.3.7 Their Tag 7cd90dd7e07b315ao0 Our tag: as43d983f7 [Dec 31 00:06:38] DEBUG[17420]: chan_sip.c:4315 find_call: = Found Their Call ID: 72899b496fa48669208d2b8327e567eb@172.31.3.2 Their Tag 44027a2dbb25bb79i0 Our tag: as30c33ae9 [Dec 31 00:06:38] DEBUG[17420]: chan_sip.c:14462 handle_request: **** Received REFER (9) - Command in SIP REFER [Dec 31 00:06:38] DEBUG[17420]: chan_sip.c:8630 get_refer_info: Attended transfer: Will use Replace-Call-ID : d686e15b-5d69d3a6@172.31.3.7 (No check of from/to tags) [Dec 31 00:06:38] DEBUG[17420]: chan_sip.c:8484 get_sip_pvt_byid_locked: Looking for callid d686e15b-5d69d3a6@172.31.3.7 (fromtag 7cd90dd7e07b315ao0 totag as43d983f7) [Dec 31 00:06:38] DEBUG[17420]: chan_sip.c:8508 get_sip_pvt_byid_locked: Matched INCOMING call - their tag is 7cd90dd7e07b315ao0 Our tag is as43d983f7 [Dec 31 00:06:38] DEBUG[17420]: chan_sip.c:12588 attempt_transfer: Sip transfer:-------------------- [Dec 31 00:06:38] DEBUG[17420]: chan_sip.c:12590 attempt_transfer: -- Transferer to PBX channel: SIP/sipura1-081da1c0 State Up [Dec 31 00:06:38] DEBUG[17420]: chan_sip.c:12594 attempt_transfer: -- Transferer to PBX second channel (target): SIP/sipura1-081e6168 State Up [Dec 31 00:06:38] DEBUG[17420]: chan_sip.c:12598 attempt_transfer: -- Bridged call to transferee: SIP/cisco-081d36b8 State Up [Dec 31 00:06:38] DEBUG[17420]: chan_sip.c:12602 attempt_transfer: -- Bridged call to transfer target: SIP/sipura2-081ea6f0 State Up [Dec 31 00:06:38] DEBUG[17420]: chan_sip.c:12605 attempt_transfer: -- END Sip transfer:-------------------- [Dec 31 00:06:38] DEBUG[17420]: chan_sip.c:12613 attempt_transfer: SIP transfer: Four channels to handle [Dec 31 00:06:38] DEBUG[17420]: chan_sip.c:12644 attempt_transfer: SIP transfer: trying to masquerade SIP/cisco-081d36b8 into SIP/sipura1-081e6168 [Dec 31 00:06:38] DEBUG[17420]: channel.c:3119 ast_channel_masquerade: Planning to masquerade channel SIP/cisco-081d36b8 into the structure of SIP/sipura1-081e6168 [Dec 31 00:06:38] DEBUG[17420]: channel.c:3132 ast_channel_masquerade: Done planning to masquerade channel SIP/cisco-081d36b8 into the structure of SIP/sipura1-081e6168 [Dec 31 00:06:38] DEBUG[17420]: chan_sip.c:12649 attempt_transfer: SIP transfer: Succeeded to masquerade channels. [Dec 31 00:06:38] DEBUG[17420]: chan_sip.c:13602 local_attended_transfer: SIP attended transfer: Unlocking channel SIP/sipura1-081e6168 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 [Dec 31 00:06:38] DEBUG[17420]: chan_sip.c:4315 find_call: = No match Their Call ID: 583d108640718a035dccf24412a210cd@172.31.3.2 Their Tag f202ac1caa6e1fdfi1 Our tag: as3ca4e158 [Dec 31 00:06:38] DEBUG[17420]: chan_sip.c:4315 find_call: = No match Their Call ID: d686e15b-5d69d3a6@172.31.3.7 Their Tag 7cd90dd7e07b315ao0 Our tag: as43d983f7 [Dec 31 00:06:38] DEBUG[17420]: chan_sip.c:4315 find_call: = Found Their Call ID: 72899b496fa48669208d2b8327e567eb@172.31.3.2 Their Tag 44027a2dbb25bb79i0 Our tag: as30c33ae9 [Dec 31 00:06:38] DEBUG[17420]: chan_sip.c:2071 __sip_ack: Stopping retransmission on '72899b496fa48669208d2b8327e567eb@172.31.3.2' of Request 103: Match Not Found [Dec 31 00:06:38] WARNING[17420]: chan_sip.c:12319 handle_response: Notify answer on an owned channel? -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] NOTICE[17445]: rtp.c:3012 bridge_p2p_loop: c0 masqr on SIP/cisco-081d36b8 -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17454]: channel.c:3249 ast_do_masquerade: Actually Masquerading SIP/cisco-081d36b8(6) into the structure of SIP/sipura1-081e6168(6) [Dec 31 00:06:38] DEBUG[17454]: channel.c:3261 ast_do_masquerade: Got clone lock for masquerade on 'SIP/cisco-081d36b8' at 0x81d9648 [Dec 31 00:06:38] DEBUG[17454]: chan_sip.c:3553 sip_fixup: SIP Fixup: New owner for dialogue d686e15b-5d69d3a6@172.31.3.7: SIP/cisco-081d36b8 (Old parent: SIP/cisco-081d36b8) [Dec 31 00:06:38] DEBUG[17454]: chan_sip.c:3278 sip_hangup: Hangup call SIP/cisco-081d36b8, SIP callid d686e15b-5d69d3a6@172.31.3.7) [Dec 31 00:06:38] DEBUG[17454]: chan_sip.c:2978 update_call_counter: Updating call counter for incoming call [Dec 31 00:06:38] DEBUG[17454]: channel.c:3456 ast_do_masquerade: Putting channel SIP/cisco-081d36b8 in 4/4 formats [Dec 31 00:06:38] DEBUG[17454]: chan_sip.c:3553 sip_fixup: SIP Fixup: New owner for dialogue 003094c3-c95e0019-47a51d42-7f68c7e7@172.31.3.8: SIP/cisco-081d36b8 (Old parent: SIP/sipura1-081e6168) [Dec 31 00:06:38] DEBUG[17454]: channel.c:3491 ast_do_masquerade: Released clone lock on 'SIP/sipura1-081e6168' [Dec 31 00:06:38] DEBUG[17454]: channel.c:3501 ast_do_masquerade: Done Masquerading SIP/cisco-081d36b8 (6) [Dec 31 00:06:38] DEBUG[17454]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out -- Packet2Packet bridging SIP/cisco-081d36b8 and SIP/sipura2-081ea6f0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:3002 bridge_p2p_loop: Oooh, something is weird, backing out [Dec 31 00:06:38] DEBUG[17445]: channel.c:3896 ast_channel_bridge: Bridge stops because we're zombie or need a soft hangup: c0=SIP/sipura1-081e6168, c1=SIP/sipura1-081da1c0, flags: Yes,Yes,No,No [Dec 31 00:06:38] DEBUG[17445]: channel.c:3990 ast_channel_bridge: Bridge stops bridging channels SIP/sipura1-081e6168 and SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/sipura1-081da1c0' [Dec 31 00:06:38] DEBUG[17445]: chan_sip.c:3263 sip_hangup: SIP Transfer: Not hanging up right now... Rescheduling hangup for 72899b496fa48669208d2b8327e567eb@172.31.3.2. [Dec 31 00:06:38] DEBUG[17445]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sipura1-081da1c0 [Dec 31 00:06:38] DEBUG[17445]: rtp.c:1465 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Dec 31 00:06:38] DEBUG[17445]: app_dial.c:1643 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Dec 31 00:06:38] DEBUG[17445]: pbx.c:2363 __ast_pbx_run: Spawn extension (local,6002,1) exited non-zero on 'SIP/sipura1-081e6168' == Spawn extension (local, 6002, 1) exited non-zero on 'SIP/sipura1-081e6168' [Dec 31 00:06:38] DEBUG[17445]: channel.c:1611 ast_hangup: Hanging up zombie 'SIP/sipura1-081e6168' [Dec 31 00:06:38] DEBUG[17445]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sipura1-081e6168 [Dec 31 00:06:38] DEBUG[17418]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - sipura1 [Dec 31 00:06:38] DEBUG[17418]: chan_sip.c:15057 sip_devicestate: Checking device state for peer sipura1 [Dec 31 00:06:38] DEBUG[17418]: devicestate.c:287 do_state_change: Changing state for SIP/sipura1 - state 1 (Not in use) [Dec 31 00:06:38] DEBUG[17461]: app_queue.c:546 changethread: Device 'SIP/sipura1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 31 00:06:38] DEBUG[17418]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - sipura1 [Dec 31 00:06:38] DEBUG[17418]: chan_sip.c:15057 sip_devicestate: Checking device state for peer sipura1 [Dec 31 00:06:38] DEBUG[17418]: devicestate.c:287 do_state_change: Changing state for SIP/sipura1 - state 1 (Not in use) [Dec 31 00:06:38] DEBUG[17462]: app_queue.c:546 changethread: Device 'SIP/sipura1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 31 00:06:38] DEBUG[17420]: chan_sip.c:4315 find_call: = No match Their Call ID: 583d108640718a035dccf24412a210cd@172.31.3.2 Their Tag f202ac1caa6e1fdfi1 Our tag: as3ca4e158 [Dec 31 00:06:38] DEBUG[17420]: chan_sip.c:4315 find_call: = Found Their Call ID: d686e15b-5d69d3a6@172.31.3.7 Their Tag 7cd90dd7e07b315ao0 Our tag: as43d983f7 [Dec 31 00:06:38] DEBUG[17420]: chan_sip.c:2071 __sip_ack: Stopping retransmission on 'd686e15b-5d69d3a6@172.31.3.7' of Request 102: Match Not Found Really destroying SIP dialog 'd686e15b-5d69d3a6@172.31.3.7' Method: ACK [Dec 31 00:06:42] DEBUG[17420]: chan_sip.c:4315 find_call: = No match Their Call ID: 583d108640718a035dccf24412a210cd@172.31.3.2 Their Tag f202ac1caa6e1fdfi1 Our tag: as3ca4e158 [Dec 31 00:06:42] DEBUG[17420]: chan_sip.c:4315 find_call: = Found Their Call ID: 72899b496fa48669208d2b8327e567eb@172.31.3.2 Their Tag 44027a2dbb25bb79i0 Our tag: as30c33ae9 [Dec 31 00:06:42] DEBUG[17420]: chan_sip.c:14462 handle_request: **** Received BYE (8) - Command in SIP BYE [Dec 31 00:06:42] DEBUG[17420]: chan_sip.c:1615 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 72899b496fa48669208d2b8327e567eb@172.31.3.2 [Dec 31 00:06:42] DEBUG[17420]: chan_sip.c:14043 handle_request_bye: Received bye, no owner, selfdestruct soon. [Dec 31 00:06:47] DEBUG[17424]: chan_iax2.c:7691 iax2_do_register: Allocate call number [Dec 31 00:06:47] DEBUG[17424]: chan_iax2.c:7697 iax2_do_register: Registration created on call 5 [Dec 31 00:06:50] DEBUG[17420]: chan_sip.c:4315 find_call: = Found Their Call ID: 583d108640718a035dccf24412a210cd@172.31.3.2 Their Tag f202ac1caa6e1fdfi1 Our tag: as3ca4e158 [Dec 31 00:06:50] DEBUG[17420]: chan_sip.c:14462 handle_request: **** Received BYE (8) - Command in SIP BYE [Dec 31 00:06:50] DEBUG[17420]: chan_sip.c:1615 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 583d108640718a035dccf24412a210cd@172.31.3.2 [Dec 31 00:06:50] DEBUG[17420]: chan_sip.c:14039 handle_request_bye: Received bye, issuing owner hangup [Dec 31 00:06:50] DEBUG[17454]: rtp.c:3043 bridge_p2p_loop: Oooh, got a hangup [Dec 31 00:06:50] DEBUG[17454]: channel.c:3924 ast_channel_bridge: Returning from native bridge, channels: SIP/cisco-081d36b8, SIP/sipura2-081ea6f0 [Dec 31 00:06:50] DEBUG[17454]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/sipura2-081ea6f0' [Dec 31 00:06:50] DEBUG[17454]: chan_sip.c:3278 sip_hangup: Hangup call SIP/sipura2-081ea6f0, SIP callid 583d108640718a035dccf24412a210cd@172.31.3.2) [Dec 31 00:06:50] DEBUG[17454]: chan_sip.c:2978 update_call_counter: Updating call counter for outgoing call [Dec 31 00:06:50] DEBUG[17454]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sipura2-081ea6f0 [Dec 31 00:06:50] DEBUG[17454]: rtp.c:1465 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Dec 31 00:06:50] DEBUG[17454]: app_dial.c:1643 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Dec 31 00:06:50] DEBUG[17454]: pbx.c:2363 __ast_pbx_run: Spawn extension (local,6003,1) exited non-zero on 'SIP/cisco-081d36b8' == Spawn extension (local, 6003, 1) exited non-zero on 'SIP/cisco-081d36b8' [Dec 31 00:06:50] DEBUG[17418]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - sipura2 [Dec 31 00:06:50] DEBUG[17418]: chan_sip.c:15057 sip_devicestate: Checking device state for peer sipura2 [Dec 31 00:06:50] DEBUG[17418]: devicestate.c:287 do_state_change: Changing state for SIP/sipura2 - state 1 (Not in use) [Dec 31 00:06:50] DEBUG[17466]: app_queue.c:546 changethread: Device 'SIP/sipura2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Really destroying SIP dialog '583d108640718a035dccf24412a210cd@172.31.3.2' Method: BYE [Dec 31 00:06:50] DEBUG[17454]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/cisco-081d36b8' [Dec 31 00:06:50] DEBUG[17454]: chan_sip.c:3278 sip_hangup: Hangup call SIP/cisco-081d36b8, SIP callid 003094c3-c95e0019-47a51d42-7f68c7e7@172.31.3.8) [Dec 31 00:06:50] DEBUG[17454]: chan_sip.c:2978 update_call_counter: Updating call counter for incoming call [Dec 31 00:06:50] DEBUG[17454]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/cisco-081d36b8 [Dec 31 00:06:50] DEBUG[17418]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - cisco [Dec 31 00:06:50] DEBUG[17418]: chan_sip.c:15057 sip_devicestate: Checking device state for peer cisco [Dec 31 00:06:50] DEBUG[17418]: devicestate.c:287 do_state_change: Changing state for SIP/cisco - state 1 (Not in use) [Dec 31 00:06:50] DEBUG[17467]: app_queue.c:546 changethread: Device 'SIP/cisco' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Dec 31 00:06:50] DEBUG[17420]: chan_sip.c:4315 find_call: = No match Their Call ID: 72899b496fa48669208d2b8327e567eb@172.31.3.2 Their Tag 44027a2dbb25bb79i0 Our tag: as30c33ae9 [Dec 31 00:06:50] DEBUG[17420]: chan_sip.c:4315 find_call: = Found Their Call ID: 003094c3-c95e0019-47a51d42-7f68c7e7@172.31.3.8 Their Tag 003094c3c95e003177dc5fad-2c667dff Our tag: as6e7a11b1 [Dec 31 00:06:50] DEBUG[17420]: chan_sip.c:2071 __sip_ack: Stopping retransmission on '003094c3-c95e0019-47a51d42-7f68c7e7@172.31.3.8' of Request 102: Match Not Found Really destroying SIP dialog '003094c3-c95e0019-47a51d42-7f68c7e7@172.31.3.8' Method: ACK stop now Beginning asterisk shutdown.... Executing last minute cleanups == Destroying musiconhold processes Asterisk cleanly ending (0). [Dec 31 00:06:52] DEBUG[17413]: asterisk.c:1191 quit_handler: Asterisk ending (0). root@avalon:/tmp# exit Script done on Sun 31 Dec 2006 12:06:52 AM EST