[Nov 21 14:43:55] Asterisk SVN-branch-12-r402968 built by dlee @ dlee-mac on a x86_64 running Darwin on 2013-11-15 19:13:54 UTC [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action DBGet [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action DBPut [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action DBDel [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action DBDelTree [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered custom function 'MESSAGE' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered custom function 'MESSAGE_DATA' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'MessageSend' [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action MessageSend [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action DataGet [Nov 21 14:43:55] VERBOSE[1287] channel.c: == Registered channel type 'Surrogate' (Surrogate channel used to pull channel from an application) [Nov 21 14:43:55] VERBOSE[1287] loader.c: Asterisk Dynamic Loader Starting: [Nov 21 14:43:55] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/modules.conf': Found [Nov 21 14:43:55] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/modules-pjsip.conf': Found [Nov 21 14:43:55] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/acl.conf': Found [Nov 21 14:43:55] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/http.conf': Found [Nov 21 14:43:55] VERBOSE[1287] http.c: Bound HTTP server to address 127.0.0.1:0 [Nov 21 14:43:55] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/indications.conf': Found [Nov 21 14:43:55] VERBOSE[1287] indications.c: -- Registered indication country 'us' [Nov 21 14:43:55] VERBOSE[1287] indications.c: -- Setting default indication country to 'us' [Nov 21 14:43:55] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/features.conf': Found [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered custom function 'FEATURE' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered custom function 'FEATUREMAP' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'Bridge' [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action Bridge [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action BridgeTechnologyList [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action BridgeTechnologySuspend [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action BridgeTechnologyUnsuspend [Nov 21 14:43:55] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/cdr.conf': Found [Nov 21 14:43:55] NOTICE[1287] cdr.c: CDR simple logging enabled. [Nov 21 14:43:55] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/udptl.conf': Found [Nov 21 14:43:55] VERBOSE[1287] pbx.c: Asterisk PBX Core Initializing [Nov 21 14:43:55] VERBOSE[1287] pbx.c: Registering builtin applications: [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered custom function 'EXCEPTION' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered custom function 'TESTTIME' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [Answer] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'Answer' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [BackGround] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'BackGround' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [Busy] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'Busy' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [Congestion] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'Congestion' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [ExecIfTime] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'ExecIfTime' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [Goto] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'Goto' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [GotoIf] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'GotoIf' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [GotoIfTime] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'GotoIfTime' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [ImportVar] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'ImportVar' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [Hangup] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'Hangup' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [Incomplete] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'Incomplete' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [NoOp] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'NoOp' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [Proceeding] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'Proceeding' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [Progress] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'Progress' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [RaiseException] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'RaiseException' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [Ringing] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'Ringing' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [SayAlpha] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'SayAlpha' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [SayAlphaCase] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'SayAlphaCase' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [SayDigits] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'SayDigits' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [SayNumber] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'SayNumber' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [SayPhonetic] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'SayPhonetic' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [Set] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'Set' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [MSet] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'MSet' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [SetAMAFlags] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'SetAMAFlags' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [Wait] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'Wait' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: [WaitExten] [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'WaitExten' [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action ShowDialPlan [Nov 21 14:43:55] VERBOSE[1287] channel.c: == Registered channel type 'Local' (Local Proxy Channel Driver) [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action LocalOptimizeAway [Nov 21 14:43:55] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/cel.conf': Found [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action Ping [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action Events [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action Logoff [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action Login [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action Challenge [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action Hangup [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action Status [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action Setvar [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action Getvar [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action GetConfig [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action GetConfigJSON [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action UpdateConfig [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action CreateConfig [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action ListCategories [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action Redirect [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action Atxfer [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action Originate [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action Command [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action ExtensionState [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action PresenceState [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action AbsoluteTimeout [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action MailboxStatus [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action MailboxCount [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action ListCommands [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action SendText [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action UserEvent [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action WaitEvent [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action CoreSettings [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action CoreStatus [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action Reload [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action CoreShowChannels [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action ModuleLoad [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action ModuleCheck [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action AOCMessage [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action Filter [Nov 21 14:43:55] VERBOSE[1287] manager.c: == Manager registered action BlindTransfer [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered custom function 'AMI_CLIENT' [Nov 21 14:43:55] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/manager.conf': Found [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'CallCompletionRequest' [Nov 21 14:43:55] VERBOSE[1287] pbx.c: == Registered application 'CallCompletionCancel' [Nov 21 14:43:55] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/ccss.conf': Found [Nov 21 14:43:55] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/ccss.conf': Found [Nov 21 14:43:55] VERBOSE[1287] loader.c: Asterisk Dynamic Loader Starting: [Nov 21 14:43:55] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/modules.conf': Found [Nov 21 14:43:55] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/modules-pjsip.conf': Found [Nov 21 14:43:55] NOTICE[1287] loader.c: 71 modules will be loaded. [Nov 21 14:43:56] WARNING[1287] loader.c: Error loading module 'res_ari_playback.so': dlopen(/opt/Asterisk/12/lib/asterisk/modules/res_ari_playback.so, 5): image not found [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_sorcery_astdb.so. [Nov 21 14:43:56] VERBOSE[1287] sorcery.c: == Sorcery registered wizard 'astdb' [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_sorcery_astdb.so => (Sorcery Astdb Object Wizard) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_sorcery_config.so. [Nov 21 14:43:56] VERBOSE[1287] sorcery.c: == Sorcery registered wizard 'config' [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_sorcery_config.so => (Sorcery Configuration File Object Wizard) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_sorcery_memory.so. [Nov 21 14:43:56] VERBOSE[1287] sorcery.c: == Sorcery registered wizard 'memory' [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_sorcery_memory.so => (Sorcery In-Memory Object Wizard) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_log_forwarder.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_log_forwarder.so => (PJSIP Log Forwarder) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip.so. [Nov 21 14:43:56] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/pjsip.conf': Found [Nov 21 14:43:56] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/pjsip.conf': Found [Nov 21 14:43:56] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/pjsip.conf': Found [Nov 21 14:43:56] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/pjsip.conf': Found [Nov 21 14:43:56] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/pjsip.conf': Found [Nov 21 14:43:56] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/pjsip.conf': Found [Nov 21 14:43:56] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/pjsip.conf': Found [Nov 21 14:43:56] VERBOSE[1287] manager.c: == Manager registered action PJSIPQualify [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip.so => (Basic SIP resource) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_pubsub.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_pubsub.so => (PJSIP event resource) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_http_websocket.so. [Nov 21 14:43:56] VERBOSE[1287] res_http_websocket.c: == WebSocket registered sub-protocol 'echo' [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_http_websocket.so => (HTTP WebSocket Support) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_exten_state.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_exten_state.so => (PJSIP Extension State Notifications) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_ari_model.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_ari_model.so => (ARI Model validators) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_stasis_recording.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_stasis_recording.so => (Stasis application recording support) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_stasis_test.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_stasis_test.so => (Stasis test utilities) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_session.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_session.so => (PJSIP Session resource) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_ari.so. [Nov 21 14:43:56] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/ari.conf': Found [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_ari.so => (Asterisk RESTful Interface) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_stasis_playback.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_stasis_playback.so => (Stasis application playback support) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_stasis_answer.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_stasis_answer.so => (Stasis application answer support) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_stasis.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_stasis.so => (Stasis application support) [Nov 21 14:43:56] WARNING[1287] loader.c: Error loading module 'res_ari_playback.so': dlopen(/opt/Asterisk/12/lib/asterisk/modules/res_ari_playback.so, 5): image not found [Nov 21 14:43:56] WARNING[1287] loader.c: Module 'res_ari_playback.so' could not be loaded. [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_musiconhold.so. [Nov 21 14:43:56] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/musiconhold.conf': Found [Nov 21 14:43:56] VERBOSE[1287] pbx.c: == Registered application 'MusicOnHold' [Nov 21 14:43:56] VERBOSE[1287] pbx.c: == Registered application 'WaitMusicOnHold' [Nov 21 14:43:56] VERBOSE[1287] pbx.c: == Registered application 'SetMusicOnHold' [Nov 21 14:43:56] VERBOSE[1287] pbx.c: == Registered application 'StartMusicOnHold' [Nov 21 14:43:56] VERBOSE[1287] pbx.c: == Registered application 'StopMusicOnHold' [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_musiconhold.so => (Music On Hold Resource) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_rtp_asterisk.so. [Nov 21 14:43:56] VERBOSE[1287] rtp_engine.c: == Registered RTP engine 'asterisk' [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_rtp_asterisk.so => (Asterisk RTP Stack) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_authenticator_digest.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_authenticator_digest.so => (PJSIP authentication resource) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_mwi.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_mwi.so => (PJSIP MWI resource) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_outbound_authenticator_digest.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_outbound_authenticator_digest.so => (PJSIP authentication resource) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_pidf.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_pidf.so => (PJSIP Extension State PIDF Provider) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading chan_pjsip.so. [Nov 21 14:43:56] VERBOSE[1287] rtp_engine.c: == Registered RTP glue 'PJSIP' [Nov 21 14:43:56] VERBOSE[1287] channel.c: == Registered channel type 'PJSIP' (PJSIP Channel Driver) [Nov 21 14:43:56] VERBOSE[1287] pbx.c: == Registered custom function 'PJSIP_DIAL_CONTACTS' [Nov 21 14:43:56] VERBOSE[1287] pbx.c: == Registered custom function 'PJSIP_MEDIA_OFFER' [Nov 21 14:43:56] VERBOSE[1287] loader.c: chan_pjsip.so => (PJSIP Channel Driver) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_sdp_rtp.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_sdp_rtp.so => (PJSIP SDP RTP/AVP stream handler) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_one_touch_record_info.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_one_touch_record_info.so => (PJSIP INFO One Touch Recording Support) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_registrar.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_registrar.so => (PJSIP Registrar Support) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_acl.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_acl.so => (PJSIP ACL Resource) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading format_wav_gsm.so. [Nov 21 14:43:56] VERBOSE[1287] file.c: == Registered file format wav49, extension(s) WAV|wav49 [Nov 21 14:43:56] VERBOSE[1287] loader.c: format_wav_gsm.so => (Microsoft WAV format (Proprietary GSM)) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_messaging.so. [Nov 21 14:43:56] VERBOSE[1287] message.c: -- Message technology handler 'pjsip' registered. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_messaging.so => (PJSIP Messaging Support) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_caller_id.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_caller_id.so => (PJSIP Caller ID Support) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_diversion.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_diversion.so => (PJSIP Add Diversion Header Support) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_dtmf_info.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_dtmf_info.so => (PJSIP DTMF INFO Support) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_endpoint_identifier_ip.so. [Nov 21 14:43:56] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/pjsip.conf': Found [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_endpoint_identifier_ip.so => (PJSIP IP endpoint identifier) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_endpoint_identifier_user.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_endpoint_identifier_user.so => (PJSIP username endpoint identifier) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_header_funcs.so. [Nov 21 14:43:56] VERBOSE[1287] pbx.c: == Registered custom function 'PJSIP_HEADER' [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_header_funcs.so => (PJSIP Header Functions) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_logger.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_logger.so => (PJSIP Packet Logger) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading format_wav.so. [Nov 21 14:43:56] VERBOSE[1287] file.c: == Registered file format wav, extension(s) wav [Nov 21 14:43:56] VERBOSE[1287] file.c: == Registered file format wav16, extension(s) wav16 [Nov 21 14:43:56] VERBOSE[1287] loader.c: format_wav.so => (Microsoft WAV/WAV16 format (8kHz/16kHz Signed Linear)) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_nat.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_nat.so => (PJSIP NAT Support) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading format_g729.so. [Nov 21 14:43:56] VERBOSE[1287] file.c: == Registered file format g729, extension(s) g729 [Nov 21 14:43:56] VERBOSE[1287] loader.c: format_g729.so => (Raw G.729 data) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_outbound_registration.so. [Nov 21 14:43:56] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/pjsip.conf': Found [Nov 21 14:43:56] VERBOSE[1287] manager.c: == Manager registered action PJSIPUnregister [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_outbound_registration.so => (PJSIP Outbound Registration Support) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_refer.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_refer.so => (PJSIP Blind and Attended Transfer Support) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading format_gsm.so. [Nov 21 14:43:56] VERBOSE[1287] file.c: == Registered file format gsm, extension(s) gsm [Nov 21 14:43:56] VERBOSE[1287] loader.c: format_gsm.so => (Raw GSM data) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_rfc3326.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_rfc3326.so => (PJSIP RFC3326 Support) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_registrar_expire.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_registrar_expire.so => (PJSIP Contact Auto-Expiration) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading app_stasis.so. [Nov 21 14:43:56] VERBOSE[1287] pbx.c: == Registered application 'Stasis' [Nov 21 14:43:56] VERBOSE[1287] loader.c: app_stasis.so => (Stasis dialplan application) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading bridge_simple.so. [Nov 21 14:43:56] VERBOSE[1287] bridge.c: == Registered bridge technology simple_bridge [Nov 21 14:43:56] VERBOSE[1287] loader.c: bridge_simple.so => (Simple two channel bridging module) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_ari_channels.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_ari_channels.so => (RESTful API module - Channel resources) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading bridge_holding.so. [Nov 21 14:43:56] VERBOSE[1287] bridge.c: == Registered bridge technology holding_bridge [Nov 21 14:43:56] VERBOSE[1287] loader.c: bridge_holding.so => (Holding bridge module) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading pbx_config.so. [Nov 21 14:43:56] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/extensions.conf': Found [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Registered extension context 'default'; registrar: pbx_config [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Including context 'phones' in context 'default' [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Including context 'apps' in context 'default' [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Registered extension context 'phones'; registrar: pbx_config [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '6001' priority 1 to phones [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '6002' priority 1 to phones [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '6003' priority 1 to phones [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '6004' priority 1 to phones [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '6005' priority 1 to phones [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Registered extension context 'macro-phone'; registrar: pbx_config [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension 's' priority 1 to macro-phone [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension 's' priority 2 to macro-phone [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension 's' priority 3 to macro-phone [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension 'ANSWER' priority 1 to macro-phone [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension 'CANCEL' priority 1 to macro-phone [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension 'NOANSWER' priority 1 to macro-phone [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension 'BUSY' priority 1 to macro-phone [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension 'CONGESTION' priority 1 to macro-phone [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension 'CHANUNAVAIL' priority 1 to macro-phone [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension 'a' priority 1 to macro-phone [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Registered extension context 'apps'; registrar: pbx_config [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '7000' priority 1 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '7000' priority 2 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '7000' priority 3 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '7000' priority 4 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '7001' priority 1 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '7001' priority 2 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '7001' priority 3 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '7001' priority 4 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '8000' priority 1 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '8000' priority 2 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '8000' priority 3 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '8000' priority 4 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '8001' priority 1 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '8001' priority 2 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '8001' priority 3 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '8001' priority 4 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '8002' priority 1 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '8002' priority 2 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '8002' priority 3 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '8002' priority 4 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '8003' priority 1 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '8003' priority 2 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '8003' priority 3 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '8003' priority 4 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '8003' priority 5 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '8003' priority 6 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Added extension '8003' priority 7 to apps [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Time to scan old dialplan and merge leftovers back into the new: 0.000002 sec [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Time to restore hints and swap in new dialplan: 0.000005 sec [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Time to delete the old dialplan: 0.000001 sec [Nov 21 14:43:56] VERBOSE[1287] pbx.c: -- Total time merge_contexts_delete: 0.000008 sec [Nov 21 14:43:56] VERBOSE[1287] loader.c: pbx_config.so => (Text Extension Configuration) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading bridge_softmix.so. [Nov 21 14:43:56] VERBOSE[1287] bridge.c: == Registered bridge technology softmix [Nov 21 14:43:56] VERBOSE[1287] loader.c: bridge_softmix.so => (Multi-party software based channel mixing) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_clialiases.so. [Nov 21 14:43:56] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/cli_aliases.conf': Found [Nov 21 14:43:56] VERBOSE[1287] res_clialiases.c: == Aliased CLI command 'hangup request' to 'channel request hangup' [Nov 21 14:43:56] VERBOSE[1287] res_clialiases.c: == Aliased CLI command 'originate' to 'channel originate' [Nov 21 14:43:56] VERBOSE[1287] res_clialiases.c: == Aliased CLI command 'help' to 'core show help' [Nov 21 14:43:56] VERBOSE[1287] res_clialiases.c: == Aliased CLI command 'pri intense debug span' to 'pri set debug intense span' [Nov 21 14:43:56] VERBOSE[1287] res_clialiases.c: == Aliased CLI command 'reload' to 'module reload' [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_clialiases.so => (CLI Aliases) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_ari_endpoints.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_ari_endpoints.so => (RESTful API module - Endpoint resources) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading codec_g722.so. [Nov 21 14:43:56] VERBOSE[1287] translate.c: == Registered translator 'g722tolin' from format g722 to slin, table cost, 960000, computational cost 9529 [Nov 21 14:43:56] VERBOSE[1287] translate.c: == Registered translator 'lintog722' from format slin to g722, table cost, 825000, computational cost 11352 [Nov 21 14:43:56] VERBOSE[1287] translate.c: == Registered translator 'g722tolin16' from format g722 to slin16, table cost, 900000, computational cost 26685 [Nov 21 14:43:56] VERBOSE[1287] translate.c: == Registered translator 'lin16tog722' from format slin16 to g722, table cost, 600000, computational cost 31265 [Nov 21 14:43:56] VERBOSE[1287] loader.c: codec_g722.so => (ITU G.722-64kbps G722 Transcoder) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading codec_g726.so. [Nov 21 14:43:56] VERBOSE[1287] translate.c: == Registered translator 'g726tolin' from format g726 to slin, table cost, 900000, computational cost 6397 [Nov 21 14:43:56] VERBOSE[1287] translate.c: == Registered translator 'lintog726' from format slin to g726, table cost, 600000, computational cost 15543 [Nov 21 14:43:56] VERBOSE[1287] translate.c: == Registered translator 'g726aal2tolin' from format g726aal2 to slin, table cost, 900000, computational cost 5765 [Nov 21 14:43:56] VERBOSE[1287] translate.c: == Registered translator 'lintog726aal2' from format slin to g726aal2, table cost, 600000, computational cost 15974 [Nov 21 14:43:56] VERBOSE[1287] loader.c: codec_g726.so => (ITU G.726-32kbps G726 Transcoder) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_ari_asterisk.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_ari_asterisk.so => (RESTful API module - Asterisk resources) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_ari_events.so. [Nov 21 14:43:56] VERBOSE[1287] res_http_websocket.c: == WebSocket registered sub-protocol 'ari' [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_ari_events.so => (RESTful API module - WebSocket resource) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading app_verbose.so. [Nov 21 14:43:56] VERBOSE[1287] pbx.c: == Registered application 'Log' [Nov 21 14:43:56] VERBOSE[1287] pbx.c: == Registered application 'Verbose' [Nov 21 14:43:56] VERBOSE[1287] loader.c: app_verbose.so => (Send verbose output) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading bridge_native_rtp.so. [Nov 21 14:43:56] VERBOSE[1287] bridge.c: == Registered bridge technology native_rtp [Nov 21 14:43:56] VERBOSE[1287] loader.c: bridge_native_rtp.so => (Native RTP bridging module) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_ari_applications.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_ari_applications.so => (RESTful API module - Stasis application resources) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_ari_bridges.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_ari_bridges.so => (RESTful API module - Bridge resources) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading codec_gsm.so. [Nov 21 14:43:56] VERBOSE[1287] translate.c: == Registered translator 'gsmtolin' from format gsm to slin, table cost, 900000, computational cost 1883 [Nov 21 14:43:56] VERBOSE[1287] translate.c: == Registered translator 'lintogsm' from format slin to gsm, table cost, 600000, computational cost 2731 [Nov 21 14:43:56] VERBOSE[1287] loader.c: codec_gsm.so => (GSM Coder/Decoder) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_pjsip_endpoint_identifier_anonymous.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_pjsip_endpoint_identifier_anonymous.so => (PJSIP Anonymous endpoint identifier) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading bridge_builtin_interval_features.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: bridge_builtin_interval_features.so => (Built in bridging interval features) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading codec_ulaw.so. [Nov 21 14:43:56] VERBOSE[1287] translate.c: == Registered translator 'ulawtolin' from format ulaw to slin, table cost, 900000, computational cost 145 [Nov 21 14:43:56] VERBOSE[1287] translate.c: == Registered translator 'lintoulaw' from format slin to ulaw, table cost, 600000, computational cost 246 [Nov 21 14:43:56] VERBOSE[1287] translate.c: == Registered translator 'lintotestlaw' from format slin to testlaw, table cost, 600000, computational cost 79 [Nov 21 14:43:56] VERBOSE[1287] translate.c: == Registered translator 'testlawtolin' from format testlaw to slin, table cost, 900000, computational cost 78 [Nov 21 14:43:56] VERBOSE[1287] loader.c: codec_ulaw.so => (mu-Law Coder/Decoder) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading app_dial.so. [Nov 21 14:43:56] VERBOSE[1287] pbx.c: == Registered application 'Dial' [Nov 21 14:43:56] VERBOSE[1287] pbx.c: == Registered application 'RetryDial' [Nov 21 14:43:56] VERBOSE[1287] loader.c: app_dial.so => (Dialing Application) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_ari_sounds.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_ari_sounds.so => (RESTful API module - Sound resources) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading bridge_builtin_features.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: bridge_builtin_features.so => (Built in bridging features) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_clioriginate.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_clioriginate.so => (Call origination and redirection from the CLI) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading res_ari_recordings.so. [Nov 21 14:43:56] VERBOSE[1287] loader.c: res_ari_recordings.so => (RESTful API module - Recording resources) [Nov 21 14:43:56] VERBOSE[1287] loader.c: Loading app_playback.so. [Nov 21 14:43:56] VERBOSE[1287] pbx.c: == Registered application 'Playback' [Nov 21 14:43:56] VERBOSE[1287] loader.c: app_playback.so => (Sound File Playback Application) [Nov 21 14:43:56] VERBOSE[1287] asterisk.c: Asterisk Ready. [Nov 21 14:44:08] Asterisk SVN-branch-12-r402968 built by dlee @ dlee-mac on a x86_64 running Darwin on 2013-11-15 19:13:54 UTC [Nov 21 14:44:08] DEBUG[1287] config.c: Parsing /opt/Asterisk/12/etc/asterisk/logger.conf [Nov 21 14:44:08] VERBOSE[1287] config.c: == Parsing '/opt/Asterisk/12/etc/asterisk/logger.conf': Found [Nov 21 14:44:08] VERBOSE[1287] logger.c: Asterisk Queue Logger restarted [Nov 21 14:44:13] DEBUG[13059] http.c: HTTP Request URI is /ari/api-docs/resources.json [Nov 21 14:44:13] DEBUG[13059] http.c: match request [ari/api-docs/resources.json] with handler [httpstatus] len 10 [Nov 21 14:44:13] DEBUG[13059] http.c: match request [ari/api-docs/resources.json] with handler [static] len 6 [Nov 21 14:44:13] DEBUG[13059] http.c: match request [ari/api-docs/resources.json] with handler [ari] len 3 [Nov 21 14:44:13] DEBUG[13059] http.c: Match made with [ari] [Nov 21 14:44:13] DEBUG[13059] res_ari.c: ast_ari_get_docs(resources.json) [Nov 21 14:44:13] DEBUG[13063] http.c: HTTP Request URI is /ari/api-docs/asterisk.json [Nov 21 14:44:13] DEBUG[13063] http.c: match request [ari/api-docs/asterisk.json] with handler [httpstatus] len 10 [Nov 21 14:44:13] DEBUG[13063] http.c: match request [ari/api-docs/asterisk.json] with handler [static] len 6 [Nov 21 14:44:13] DEBUG[13063] http.c: match request [ari/api-docs/asterisk.json] with handler [ari] len 3 [Nov 21 14:44:13] DEBUG[13063] http.c: Match made with [ari] [Nov 21 14:44:13] DEBUG[13063] res_ari.c: ast_ari_get_docs(asterisk.json) [Nov 21 14:44:13] DEBUG[13067] http.c: HTTP Request URI is /ari/api-docs/endpoints.json [Nov 21 14:44:13] DEBUG[13067] http.c: match request [ari/api-docs/endpoints.json] with handler [httpstatus] len 10 [Nov 21 14:44:13] DEBUG[13067] http.c: match request [ari/api-docs/endpoints.json] with handler [static] len 6 [Nov 21 14:44:13] DEBUG[13067] http.c: match request [ari/api-docs/endpoints.json] with handler [ari] len 3 [Nov 21 14:44:13] DEBUG[13067] http.c: Match made with [ari] [Nov 21 14:44:13] DEBUG[13067] res_ari.c: ast_ari_get_docs(endpoints.json) [Nov 21 14:44:13] DEBUG[13071] http.c: HTTP Request URI is /ari/api-docs/channels.json [Nov 21 14:44:13] DEBUG[13071] http.c: match request [ari/api-docs/channels.json] with handler [httpstatus] len 10 [Nov 21 14:44:13] DEBUG[13071] http.c: match request [ari/api-docs/channels.json] with handler [static] len 6 [Nov 21 14:44:13] DEBUG[13071] http.c: match request [ari/api-docs/channels.json] with handler [ari] len 3 [Nov 21 14:44:13] DEBUG[13071] http.c: Match made with [ari] [Nov 21 14:44:13] DEBUG[13071] res_ari.c: ast_ari_get_docs(channels.json) [Nov 21 14:44:13] DEBUG[13075] http.c: HTTP Request URI is /ari/api-docs/bridges.json [Nov 21 14:44:13] DEBUG[13075] http.c: match request [ari/api-docs/bridges.json] with handler [httpstatus] len 10 [Nov 21 14:44:13] DEBUG[13075] http.c: match request [ari/api-docs/bridges.json] with handler [static] len 6 [Nov 21 14:44:13] DEBUG[13075] http.c: match request [ari/api-docs/bridges.json] with handler [ari] len 3 [Nov 21 14:44:13] DEBUG[13075] http.c: Match made with [ari] [Nov 21 14:44:13] DEBUG[13075] res_ari.c: ast_ari_get_docs(bridges.json) [Nov 21 14:44:13] DEBUG[13079] http.c: HTTP Request URI is /ari/api-docs/recordings.json [Nov 21 14:44:13] DEBUG[13079] http.c: match request [ari/api-docs/recordings.json] with handler [httpstatus] len 10 [Nov 21 14:44:13] DEBUG[13079] http.c: match request [ari/api-docs/recordings.json] with handler [static] len 6 [Nov 21 14:44:13] DEBUG[13079] http.c: match request [ari/api-docs/recordings.json] with handler [ari] len 3 [Nov 21 14:44:13] DEBUG[13079] http.c: Match made with [ari] [Nov 21 14:44:13] DEBUG[13079] res_ari.c: ast_ari_get_docs(recordings.json) [Nov 21 14:44:13] DEBUG[13083] http.c: HTTP Request URI is /ari/api-docs/sounds.json [Nov 21 14:44:13] DEBUG[13083] http.c: match request [ari/api-docs/sounds.json] with handler [httpstatus] len 10 [Nov 21 14:44:13] DEBUG[13083] http.c: match request [ari/api-docs/sounds.json] with handler [static] len 6 [Nov 21 14:44:13] DEBUG[13083] http.c: match request [ari/api-docs/sounds.json] with handler [ari] len 3 [Nov 21 14:44:13] DEBUG[13083] http.c: Match made with [ari] [Nov 21 14:44:13] DEBUG[13083] res_ari.c: ast_ari_get_docs(sounds.json) [Nov 21 14:44:13] DEBUG[13087] http.c: HTTP Request URI is /ari/api-docs/playbacks.json [Nov 21 14:44:13] DEBUG[13087] http.c: match request [ari/api-docs/playbacks.json] with handler [httpstatus] len 10 [Nov 21 14:44:13] DEBUG[13087] http.c: match request [ari/api-docs/playbacks.json] with handler [static] len 6 [Nov 21 14:44:13] DEBUG[13087] http.c: match request [ari/api-docs/playbacks.json] with handler [ari] len 3 [Nov 21 14:44:13] DEBUG[13087] http.c: Match made with [ari] [Nov 21 14:44:13] DEBUG[13087] res_ari.c: ast_ari_get_docs(playbacks.json) [Nov 21 14:44:13] DEBUG[13091] http.c: HTTP Request URI is /ari/api-docs/events.json [Nov 21 14:44:13] DEBUG[13091] http.c: match request [ari/api-docs/events.json] with handler [httpstatus] len 10 [Nov 21 14:44:13] DEBUG[13091] http.c: match request [ari/api-docs/events.json] with handler [static] len 6 [Nov 21 14:44:13] DEBUG[13091] http.c: match request [ari/api-docs/events.json] with handler [ari] len 3 [Nov 21 14:44:13] DEBUG[13091] http.c: Match made with [ari] [Nov 21 14:44:13] DEBUG[13091] res_ari.c: ast_ari_get_docs(events.json) [Nov 21 14:44:13] DEBUG[13095] http.c: HTTP Request URI is /ari/api-docs/applications.json [Nov 21 14:44:13] DEBUG[13095] http.c: match request [ari/api-docs/applications.json] with handler [httpstatus] len 10 [Nov 21 14:44:13] DEBUG[13095] http.c: match request [ari/api-docs/applications.json] with handler [static] len 6 [Nov 21 14:44:13] DEBUG[13095] http.c: match request [ari/api-docs/applications.json] with handler [ari] len 3 [Nov 21 14:44:13] DEBUG[13095] http.c: Match made with [ari] [Nov 21 14:44:13] DEBUG[13095] res_ari.c: ast_ari_get_docs(applications.json) [Nov 21 14:44:13] DEBUG[13099] http.c: HTTP Request URI is /ari/bridges?type=mixing [Nov 21 14:44:13] DEBUG[13099] http.c: match request [ari/bridges] with handler [httpstatus] len 10 [Nov 21 14:44:13] DEBUG[13099] http.c: match request [ari/bridges] with handler [static] len 6 [Nov 21 14:44:13] DEBUG[13099] http.c: match request [ari/bridges] with handler [ari] len 3 [Nov 21 14:44:13] DEBUG[13099] http.c: Match made with [ari] [Nov 21 14:44:13] DEBUG[13099] res_ari.c: Finding handler for bridges [Nov 21 14:44:13] DEBUG[13099] res_ari.c: Checking channels [Nov 21 14:44:13] DEBUG[13099] res_ari.c: Checking endpoints [Nov 21 14:44:13] DEBUG[13099] res_ari.c: Checking asterisk [Nov 21 14:44:13] DEBUG[13099] res_ari.c: Checking events [Nov 21 14:44:13] DEBUG[13099] res_ari.c: Checking applications [Nov 21 14:44:13] DEBUG[13099] res_ari.c: Checking bridges [Nov 21 14:44:13] DEBUG[13099] res_ari.c: Got it! [Nov 21 14:44:13] DEBUG[13099] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Nov 21 14:44:13] DEBUG[13099] bridge.c: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping. [Nov 21 14:44:13] DEBUG[13099] bridge_native_rtp.c: Bridge 'bad81495-5672-41b3-bdbc-6cb00a942f0d' can not use native RTP bridge as two channels are required [Nov 21 14:44:13] DEBUG[13099] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Nov 21 14:44:13] DEBUG[13099] bridge.c: Chose bridge technology simple_bridge [Nov 21 14:44:13] DEBUG[13099] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d: calling simple_bridge technology constructor [Nov 21 14:44:13] DEBUG[13099] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d: calling simple_bridge technology start [Nov 21 14:44:13] DEBUG[13103] http.c: HTTP Request URI is /ari/events?app=hello [Nov 21 14:44:13] DEBUG[13103] http.c: match request [ari/events] with handler [httpstatus] len 10 [Nov 21 14:44:13] DEBUG[13103] http.c: match request [ari/events] with handler [static] len 6 [Nov 21 14:44:13] DEBUG[13103] http.c: match request [ari/events] with handler [ari] len 3 [Nov 21 14:44:13] DEBUG[13103] http.c: Match made with [ari] [Nov 21 14:44:13] DEBUG[13103] res_ari.c: Finding handler for events [Nov 21 14:44:13] DEBUG[13103] res_ari.c: Checking channels [Nov 21 14:44:13] DEBUG[13103] res_ari.c: Checking endpoints [Nov 21 14:44:13] DEBUG[13103] res_ari.c: Checking asterisk [Nov 21 14:44:13] DEBUG[13103] res_ari.c: Checking events [Nov 21 14:44:13] DEBUG[13103] res_ari.c: Got it! [Nov 21 14:44:13] VERBOSE[13103] res_http_websocket.c: == WebSocket connection from '127.0.0.1:52935' for protocol '' accepted using version '13' [Nov 21 14:44:13] DEBUG[13103] ari/resource_events.c: /events WebSocket connection [Nov 21 14:44:13] VERBOSE[13103] stasis/app.c: Creating Stasis app 'hello' [Nov 21 14:44:22] DEBUG[8963] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=27537 (rdata0x103032a28) [Nov 21 14:44:22] DEBUG[9219] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=27537 (rdata0x10186b428) [Nov 21 14:44:22] DEBUG[9219] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Nov 21 14:44:22] DEBUG[9219] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint blink [Nov 21 14:44:22] DEBUG[9219] pjsip: endpoint .Response msg 401/INVITE/cseq=27537 (tdta0x100836e00) created [Nov 21 14:44:22] DEBUG[9219] netsock2.c: Splitting '10.24.21.100' into... [Nov 21 14:44:22] DEBUG[9219] netsock2.c: ...host '10.24.21.100' and port ''. [Nov 21 14:44:22] DEBUG[9219] netsock2.c: Splitting '127.0.0.1' into... [Nov 21 14:44:22] DEBUG[9219] netsock2.c: ...host '127.0.0.1' and port ''. [Nov 21 14:44:22] DEBUG[9219] pjsip: tdta0x100836e0 .Destroying txdata Response msg 401/INVITE/cseq=27537 (tdta0x100836e00) [Nov 21 14:44:22] DEBUG[8963] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=27537 (rdata0x10186d428) [Nov 21 14:44:22] DEBUG[9219] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=27537 (rdata0x103032a28) [Nov 21 14:44:22] DEBUG[9219] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Nov 21 14:44:22] DEBUG[9219] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint blink [Nov 21 14:44:22] DEBUG[8963] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=27538 (rdata0x10304d828) [Nov 21 14:44:22] DEBUG[9219] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=27538 (rdata0x103032a28) [Nov 21 14:44:22] DEBUG[9219] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Nov 21 14:44:22] DEBUG[9219] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint blink [Nov 21 14:44:22] DEBUG[9219] pjsip: endpoint .Response msg 401/INVITE/cseq=27538 (tdta0x100836e00) created [Nov 21 14:44:22] DEBUG[9219] res_pjsip_authenticator_digest.c: Calculated nonce 1385066662/031b7b6e39ca273ec8bedb8975c087f0. Actual nonce is 1385066662/031b7b6e39ca273ec8bedb8975c087f0 [Nov 21 14:44:22] DEBUG[9219] netsock2.c: Splitting '10.24.21.100' into... [Nov 21 14:44:22] DEBUG[9219] netsock2.c: ...host '10.24.21.100' and port ''. [Nov 21 14:44:22] DEBUG[8963] pjsip: sip_endpoint.c Processing incoming message: Request msg PUBLISH/cseq=1 (rdata0x10304d828) [Nov 21 14:44:22] DEBUG[9219] netsock2.c: Splitting '127.0.0.1' into... [Nov 21 14:44:22] DEBUG[9219] netsock2.c: ...host '127.0.0.1' and port ''. [Nov 21 14:44:22] DEBUG[9219] pjsip: tdta0x100836e0 .Destroying txdata Response msg 401/INVITE/cseq=27538 (tdta0x100836e00) [Nov 21 14:44:22] DEBUG[9475] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg PUBLISH/cseq=1 (rdata0x10306f628) [Nov 21 14:44:22] DEBUG[9475] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Nov 21 14:44:22] DEBUG[9475] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint blink [Nov 21 14:44:22] DEBUG[9475] pjsip: endpoint .Response msg 401/PUBLISH/cseq=1 (tdta0x100836e00) created [Nov 21 14:44:22] DEBUG[9475] netsock2.c: Splitting '10.24.21.100' into... [Nov 21 14:44:22] DEBUG[9475] netsock2.c: ...host '10.24.21.100' and port ''. [Nov 21 14:44:22] DEBUG[9475] netsock2.c: Splitting '127.0.0.1' into... [Nov 21 14:44:22] DEBUG[9475] netsock2.c: ...host '127.0.0.1' and port ''. [Nov 21 14:44:22] DEBUG[9475] pjsip: tdta0x100836e0 .Destroying txdata Response msg 401/PUBLISH/cseq=1 (tdta0x100836e00) [Nov 21 14:44:22] DEBUG[8963] pjsip: sip_endpoint.c Processing incoming message: Request msg PUBLISH/cseq=2 (rdata0x10304d828) [Nov 21 14:44:22] DEBUG[9475] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg PUBLISH/cseq=2 (rdata0x10282b828) [Nov 21 14:44:22] DEBUG[9475] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Nov 21 14:44:22] DEBUG[9475] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint blink [Nov 21 14:44:22] DEBUG[9475] pjsip: endpoint .Response msg 401/PUBLISH/cseq=2 (tdta0x100836e00) created [Nov 21 14:44:22] DEBUG[9475] res_pjsip_authenticator_digest.c: Calculated nonce 1385066662/031b7b6e39ca273ec8bedb8975c087f0. Actual nonce is 1385066662/031b7b6e39ca273ec8bedb8975c087f0 [Nov 21 14:44:22] DEBUG[9475] netsock2.c: Splitting '10.24.21.100' into... [Nov 21 14:44:22] DEBUG[9475] netsock2.c: ...host '10.24.21.100' and port ''. [Nov 21 14:44:22] DEBUG[9475] netsock2.c: Splitting '127.0.0.1' into... [Nov 21 14:44:22] DEBUG[9475] netsock2.c: ...host '127.0.0.1' and port ''. [Nov 21 14:44:22] DEBUG[9475] pjsip: tdta0x100836e0 .Destroying txdata Response msg 401/PUBLISH/cseq=2 (tdta0x100836e00) [Nov 21 14:44:22] WARNING[9475] res_pjsip_pubsub.c: No registered publish handler for event presence [Nov 21 14:44:22] DEBUG[9475] pjsip: endpoint .Response msg 489/PUBLISH/cseq=2 (tdta0x100836e00) created [Nov 21 14:44:22] DEBUG[9475] pjsip: tdta0x100836e0 .Destroying txdata Response msg 489/PUBLISH/cseq=2 (tdta0x100836e00) [Nov 21 14:44:22] DEBUG[9219] pjsip: tsx0x10306f6a8 ..Transaction created for Request msg INVITE/cseq=27538 (rdata0x103032a28) [Nov 21 14:44:22] DEBUG[9219] pjsip: tsx0x10306f6a8 .Incoming Request msg INVITE/cseq=27538 (rdata0x103032a28) in state Null [Nov 21 14:44:22] DEBUG[9219] pjsip: tsx0x10306f6a8 ..State changed from Null to Trying, event=RX_MSG [Nov 21 14:44:22] DEBUG[9219] pjsip: dlg0x10300a4a8 ...Transaction tsx0x10306f6a8 state changed to Trying [Nov 21 14:44:22] DEBUG[9219] pjsip: dlg0x10300a4a8 .UAS dialog created [Nov 21 14:44:22] DEBUG[9219] pjsip: dlg0x10300a4a8 .Module mod-invite added as dialog usage, data=0x105025468 [Nov 21 14:44:22] DEBUG[9219] pjsip: dlg0x10300a4a8 ..Session count inc to 2 by mod-invite [Nov 21 14:44:22] DEBUG[9219] pjsip: inv0x10300a4a8 .UAS invite session created for dialog dlg0x10300a4a8 [Nov 21 14:44:22] DEBUG[9219] pjsip: dlg0x10300a4a8 .Module Session Module added as dialog usage, data=0x0 [Nov 21 14:44:22] DEBUG[9219] pjsip: dlg0x10300a4a8 ..Session count inc to 2 by Session Module [Nov 21 14:44:22] DEBUG[9219] netsock2.c: Splitting '127.0.0.1' into... [Nov 21 14:44:22] DEBUG[9219] netsock2.c: ...host '127.0.0.1' and port ''. [Nov 21 14:44:22] DEBUG[9219] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x10083fa70' [Nov 21 14:44:22] DEBUG[9219] res_rtp_asterisk.c: Allocated port 18152 for RTP instance '0x10083fa70' [Nov 21 14:44:22] DEBUG[9219] pjsip: icess0x1008488 ICE session created, comp_cnt=2, role is Unknown agent [Nov 21 14:44:22] DEBUG[9219] netsock2.c: Splitting '10.24.21.100' into... [Nov 21 14:44:22] DEBUG[9219] netsock2.c: ...host '10.24.21.100' and port ''. [Nov 21 14:44:22] DEBUG[9219] pjsip: icess0x1008488 Candidate 0 added: comp_id=1, type=host, foundation=Ha181564, addr=10.24.21.100:18152, base=10.24.21.100:18152, prio=0x7effffff (2130706431) [Nov 21 14:44:22] DEBUG[9219] netsock2.c: Splitting '10.24.68.68' into... [Nov 21 14:44:22] DEBUG[9219] netsock2.c: ...host '10.24.68.68' and port ''. [Nov 21 14:44:22] DEBUG[9219] pjsip: icess0x1008488 Candidate 1 added: comp_id=1, type=host, foundation=Ha184444, addr=10.24.68.68:18152, base=10.24.68.68:18152, prio=0x7effffff (2130706431) [Nov 21 14:44:22] DEBUG[9219] netsock2.c: Splitting '10.211.55.2' into... [Nov 21 14:44:22] DEBUG[9219] netsock2.c: ...host '10.211.55.2' and port ''. [Nov 21 14:44:22] DEBUG[9219] pjsip: icess0x1008488 Candidate 2 added: comp_id=1, type=host, foundation=Had33702, addr=10.211.55.2:18152, base=10.211.55.2:18152, prio=0x7effffff (2130706431) [Nov 21 14:44:22] DEBUG[9219] netsock2.c: Splitting '10.37.129.2' into... [Nov 21 14:44:22] DEBUG[9219] netsock2.c: ...host '10.37.129.2' and port ''. [Nov 21 14:44:22] DEBUG[9219] pjsip: icess0x1008488 Candidate 3 added: comp_id=1, type=host, foundation=Ha258102, addr=10.37.129.2:18152, base=10.37.129.2:18152, prio=0x7effffff (2130706431) [Nov 21 14:44:22] DEBUG[9219] rtp_engine.c: RTP instance '0x10083fa70' is setup and ready to go [Nov 21 14:44:22] DEBUG[9219] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x10083fa70' [Nov 21 14:44:22] DEBUG[9219] netsock2.c: Splitting '10.24.21.100' into... [Nov 21 14:44:22] DEBUG[9219] netsock2.c: ...host '10.24.21.100' and port ''. [Nov 21 14:44:22] DEBUG[9219] pjsip: icess0x1008488 Candidate 4 added: comp_id=2, type=host, foundation=Ha181564, addr=10.24.21.100:18153, base=10.24.21.100:18153, prio=0x7efffffe (2130706430) [Nov 21 14:44:22] DEBUG[9219] netsock2.c: Splitting '10.24.68.68' into... [Nov 21 14:44:22] DEBUG[9219] netsock2.c: ...host '10.24.68.68' and port ''. [Nov 21 14:44:22] DEBUG[9219] pjsip: icess0x1008488 Candidate 5 added: comp_id=2, type=host, foundation=Ha184444, addr=10.24.68.68:18153, base=10.24.68.68:18153, prio=0x7efffffe (2130706430) [Nov 21 14:44:22] DEBUG[9219] netsock2.c: Splitting '10.211.55.2' into... [Nov 21 14:44:22] DEBUG[9219] netsock2.c: ...host '10.211.55.2' and port ''. [Nov 21 14:44:22] DEBUG[9219] pjsip: icess0x1008488 Candidate 6 added: comp_id=2, type=host, foundation=Had33702, addr=10.211.55.2:18153, base=10.211.55.2:18153, prio=0x7efffffe (2130706430) [Nov 21 14:44:22] DEBUG[9219] netsock2.c: Splitting '10.37.129.2' into... [Nov 21 14:44:22] DEBUG[9219] netsock2.c: ...host '10.37.129.2' and port ''. [Nov 21 14:44:22] DEBUG[9219] pjsip: icess0x1008488 Candidate 7 added: comp_id=2, type=host, foundation=Ha258102, addr=10.37.129.2:18153, base=10.37.129.2:18153, prio=0x7efffffe (2130706430) [Nov 21 14:44:22] DEBUG[9219] pjsip: icess0x1008488 Destroying ICE session 0x100848828 [Nov 21 14:44:22] DEBUG[9219] pjsip: stuse0x1008454 STUN session 0x100836028 destroy request, ref_cnt=4 [Nov 21 14:44:22] DEBUG[9219] pjsip: stuse0x1008368 STUN session 0x10084a828 destroy request, ref_cnt=3 [Nov 21 14:44:22] DEBUG[9219] pjsip: ice_session.c ICE session 0x100848828 destroyed [Nov 21 14:44:22] DEBUG[9219] pjsip: stun_session.c STUN session 0x100836028 destroyed [Nov 21 14:44:22] DEBUG[9219] pjsip: stun_session.c STUN session 0x10084a828 destroyed [Nov 21 14:44:22] DEBUG[9219] rtp_engine.c: Setting payload 108 based on m type on 0x1045ac480 [Nov 21 14:44:22] DEBUG[9219] rtp_engine.c: Setting payload 99 based on m type on 0x1045ac480 [Nov 21 14:44:22] DEBUG[9219] rtp_engine.c: Setting payload 98 based on m type on 0x1045ac480 [Nov 21 14:44:22] DEBUG[9219] rtp_engine.c: Setting payload 9 based on m type on 0x1045ac480 [Nov 21 14:44:22] DEBUG[9219] rtp_engine.c: Setting payload 0 based on m type on 0x1045ac480 [Nov 21 14:44:22] DEBUG[9219] rtp_engine.c: Setting payload 8 based on m type on 0x1045ac480 [Nov 21 14:44:22] DEBUG[9219] rtp_engine.c: Setting payload 96 based on m type on 0x1045ac480 [Nov 21 14:44:22] DEBUG[9219] rtp_engine.c: Copying payload 0 from 0x1045ac480 to 0x10083fbb0 [Nov 21 14:44:22] DEBUG[9219] rtp_engine.c: Copying payload 8 from 0x1045ac480 to 0x10083fbb0 [Nov 21 14:44:22] DEBUG[9219] rtp_engine.c: Copying payload 9 from 0x1045ac480 to 0x10083fbb0 [Nov 21 14:44:22] DEBUG[9219] rtp_engine.c: Copying payload 96 from 0x1045ac480 to 0x10083fbb0 [Nov 21 14:44:22] DEBUG[9219] rtp_engine.c: Copying payload 98 from 0x1045ac480 to 0x10083fbb0 [Nov 21 14:44:22] DEBUG[9219] rtp_engine.c: Copying payload 99 from 0x1045ac480 to 0x10083fbb0 [Nov 21 14:44:22] DEBUG[9219] rtp_engine.c: Copying payload 108 from 0x1045ac480 to 0x10083fbb0 [Nov 21 14:44:22] DEBUG[9219] pjsip: endpoint .Response msg 100/INVITE/cseq=27538 (tdta0x10186a400) created [Nov 21 14:44:22] DEBUG[9219] pjsip: dlg0x10300a4a8 .Initial answer Response msg 100/INVITE/cseq=27538 (tdta0x10186a400) [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Nov 21 14:44:22] DEBUG[9219] pjsip: inv0x10300a4a8 .Sending Response msg 100/INVITE/cseq=27538 (tdta0x10186a400) [Nov 21 14:44:22] DEBUG[9219] pjsip: dlg0x10300a4a8 ..Sending Response msg 100/INVITE/cseq=27538 (tdta0x10186a400) [Nov 21 14:44:22] DEBUG[9219] pjsip: tsx0x10306f6a8 ..Sending Response msg 100/INVITE/cseq=27538 (tdta0x10186a400) in state Trying [Nov 21 14:44:22] DEBUG[9219] pjsip: tsx0x10306f6a8 ...State changed from Trying to Proceeding, event=TX_MSG [Nov 21 14:44:22] DEBUG[9219] pjsip: dlg0x10300a4a8 ....Transaction tsx0x10306f6a8 state changed to Proceeding [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The inv session still has an invite_tsx (0x10306f6a8) [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: There is no transaction involved in this state change [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The current inv state is INCOMING [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: Source of transaction state change is TX_MSG [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: Sending response [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The inv session still has an invite_tsx (0x10306f6a8) [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The transaction involved in this state change is 0x10306f6a8 [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The current transaction state is Proceeding [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The transaction state change event is TX_MSG [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The current inv state is INCOMING [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: Method is INVITE [Nov 21 14:44:22] DEBUG[9219] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/blink-00000000 [Nov 21 14:44:22] DEBUG[14083] logger.c: CALL_ID [C-00000000] created by thread. [Nov 21 14:44:22] DEBUG[14083][C-00000000] logger.c: CALL_ID [C-00000000] bound to thread. [Nov 21 14:44:22] DEBUG[14083][C-00000000] pbx.c: Launching 'NoOp' [Nov 21 14:44:22] VERBOSE[14083][C-00000000] pbx.c: -- Executing [7000@default:1] NoOp("PJSIP/blink-00000000", "") in new stack [Nov 21 14:44:22] DEBUG[14083][C-00000000] pbx.c: Launching 'Stasis' [Nov 21 14:44:22] VERBOSE[14083][C-00000000] pbx.c: -- Executing [7000@default:2] Stasis("PJSIP/blink-00000000", "hello") in new stack [Nov 21 14:44:22] DEBUG[14339] http.c: HTTP Request URI is /ari/channels/1385066662.0/answer [Nov 21 14:44:22] DEBUG[14339] http.c: match request [ari/channels/1385066662.0/answer] with handler [httpstatus] len 10 [Nov 21 14:44:22] DEBUG[14339] http.c: match request [ari/channels/1385066662.0/answer] with handler [static] len 6 [Nov 21 14:44:22] DEBUG[14339] http.c: match request [ari/channels/1385066662.0/answer] with handler [ari] len 3 [Nov 21 14:44:22] DEBUG[14339] http.c: Match made with [ari] [Nov 21 14:44:22] DEBUG[14339] res_ari.c: Finding handler for channels [Nov 21 14:44:22] DEBUG[14339] res_ari.c: Checking channels [Nov 21 14:44:22] DEBUG[14339] res_ari.c: Got it! [Nov 21 14:44:22] DEBUG[14339] res_ari.c: Finding handler for 1385066662.0 [Nov 21 14:44:22] DEBUG[14339] res_ari.c: Checking channelId [Nov 21 14:44:22] DEBUG[14339] res_ari.c: Got it! [Nov 21 14:44:22] DEBUG[14339] res_ari.c: Finding handler for answer [Nov 21 14:44:22] DEBUG[14339] res_ari.c: Checking continue [Nov 21 14:44:22] DEBUG[14339] res_ari.c: Checking answer [Nov 21 14:44:22] DEBUG[14339] res_ari.c: Got it! [Nov 21 14:44:22] DEBUG[14339] res_stasis_answer.c: 1385066662.0: Sending answer command [Nov 21 14:44:22] DEBUG[14083][C-00000000] res_stasis_answer.c: 1385066662.0: Answering[Nov 21 14:44:22] DEBUG[6659] devicestate.c: No provider found, checking channel drivers for PJSIP - blink [Nov 21 14:44:22] DEBUG[6659] devicestate.c: Changing state for PJSIP/blink - state 2 (In use) [Nov 21 14:44:22] DEBUG[5123] devicestate.c: Processing device state change for 'PJSIP/blink' [Nov 21 14:44:22] DEBUG[5123] devicestate.c: Adding per-server state of 'In use' for 'PJSIP/blink' [Nov 21 14:44:22] DEBUG[5123] devicestate.c: Aggregate devstate result is 'In use' for 'PJSIP/blink' [Nov 21 14:44:22] DEBUG[5123] devicestate.c: Aggregate state for device 'PJSIP/blink' has changed to 'In use' [Nov 21 14:44:22] DEBUG[9219] pjsip: inv0x10300a4a8 .SDP negotiation done, status=0 [Nov 21 14:44:22] DEBUG[9219] netsock2.c: Splitting '127.0.0.1' into... [Nov 21 14:44:22] DEBUG[9219] netsock2.c: ...host '127.0.0.1' and port ''. [Nov 21 14:44:22] DEBUG[9219] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x10083fa70' [Nov 21 14:44:22] DEBUG[9219] rtp_engine.c: Setting payload 0 based on m type on 0x1045abe90 [Nov 21 14:44:22] DEBUG[9219] rtp_engine.c: Setting payload 96 based on m type on 0x1045abe90 [Nov 21 14:44:22] DEBUG[9219] rtp_engine.c: Copying payload 0 from 0x1045abe90 to 0x10083fbb0 [Nov 21 14:44:22] DEBUG[9219] rtp_engine.c: Copying payload 96 from 0x1045abe90 to 0x10083fbb0 [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Nov 21 14:44:22] DEBUG[9219] pjsip: inv0x10300a4a8 .Sending Response msg 200/INVITE/cseq=27538 (tdta0x10186a400) [Nov 21 14:44:22] DEBUG[9219] pjsip: dlg0x10300a4a8 ..Sending Response msg 200/INVITE/cseq=27538 (tdta0x10186a400) [Nov 21 14:44:22] DEBUG[9219] pjsip: tsx0x10306f6a8 ..Sending Response msg 200/INVITE/cseq=27538 (tdta0x10186a400) in state Proceeding [Nov 21 14:44:22] DEBUG[9219] pjsip: tsx0x10306f6a8 ...State changed from Proceeding to Completed, event=TX_MSG [Nov 21 14:44:22] DEBUG[9219] pjsip: dlg0x10300a4a8 ....Transaction tsx0x10306f6a8 state changed to Completed [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The inv session still has an invite_tsx (0x10306f6a8) [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: There is no transaction involved in this state change [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The current inv state is CONNECTING [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: Source of transaction state change is TX_MSG [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: Sending response [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The inv session still has an invite_tsx (0x10306f6a8) [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The transaction involved in this state change is 0x10306f6a8 [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The current transaction state is Completed [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The transaction state change event is TX_MSG [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The current inv state is CONNECTING [Nov 21 14:44:22] DEBUG[8963] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=27538 (rdata0x102833228) [Nov 21 14:44:22] DEBUG[9219] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=27538 (rdata0x10305e028) [Nov 21 14:44:22] DEBUG[9219] pjsip: dlg0x10300a4a8 .Received Request msg ACK/cseq=27538 (rdata0x10305e028) [Nov 21 14:44:22] DEBUG[9219] pjsip: tsx0x10306f6a8 ..Request to terminate transaction [Nov 21 14:44:22] DEBUG[9219] pjsip: tsx0x10306f6a8 ...State changed from Completed to Terminated, event=USER [Nov 21 14:44:22] DEBUG[9219] pjsip: dlg0x10300a4a8 ....Transaction tsx0x10306f6a8 state changed to Terminated [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The inv session still has an invite_tsx (0x10306f6a8) [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The transaction involved in this state change is 0x10306f6a8 [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The current transaction state is Terminated [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The transaction state change event is USER [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The current inv state is CONNECTING [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: There is no transaction involved in this state change [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: The current inv state is CONFIRMED [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: Received request [Nov 21 14:44:22] DEBUG[9219] res_pjsip_session.c: Method is ACK [Nov 21 14:44:22] DEBUG[14083][C-00000000] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Nov 21 14:44:22] DEBUG[8963] pjsip: tsx0x10306f6a8 Timeout timer event [Nov 21 14:44:22] DEBUG[8963] pjsip: tsx0x10306f6a8 .State changed from Terminated to Destroyed, event=TIMER [Nov 21 14:44:22] DEBUG[8963] pjsip: tdta0x10186a40 ..Destroying txdata Response msg 200/INVITE/cseq=27538 (tdta0x10186a400) [Nov 21 14:44:22] DEBUG[8963] pjsip: tsx0x10306f6a8 ..Transaction destroyed! [Nov 21 14:44:22] DEBUG[14083][C-00000000] res_rtp_asterisk.c: 0x100845c00 -- Probation learning mode pass with source address 10.24.21.100:50076 [Nov 21 14:44:22] DEBUG[14343] http.c: HTTP Request URI is /ari/bridges/bad81495-5672-41b3-bdbc-6cb00a942f0d/addChannel?channel=1385066662.0 [Nov 21 14:44:22] DEBUG[14343] http.c: match request [ari/bridges/bad81495-5672-41b3-bdbc-6cb00a942f0d/addChannel] with handler [httpstatus] len 10 [Nov 21 14:44:22] DEBUG[14343] http.c: match request [ari/bridges/bad81495-5672-41b3-bdbc-6cb00a942f0d/addChannel] with handler [static] len 6 [Nov 21 14:44:22] DEBUG[14343] http.c: match request [ari/bridges/bad81495-5672-41b3-bdbc-6cb00a942f0d/addChannel] with handler [ari] len 3 [Nov 21 14:44:22] DEBUG[14343] http.c: Match made with [ari] [Nov 21 14:44:22] DEBUG[14343] res_ari.c: Finding handler for bridges [Nov 21 14:44:22] DEBUG[14343] res_ari.c: Checking channels [Nov 21 14:44:22] DEBUG[14343] res_ari.c: Checking endpoints [Nov 21 14:44:22] DEBUG[14343] res_ari.c: Checking asterisk [Nov 21 14:44:22] DEBUG[14343] res_ari.c: Checking events [Nov 21 14:44:22] DEBUG[14343] res_ari.c: Checking applications [Nov 21 14:44:22] DEBUG[14343] res_ari.c: Checking bridges [Nov 21 14:44:22] DEBUG[14343] res_ari.c: Got it! [Nov 21 14:44:22] DEBUG[14343] res_ari.c: Finding handler for bad81495-5672-41b3-bdbc-6cb00a942f0d [Nov 21 14:44:22] DEBUG[14343] res_ari.c: Checking bridgeId [Nov 21 14:44:22] DEBUG[14343] res_ari.c: Got it! [Nov 21 14:44:22] DEBUG[14343] res_ari.c: Finding handler for addChannel [Nov 21 14:44:22] DEBUG[14343] res_ari.c: Checking addChannel [Nov 21 14:44:22] DEBUG[14343] res_ari.c: Got it! [Nov 21 14:44:22] DEBUG[14343] bridge_roles.c: Roles did not exist on channel PJSIP/blink-00000000 [Nov 21 14:44:22] DEBUG[14343] stasis/control.c: 1385066662.0: Sending channel add_to_bridge command [Nov 21 14:44:22] DEBUG[14083][C-00000000] stasis/control.c: 1385066662.0: Adding to bridge bad81495-5672-41b3-bdbc-6cb00a942f0d [Nov 21 14:44:22] DEBUG[14851][C-00000000] logger.c: CALL_ID [C-00000000] bound to thread. [Nov 21 14:44:22] DEBUG[14851][C-00000000] bridge_channel.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d: 0x105033010(PJSIP/blink-00000000) is joining [Nov 21 14:44:22] DEBUG[14851][C-00000000] bridge_channel.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d: pushing 0x105033010(PJSIP/blink-00000000) [Nov 21 14:44:22] VERBOSE[14851][C-00000000] bridge_channel.c: -- Channel PJSIP/blink-00000000 joined 'simple_bridge' base-bridge [Nov 21 14:44:22] DEBUG[14851][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Nov 21 14:44:22] DEBUG[14851][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [Nov 21 14:44:22] DEBUG[14851][C-00000000] bridge_native_rtp.c: Bridge 'bad81495-5672-41b3-bdbc-6cb00a942f0d' can not use native RTP bridge as two channels are required [Nov 21 14:44:22] DEBUG[14851][C-00000000] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Nov 21 14:44:22] DEBUG[14851][C-00000000] bridge.c: Chose bridge technology simple_bridge [Nov 21 14:44:22] DEBUG[14851][C-00000000] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d is already using the new technology. [Nov 21 14:44:22] DEBUG[14851][C-00000000] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d is happy that channel PJSIP/blink-00000000 already has read format ulaw [Nov 21 14:44:22] DEBUG[14851][C-00000000] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d is happy that channel PJSIP/blink-00000000 already has write format ulaw [Nov 21 14:44:22] DEBUG[14851][C-00000000] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d: 0x105033010(PJSIP/blink-00000000) is joining simple_bridge technology [Nov 21 14:44:25] DEBUG[8963] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=27539 (rdata0x103060028) [Nov 21 14:44:25] DEBUG[9219] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=27539 (rdata0x102833228) [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10300a4a8 .Received Request msg INVITE/cseq=27539 (rdata0x102833228) [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x10306f6a8 ...Transaction created for Request msg INVITE/cseq=27539 (rdata0x102833228) [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x10306f6a8 ..Incoming Request msg INVITE/cseq=27539 (rdata0x102833228) in state Null [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x10306f6a8 ...State changed from Null to Trying, event=RX_MSG [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10300a4a8 ....Transaction tsx0x10306f6a8 state changed to Trying [Nov 21 14:44:25] DEBUG[9219] pjsip: inv0x10300a4a8 .....Got SDP offer in Request msg INVITE/cseq=27539 (rdata0x102833228) [Nov 21 14:44:25] DEBUG[9219] netsock2.c: Splitting '127.0.0.1' into... [Nov 21 14:44:25] DEBUG[9219] netsock2.c: ...host '127.0.0.1' and port ''. [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Setting payload 0 based on m type on 0x1045ac0b0 [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Setting payload 96 based on m type on 0x1045ac0b0 [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Copying payload 0 from 0x1045ac0b0 to 0x10083fbb0 [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Copying payload 96 from 0x1045ac0b0 to 0x10083fbb0 [Nov 21 14:44:25] DEBUG[9219] pjsip: endpoint .....Response msg 200/INVITE/cseq=27539 (tdta0x10305a400) created [Nov 21 14:44:25] DEBUG[9219] pjsip: inv0x10300a4a8 .....SDP negotiation done, status=0 [Nov 21 14:44:25] DEBUG[9219] netsock2.c: Splitting '127.0.0.1' into... [Nov 21 14:44:25] DEBUG[9219] netsock2.c: ...host '127.0.0.1' and port ''. [Nov 21 14:44:25] DEBUG[9219] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x10083fa70' [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Setting payload 0 based on m type on 0x1045abb40 [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Setting payload 96 based on m type on 0x1045abb40 [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Copying payload 0 from 0x1045abb40 to 0x10083fbb0 [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Copying payload 96 from 0x1045abb40 to 0x10083fbb0 [Nov 21 14:44:25] DEBUG[9219] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x10083fa70' [Nov 21 14:44:25] DEBUG[9219] pjsip: inv0x10300a4a8 ......Sending Response msg 200/INVITE/cseq=27539 (tdta0x10305a400) [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10300a4a8 .......Sending Response msg 200/INVITE/cseq=27539 (tdta0x10305a400) [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x10306f6a8 .......Sending Response msg 200/INVITE/cseq=27539 (tdta0x10305a400) in state Trying [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x10306f6a8 ........State changed from Trying to Completed, event=TX_MSG [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10300a4a8 .........Transaction tsx0x10306f6a8 state changed to Completed [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The inv session still has an invite_tsx (0x10306f6a8) [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The transaction involved in this state change is 0x10306f6a8 [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current transaction state is Completed [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The transaction state change event is TX_MSG [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current inv state is CONFIRMED [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The inv session still has an invite_tsx (0x10306f6a8) [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The transaction involved in this state change is 0x10306f6a8 [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current transaction state is Completed [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The transaction state change event is RX_MSG [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current inv state is CONFIRMED [Nov 21 14:44:25] DEBUG[8963] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=27539 (rdata0x10282b828) [Nov 21 14:44:25] DEBUG[9219] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=27539 (rdata0x100848828) [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10300a4a8 .Received Request msg ACK/cseq=27539 (rdata0x100848828) [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x10306f6a8 ..Request to terminate transaction [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x10306f6a8 ...State changed from Completed to Terminated, event=USER [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10300a4a8 ....Transaction tsx0x10306f6a8 state changed to Terminated [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The inv session still has an invite_tsx (0x10306f6a8) [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The transaction involved in this state change is 0x10306f6a8 [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current transaction state is Terminated [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The transaction state change event is USER [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current inv state is CONFIRMED [Nov 21 14:44:25] DEBUG[8963] pjsip: tsx0x10306f6a8 Timeout timer event [Nov 21 14:44:25] DEBUG[8963] pjsip: tsx0x10306f6a8 .State changed from Terminated to Destroyed, event=TIMER [Nov 21 14:44:25] DEBUG[8963] pjsip: tdta0x10305a40 ..Destroying txdata Response msg 200/INVITE/cseq=27539 (tdta0x10305a400) [Nov 21 14:44:25] DEBUG[8963] pjsip: tsx0x10306f6a8 ..Transaction destroyed! [Nov 21 14:44:25] DEBUG[14851][C-00000000] res_rtp_asterisk.c: 0x100845c00 -- Probation learning mode pass with source address 10.24.21.100:50076 [Nov 21 14:44:25] DEBUG[8963] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=1066 (rdata0x10084ce28) [Nov 21 14:44:25] DEBUG[9219] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=1066 (rdata0x100848828) [Nov 21 14:44:25] DEBUG[9219] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Nov 21 14:44:25] DEBUG[9219] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint blink [Nov 21 14:44:25] DEBUG[9219] pjsip: endpoint .Response msg 401/INVITE/cseq=1066 (tdta0x10186a400) created [Nov 21 14:44:25] DEBUG[9219] netsock2.c: Splitting '10.24.21.100' into... [Nov 21 14:44:25] DEBUG[9219] netsock2.c: ...host '10.24.21.100' and port ''. [Nov 21 14:44:25] DEBUG[9219] netsock2.c: Splitting '127.0.0.1' into... [Nov 21 14:44:25] DEBUG[9219] netsock2.c: ...host '127.0.0.1' and port ''. [Nov 21 14:44:25] DEBUG[9219] pjsip: tdta0x10186a40 .Destroying txdata Response msg 401/INVITE/cseq=1066 (tdta0x10186a400) [Nov 21 14:44:25] DEBUG[8963] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=1066 (rdata0x10084ce28) [Nov 21 14:44:25] DEBUG[8963] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=1067 (rdata0x10084ce28) [Nov 21 14:44:25] DEBUG[9219] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=1066 (rdata0x100848828) [Nov 21 14:44:25] DEBUG[9219] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Nov 21 14:44:25] DEBUG[9219] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint blink [Nov 21 14:44:25] DEBUG[9219] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=1067 (rdata0x10084ee28) [Nov 21 14:44:25] DEBUG[9219] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Nov 21 14:44:25] DEBUG[9219] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint blink [Nov 21 14:44:25] DEBUG[9219] pjsip: endpoint .Response msg 401/INVITE/cseq=1067 (tdta0x10305a400) created [Nov 21 14:44:25] DEBUG[9219] res_pjsip_authenticator_digest.c: Calculated nonce 1385066665/bc2acb41e02251db57d47bc5ea13f63a. Actual nonce is 1385066665/bc2acb41e02251db57d47bc5ea13f63a [Nov 21 14:44:25] DEBUG[9219] netsock2.c: Splitting '10.24.21.100' into... [Nov 21 14:44:25] DEBUG[9219] netsock2.c: ...host '10.24.21.100' and port ''. [Nov 21 14:44:25] DEBUG[9219] netsock2.c: Splitting '127.0.0.1' into... [Nov 21 14:44:25] DEBUG[9219] netsock2.c: ...host '127.0.0.1' and port ''. [Nov 21 14:44:25] DEBUG[9219] pjsip: tdta0x10305a40 .Destroying txdata Response msg 401/INVITE/cseq=1067 (tdta0x10305a400) [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x1028332a8 ..Transaction created for Request msg INVITE/cseq=1067 (rdata0x10084ee28) [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x1028332a8 .Incoming Request msg INVITE/cseq=1067 (rdata0x10084ee28) in state Null [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x1028332a8 ..State changed from Null to Trying, event=RX_MSG [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10306f6a8 ...Transaction tsx0x1028332a8 state changed to Trying [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10306f6a8 .UAS dialog created [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10306f6a8 .Module mod-invite added as dialog usage, data=0x100746108 [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10306f6a8 ..Session count inc to 2 by mod-invite [Nov 21 14:44:25] DEBUG[9219] pjsip: inv0x10306f6a8 .UAS invite session created for dialog dlg0x10306f6a8 [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10306f6a8 .Module Session Module added as dialog usage, data=0x0 [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10306f6a8 ..Session count inc to 2 by Session Module [Nov 21 14:44:25] DEBUG[9219] netsock2.c: Splitting '127.0.0.1' into... [Nov 21 14:44:25] DEBUG[9219] netsock2.c: ...host '127.0.0.1' and port ''. [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x101877470' [Nov 21 14:44:25] DEBUG[9219] res_rtp_asterisk.c: Allocated port 14676 for RTP instance '0x101877470' [Nov 21 14:44:25] DEBUG[9219] pjsip: icess0x10187fa ICE session created, comp_cnt=2, role is Unknown agent [Nov 21 14:44:25] DEBUG[9219] netsock2.c: Splitting '10.24.21.100' into... [Nov 21 14:44:25] DEBUG[9219] netsock2.c: ...host '10.24.21.100' and port ''. [Nov 21 14:44:25] DEBUG[9219] pjsip: icess0x10187fa Candidate 0 added: comp_id=1, type=host, foundation=Ha181564, addr=10.24.21.100:14676, base=10.24.21.100:14676, prio=0x7effffff (2130706431) [Nov 21 14:44:25] DEBUG[9219] netsock2.c: Splitting '10.24.68.68' into... [Nov 21 14:44:25] DEBUG[9219] netsock2.c: ...host '10.24.68.68' and port ''. [Nov 21 14:44:25] DEBUG[9219] pjsip: icess0x10187fa Candidate 1 added: comp_id=1, type=host, foundation=Ha184444, addr=10.24.68.68:14676, base=10.24.68.68:14676, prio=0x7effffff (2130706431) [Nov 21 14:44:25] DEBUG[9219] netsock2.c: Splitting '10.211.55.2' into... [Nov 21 14:44:25] DEBUG[9219] netsock2.c: ...host '10.211.55.2' and port ''. [Nov 21 14:44:25] DEBUG[9219] pjsip: icess0x10187fa Candidate 2 added: comp_id=1, type=host, foundation=Had33702, addr=10.211.55.2:14676, base=10.211.55.2:14676, prio=0x7effffff (2130706431) [Nov 21 14:44:25] DEBUG[9219] netsock2.c: Splitting '10.37.129.2' into... [Nov 21 14:44:25] DEBUG[9219] netsock2.c: ...host '10.37.129.2' and port ''. [Nov 21 14:44:25] DEBUG[9219] pjsip: icess0x10187fa Candidate 3 added: comp_id=1, type=host, foundation=Ha258102, addr=10.37.129.2:14676, base=10.37.129.2:14676, prio=0x7effffff (2130706431) [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: RTP instance '0x101877470' is setup and ready to go [Nov 21 14:44:25] DEBUG[9219] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x101877470' [Nov 21 14:44:25] DEBUG[9219] netsock2.c: Splitting '10.24.21.100' into... [Nov 21 14:44:25] DEBUG[9219] netsock2.c: ...host '10.24.21.100' and port ''. [Nov 21 14:44:25] DEBUG[9219] pjsip: icess0x10187fa Candidate 4 added: comp_id=2, type=host, foundation=Ha181564, addr=10.24.21.100:14677, base=10.24.21.100:14677, prio=0x7efffffe (2130706430) [Nov 21 14:44:25] DEBUG[9219] netsock2.c: Splitting '10.24.68.68' into... [Nov 21 14:44:25] DEBUG[9219] netsock2.c: ...host '10.24.68.68' and port ''. [Nov 21 14:44:25] DEBUG[9219] pjsip: icess0x10187fa Candidate 5 added: comp_id=2, type=host, foundation=Ha184444, addr=10.24.68.68:14677, base=10.24.68.68:14677, prio=0x7efffffe (2130706430) [Nov 21 14:44:25] DEBUG[9219] netsock2.c: Splitting '10.211.55.2' into... [Nov 21 14:44:25] DEBUG[9219] netsock2.c: ...host '10.211.55.2' and port ''. [Nov 21 14:44:25] DEBUG[9219] pjsip: icess0x10187fa Candidate 6 added: comp_id=2, type=host, foundation=Had33702, addr=10.211.55.2:14677, base=10.211.55.2:14677, prio=0x7efffffe (2130706430) [Nov 21 14:44:25] DEBUG[9219] netsock2.c: Splitting '10.37.129.2' into... [Nov 21 14:44:25] DEBUG[9219] netsock2.c: ...host '10.37.129.2' and port ''. [Nov 21 14:44:25] DEBUG[9219] pjsip: icess0x10187fa Candidate 7 added: comp_id=2, type=host, foundation=Ha258102, addr=10.37.129.2:14677, base=10.37.129.2:14677, prio=0x7efffffe (2130706430) [Nov 21 14:44:25] DEBUG[9219] pjsip: icess0x10187fa Destroying ICE session 0x10187fa28 [Nov 21 14:44:25] DEBUG[9219] pjsip: stuse0x10186f6 STUN session 0x101864228 destroy request, ref_cnt=4 [Nov 21 14:44:25] DEBUG[9219] pjsip: stuse0x101881a STUN session 0x101881e28 destroy request, ref_cnt=3 [Nov 21 14:44:25] DEBUG[9219] pjsip: ice_session.c ICE session 0x10187fa28 destroyed [Nov 21 14:44:25] DEBUG[9219] pjsip: stun_session.c STUN session 0x101864228 destroyed [Nov 21 14:44:25] DEBUG[9219] pjsip: stun_session.c STUN session 0x101881e28 destroyed [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Setting payload 108 based on m type on 0x1045ac480 [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Setting payload 99 based on m type on 0x1045ac480 [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Setting payload 98 based on m type on 0x1045ac480 [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Setting payload 9 based on m type on 0x1045ac480 [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Setting payload 0 based on m type on 0x1045ac480 [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Setting payload 8 based on m type on 0x1045ac480 [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Setting payload 96 based on m type on 0x1045ac480 [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Copying payload 0 from 0x1045ac480 to 0x1018775b0 [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Copying payload 8 from 0x1045ac480 to 0x1018775b0 [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Copying payload 9 from 0x1045ac480 to 0x1018775b0 [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Copying payload 96 from 0x1045ac480 to 0x1018775b0 [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Copying payload 98 from 0x1045ac480 to 0x1018775b0 [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Copying payload 99 from 0x1045ac480 to 0x1018775b0 [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Copying payload 108 from 0x1045ac480 to 0x1018775b0 [Nov 21 14:44:25] DEBUG[9219] pjsip: endpoint .Response msg 100/INVITE/cseq=1067 (tdta0x10186a400) created [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10306f6a8 .Initial answer Response msg 100/INVITE/cseq=1067 (tdta0x10186a400) [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Nov 21 14:44:25] DEBUG[9219] pjsip: inv0x10306f6a8 .Sending Response msg 100/INVITE/cseq=1067 (tdta0x10186a400) [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10306f6a8 ..Sending Response msg 100/INVITE/cseq=1067 (tdta0x10186a400) [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x1028332a8 ..Sending Response msg 100/INVITE/cseq=1067 (tdta0x10186a400) in state Trying [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x1028332a8 ...State changed from Trying to Proceeding, event=TX_MSG [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10306f6a8 ....Transaction tsx0x1028332a8 state changed to Proceeding [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The inv session still has an invite_tsx (0x1028332a8) [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: There is no transaction involved in this state change [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current inv state is INCOMING [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Source of transaction state change is TX_MSG [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Sending response [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The inv session still has an invite_tsx (0x1028332a8) [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The transaction involved in this state change is 0x1028332a8 [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current transaction state is Proceeding [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The transaction state change event is TX_MSG [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current inv state is INCOMING [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Method is INVITE [Nov 21 14:44:25] DEBUG[9219] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/blink-00000001 [Nov 21 14:44:25] DEBUG[14347] logger.c: CALL_ID [C-00000001] created by thread. [Nov 21 14:44:25] DEBUG[14347][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [Nov 21 14:44:25] DEBUG[14347][C-00000001] pbx.c: Launching 'NoOp' [Nov 21 14:44:25] VERBOSE[14347][C-00000001] pbx.c: -- Executing [7000@default:1] NoOp("PJSIP/blink-00000001", "") in new stack [Nov 21 14:44:25] DEBUG[14347][C-00000001] pbx.c: Launching 'Stasis' [Nov 21 14:44:25] VERBOSE[14347][C-00000001] pbx.c: -- Executing [7000@default:2] Stasis("PJSIP/blink-00000001", "hello") in new stack [Nov 21 14:44:25] DEBUG[15107] http.c: HTTP Request URI is /ari/channels/1385066665.1/answer [Nov 21 14:44:25] DEBUG[15107] http.c: match request [ari/channels/1385066665.1/answer] with handler [httpstatus] len 10 [Nov 21 14:44:25] DEBUG[15107] http.c: match request [ari/channels/1385066665.1/answer] with handler [static] len 6 [Nov 21 14:44:25] DEBUG[15107] http.c: match request [ari/channels/1385066665.1/answer] with handler [ari] len 3 [Nov 21 14:44:25] DEBUG[15107] http.c: Match made with [ari] [Nov 21 14:44:25] DEBUG[15107] res_ari.c: Finding handler for channels [Nov 21 14:44:25] DEBUG[15107] res_ari.c: Checking channels [Nov 21 14:44:25] DEBUG[15107] res_ari.c: Got it! [Nov 21 14:44:25] DEBUG[15107] res_ari.c: Finding handler for 1385066665.1 [Nov 21 14:44:25] DEBUG[15107] res_ari.c: Checking channelId [Nov 21 14:44:25] DEBUG[15107] res_ari.c: Got it! [Nov 21 14:44:25] DEBUG[15107] res_ari.c: Finding handler for answer [Nov 21 14:44:25] DEBUG[15107] res_ari.c: Checking continue [Nov 21 14:44:25] DEBUG[15107] res_ari.c: Checking answer [Nov 21 14:44:25] DEBUG[15107] res_ari.c: Got it! [Nov 21 14:44:25] DEBUG[15107] res_stasis_answer.c: 1385066665.1: Sending answer command [Nov 21 14:44:25] DEBUG[14347][C-00000001] res_stasis_answer.c: 1385066665.1: Answering[Nov 21 14:44:25] DEBUG[6659] devicestate.c: No provider found, checking channel drivers for PJSIP - blink [Nov 21 14:44:25] DEBUG[6659] devicestate.c: Changing state for PJSIP/blink - state 2 (In use) [Nov 21 14:44:25] DEBUG[9219] pjsip: inv0x10306f6a8 .SDP negotiation done, status=0 [Nov 21 14:44:25] DEBUG[9219] netsock2.c: Splitting '127.0.0.1' into... [Nov 21 14:44:25] DEBUG[9219] netsock2.c: ...host '127.0.0.1' and port ''. [Nov 21 14:44:25] DEBUG[5123] devicestate.c: Processing device state change for 'PJSIP/blink' [Nov 21 14:44:25] DEBUG[9219] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x101877470' [Nov 21 14:44:25] DEBUG[5123] devicestate.c: Adding per-server state of 'In use' for 'PJSIP/blink' [Nov 21 14:44:25] DEBUG[5123] devicestate.c: Aggregate devstate result is 'In use' for 'PJSIP/blink' [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Setting payload 0 based on m type on 0x1045abe90 [Nov 21 14:44:25] DEBUG[5123] devicestate.c: Aggregate state for device 'PJSIP/blink' has not changed from 'In use' [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Setting payload 96 based on m type on 0x1045abe90 [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Copying payload 0 from 0x1045abe90 to 0x1018775b0 [Nov 21 14:44:25] DEBUG[9219] rtp_engine.c: Copying payload 96 from 0x1045abe90 to 0x1018775b0 [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Nov 21 14:44:25] DEBUG[9219] pjsip: inv0x10306f6a8 .Sending Response msg 200/INVITE/cseq=1067 (tdta0x10186a400) [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10306f6a8 ..Sending Response msg 200/INVITE/cseq=1067 (tdta0x10186a400) [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x1028332a8 ..Sending Response msg 200/INVITE/cseq=1067 (tdta0x10186a400) in state Proceeding [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x1028332a8 ...State changed from Proceeding to Completed, event=TX_MSG [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10306f6a8 ....Transaction tsx0x1028332a8 state changed to Completed [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The inv session still has an invite_tsx (0x1028332a8) [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: There is no transaction involved in this state change [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current inv state is CONNECTING [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Source of transaction state change is TX_MSG [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Sending response [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The inv session still has an invite_tsx (0x1028332a8) [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The transaction involved in this state change is 0x1028332a8 [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current transaction state is Completed [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The transaction state change event is TX_MSG [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current inv state is CONNECTING [Nov 21 14:44:25] DEBUG[8963] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=1067 (rdata0x10084ce28) [Nov 21 14:44:25] DEBUG[9219] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=1067 (rdata0x102834828) [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10306f6a8 .Received Request msg ACK/cseq=1067 (rdata0x102834828) [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x1028332a8 ..Request to terminate transaction [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x1028332a8 ...State changed from Completed to Terminated, event=USER [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10306f6a8 ....Transaction tsx0x1028332a8 state changed to Terminated [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The inv session still has an invite_tsx (0x1028332a8) [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The transaction involved in this state change is 0x1028332a8 [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current transaction state is Terminated [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The transaction state change event is USER [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current inv state is CONNECTING [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: There is no transaction involved in this state change [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current inv state is CONFIRMED [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Received request [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Method is ACK [Nov 21 14:44:25] DEBUG[14347][C-00000001] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Nov 21 14:44:25] DEBUG[8963] pjsip: tsx0x1028332a8 Timeout timer event [Nov 21 14:44:25] DEBUG[8963] pjsip: tsx0x1028332a8 .State changed from Terminated to Destroyed, event=TIMER [Nov 21 14:44:25] DEBUG[8963] pjsip: tdta0x10186a40 ..Destroying txdata Response msg 200/INVITE/cseq=1067 (tdta0x10186a400) [Nov 21 14:44:25] DEBUG[8963] pjsip: tsx0x1028332a8 ..Transaction destroyed! [Nov 21 14:44:25] DEBUG[14347][C-00000001] res_rtp_asterisk.c: 0x10187ce00 -- Probation learning mode pass with source address 10.24.21.100:50078 [Nov 21 14:44:25] DEBUG[15111] http.c: HTTP Request URI is /ari/bridges/bad81495-5672-41b3-bdbc-6cb00a942f0d/addChannel?channel=1385066665.1 [Nov 21 14:44:25] DEBUG[15111] http.c: match request [ari/bridges/bad81495-5672-41b3-bdbc-6cb00a942f0d/addChannel] with handler [httpstatus] len 10 [Nov 21 14:44:25] DEBUG[15111] http.c: match request [ari/bridges/bad81495-5672-41b3-bdbc-6cb00a942f0d/addChannel] with handler [static] len 6 [Nov 21 14:44:25] DEBUG[15111] http.c: match request [ari/bridges/bad81495-5672-41b3-bdbc-6cb00a942f0d/addChannel] with handler [ari] len 3 [Nov 21 14:44:25] DEBUG[15111] http.c: Match made with [ari] [Nov 21 14:44:25] DEBUG[15111] res_ari.c: Finding handler for bridges [Nov 21 14:44:25] DEBUG[15111] res_ari.c: Checking channels [Nov 21 14:44:25] DEBUG[15111] res_ari.c: Checking endpoints [Nov 21 14:44:25] DEBUG[15111] res_ari.c: Checking asterisk [Nov 21 14:44:25] DEBUG[15111] res_ari.c: Checking events [Nov 21 14:44:25] DEBUG[15111] res_ari.c: Checking applications [Nov 21 14:44:25] DEBUG[15111] res_ari.c: Checking bridges [Nov 21 14:44:25] DEBUG[15111] res_ari.c: Got it! [Nov 21 14:44:25] DEBUG[15111] res_ari.c: Finding handler for bad81495-5672-41b3-bdbc-6cb00a942f0d [Nov 21 14:44:25] DEBUG[15111] res_ari.c: Checking bridgeId [Nov 21 14:44:25] DEBUG[15111] res_ari.c: Got it! [Nov 21 14:44:25] DEBUG[15111] res_ari.c: Finding handler for addChannel [Nov 21 14:44:25] DEBUG[15111] res_ari.c: Checking addChannel [Nov 21 14:44:25] DEBUG[15111] res_ari.c: Got it! [Nov 21 14:44:25] DEBUG[15111] bridge_roles.c: Roles did not exist on channel PJSIP/blink-00000001 [Nov 21 14:44:25] DEBUG[15111] stasis/control.c: 1385066665.1: Sending channel add_to_bridge command [Nov 21 14:44:25] DEBUG[14347][C-00000001] stasis/control.c: 1385066665.1: Adding to bridge bad81495-5672-41b3-bdbc-6cb00a942f0d [Nov 21 14:44:25] DEBUG[15363][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [Nov 21 14:44:25] DEBUG[15363][C-00000001] bridge_channel.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d: 0x10242e380(PJSIP/blink-00000001) is joining [Nov 21 14:44:25] DEBUG[15363][C-00000001] bridge_channel.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d: pushing 0x10242e380(PJSIP/blink-00000001) [Nov 21 14:44:25] VERBOSE[15363][C-00000001] bridge_channel.c: -- Channel PJSIP/blink-00000001 joined 'simple_bridge' base-bridge [Nov 21 14:44:25] DEBUG[15363][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Nov 21 14:44:25] DEBUG[15363][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Nov 21 14:44:25] DEBUG[15363][C-00000001] bridge.c: Chose bridge technology native_rtp [Nov 21 14:44:25] DEBUG[15363][C-00000001] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d: calling native_rtp technology constructor [Nov 21 14:44:25] DEBUG[15363][C-00000001] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d: calling simple_bridge technology stop [Nov 21 14:44:25] DEBUG[15363][C-00000001] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d: 0x105033010(PJSIP/blink-00000000) is leaving simple_bridge technology (dummy) [Nov 21 14:44:25] DEBUG[15363][C-00000001] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d is happy that channel PJSIP/blink-00000000 already has read format ulaw [Nov 21 14:44:25] DEBUG[15363][C-00000001] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d is happy that channel PJSIP/blink-00000000 already has write format ulaw [Nov 21 14:44:25] DEBUG[15363][C-00000001] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d: 0x105033010(PJSIP/blink-00000000) is joining native_rtp technology [Nov 21 14:44:25] DEBUG[6403] cdr.c: Finalized CDR for PJSIP/blink-00000001 - start 1385066665.319342 answer 1385066665.520543 end 1385066665.554553 dispo ANSWERED [Nov 21 14:44:25] DEBUG[15363][C-00000001] bridge_native_rtp.c: Remotely bridged 'PJSIP/blink-00000000' and 'PJSIP/blink-00000001' - media will flow directly between them [Nov 21 14:44:25] DEBUG[15363][C-00000001] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d is happy that channel PJSIP/blink-00000001 already has read format ulaw [Nov 21 14:44:25] DEBUG[15363][C-00000001] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d is happy that channel PJSIP/blink-00000001 already has write format ulaw [Nov 21 14:44:25] DEBUG[15363][C-00000001] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d: 0x10242e380(PJSIP/blink-00000001) is joining native_rtp technology [Nov 21 14:44:25] DEBUG[15363][C-00000001] bridge_native_rtp.c: Remotely bridged 'PJSIP/blink-00000000' and 'PJSIP/blink-00000001' - media will flow directly between them [Nov 21 14:44:25] DEBUG[15363][C-00000001] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d: calling native_rtp technology start [Nov 21 14:44:25] DEBUG[15363][C-00000001] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d: calling simple_bridge technology destructor [Nov 21 14:44:25] DEBUG[9219] pjsip: endpoint .Request msg INVITE/cseq=14286 (tdta0x10186a400) created. [Nov 21 14:44:25] DEBUG[9475] pjsip: endpoint .Request msg INVITE/cseq=16416 (tdta0x10305a400) created. [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Method is INVITE [Nov 21 14:44:25] DEBUG[9475] res_pjsip_session.c: Method is INVITE [Nov 21 14:44:25] DEBUG[9219] pjsip: inv0x10300a4a8 .Sending Request msg INVITE/cseq=14286 (tdta0x10186a400) [Nov 21 14:44:25] DEBUG[9475] pjsip: inv0x10306f6a8 .Sending Request msg INVITE/cseq=16416 (tdta0x10305a400) [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10300a4a8 ..Sending Request msg INVITE/cseq=14286 (tdta0x10186a400) [Nov 21 14:44:25] DEBUG[9475] pjsip: dlg0x10306f6a8 ..Sending Request msg INVITE/cseq=16416 (tdta0x10305a400) [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x1028332a8 ...Transaction created for Request msg INVITE/cseq=14285 (tdta0x10186a400) [Nov 21 14:44:25] DEBUG[9475] pjsip: tsx0x1028576a8 ...Transaction created for Request msg INVITE/cseq=16415 (tdta0x10305a400) [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x1028332a8 ..Sending Request msg INVITE/cseq=14285 (tdta0x10186a400) in state Null [Nov 21 14:44:25] DEBUG[9475] pjsip: tsx0x1028576a8 ..Sending Request msg INVITE/cseq=16415 (tdta0x10305a400) in state Null [Nov 21 14:44:25] DEBUG[9219] pjsip: sip_resolve.c ...Target '127.0.0.1:63424' type=Unspecified resolved to '127.0.0.1:63424' type=UDP (UDP transport) [Nov 21 14:44:25] DEBUG[9475] pjsip: sip_resolve.c ...Target '127.0.0.1:63424' type=Unspecified resolved to '127.0.0.1:63424' type=UDP (UDP transport) [Nov 21 14:44:25] DEBUG[9219] pjsip: endpoint ...Request msg INVITE/cseq=14285 (tdta0x10186a400) exceeds UDP size threshold (1300), sending with TCP [Nov 21 14:44:25] DEBUG[9475] pjsip: endpoint ...Request msg INVITE/cseq=16415 (tdta0x10305a400) exceeds UDP size threshold (1300), sending with TCP [Nov 21 14:44:25] WARNING[9219] pjsip: tsx0x1028332a8 ...Temporary failure in sending Request msg INVITE/cseq=14285 (tdta0x10186a400), will try next server. Err=171060 (Unsupported transport (PJSIP_EUNSUPTRANSPORT)) [Nov 21 14:44:25] WARNING[9475] pjsip: tsx0x1028576a8 ...Temporary failure in sending Request msg INVITE/cseq=16415 (tdta0x10305a400), will try next server. Err=171060 (Unsupported transport (PJSIP_EUNSUPTRANSPORT)) [Nov 21 14:44:25] DEBUG[9475] pjsip: tsx0x1028576a8 ...State changed from Null to Calling, event=TX_MSG [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x1028332a8 ...State changed from Null to Calling, event=TX_MSG [Nov 21 14:44:25] DEBUG[9475] pjsip: dlg0x10306f6a8 ....Transaction tsx0x1028576a8 state changed to Calling [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10300a4a8 ....Transaction tsx0x1028332a8 state changed to Calling [Nov 21 14:44:25] DEBUG[9475] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 21 14:44:25] DEBUG[9475] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:25] DEBUG[9475] res_pjsip_session.c: The inv session still has an invite_tsx (0x1028576a8) [Nov 21 14:44:25] DEBUG[9475] res_pjsip_session.c: The transaction involved in this state change is 0x1028576a8 [Nov 21 14:44:25] DEBUG[9475] res_pjsip_session.c: The current transaction state is Calling [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The inv session still has an invite_tsx (0x1028332a8) [Nov 21 14:44:25] DEBUG[9475] res_pjsip_session.c: The transaction state change event is TX_MSG [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The transaction involved in this state change is 0x1028332a8 [Nov 21 14:44:25] DEBUG[9475] res_pjsip_session.c: The current inv state is CONFIRMED [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current transaction state is Calling [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The transaction state change event is TX_MSG [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current inv state is CONFIRMED [Nov 21 14:44:25] DEBUG[8963] pjsip: sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=27538 (rdata0x102836828) [Nov 21 14:44:25] DEBUG[9219] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=27538 (rdata0x10305cc28) [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x1028332a8 .Incoming Response msg 100/INVITE/cseq=27538 (rdata0x10305cc28) in state Calling [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x1028332a8 ..State changed from Calling to Proceeding, event=RX_MSG [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10300a4a8 ...Received Response msg 100/INVITE/cseq=27538 (rdata0x10305cc28) [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10300a4a8 ...Transaction tsx0x1028332a8 state changed to Proceeding [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The inv session still has an invite_tsx (0x1028332a8) [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The transaction involved in this state change is 0x1028332a8 [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current transaction state is Proceeding [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The transaction state change event is RX_MSG [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current inv state is CONFIRMED [Nov 21 14:44:25] DEBUG[8963] pjsip: sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=1067 (rdata0x10305ec28) [Nov 21 14:44:25] DEBUG[9219] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=1067 (rdata0x10305cc28) [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x1028576a8 .Incoming Response msg 100/INVITE/cseq=1067 (rdata0x10305cc28) in state Calling [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x1028576a8 ..State changed from Calling to Proceeding, event=RX_MSG [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10306f6a8 ...Received Response msg 100/INVITE/cseq=1067 (rdata0x10305cc28) [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10306f6a8 ...Transaction tsx0x1028576a8 state changed to Proceeding [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The inv session still has an invite_tsx (0x1028576a8) [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The transaction involved in this state change is 0x1028576a8 [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current transaction state is Proceeding [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The transaction state change event is RX_MSG [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current inv state is CONFIRMED [Nov 21 14:44:25] DEBUG[15363][C-00000001] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [Nov 21 14:44:25] DEBUG[15363][C-00000001] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [Nov 21 14:44:25] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:25] DEBUG[8963] pjsip: sip_endpoint.c Processing incoming message: Response msg 180/INVITE/cseq=27538 (rdata0x10305ec28) [Nov 21 14:44:25] DEBUG[9219] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 180/INVITE/cseq=27538 (rdata0x10084ee28) [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x1028332a8 .Incoming Response msg 180/INVITE/cseq=27538 (rdata0x10084ee28) in state Proceeding [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x1028332a8 ..State changed from Proceeding to Proceeding, event=RX_MSG [Nov 21 14:44:25] DEBUG[9219] pjsip: sip_ua_layer.c ...Received forked Response msg 180/INVITE/cseq=27538 (rdata0x10084ee28) for existing dialog dlg0x10300a4a8 [Nov 21 14:44:25] DEBUG[9219] pjsip: sip_ua_layer.c ...Unhandled forked Response msg 180/INVITE/cseq=27538 (rdata0x10084ee28) from 127.0.0.1:63424, response will be handed over to the first dialog [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10300a4a8 ...Received Response msg 180/INVITE/cseq=27538 (rdata0x10084ee28) [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10300a4a8 ...Transaction tsx0x1028332a8 state changed to Proceeding [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The inv session still has an invite_tsx (0x1028332a8) [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The transaction involved in this state change is 0x1028332a8 [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current transaction state is Proceeding [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The transaction state change event is RX_MSG [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current inv state is CONFIRMED [Nov 21 14:44:25] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:25] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:25] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:25] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:25] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:25] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:25] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:25] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:25] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:25] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:25] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:25] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:25] DEBUG[8963] pjsip: sip_endpoint.c Processing incoming message: Response msg 180/INVITE/cseq=1067 (rdata0x100855028) [Nov 21 14:44:25] DEBUG[9219] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 180/INVITE/cseq=1067 (rdata0x102836828) [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x1028576a8 .Incoming Response msg 180/INVITE/cseq=1067 (rdata0x102836828) in state Proceeding [Nov 21 14:44:25] DEBUG[9219] pjsip: tsx0x1028576a8 ..State changed from Proceeding to Proceeding, event=RX_MSG [Nov 21 14:44:25] DEBUG[9219] pjsip: sip_ua_layer.c ...Received forked Response msg 180/INVITE/cseq=1067 (rdata0x102836828) for existing dialog dlg0x10306f6a8 [Nov 21 14:44:25] DEBUG[9219] pjsip: sip_ua_layer.c ...Unhandled forked Response msg 180/INVITE/cseq=1067 (rdata0x102836828) from 127.0.0.1:63424, response will be handed over to the first dialog [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10306f6a8 ...Received Response msg 180/INVITE/cseq=1067 (rdata0x102836828) [Nov 21 14:44:25] DEBUG[9219] pjsip: dlg0x10306f6a8 ...Transaction tsx0x1028576a8 state changed to Proceeding [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The inv session still has an invite_tsx (0x1028576a8) [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The transaction involved in this state change is 0x1028576a8 [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current transaction state is Proceeding [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The transaction state change event is RX_MSG [Nov 21 14:44:25] DEBUG[9219] res_pjsip_session.c: The current inv state is CONFIRMED [Nov 21 14:44:25] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:25] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:25] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:25] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:25] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:25] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:25] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:25] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:25] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:26] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:27] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:27] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:27] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:27] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:27] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:27] DEBUG[8963] pjsip: sip_endpoint.c Processing incoming message: Response msg 603/INVITE/cseq=1067 (rdata0x102857e28) [Nov 21 14:44:27] DEBUG[9219] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 603/INVITE/cseq=1067 (rdata0x10186d628) [Nov 21 14:44:27] DEBUG[9219] pjsip: tsx0x1028576a8 .Incoming Response msg 603/INVITE/cseq=1067 (rdata0x10186d628) in state Proceeding [Nov 21 14:44:27] DEBUG[9219] pjsip: endpoint ..Request msg ACK/cseq=16415 (tdta0x102836800) created. [Nov 21 14:44:27] DEBUG[9219] pjsip: tsx0x1028576a8 ..State changed from Proceeding to Completed, event=RX_MSG [Nov 21 14:44:27] DEBUG[9219] pjsip: dlg0x10306f6a8 ...Received Response msg 603/INVITE/cseq=1067 (rdata0x10186d628) [Nov 21 14:44:27] DEBUG[9219] pjsip: dlg0x10306f6a8 ...Transaction tsx0x1028576a8 state changed to Completed [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The transaction involved in this state change is 0x1028576a8 [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The current transaction state is Completed [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The transaction state change event is RX_MSG [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The current inv state is CONFIRMED [Nov 21 14:44:27] DEBUG[9219] pjsip: endpoint .....Request msg BYE/cseq=16417 (tdta0x102837800) created. [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: Method is BYE [Nov 21 14:44:27] DEBUG[9219] pjsip: inv0x10306f6a8 .....Sending Request msg BYE/cseq=16417 (tdta0x102837800) [Nov 21 14:44:27] DEBUG[9219] pjsip: dlg0x10306f6a8 ......Sending Request msg BYE/cseq=16417 (tdta0x102837800) [Nov 21 14:44:27] DEBUG[9219] pjsip: tsx0x10285a4a8 .......Transaction created for Request msg BYE/cseq=16416 (tdta0x102837800) [Nov 21 14:44:27] DEBUG[9219] pjsip: tsx0x10285a4a8 ......Sending Request msg BYE/cseq=16416 (tdta0x102837800) in state Null [Nov 21 14:44:27] DEBUG[9219] pjsip: sip_resolve.c .......Target '127.0.0.1:63424' type=Unspecified resolved to '127.0.0.1:63424' type=UDP (UDP transport) [Nov 21 14:44:27] DEBUG[9219] pjsip: tsx0x10285a4a8 .......State changed from Null to Calling, event=TX_MSG [Nov 21 14:44:27] DEBUG[9219] pjsip: dlg0x10306f6a8 ........Transaction tsx0x10285a4a8 state changed to Calling [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The transaction involved in this state change is 0x10285a4a8 [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The current transaction state is Calling [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The transaction state change event is TX_MSG [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The current inv state is CONFIRMED [Nov 21 14:44:27] DEBUG[9219] pjsip: tdta0x10305a40 ..Destroying txdata Request msg INVITE/cseq=16415 (tdta0x10305a400) [Nov 21 14:44:27] DEBUG[8963] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/BYE/cseq=16416 (rdata0x100855028) [Nov 21 14:44:27] DEBUG[9219] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/BYE/cseq=16416 (rdata0x10186d628) [Nov 21 14:44:27] DEBUG[9219] pjsip: tsx0x10285a4a8 .Incoming Response msg 200/BYE/cseq=16416 (rdata0x10186d628) in state Calling [Nov 21 14:44:27] DEBUG[9219] pjsip: tsx0x10285a4a8 ..State changed from Calling to Completed, event=RX_MSG [Nov 21 14:44:27] DEBUG[9219] pjsip: dlg0x10306f6a8 ...Received Response msg 200/BYE/cseq=16416 (rdata0x10186d628) [Nov 21 14:44:27] DEBUG[9219] pjsip: dlg0x10306f6a8 ...Transaction tsx0x10285a4a8 state changed to Completed [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Nov 21 14:44:27] DEBUG[14851][C-00000000] res_rtp_asterisk.c: No remote address on RTP instance '0x10083fa70' so dropping frame [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: There is no transaction involved in this state change [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The current inv state is DISCONNCTD [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: Source of transaction state change is RX_MSG [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: Received response [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: Response is 200 OK [Nov 21 14:44:27] DEBUG[9219] pjsip: dlg0x10306f6a8 .....Session count dec to 2 by mod-invite [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: inv_session 0x100746108 has no ast session [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The transaction involved in this state change is 0x10285a4a8 [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The current transaction state is Completed [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The transaction state change event is RX_MSG [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The current inv state is DISCONNCTD [Nov 21 14:44:27] DEBUG[15363][C-00000001] bridge_channel.c: Setting 0x10242e380(PJSIP/blink-00000001) state from:0 to:1 [Nov 21 14:44:27] DEBUG[15363][C-00000001] bridge_channel.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d: pulling 0x10242e380(PJSIP/blink-00000001) [Nov 21 14:44:27] VERBOSE[15363][C-00000001] bridge_channel.c: -- Channel PJSIP/blink-00000001 left 'native_rtp' base-bridge [Nov 21 14:44:27] DEBUG[15363][C-00000001] bridge_channel.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d: 0x10242e380(PJSIP/blink-00000001) is leaving native_rtp technology [Nov 21 14:44:27] DEBUG[15363][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x10083fa70' [Nov 21 14:44:27] DEBUG[15363][C-00000001] bridge_native_rtp.c: Discontinued RTP bridging of 'PJSIP/blink-00000000' and 'PJSIP/blink-00000001' - media will flow through Asterisk core [Nov 21 14:44:27] DEBUG[15363][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Nov 21 14:44:27] DEBUG[15363][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Nov 21 14:44:27] DEBUG[15363][C-00000001] bridge_native_rtp.c: Bridge 'bad81495-5672-41b3-bdbc-6cb00a942f0d' can not use native RTP bridge as two channels are required [Nov 21 14:44:27] DEBUG[15363][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Nov 21 14:44:27] DEBUG[15363][C-00000001] bridge.c: Chose bridge technology simple_bridge [Nov 21 14:44:27] DEBUG[15363][C-00000001] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d: calling simple_bridge technology constructor [Nov 21 14:44:27] DEBUG[15363][C-00000001] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d: calling native_rtp technology stop [Nov 21 14:44:27] DEBUG[15363][C-00000001] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d: 0x105033010(PJSIP/blink-00000000) is leaving native_rtp technology (dummy) [Nov 21 14:44:27] DEBUG[15363][C-00000001] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d is happy that channel PJSIP/blink-00000000 already has read format ulaw [Nov 21 14:44:27] DEBUG[15363][C-00000001] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d is happy that channel PJSIP/blink-00000000 already has write format ulaw [Nov 21 14:44:27] DEBUG[15363][C-00000001] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d: 0x105033010(PJSIP/blink-00000000) is joining simple_bridge technology [Nov 21 14:44:27] DEBUG[15363][C-00000001] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d: calling simple_bridge technology start [Nov 21 14:44:27] DEBUG[15363][C-00000001] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d: calling native_rtp technology destructor [Nov 21 14:44:27] DEBUG[15363][C-00000001] stasis/control.c: 1385066665.1, bad81495-5672-41b3-bdbc-6cb00a942f0d: Channel leaving bridge [Nov 21 14:44:27] DEBUG[15363][C-00000001] stasis/control.c: reason: Channel was departed from bridge [Nov 21 14:44:27] DEBUG[6403] cdr.c: Finalized CDR for PJSIP/blink-00000000 - start 1385066662.639397 answer 1385066662.840590 end 1385066667.123192 dispo ANSWERED [Nov 21 14:44:27] DEBUG[14347][C-00000001] stasis/control.c: 1385066665.1: Channel departing bridge [Nov 21 14:44:27] DEBUG[14347][C-00000001] bridge.c: Waiting for 0x10242e380(PJSIP/blink-00000001) bridge thread to die. [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: Delaying sending reinvite to blink because of outstanding transaction... [Nov 21 14:44:27] DEBUG[14347][C-00000001] pbx.c: Extension 7000, priority 2 returned normally even though call was hung up [Nov 21 14:44:27] DEBUG[14347][C-00000001] channel.c: Soft-Hanging up channel 'PJSIP/blink-00000001' [Nov 21 14:44:27] DEBUG[14347][C-00000001] channel.c: Hanging up channel 'PJSIP/blink-00000001' [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: Destroying SIP session with endpoint blink [Nov 21 14:44:27] DEBUG[9219] rtp_engine.c: Destroyed RTP instance '0x101877470' [Nov 21 14:44:27] DEBUG[9219] pjsip: dlg0x10306f6a8 .Session count dec to 0 by Session Module [Nov 21 14:44:27] DEBUG[9219] taskprocessor.c: destroying taskprocessor '42fe656d-4c73-4fea-a618-6e87611efa93' [Nov 21 14:44:27] DEBUG[6659] devicestate.c: No provider found, checking channel drivers for PJSIP - blink [Nov 21 14:44:27] DEBUG[6659] devicestate.c: Changing state for PJSIP/blink - state 2 (In use) [Nov 21 14:44:27] DEBUG[5123] devicestate.c: Processing device state change for 'PJSIP/blink' [Nov 21 14:44:27] DEBUG[5123] devicestate.c: Adding per-server state of 'In use' for 'PJSIP/blink' [Nov 21 14:44:27] DEBUG[5123] devicestate.c: Aggregate devstate result is 'In use' for 'PJSIP/blink' [Nov 21 14:44:27] DEBUG[5123] devicestate.c: Aggregate state for device 'PJSIP/blink' has not changed from 'In use' [Nov 21 14:44:27] DEBUG[8963] pjsip: sip_endpoint.c Processing incoming message: Response msg 603/INVITE/cseq=27538 (rdata0x100855028) [Nov 21 14:44:27] DEBUG[9219] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 603/INVITE/cseq=27538 (rdata0x101881e28) [Nov 21 14:44:27] DEBUG[9219] pjsip: tsx0x1028332a8 .Incoming Response msg 603/INVITE/cseq=27538 (rdata0x101881e28) in state Proceeding [Nov 21 14:44:27] DEBUG[9219] pjsip: endpoint ..Request msg ACK/cseq=14285 (tdta0x10305a400) created. [Nov 21 14:44:27] DEBUG[9219] pjsip: tsx0x1028332a8 ..State changed from Proceeding to Completed, event=RX_MSG [Nov 21 14:44:27] DEBUG[9219] pjsip: dlg0x10300a4a8 ...Received Response msg 603/INVITE/cseq=27538 (rdata0x101881e28) [Nov 21 14:44:27] DEBUG[9219] pjsip: dlg0x10300a4a8 ...Transaction tsx0x1028332a8 state changed to Completed [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The transaction involved in this state change is 0x1028332a8 [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The current transaction state is Completed [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The transaction state change event is RX_MSG [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The current inv state is CONFIRMED [Nov 21 14:44:27] DEBUG[9219] pjsip: endpoint .....Request msg BYE/cseq=14287 (tdta0x100839000) created. [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: Method is BYE [Nov 21 14:44:27] DEBUG[9219] pjsip: inv0x10300a4a8 .....Sending Request msg BYE/cseq=14287 (tdta0x100839000) [Nov 21 14:44:27] DEBUG[9219] pjsip: dlg0x10300a4a8 ......Sending Request msg BYE/cseq=14287 (tdta0x100839000) [Nov 21 14:44:27] DEBUG[9219] pjsip: tsx0x1008360a8 .......Transaction created for Request msg BYE/cseq=14286 (tdta0x100839000) [Nov 21 14:44:27] DEBUG[9219] pjsip: tsx0x1008360a8 ......Sending Request msg BYE/cseq=14286 (tdta0x100839000) in state Null [Nov 21 14:44:27] DEBUG[9219] pjsip: sip_resolve.c .......Target '127.0.0.1:63424' type=Unspecified resolved to '127.0.0.1:63424' type=UDP (UDP transport) [Nov 21 14:44:27] DEBUG[9219] pjsip: tsx0x1008360a8 .......State changed from Null to Calling, event=TX_MSG [Nov 21 14:44:27] DEBUG[9219] pjsip: dlg0x10300a4a8 ........Transaction tsx0x1008360a8 state changed to Calling [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The transaction involved in this state change is 0x1008360a8 [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The current transaction state is Calling [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The transaction state change event is TX_MSG [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The current inv state is CONFIRMED [Nov 21 14:44:27] DEBUG[9219] pjsip: tdta0x10186a40 ..Destroying txdata Request msg INVITE/cseq=14285 (tdta0x10186a400) [Nov 21 14:44:27] DEBUG[8963] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/BYE/cseq=14286 (rdata0x10186c628) [Nov 21 14:44:27] DEBUG[9219] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/BYE/cseq=14286 (rdata0x10084ce28) [Nov 21 14:44:27] DEBUG[9219] pjsip: tsx0x1008360a8 .Incoming Response msg 200/BYE/cseq=14286 (rdata0x10084ce28) in state Calling [Nov 21 14:44:27] DEBUG[9219] pjsip: tsx0x1008360a8 ..State changed from Calling to Completed, event=RX_MSG [Nov 21 14:44:27] DEBUG[9219] pjsip: dlg0x10300a4a8 ...Received Response msg 200/BYE/cseq=14286 (rdata0x10084ce28) [Nov 21 14:44:27] DEBUG[9219] pjsip: dlg0x10300a4a8 ...Transaction tsx0x1008360a8 state changed to Completed [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The state change pertains to the session with blink [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: There is no transaction involved in this state change [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The current inv state is DISCONNCTD [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: Source of transaction state change is RX_MSG [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: Received response [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: Response is 200 OK [Nov 21 14:44:27] DEBUG[9219] pjsip: dlg0x10300a4a8 .....Session count dec to 2 by mod-invite [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 21 14:44:27] DEBUG[14851][C-00000000] bridge_channel.c: Setting 0x105033010(PJSIP/blink-00000000) state from:0 to:1 [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: inv_session 0x105025468 has no ast session [Nov 21 14:44:27] DEBUG[14851][C-00000000] bridge_channel.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d: pulling 0x105033010(PJSIP/blink-00000000) [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The transaction involved in this state change is 0x1008360a8 [Nov 21 14:44:27] VERBOSE[14851][C-00000000] bridge_channel.c: -- Channel PJSIP/blink-00000000 left 'simple_bridge' base-bridge [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The current transaction state is Completed [Nov 21 14:44:27] DEBUG[14851][C-00000000] bridge_channel.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d: 0x105033010(PJSIP/blink-00000000) is leaving simple_bridge technology [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The transaction state change event is RX_MSG [Nov 21 14:44:27] DEBUG[14851][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: The current inv state is DISCONNCTD [Nov 21 14:44:27] DEBUG[14851][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [Nov 21 14:44:27] DEBUG[14851][C-00000000] bridge_native_rtp.c: Bridge 'bad81495-5672-41b3-bdbc-6cb00a942f0d' can not use native RTP bridge as two channels are required [Nov 21 14:44:27] DEBUG[14851][C-00000000] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Nov 21 14:44:27] DEBUG[14851][C-00000000] bridge.c: Chose bridge technology simple_bridge [Nov 21 14:44:27] DEBUG[14851][C-00000000] bridge.c: Bridge bad81495-5672-41b3-bdbc-6cb00a942f0d is already using the new technology. [Nov 21 14:44:27] DEBUG[14851][C-00000000] stasis/control.c: 1385066662.0, bad81495-5672-41b3-bdbc-6cb00a942f0d: Channel leaving bridge [Nov 21 14:44:27] DEBUG[14851][C-00000000] stasis/control.c: reason: Channel was departed from bridge [Nov 21 14:44:27] DEBUG[14083][C-00000000] stasis/control.c: 1385066662.0: Channel departing bridge [Nov 21 14:44:27] DEBUG[14083][C-00000000] bridge.c: Waiting for 0x105033010(PJSIP/blink-00000000) bridge thread to die. [Nov 21 14:44:27] DEBUG[14083][C-00000000] pbx.c: Extension 7000, priority 2 returned normally even though call was hung up [Nov 21 14:44:27] DEBUG[14083][C-00000000] channel.c: Soft-Hanging up channel 'PJSIP/blink-00000000' [Nov 21 14:44:27] DEBUG[14083][C-00000000] channel.c: Hanging up channel 'PJSIP/blink-00000000' [Nov 21 14:44:27] DEBUG[9219] res_pjsip_session.c: Destroying SIP session with endpoint blink [Nov 21 14:44:27] DEBUG[9219] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x10083fa70' [Nov 21 14:44:27] DEBUG[9219] rtp_engine.c: Destroyed RTP instance '0x10083fa70' [Nov 21 14:44:27] DEBUG[9219] pjsip: dlg0x10300a4a8 .Session count dec to 0 by Session Module [Nov 21 14:44:27] DEBUG[9219] taskprocessor.c: destroying taskprocessor '550991a2-2565-4d6e-ab91-128fec87ceda' [Nov 21 14:44:27] DEBUG[6659] devicestate.c: No provider found, checking channel drivers for PJSIP - blink [Nov 21 14:44:27] DEBUG[6659] devicestate.c: Changing state for PJSIP/blink - state 1 (Not in use) [Nov 21 14:44:27] DEBUG[5123] devicestate.c: Processing device state change for 'PJSIP/blink' [Nov 21 14:44:27] DEBUG[5123] devicestate.c: Adding per-server state of 'Not in use' for 'PJSIP/blink' [Nov 21 14:44:27] DEBUG[5123] devicestate.c: Aggregate devstate result is 'Not in use' for 'PJSIP/blink' [Nov 21 14:44:27] DEBUG[5123] devicestate.c: Aggregate state for device 'PJSIP/blink' has changed to 'Not in use' [Nov 21 14:44:32] DEBUG[8963] pjsip: tsx0x10285a4a8 Timeout timer event [Nov 21 14:44:32] DEBUG[8963] pjsip: tsx0x10285a4a8 .State changed from Completed to Terminated, event=TIMER [Nov 21 14:44:32] DEBUG[8963] pjsip: dlg0x10306f6a8 ..Transaction tsx0x10285a4a8 state changed to Terminated [Nov 21 14:44:32] DEBUG[8963] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 21 14:44:32] DEBUG[8963] res_pjsip_session.c: inv_session 0x100746108 has no ast session [Nov 21 14:44:32] DEBUG[8963] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Nov 21 14:44:32] DEBUG[8963] res_pjsip_session.c: The transaction involved in this state change is 0x10285a4a8 [Nov 21 14:44:32] DEBUG[8963] res_pjsip_session.c: The current transaction state is Terminated [Nov 21 14:44:32] DEBUG[8963] res_pjsip_session.c: The transaction state change event is TIMER [Nov 21 14:44:32] DEBUG[8963] res_pjsip_session.c: The current inv state is DISCONNCTD [Nov 21 14:44:32] DEBUG[8963] pjsip: tsx0x10285a4a8 Timeout timer event [Nov 21 14:44:32] DEBUG[8963] pjsip: tsx0x10285a4a8 .State changed from Terminated to Destroyed, event=TIMER [Nov 21 14:44:32] DEBUG[8963] pjsip: tdta0x10283780 ..Destroying txdata Request msg BYE/cseq=16416 (tdta0x102837800) [Nov 21 14:44:32] DEBUG[8963] pjsip: tsx0x10285a4a8 ..Transaction destroyed! [Nov 21 14:44:32] DEBUG[8963] pjsip: tsx0x1008360a8 Timeout timer event [Nov 21 14:44:32] DEBUG[8963] pjsip: tsx0x1008360a8 .State changed from Completed to Terminated, event=TIMER [Nov 21 14:44:32] DEBUG[8963] pjsip: dlg0x10300a4a8 ..Transaction tsx0x1008360a8 state changed to Terminated [Nov 21 14:44:32] DEBUG[8963] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Nov 21 14:44:32] DEBUG[8963] res_pjsip_session.c: inv_session 0x105025468 has no ast session [Nov 21 14:44:32] DEBUG[8963] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Nov 21 14:44:32] DEBUG[8963] res_pjsip_session.c: The transaction involved in this state change is 0x1008360a8 [Nov 21 14:44:32] DEBUG[8963] res_pjsip_session.c: The current transaction state is Terminated [Nov 21 14:44:32] DEBUG[8963] res_pjsip_session.c: The transaction state change event is TIMER [Nov 21 14:44:32] DEBUG[8963] res_pjsip_session.c: The current inv state is DISCONNCTD [Nov 21 14:44:32] DEBUG[8963] pjsip: tsx0x1008360a8 Timeout timer event [Nov 21 14:44:32] DEBUG[8963] pjsip: tsx0x1008360a8 .State changed from Terminated to Destroyed, event=TIMER [Nov 21 14:44:32] DEBUG[8963] pjsip: tdta0x10083900 ..Destroying txdata Request msg BYE/cseq=14286 (tdta0x100839000) [Nov 21 14:44:32] DEBUG[8963] pjsip: tsx0x1008360a8 ..Transaction destroyed! [Nov 21 14:44:32] DEBUG[8963] pjsip: sip_endpoint.c Processing incoming message: Request msg PUBLISH/cseq=1 (rdata0x10084ee28) [Nov 21 14:44:32] DEBUG[9219] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg PUBLISH/cseq=1 (rdata0x100849828) [Nov 21 14:44:32] DEBUG[9219] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Nov 21 14:44:32] DEBUG[9219] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint blink [Nov 21 14:44:32] DEBUG[9219] pjsip: endpoint .Response msg 401/PUBLISH/cseq=1 (tdta0x102837800) created [Nov 21 14:44:32] DEBUG[9219] netsock2.c: Splitting '10.24.21.100' into... [Nov 21 14:44:32] DEBUG[9219] netsock2.c: ...host '10.24.21.100' and port ''. [Nov 21 14:44:32] DEBUG[9219] netsock2.c: Splitting '127.0.0.1' into... [Nov 21 14:44:32] DEBUG[9219] netsock2.c: ...host '127.0.0.1' and port ''. [Nov 21 14:44:32] DEBUG[9219] pjsip: tdta0x10283780 .Destroying txdata Response msg 401/PUBLISH/cseq=1 (tdta0x102837800) [Nov 21 14:44:32] DEBUG[8963] pjsip: sip_endpoint.c Processing incoming message: Request msg PUBLISH/cseq=2 (rdata0x10084ee28) [Nov 21 14:44:32] DEBUG[9219] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg PUBLISH/cseq=2 (rdata0x103032628) [Nov 21 14:44:32] DEBUG[9219] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Nov 21 14:44:32] DEBUG[9219] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint blink [Nov 21 14:44:32] DEBUG[9219] pjsip: endpoint .Response msg 401/PUBLISH/cseq=2 (tdta0x102837800) created [Nov 21 14:44:32] DEBUG[9219] res_pjsip_authenticator_digest.c: Calculated nonce 1385066672/130e692822b03a650458e4a37ce19a4a. Actual nonce is 1385066672/130e692822b03a650458e4a37ce19a4a [Nov 21 14:44:32] DEBUG[9219] netsock2.c: Splitting '10.24.21.100' into... [Nov 21 14:44:32] DEBUG[9219] netsock2.c: ...host '10.24.21.100' and port ''. [Nov 21 14:44:32] DEBUG[9219] netsock2.c: Splitting '127.0.0.1' into... [Nov 21 14:44:32] DEBUG[9219] netsock2.c: ...host '127.0.0.1' and port ''. [Nov 21 14:44:32] DEBUG[9219] pjsip: tdta0x10283780 .Destroying txdata Response msg 401/PUBLISH/cseq=2 (tdta0x102837800) [Nov 21 14:44:32] WARNING[9219] res_pjsip_pubsub.c: No registered publish handler for event presence [Nov 21 14:44:32] DEBUG[9219] pjsip: endpoint .Response msg 489/PUBLISH/cseq=2 (tdta0x102837800) created [Nov 21 14:44:32] DEBUG[9219] pjsip: tdta0x10283780 .Destroying txdata Response msg 489/PUBLISH/cseq=2 (tdta0x102837800) [Nov 21 14:44:41] DEBUG[1287] taskprocessor.c: destroying taskprocessor 'ast_msg_queue' [Nov 21 14:44:41] VERBOSE[1287] asterisk.c: Beginning asterisk shutdown.... [Nov 21 14:44:41] VERBOSE[1287] asterisk.c: Asterisk cleanly ending (0). [Nov 21 14:44:41] VERBOSE[1287] asterisk.c: Executing last minute cleanups [Nov 21 14:44:41] VERBOSE[1287] res_musiconhold.c: == Destroying musiconhold processes [Nov 21 14:44:41] DEBUG[1287] res_musiconhold.c: Destroying MOH class 'default' [Nov 21 14:44:41] DEBUG[1287] taskprocessor.c: destroying taskprocessor '18a09a73-43f0-4771-adae-ae0e6845e4fa' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'CallCompletionCancel' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'CallCompletionRequest' [Nov 21 14:44:41] DEBUG[1287] logger.c: Unregistered dynamic logger level 'CC' with index 16. [Nov 21 14:44:41] DEBUG[1287] taskprocessor.c: destroying taskprocessor 'CCSS core' [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action Ping [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action Events [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action Logoff [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action Login [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action Challenge [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action Hangup [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action Status [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action Setvar [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action Getvar [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action GetConfig [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action GetConfigJSON [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action UpdateConfig [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action CreateConfig [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action ListCategories [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action Redirect [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action Atxfer [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action Originate [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action Command [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action ExtensionState [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action PresenceState [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action AbsoluteTimeout [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action MailboxStatus [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action MailboxCount [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action ListCommands [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action SendText [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action UserEvent [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action WaitEvent [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action CoreSettings [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action CoreStatus [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action Reload [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action CoreShowChannels [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action ModuleLoad [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action ModuleCheck [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action AOCMessage [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action Filter [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action BlindTransfer [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered custom function AMI_CLIENT [Nov 21 14:44:41] DEBUG[1287] tcptls.c: Stopped server :: AMI server [Nov 21 14:44:41] DEBUG[1287] tcptls.c: Stopped server :: AMI TLS server [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action LocalOptimizeAway [Nov 21 14:44:41] DEBUG[1287] channel.c: Unregistering channel type 'Local' [Nov 21 14:44:41] VERBOSE[1287] channel.c: == Unregistered channel type 'Local' [Nov 21 14:44:41] DEBUG[7171] taskprocessor.c: destroying taskprocessor '64cbd531-bad2-4772-8742-4b306b250f76' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'Answer' [Nov 21 14:44:41] DEBUG[6915] taskprocessor.c: destroying taskprocessor '070590af-36a8-4636-ba15-a71a5a6a60e2' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'BackGround' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'Busy' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'Congestion' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'ExecIfTime' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'Goto' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'GotoIf' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'GotoIfTime' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'ImportVar' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'Hangup' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'Incomplete' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'NoOp' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'Proceeding' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'Progress' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'RaiseException' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'Ringing' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'SayAlpha' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'SayAlphaCase' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'SayDigits' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'SayNumber' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'SayPhonetic' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'Set' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'MSet' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'SetAMAFlags' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'Wait' [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'WaitExten' [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action ShowDialPlan [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered custom function EXCEPTION [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered custom function TESTTIME [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action BridgeTechnologyList [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action BridgeTechnologySuspend [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action BridgeTechnologyUnsuspend [Nov 21 14:44:41] DEBUG[1287] bridge.c: Waiting for bridge manager thread to die. [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered custom function FEATUREMAP [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered custom function FEATURE [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action Bridge [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'Bridge' [Nov 21 14:44:41] DEBUG[1287] tcptls.c: Stopped server :: http server [Nov 21 14:44:41] DEBUG[1287] channel.c: Unregistering channel type 'Surrogate' [Nov 21 14:44:41] VERBOSE[1287] channel.c: == Unregistered channel type 'Surrogate' [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action DataGet [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered custom function MESSAGE [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered custom function MESSAGE_DATA [Nov 21 14:44:41] VERBOSE[1287] pbx.c: == Unregistered application 'MessageSend' [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action MessageSend [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action DBGet [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action DBPut [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action DBDel [Nov 21 14:44:41] VERBOSE[1287] manager.c: == Manager unregistered action DBDelTree [Nov 21 14:44:41] DEBUG[1287] taskprocessor.c: destroying taskprocessor 'Sorcery-control' [Nov 21 14:44:41] DEBUG[1287] threadpool.c: Destroying worker thread 5 [Nov 21 14:44:41] DEBUG[1287] taskprocessor.c: destroying taskprocessor 'Sorcery' [Nov 21 14:44:41] DEBUG[1287] asterisk.c: Asterisk ending (0).