Skip to content

Instantly share code, notes, and snippets.

@ggayan

ggayan/adhearsion_log.txt Secret

Created October 9, 2014 15:49
Show Gist options
  • Save ggayan/256204da1efce6a66ecc to your computer and use it in GitHub Desktop.
Save ggayan/256204da1efce6a66ecc to your computer and use it in GitHub Desktop.
Download ZIP
Unknown Exec Congestion on async AGI + AMI call
Raw
adhearsion_log.txt
[2014-10-09 11:55:05.471] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="Newchannel", headers={"Privilege"=>"call,all", "Timestamp"=>"1412866505.464938", "SequenceNumber"=>"317", "File"=>"channel.c", "Line"=>"1172", "Func"=>"__ast_channel_alloc_ap", "Channel"=>"SIP/192.168.246.1-0000000b", "ChannelState"=>"0", "ChannelStateDesc"=>"Down", "CallerIDNum"=>"sipp", "CallerIDName"=>"sipp", "AccountCode"=>"", "Exten"=>"1", "Context"=>"adhearsion", "Uniqueid"=>"1412866505.11"}, text_body=nil, events=[]>
[2014-10-09 11:55:05.471] TRACE Punchblock::Connection::Asterisk: [RECV] Event: VarSet
Privilege: dialplan,all
Timestamp: 1412866505.464992
SequenceNumber: 318
File: pbx.c
Line: 11681
Func: pbx_builtin_setvar_helper
Channel: SIP/192.168.246.1-0000000b
Variable: SIPURI
Value: sip:sipp@192.168.246.1:8836
Uniqueid: 1412866505.11
Event: VarSet
Privilege: dialplan,all
Timestamp: 1412866505.464998
SequenceNumber: 319
File: pbx.c
Line: 11681
Func: pbx_builtin_setvar_helper
Channel: SIP/192.168.246.1-0000000b
Variable: SIPDOMAIN
Value: 192.168.246.144
Uniqueid: 1412866505.11
Event: VarSet
Privilege: dialplan,all
Timestamp: 1412866505.465002
SequenceNumber: 320
File: pbx.c
Line: 11681
Func: pbx_builtin_setvar_helper
Channel: SIP/192.168.246.1-0000000b
Variable: SIPCALLID
Value: 2-22407@192.168.246.1
Uniqueid: 1412866505.11
Event: Newstate
Privilege: call,all
Timestamp: 1412866505.465136
SequenceNumber: 321
File: channel.c
Line: 7469
Func: ast_setstate
Channel: SIP/192.168.246.1-0000000b
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum:
ConnectedLineName:
Uniqueid: 1412866505.11
[2014-10-09 11:55:05.471] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Timestamp"=>"1412866505.464992", "SequenceNumber"=>"318", "File"=>"pbx.c", "Line"=>"11681", "Func"=>"pbx_builtin_setvar_helper", "Channel"=>"SIP/192.168.246.1-0000000b", "Variable"=>"SIPURI", "Value"=>"sip:sipp@192.168.246.1:8836", "Uniqueid"=>"1412866505.11"}, text_body=nil, events=[]>
[2014-10-09 11:55:05.472] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Timestamp"=>"1412866505.464998", "SequenceNumber"=>"319", "File"=>"pbx.c", "Line"=>"11681", "Func"=>"pbx_builtin_setvar_helper", "Channel"=>"SIP/192.168.246.1-0000000b", "Variable"=>"SIPDOMAIN", "Value"=>"192.168.246.144", "Uniqueid"=>"1412866505.11"}, text_body=nil, events=[]>
[2014-10-09 11:55:05.472] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Timestamp"=>"1412866505.465002", "SequenceNumber"=>"320", "File"=>"pbx.c", "Line"=>"11681", "Func"=>"pbx_builtin_setvar_helper", "Channel"=>"SIP/192.168.246.1-0000000b", "Variable"=>"SIPCALLID", "Value"=>"2-22407@192.168.246.1", "Uniqueid"=>"1412866505.11"}, text_body=nil, events=[]>
[2014-10-09 11:55:05.473] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="Newstate", headers={"Privilege"=>"call,all", "Timestamp"=>"1412866505.465136", "SequenceNumber"=>"321", "File"=>"channel.c", "Line"=>"7469", "Func"=>"ast_setstate", "Channel"=>"SIP/192.168.246.1-0000000b", "ChannelState"=>"4", "ChannelStateDesc"=>"Ring", "CallerIDNum"=>"sipp", "CallerIDName"=>"sipp", "ConnectedLineNum"=>"", "ConnectedLineName"=>"", "Uniqueid"=>"1412866505.11"}, text_body=nil, events=[]>
[2014-10-09 11:55:05.474] TRACE Punchblock::Connection::Asterisk: [RECV] Event: Newexten
Privilege: dialplan,all
Timestamp: 1412866505.471825
SequenceNumber: 322
File: pbx.c
Line: 4914
Func: pbx_extension_helper
Channel: SIP/192.168.246.1-0000000b
Context: adhearsion
Extension: 1
Priority: 1
Application: AGI
AppData: agi:async
Uniqueid: 1412866505.11
[2014-10-09 11:55:05.475] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="Newexten", headers={"Privilege"=>"dialplan,all", "Timestamp"=>"1412866505.471825", "SequenceNumber"=>"322", "File"=>"pbx.c", "Line"=>"4914", "Func"=>"pbx_extension_helper", "Channel"=>"SIP/192.168.246.1-0000000b", "Context"=>"adhearsion", "Extension"=>"1", "Priority"=>"1", "Application"=>"AGI", "AppData"=>"agi:async", "Uniqueid"=>"1412866505.11"}, text_body=nil, events=[]>
[2014-10-09 11:55:05.475] TRACE Punchblock::Connection::Asterisk: [RECV] Event: AsyncAGI
Privilege: agi,all
Timestamp: 1412866505.475152
SequenceNumber: 323
File: res_agi.c
Line: 1320
Func: launch_asyncagi
SubEvent: Start
Channel: SIP/192.168.246.1-0000000b
Env: agi_request%3A%20async%0Aagi_channel%3A%20SIP%2F192.168.246.1-0000000b%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201412866505.11%0Aagi_version%3A%2011.13.0%0Aagi_callerid%3A%20sipp%0Aagi_calleridname%3A%20sipp%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%201%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20adhearsion%0Aagi_extension%3A%201%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140621241370368%0A%0A
[2014-10-09 11:55:05.476] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866505.475152", "SequenceNumber"=>"323", "File"=>"res_agi.c", "Line"=>"1320", "Func"=>"launch_asyncagi", "SubEvent"=>"Start", "Channel"=>"SIP/192.168.246.1-0000000b", "Env"=>"agi_request%3A%20async%0Aagi_channel%3A%20SIP%2F192.168.246.1-0000000b%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201412866505.11%0Aagi_version%3A%2011.13.0%0Aagi_callerid%3A%20sipp%0Aagi_calleridname%3A%20sipp%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%201%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20adhearsion%0Aagi_extension%3A%201%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140621241370368%0A%0A"}, text_body=nil, events=[]>
[2014-10-09 11:55:05.477] DEBUG Adhearsion::Call: @: Receiving message: #<Punchblock::Event::Offer target_call_id="30e1d560-d014-4509-b3aa-d6651ef2ebba", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:55:05 -0300, headers={"X-agi_request"=>"async", "X-agi_channel"=>"SIP/192.168.246.1-0000000b", "X-agi_language"=>"en", "X-agi_type"=>"SIP", "X-agi_uniqueid"=>"1412866505.11", "X-agi_version"=>"11.13.0", "X-agi_callerid"=>"sipp", "X-agi_calleridname"=>"sipp", "X-agi_callingpres"=>"0", "X-agi_callingani2"=>"0", "X-agi_callington"=>"0", "X-agi_callingtns"=>"0", "X-agi_dnid"=>"1", "X-agi_rdnis"=>"unknown", "X-agi_context"=>"adhearsion", "X-agi_extension"=>"1", "X-agi_priority"=>"1", "X-agi_enhanced"=>"0.0", "X-agi_accountcode"=>"", "X-agi_threadid"=>"140621241370368"}, to="1", from="sipp <SIP/sipp>">
[2014-10-09 11:55:05.478] INFO Adhearsion::Router: Call 30e1d560-d014-4509-b3aa-d6651ef2ebba selected route "default" (AsteriskRaceCondition)
[2014-10-09 11:55:05.479] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Executing command #<Punchblock::Command::Accept target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:55:05 -0300, request_id="d00fb392-c518-41e2-8fc6-200332344447", headers={}>
[2014-10-09 11:55:05.575] TRACE Punchblock::Connection::Asterisk: [RECV] Event: AGIExec
Privilege: agi,all
Timestamp: 1412866505.575498
SequenceNumber: 346
File: res_agi.c
Line: 3445
Func: agi_handle_command
SubEvent: Start
Channel: SIP/192.168.246.1-0000000b
CommandId: 470325664
Command: EXEC RINGING
[2014-10-09 11:55:05.576] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866505.575498", "SequenceNumber"=>"346", "File"=>"res_agi.c", "Line"=>"3445", "Func"=>"agi_handle_command", "SubEvent"=>"Start", "Channel"=>"SIP/192.168.246.1-0000000b", "CommandId"=>"470325664", "Command"=>"EXEC RINGING"}, text_body=nil, events=[]>
[2014-10-09 11:55:05.576] TRACE Punchblock::Connection::Asterisk: [RECV] Event: AGIExec
Privilege: agi,all
Timestamp: 1412866505.576310
SequenceNumber: 347
File: res_agi.c
Line: 3486
Func: agi_handle_command
SubEvent: End
Channel: SIP/192.168.246.1-0000000b
CommandId: 470325664
Command: EXEC RINGING
ResultCode: 200
Result: Success
Event: AsyncAGI
Privilege: agi,all
Timestamp: 1412866505.576482
SequenceNumber: 348
File: res_agi.c
Line: 1360
Func: launch_asyncagi
SubEvent: Exec
Channel: SIP/192.168.246.1-0000000b
CommandID: fa39a9d5-924a-4753-8902-88a08cac04c7
Result: 200%20result%3D0%0A
[2014-10-09 11:55:05.578] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event target_call_id="30e1d560-d014-4509-b3aa-d6651ef2ebba", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:55:05 -0300, name="AGIExec", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866505.575498", "SequenceNumber"=>"346", "File"=>"res_agi.c", "Line"=>"3445", "Func"=>"agi_handle_command", "SubEvent"=>"Start", "Channel"=>"SIP/192.168.246.1-0000000b", "CommandId"=>"470325664", "Command"=>"EXEC RINGING"}>
[2014-10-09 11:55:05.577] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866505.576310", "SequenceNumber"=>"347", "File"=>"res_agi.c", "Line"=>"3486", "Func"=>"agi_handle_command", "SubEvent"=>"End", "Channel"=>"SIP/192.168.246.1-0000000b", "CommandId"=>"470325664", "Command"=>"EXEC RINGING", "ResultCode"=>"200", "Result"=>"Success"}, text_body=nil, events=[]>
[2014-10-09 11:55:05.578] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866505.576482", "SequenceNumber"=>"348", "File"=>"res_agi.c", "Line"=>"1360", "Func"=>"launch_asyncagi", "SubEvent"=>"Exec", "Channel"=>"SIP/192.168.246.1-0000000b", "CommandID"=>"fa39a9d5-924a-4753-8902-88a08cac04c7", "Result"=>"200%20result%3D0%0A"}, text_body=nil, events=[]>
[2014-10-09 11:55:05.581] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event target_call_id="30e1d560-d014-4509-b3aa-d6651ef2ebba", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:55:05 -0300, name="AGIExec", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866505.576310", "SequenceNumber"=>"347", "File"=>"res_agi.c", "Line"=>"3486", "Func"=>"agi_handle_command", "SubEvent"=>"End", "Channel"=>"SIP/192.168.246.1-0000000b", "CommandId"=>"470325664", "Command"=>"EXEC RINGING", "ResultCode"=>"200", "Result"=>"Success"}>
[2014-10-09 11:55:05.582] TRACE Punchblock::Connection::Asterisk: [RECV] Response: Success
ActionID: 787c04d5-836e-4724-8d0e-3393c5d603f6
[2014-10-09 11:55:05.582] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event target_call_id="30e1d560-d014-4509-b3aa-d6651ef2ebba", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:55:05 -0300, name="AsyncAGI", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866505.576482", "SequenceNumber"=>"348", "File"=>"res_agi.c", "Line"=>"1360", "Func"=>"launch_asyncagi", "SubEvent"=>"Exec", "Channel"=>"SIP/192.168.246.1-0000000b", "CommandID"=>"fa39a9d5-924a-4753-8902-88a08cac04c7", "Result"=>"200%20result%3D0%0A"}>
[2014-10-09 11:55:05.582] TRACE Punchblock::Connection::Asterisk: [RECV] Message: Added AGI command to queue
[2014-10-09 11:55:05.582] INFO Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Executing controller #<AsteriskRaceCondition call=30e1d560-d014-4509-b3aa-d6651ef2ebba, metadata={}>
[2014-10-09 11:55:05.583] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Receiving message: #<Punchblock::Event::Offer target_call_id="30e1d560-d014-4509-b3aa-d6651ef2ebba", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:55:05 -0300, headers={"X-agi_request"=>"async", "X-agi_channel"=>"SIP/192.168.246.1-0000000b", "X-agi_language"=>"en", "X-agi_type"=>"SIP", "X-agi_uniqueid"=>"1412866505.11", "X-agi_version"=>"11.13.0", "X-agi_callerid"=>"sipp", "X-agi_calleridname"=>"sipp", "X-agi_callingpres"=>"0", "X-agi_callingani2"=>"0", "X-agi_callington"=>"0", "X-agi_callingtns"=>"0", "X-agi_dnid"=>"1", "X-agi_rdnis"=>"unknown", "X-agi_context"=>"adhearsion", "X-agi_extension"=>"1", "X-agi_priority"=>"1", "X-agi_enhanced"=>"0.0", "X-agi_accountcode"=>"", "X-agi_threadid"=>"140621241370368"}, to="1", from="sipp <SIP/sipp>">
[2014-10-09 11:55:05.584] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Executing command #<Punchblock::Command::Answer target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:55:05 -0300, request_id="9abf007c-31f3-4dea-b946-521597412d05", headers={}>
[2014-10-09 11:55:05.585] TRACE Punchblock::Connection::Asterisk: [SEND] Action: agi
ActionID: d24e4f49-179b-4e61-891a-3922818df006
Channel: SIP/192.168.246.1-0000000b
Command: ANSWER
CommandID: 9edbe7a1-3c31-4afb-9606-23cda1e37138
[2014-10-09 11:55:05.586] TRACE Punchblock::Connection::Asterisk: [RECV] Response: Success
ActionID: d24e4f49-179b-4e61-891a-3922818df006
[2014-10-09 11:55:05.586] TRACE Punchblock::Connection::Asterisk: [RECV] Message: Added AGI command to queue
[2014-10-09 11:55:05.586] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Response headers={"ActionID"=>"d24e4f49-179b-4e61-891a-3922818df006", "Message"=>"Added AGI command to queue"}, text_body=nil, events=[]>
[2014-10-09 11:55:05.679] TRACE Punchblock::Connection::Asterisk: [RECV] Event: AGIExec
Privilege: agi,all
Timestamp: 1412866505.678283
SequenceNumber: 359
File: res_agi.c
Line: 3445
Func: agi_handle_command
SubEvent: Start
Channel: SIP/192.168.246.1-0000000b
CommandId: 1408681741
Command: ANSWER
Event: Newstate
Privilege: call,all
Timestamp: 1412866505.678316
SequenceNumber: 360
File: channel.c
Line: 7469
Func: ast_setstate
Channel: SIP/192.168.246.1-0000000b
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum:
ConnectedLineName:
Uniqueid: 1412866505.11
[2014-10-09 11:55:05.679] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866505.678283", "SequenceNumber"=>"359", "File"=>"res_agi.c", "Line"=>"3445", "Func"=>"agi_handle_command", "SubEvent"=>"Start", "Channel"=>"SIP/192.168.246.1-0000000b", "CommandId"=>"1408681741", "Command"=>"ANSWER"}, text_body=nil, events=[]>
[2014-10-09 11:55:05.681] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="Newstate", headers={"Privilege"=>"call,all", "Timestamp"=>"1412866505.678316", "SequenceNumber"=>"360", "File"=>"channel.c", "Line"=>"7469", "Func"=>"ast_setstate", "Channel"=>"SIP/192.168.246.1-0000000b", "ChannelState"=>"6", "ChannelStateDesc"=>"Up", "CallerIDNum"=>"sipp", "CallerIDName"=>"sipp", "ConnectedLineNum"=>"", "ConnectedLineName"=>"", "Uniqueid"=>"1412866505.11"}, text_body=nil, events=[]>
[2014-10-09 11:55:05.684] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event target_call_id="30e1d560-d014-4509-b3aa-d6651ef2ebba", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:55:05 -0300, name="AGIExec", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866505.678283", "SequenceNumber"=>"359", "File"=>"res_agi.c", "Line"=>"3445", "Func"=>"agi_handle_command", "SubEvent"=>"Start", "Channel"=>"SIP/192.168.246.1-0000000b", "CommandId"=>"1408681741", "Command"=>"ANSWER"}>
[2014-10-09 11:55:05.684] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event target_call_id="30e1d560-d014-4509-b3aa-d6651ef2ebba", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:55:05 -0300, name="Newstate", headers={"Privilege"=>"call,all", "Timestamp"=>"1412866505.678316", "SequenceNumber"=>"360", "File"=>"channel.c", "Line"=>"7469", "Func"=>"ast_setstate", "Channel"=>"SIP/192.168.246.1-0000000b", "ChannelState"=>"6", "ChannelStateDesc"=>"Up", "CallerIDNum"=>"sipp", "CallerIDName"=>"sipp", "ConnectedLineNum"=>"", "ConnectedLineName"=>"", "Uniqueid"=>"1412866505.11"}>
[2014-10-09 11:55:06.196] TRACE Punchblock::Connection::Asterisk: [RECV] Event: AGIExec
Privilege: agi,all
Timestamp: 1412866506.180613
SequenceNumber: 414
File: res_agi.c
Line: 3486
Func: agi_handle_command
SubEvent: End
Channel: SIP/192.168.246.1-0000000b
CommandId: 1408681741
Command: ANSWER
ResultCode: 200
Result: Success
Event: AsyncAGI
Privilege: agi,all
Timestamp: 1412866506.180649
SequenceNumber: 415
File: res_agi.c
Line: 1360
Func: launch_asyncagi
SubEvent: Exec
Channel: SIP/192.168.246.1-0000000b
CommandID: 9edbe7a1-3c31-4afb-9606-23cda1e37138
Result: 200%20result%3D0%0A
[2014-10-09 11:55:06.196] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866506.180613", "SequenceNumber"=>"414", "File"=>"res_agi.c", "Line"=>"3486", "Func"=>"agi_handle_command", "SubEvent"=>"End", "Channel"=>"SIP/192.168.246.1-0000000b", "CommandId"=>"1408681741", "Command"=>"ANSWER", "ResultCode"=>"200", "Result"=>"Success"}, text_body=nil, events=[]>
[2014-10-09 11:55:06.197] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866506.180649", "SequenceNumber"=>"415", "File"=>"res_agi.c", "Line"=>"1360", "Func"=>"launch_asyncagi", "SubEvent"=>"Exec", "Channel"=>"SIP/192.168.246.1-0000000b", "CommandID"=>"9edbe7a1-3c31-4afb-9606-23cda1e37138", "Result"=>"200%20result%3D0%0A"}, text_body=nil, events=[]>
[2014-10-09 11:55:06.198] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event target_call_id="30e1d560-d014-4509-b3aa-d6651ef2ebba", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:55:06 -0300, name="AGIExec", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866506.180613", "SequenceNumber"=>"414", "File"=>"res_agi.c", "Line"=>"3486", "Func"=>"agi_handle_command", "SubEvent"=>"End", "Channel"=>"SIP/192.168.246.1-0000000b", "CommandId"=>"1408681741", "Command"=>"ANSWER", "ResultCode"=>"200", "Result"=>"Success"}>
[2014-10-09 11:55:06.199] TRACE Punchblock::Connection::Asterisk: [RECV] Event: AGIExec
Privilege: agi,all
Timestamp: 1412866506.180662
SequenceNumber: 416
File: res_agi.c
Line: 3445
Func: agi_handle_command
SubEvent: Start
Channel: SIP/192.168.246.1-0000000b
CommandId: 1138078742
Command: EXEC Congestion
[2014-10-09 11:55:06.199] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event target_call_id="30e1d560-d014-4509-b3aa-d6651ef2ebba", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:55:06 -0300, name="AsyncAGI", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866506.180649", "SequenceNumber"=>"415", "File"=>"res_agi.c", "Line"=>"1360", "Func"=>"launch_asyncagi", "SubEvent"=>"Exec", "Channel"=>"SIP/192.168.246.1-0000000b", "CommandID"=>"9edbe7a1-3c31-4afb-9606-23cda1e37138", "Result"=>"200%20result%3D0%0A"}>
[2014-10-09 11:55:06.200] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866506.180662", "SequenceNumber"=>"416", "File"=>"res_agi.c", "Line"=>"3445", "Func"=>"agi_handle_command", "SubEvent"=>"Start", "Channel"=>"SIP/192.168.246.1-0000000b", "CommandId"=>"1138078742", "Command"=>"EXEC Congestion"}, text_body=nil, events=[]>
[2014-10-09 11:55:06.201] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Executing command #<Punchblock::Component::Asterisk::AGI::Command target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:55:06 -0300, request_id="ac47390c-6e22-4f52-bae8-017372f31611", name="EXEC MixMonitor", params=["/tmp/30e1d560-d014-4509-b3aa-d6651ef2ebba.wav"]>
[2014-10-09 11:55:06.203] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event target_call_id="30e1d560-d014-4509-b3aa-d6651ef2ebba", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:55:06 -0300, name="AGIExec", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866506.180662", "SequenceNumber"=>"416", "File"=>"res_agi.c", "Line"=>"3445", "Func"=>"agi_handle_command", "SubEvent"=>"Start", "Channel"=>"SIP/192.168.246.1-0000000b", "CommandId"=>"1138078742", "Command"=>"EXEC Congestion"}>
[2014-10-09 11:55:06.213] TRACE Punchblock::Connection::Asterisk: [SEND] Action: agi
ActionID: 8d534af0-dd1a-4f29-ae9d-86d145dab843
Channel: SIP/192.168.246.1-0000000b
Command: EXEC MixMonitor "/tmp/30e1d560-d014-4509-b3aa-d6651ef2ebba.wav"
CommandID: 2316fa0a-0d1c-4190-9354-174291039616
[2014-10-09 11:55:05.471] TRACE Punchblock::Connection::Asterisk: [RECV] Event: Newchannel
Privilege: call,all
Timestamp: 1412866505.464938
SequenceNumber: 317
File: channel.c
Line: 1172
Func: __ast_channel_alloc_ap
Channel: SIP/192.168.246.1-0000000b
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum: sipp
CallerIDName: sipp
AccountCode:
Exten: 1
Context: adhearsion
Uniqueid: 1412866505.11
[2014-10-09 11:55:05.471] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="Newchannel", headers={"Privilege"=>"call,all", "Timestamp"=>"1412866505.464938", "SequenceNumber"=>"317", "File"=>"channel.c", "Line"=>"1172", "Func"=>"__ast_channel_alloc_ap", "Channel"=>"SIP/192.168.246.1-0000000b", "ChannelState"=>"0", "ChannelStateDesc"=>"Down", "CallerIDNum"=>"sipp", "CallerIDName"=>"sipp", "AccountCode"=>"", "Exten"=>"1", "Context"=>"adhearsion", "Uniqueid"=>"1412866505.11"}, text_body=nil, events=[]>
[2014-10-09 11:55:05.471] TRACE Punchblock::Connection::Asterisk: [RECV] Event: VarSet
Privilege: dialplan,all
Timestamp: 1412866505.464992
SequenceNumber: 318
File: pbx.c
Line: 11681
Func: pbx_builtin_setvar_helper
Channel: SIP/192.168.246.1-0000000b
Variable: SIPURI
Value: sip:sipp@192.168.246.1:8836
Uniqueid: 1412866505.11
Event: VarSet
Privilege: dialplan,all
Timestamp: 1412866505.464998
SequenceNumber: 319
File: pbx.c
Line: 11681
Func: pbx_builtin_setvar_helper
Channel: SIP/192.168.246.1-0000000b
Variable: SIPDOMAIN
Value: 192.168.246.144
Uniqueid: 1412866505.11
Event: VarSet
Privilege: dialplan,all
Timestamp: 1412866505.465002
SequenceNumber: 320
File: pbx.c
Line: 11681
Func: pbx_builtin_setvar_helper
Channel: SIP/192.168.246.1-0000000b
Variable: SIPCALLID
Value: 2-22407@192.168.246.1
Uniqueid: 1412866505.11
Event: Newstate
Privilege: call,all
Timestamp: 1412866505.465136
SequenceNumber: 321
File: channel.c
Line: 7469
Func: ast_setstate
Channel: SIP/192.168.246.1-0000000b
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum:
ConnectedLineName:
Uniqueid: 1412866505.11
[2014-10-09 11:55:05.471] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Timestamp"=>"1412866505.464992", "SequenceNumber"=>"318", "File"=>"pbx.c", "Line"=>"11681", "Func"=>"pbx_builtin_setvar_helper", "Channel"=>"SIP/192.168.246.1-0000000b", "Variable"=>"SIPURI", "Value"=>"sip:sipp@192.168.246.1:8836", "Uniqueid"=>"1412866505.11"}, text_body=nil, events=[]>
[2014-10-09 11:55:05.472] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Timestamp"=>"1412866505.464998", "SequenceNumber"=>"319", "File"=>"pbx.c", "Line"=>"11681", "Func"=>"pbx_builtin_setvar_helper", "Channel"=>"SIP/192.168.246.1-0000000b", "Variable"=>"SIPDOMAIN", "Value"=>"192.168.246.144", "Uniqueid"=>"1412866505.11"}, text_body=nil, events=[]>
[2014-10-09 11:55:05.472] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Timestamp"=>"1412866505.465002", "SequenceNumber"=>"320", "File"=>"pbx.c", "Line"=>"11681", "Func"=>"pbx_builtin_setvar_helper", "Channel"=>"SIP/192.168.246.1-0000000b", "Variable"=>"SIPCALLID", "Value"=>"2-22407@192.168.246.1", "Uniqueid"=>"1412866505.11"}, text_body=nil, events=[]>
[2014-10-09 11:55:05.473] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="Newstate", headers={"Privilege"=>"call,all", "Timestamp"=>"1412866505.465136", "SequenceNumber"=>"321", "File"=>"channel.c", "Line"=>"7469", "Func"=>"ast_setstate", "Channel"=>"SIP/192.168.246.1-0000000b", "ChannelState"=>"4", "ChannelStateDesc"=>"Ring", "CallerIDNum"=>"sipp", "CallerIDName"=>"sipp", "ConnectedLineNum"=>"", "ConnectedLineName"=>"", "Uniqueid"=>"1412866505.11"}, text_body=nil, events=[]>
[2014-10-09 11:55:05.474] TRACE Punchblock::Connection::Asterisk: [RECV] Event: Newexten
Privilege: dialplan,all
Timestamp: 1412866505.471825
SequenceNumber: 322
File: pbx.c
Line: 4914
Func: pbx_extension_helper
Channel: SIP/192.168.246.1-0000000b
Context: adhearsion
Extension: 1
Priority: 1
Application: AGI
AppData: agi:async
Uniqueid: 1412866505.11
[2014-10-09 11:55:05.475] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="Newexten", headers={"Privilege"=>"dialplan,all", "Timestamp"=>"1412866505.471825", "SequenceNumber"=>"322", "File"=>"pbx.c", "Line"=>"4914", "Func"=>"pbx_extension_helper", "Channel"=>"SIP/192.168.246.1-0000000b", "Context"=>"adhearsion", "Extension"=>"1", "Priority"=>"1", "Application"=>"AGI", "AppData"=>"agi:async", "Uniqueid"=>"1412866505.11"}, text_body=nil, events=[]>
[2014-10-09 11:55:05.475] TRACE Punchblock::Connection::Asterisk: [RECV] Event: AsyncAGI
Privilege: agi,all
Timestamp: 1412866505.475152
SequenceNumber: 323
File: res_agi.c
Line: 1320
Func: launch_asyncagi
SubEvent: Start
Channel: SIP/192.168.246.1-0000000b
Env: agi_request%3A%20async%0Aagi_channel%3A%20SIP%2F192.168.246.1-0000000b%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201412866505.11%0Aagi_version%3A%2011.13.0%0Aagi_callerid%3A%20sipp%0Aagi_calleridname%3A%20sipp%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%201%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20adhearsion%0Aagi_extension%3A%201%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140621241370368%0A%0A
[2014-10-09 11:55:05.476] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866505.475152", "SequenceNumber"=>"323", "File"=>"res_agi.c", "Line"=>"1320", "Func"=>"launch_asyncagi", "SubEvent"=>"Start", "Channel"=>"SIP/192.168.246.1-0000000b", "Env"=>"agi_request%3A%20async%0Aagi_channel%3A%20SIP%2F192.168.246.1-0000000b%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201412866505.11%0Aagi_version%3A%2011.13.0%0Aagi_callerid%3A%20sipp%0Aagi_calleridname%3A%20sipp%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%201%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20adhearsion%0Aagi_extension%3A%201%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140621241370368%0A%0A"}, text_body=nil, events=[]>
[2014-10-09 11:55:05.477] DEBUG Adhearsion::Call: @: Receiving message: #<Punchblock::Event::Offer target_call_id="30e1d560-d014-4509-b3aa-d6651ef2ebba", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:55:05 -0300, headers={"X-agi_request"=>"async", "X-agi_channel"=>"SIP/192.168.246.1-0000000b", "X-agi_language"=>"en", "X-agi_type"=>"SIP", "X-agi_uniqueid"=>"1412866505.11", "X-agi_version"=>"11.13.0", "X-agi_callerid"=>"sipp", "X-agi_calleridname"=>"sipp", "X-agi_callingpres"=>"0", "X-agi_callingani2"=>"0", "X-agi_callington"=>"0", "X-agi_callingtns"=>"0", "X-agi_dnid"=>"1", "X-agi_rdnis"=>"unknown", "X-agi_context"=>"adhearsion", "X-agi_extension"=>"1", "X-agi_priority"=>"1", "X-agi_enhanced"=>"0.0", "X-agi_accountcode"=>"", "X-agi_threadid"=>"140621241370368"}, to="1", from="sipp <SIP/sipp>">
[2014-10-09 11:55:05.478] INFO Adhearsion::Router: Call 30e1d560-d014-4509-b3aa-d6651ef2ebba selected route "default" (AsteriskRaceCondition)
[2014-10-09 11:55:05.479] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Executing command #<Punchblock::Command::Accept target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:55:05 -0300, request_id="d00fb392-c518-41e2-8fc6-200332344447", headers={}>
[2014-10-09 11:56:06.230] TRACE Punchblock::Connection::Asterisk: [RECV] Event: SessionTimeout
Privilege: call,all
Timestamp: 1412866566.224255
SequenceNumber: 607
File: chan_sip.c
Line: 28945
Func: check_rtp_timeout
Source: RTPTimeout
Channel: SIP/192.168.246.1-0000000b
Uniqueid: 1412866505.11
[2014-10-09 11:56:06.230] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="SessionTimeout", headers={"Privilege"=>"call,all", "Timestamp"=>"1412866566.224255", "SequenceNumber"=>"607", "File"=>"chan_sip.c", "Line"=>"28945", "Func"=>"check_rtp_timeout", "Source"=>"RTPTimeout", "Channel"=>"SIP/192.168.246.1-0000000b", "Uniqueid"=>"1412866505.11"}, text_body=nil, events=[]>
[2014-10-09 11:56:06.233] TRACE Punchblock::Connection::Asterisk: [RECV] Event: AGIExec
Privilege: agi,all
Timestamp: 1412866566.230136
SequenceNumber: 608
File: res_agi.c
Line: 3486
Func: agi_handle_command
SubEvent: End
Channel: SIP/192.168.246.1-0000000b
CommandId: 1138078742
Command: EXEC Congestion
ResultCode: 200
Result: Unknown Result
Event: AsyncAGI
Privilege: agi,all
Timestamp: 1412866566.230530
SequenceNumber: 609
File: res_agi.c
Line: 1360
Func: launch_asyncagi
SubEvent: Exec
Channel: SIP/192.168.246.1-0000000b
CommandID: 9d14bab5-8143-4384-8402-7685d5091ac3
Result: 200%20result%3D-1%0A
Event: AsyncAGI
Privilege: agi,all
Timestamp: 1412866566.230665
SequenceNumber: 610
File: res_agi.c
Line: 1423
Func: launch_asyncagi
SubEvent: End
Channel: SIP/192.168.246.1-0000000b
Event: VarSet
Privilege: dialplan,all
Timestamp: 1412866566.230856
SequenceNumber: 611
File: pbx.c
Line: 11681
Func: pbx_builtin_setvar_helper
Channel: SIP/192.168.246.1-0000000b
Variable: AGISTATUS
Value: HANGUP
Uniqueid: 1412866505.11
[2014-10-09 11:56:06.233] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="AGIExec", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866566.230136", "SequenceNumber"=>"608", "File"=>"res_agi.c", "Line"=>"3486", "Func"=>"agi_handle_command", "SubEvent"=>"End", "Channel"=>"SIP/192.168.246.1-0000000b", "CommandId"=>"1138078742", "Command"=>"EXEC Congestion", "ResultCode"=>"200", "Result"=>"Unknown Result"}, text_body=nil, events=[]>
[2014-10-09 11:56:06.234] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866566.230530", "SequenceNumber"=>"609", "File"=>"res_agi.c", "Line"=>"1360", "Func"=>"launch_asyncagi", "SubEvent"=>"Exec", "Channel"=>"SIP/192.168.246.1-0000000b", "CommandID"=>"9d14bab5-8143-4384-8402-7685d5091ac3", "Result"=>"200%20result%3D-1%0A"}, text_body=nil, events=[]>
[2014-10-09 11:56:06.235] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866566.230665", "SequenceNumber"=>"610", "File"=>"res_agi.c", "Line"=>"1423", "Func"=>"launch_asyncagi", "SubEvent"=>"End", "Channel"=>"SIP/192.168.246.1-0000000b"}, text_body=nil, events=[]>
[2014-10-09 11:56:06.237] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Timestamp"=>"1412866566.230856", "SequenceNumber"=>"611", "File"=>"pbx.c", "Line"=>"11681", "Func"=>"pbx_builtin_setvar_helper", "Channel"=>"SIP/192.168.246.1-0000000b", "Variable"=>"AGISTATUS", "Value"=>"HANGUP", "Uniqueid"=>"1412866505.11"}, text_body=nil, events=[]>
[2014-10-09 11:56:06.239] TRACE Punchblock::Connection::Asterisk: [RECV] Event: SoftHangupRequest
Privilege: call,all
Timestamp: 1412866566.231313
SequenceNumber: 612
File: channel.c
Line: 2692
Func: ast_softhangup
Channel: SIP/192.168.246.1-0000000b
Uniqueid: 1412866505.11
Cause: 16
Event: Newexten
Privilege: dialplan,all
Timestamp: 1412866566.231837
SequenceNumber: 613
File: pbx.c
Line: 4914
Func: pbx_extension_helper
Channel: SIP/192.168.246.1-0000000b
Context: adhearsion
Extension: h
Priority: 1
Application: AGI
AppData: agi:async
Uniqueid: 1412866505.11
[2014-10-09 11:56:06.237] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event target_call_id="30e1d560-d014-4509-b3aa-d6651ef2ebba", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:56:06 -0300, name="SessionTimeout", headers={"Privilege"=>"call,all", "Timestamp"=>"1412866566.224255", "SequenceNumber"=>"607", "File"=>"chan_sip.c", "Line"=>"28945", "Func"=>"check_rtp_timeout", "Source"=>"RTPTimeout", "Channel"=>"SIP/192.168.246.1-0000000b", "Uniqueid"=>"1412866505.11"}>
[2014-10-09 11:56:06.240] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event target_call_id="30e1d560-d014-4509-b3aa-d6651ef2ebba", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:56:06 -0300, name="AGIExec", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866566.230136", "SequenceNumber"=>"608", "File"=>"res_agi.c", "Line"=>"3486", "Func"=>"agi_handle_command", "SubEvent"=>"End", "Channel"=>"SIP/192.168.246.1-0000000b", "CommandId"=>"1138078742", "Command"=>"EXEC Congestion", "ResultCode"=>"200", "Result"=>"Unknown Result"}>
[2014-10-09 11:56:06.240] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="SoftHangupRequest", headers={"Privilege"=>"call,all", "Timestamp"=>"1412866566.231313", "SequenceNumber"=>"612", "File"=>"channel.c", "Line"=>"2692", "Func"=>"ast_softhangup", "Channel"=>"SIP/192.168.246.1-0000000b", "Uniqueid"=>"1412866505.11", "Cause"=>"16"}, text_body=nil, events=[]>
[2014-10-09 11:56:06.240] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="Newexten", headers={"Privilege"=>"dialplan,all", "Timestamp"=>"1412866566.231837", "SequenceNumber"=>"613", "File"=>"pbx.c", "Line"=>"4914", "Func"=>"pbx_extension_helper", "Channel"=>"SIP/192.168.246.1-0000000b", "Context"=>"adhearsion", "Extension"=>"h", "Priority"=>"1", "Application"=>"AGI", "AppData"=>"agi:async", "Uniqueid"=>"1412866505.11"}, text_body=nil, events=[]>
[2014-10-09 11:56:06.242] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event target_call_id="30e1d560-d014-4509-b3aa-d6651ef2ebba", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:56:06 -0300, name="AsyncAGI", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866566.230530", "SequenceNumber"=>"609", "File"=>"res_agi.c", "Line"=>"1360", "Func"=>"launch_asyncagi", "SubEvent"=>"Exec", "Channel"=>"SIP/192.168.246.1-0000000b", "CommandID"=>"9d14bab5-8143-4384-8402-7685d5091ac3", "Result"=>"200%20result%3D-1%0A"}>
[2014-10-09 11:56:06.242] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event target_call_id="30e1d560-d014-4509-b3aa-d6651ef2ebba", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:56:06 -0300, name="AsyncAGI", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866566.230665", "SequenceNumber"=>"610", "File"=>"res_agi.c", "Line"=>"1423", "Func"=>"launch_asyncagi", "SubEvent"=>"End", "Channel"=>"SIP/192.168.246.1-0000000b"}>
[2014-10-09 11:56:06.242] TRACE Punchblock::Connection::Asterisk: [RECV] Event: AsyncAGI
Privilege: agi,all
Timestamp: 1412866566.240852
SequenceNumber: 614
File: res_agi.c
Line: 1320
Func: launch_asyncagi
SubEvent: Start
Channel: SIP/192.168.246.1-0000000b
Env: agi_request%3A%20async%0Aagi_channel%3A%20SIP%2F192.168.246.1-0000000b%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201412866505.11%0Aagi_version%3A%2011.13.0%0Aagi_callerid%3A%20sipp%0Aagi_calleridname%3A%20sipp%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%201%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20adhearsion%0Aagi_extension%3A%20h%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140621241370368%0A%0A
Event: AsyncAGI
Privilege: agi,all
Timestamp: 1412866566.241139
SequenceNumber: 615
File: res_agi.c
Line: 1423
Func: launch_asyncagi
SubEvent: End
Channel: SIP/192.168.246.1-0000000b
Event: VarSet
Privilege: dialplan,all
Timestamp: 1412866566.241371
SequenceNumber: 616
File: pbx.c
Line: 11681
Func: pbx_builtin_setvar_helper
Channel: SIP/192.168.246.1-0000000b
Variable: AGISTATUS
Value: HANGUP
Uniqueid: 1412866505.11
[2014-10-09 11:56:06.244] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event target_call_id="30e1d560-d014-4509-b3aa-d6651ef2ebba", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:56:06 -0300, name="VarSet", headers={"Privilege"=>"dialplan,all", "Timestamp"=>"1412866566.230856", "SequenceNumber"=>"611", "File"=>"pbx.c", "Line"=>"11681", "Func"=>"pbx_builtin_setvar_helper", "Channel"=>"SIP/192.168.246.1-0000000b", "Variable"=>"AGISTATUS", "Value"=>"HANGUP", "Uniqueid"=>"1412866505.11"}>
[2014-10-09 11:56:06.243] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866566.240852", "SequenceNumber"=>"614", "File"=>"res_agi.c", "Line"=>"1320", "Func"=>"launch_asyncagi", "SubEvent"=>"Start", "Channel"=>"SIP/192.168.246.1-0000000b", "Env"=>"agi_request%3A%20async%0Aagi_channel%3A%20SIP%2F192.168.246.1-0000000b%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201412866505.11%0Aagi_version%3A%2011.13.0%0Aagi_callerid%3A%20sipp%0Aagi_calleridname%3A%20sipp%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%201%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20adhearsion%0Aagi_extension%3A%20h%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140621241370368%0A%0A"}, text_body=nil, events=[]>
[2014-10-09 11:56:06.258] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="AsyncAGI", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866566.241139", "SequenceNumber"=>"615", "File"=>"res_agi.c", "Line"=>"1423", "Func"=>"launch_asyncagi", "SubEvent"=>"End", "Channel"=>"SIP/192.168.246.1-0000000b"}, text_body=nil, events=[]>
[2014-10-09 11:56:06.259] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event target_call_id="30e1d560-d014-4509-b3aa-d6651ef2ebba", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:56:06 -0300, name="SoftHangupRequest", headers={"Privilege"=>"call,all", "Timestamp"=>"1412866566.231313", "SequenceNumber"=>"612", "File"=>"channel.c", "Line"=>"2692", "Func"=>"ast_softhangup", "Channel"=>"SIP/192.168.246.1-0000000b", "Uniqueid"=>"1412866505.11", "Cause"=>"16"}>
[2014-10-09 11:56:06.260] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="VarSet", headers={"Privilege"=>"dialplan,all", "Timestamp"=>"1412866566.241371", "SequenceNumber"=>"616", "File"=>"pbx.c", "Line"=>"11681", "Func"=>"pbx_builtin_setvar_helper", "Channel"=>"SIP/192.168.246.1-0000000b", "Variable"=>"AGISTATUS", "Value"=>"HANGUP", "Uniqueid"=>"1412866505.11"}, text_body=nil, events=[]>
[2014-10-09 11:56:06.259] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event target_call_id="30e1d560-d014-4509-b3aa-d6651ef2ebba", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:56:06 -0300, name="Newexten", headers={"Privilege"=>"dialplan,all", "Timestamp"=>"1412866566.231837", "SequenceNumber"=>"613", "File"=>"pbx.c", "Line"=>"4914", "Func"=>"pbx_extension_helper", "Channel"=>"SIP/192.168.246.1-0000000b", "Context"=>"adhearsion", "Extension"=>"h", "Priority"=>"1", "Application"=>"AGI", "AppData"=>"agi:async", "Uniqueid"=>"1412866505.11"}>
[2014-10-09 11:56:06.264] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event target_call_id="30e1d560-d014-4509-b3aa-d6651ef2ebba", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:56:06 -0300, name="AsyncAGI", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866566.240852", "SequenceNumber"=>"614", "File"=>"res_agi.c", "Line"=>"1320", "Func"=>"launch_asyncagi", "SubEvent"=>"Start", "Channel"=>"SIP/192.168.246.1-0000000b", "Env"=>"agi_request%3A%20async%0Aagi_channel%3A%20SIP%2F192.168.246.1-0000000b%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201412866505.11%0Aagi_version%3A%2011.13.0%0Aagi_callerid%3A%20sipp%0Aagi_calleridname%3A%20sipp%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%201%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20adhearsion%0Aagi_extension%3A%20h%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140621241370368%0A%0A"}>
[2014-10-09 11:56:06.266] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event target_call_id="30e1d560-d014-4509-b3aa-d6651ef2ebba", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:56:06 -0300, name="AsyncAGI", headers={"Privilege"=>"agi,all", "Timestamp"=>"1412866566.241139", "SequenceNumber"=>"615", "File"=>"res_agi.c", "Line"=>"1423", "Func"=>"launch_asyncagi", "SubEvent"=>"End", "Channel"=>"SIP/192.168.246.1-0000000b"}>
[2014-10-09 11:56:06.267] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event target_call_id="30e1d560-d014-4509-b3aa-d6651ef2ebba", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:56:06 -0300, name="VarSet", headers={"Privilege"=>"dialplan,all", "Timestamp"=>"1412866566.241371", "SequenceNumber"=>"616", "File"=>"pbx.c", "Line"=>"11681", "Func"=>"pbx_builtin_setvar_helper", "Channel"=>"SIP/192.168.246.1-0000000b", "Variable"=>"AGISTATUS", "Value"=>"HANGUP", "Uniqueid"=>"1412866505.11"}>
[2014-10-09 11:56:06.266] TRACE Punchblock::Connection::Asterisk: [RECV] Event: Hangup
Privilege: call,all
Timestamp: 1412866566.243703
SequenceNumber: 622
File: channel.c
Line: 2880
Func: ast_hangup
Channel: SIP/192.168.246.1-0000000b
Uniqueid: 1412866505.11
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
AccountCode:
Cause: 0
Cause-txt: Unknown
[2014-10-09 11:56:06.268] TRACE Punchblock::Connection::Asterisk: [RECV] #<RubyAMI::Event name="Hangup", headers={"Privilege"=>"call,all", "Timestamp"=>"1412866566.243703", "SequenceNumber"=>"622", "File"=>"channel.c", "Line"=>"2880", "Func"=>"ast_hangup", "Channel"=>"SIP/192.168.246.1-0000000b", "Uniqueid"=>"1412866505.11", "CallerIDNum"=>"sipp", "CallerIDName"=>"sipp", "ConnectedLineNum"=>"<unknown>", "ConnectedLineName"=>"<unknown>", "AccountCode"=>"", "Cause"=>"0", "Cause-txt"=>"Unknown"}, text_body=nil, events=[]>
[2014-10-09 11:56:06.275] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Receiving message: #<Punchblock::Event::Asterisk::AMI::Event target_call_id="30e1d560-d014-4509-b3aa-d6651ef2ebba", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:56:06 -0300, name="Hangup", headers={"Privilege"=>"call,all", "Timestamp"=>"1412866566.243703", "SequenceNumber"=>"622", "File"=>"channel.c", "Line"=>"2880", "Func"=>"ast_hangup", "Channel"=>"SIP/192.168.246.1-0000000b", "Uniqueid"=>"1412866505.11", "CallerIDNum"=>"sipp", "CallerIDName"=>"sipp", "ConnectedLineNum"=>"<unknown>", "ConnectedLineName"=>"<unknown>", "AccountCode"=>"", "Cause"=>"0", "Cause-txt"=>"Unknown"}>
[2014-10-09 11:56:06.276] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Receiving message: #<Punchblock::Event::Complete target_call_id="30e1d560-d014-4509-b3aa-d6651ef2ebba", target_mixer_name=nil, component_id="2316fa0a-0d1c-4190-9354-174291039616", source_uri="2316fa0a-0d1c-4190-9354-174291039616", domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:56:06 -0300, reason=#<Punchblock::Event::Complete::Hangup target_call_id=nil, target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 11:56:06 -0300, name=:hangup>, recording=nil, fax=nil, fax_metadata={}>
[2014-10-09 11:56:06.276] INFO Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Call was hung up while executing a controller
[2014-10-09 11:56:06.277] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Receiving message: #<Punchblock::Event::End target_call_id="30e1d560-d014-4509-b3aa-d6651ef2ebba", target_mixer_name=nil, component_id=nil, source_uri=nil, domain=nil, transport=nil, timestamp=Thu, 09 Oct 2014 14:56:06 +0000, headers={}, reason=:hungup, platform_code="0">
[2014-10-09 11:56:06.277] INFO Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Call ended due to hungup
[2014-10-09 11:56:06.278] DEBUG Adhearsion::Call: 30e1d560-d014-4509-b3aa-d6651ef2ebba@: Finished executing controller #<AsteriskRaceCondition call=30e1d560-d014-4509-b3aa-d6651ef2ebba, metadata={}>
[2014-10-09 11:56:06.278] INFO Adhearsion::Router::Route: Call 30e1d560-d014-4509-b3aa-d6651ef2ebba routing completed. Hanging up now.
Raw
ami_dump.txt
2014-10-09 14:55:05.471040 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 340
E.....@.@..................nmUYG....o^.....
..vm"c.SEvent: Newchannel
Privilege: call,all
Timestamp: 1412866505.464938
SequenceNumber: 317
File: channel.c
Line: 1172
Func: __ast_channel_alloc_ap
Channel: SIP/192.168.246.1-0000000b
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum: sipp
CallerIDName: sipp
AccountCode:
Exten: 1
Context: adhearsion
Uniqueid: 1412866505.11
2014-10-09 14:55:05.471147 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 268
E..@..@.@..N................mUYG....o......
..vm"c..Event: VarSet
Privilege: dialplan,all
Timestamp: 1412866505.464992
SequenceNumber: 318
File: pbx.c
Line: 11681
Func: pbx_builtin_setvar_helper
Channel: SIP/192.168.246.1-0000000b
Variable: SIPURI
Value: sip:sipp@192.168.246.1:8836
Uniqueid: 1412866505.11
2014-10-09 14:55:05.471207 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 259
......@.@..V................mUYG....o
..vm"c..Event: VarSet
Privilege: dialplan,all
Timestamp: 1412866505.464998
SequenceNumber: 319
File: pbx.c
Line: 11681
Func: pbx_builtin_setvar_helper
Channel: SIP/192.168.246.1-0000000b
Variable: SIPDOMAIN
Value: 192.168.246.144
Uniqueid: 1412866505.11
2014-10-09 14:55:05.471298 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 265
E..=..@.@..O................mUYG....o......
..vm"c..Event: VarSet
Privilege: dialplan,all
Timestamp: 1412866505.465002
SequenceNumber: 320
File: pbx.c
Line: 11681
Func: pbx_builtin_setvar_helper
Channel: SIP/192.168.246.1-0000000b
Variable: SIPCALLID
Value: 2-22407@192.168.246.1
Uniqueid: 1412866505.11
2014-10-09 14:55:05.471432 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 323
E..w..@.@...................mUYG....oM.....
..vm"c..Event: Newstate
Privilege: call,all
Timestamp: 1412866505.465136
SequenceNumber: 321
File: channel.c
Line: 7469
Func: ast_setstate
Channel: SIP/192.168.246.1-0000000b
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum:
ConnectedLineName:
Uniqueid: 1412866505.11
2014-10-09 14:55:05.471890 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 296
E..\..@.@...................mUYG....o2.....
..vm"c..Event: Newexten
Privilege: dialplan,all
Timestamp: 1412866505.471825
SequenceNumber: 322
File: pbx.c
Line: 4914
Func: pbx_extension_helper
Channel: SIP/192.168.246.1-0000000b
Context: adhearsion
Extension: 1
Priority: 1
Application: AGI
AppData: agi:async
Uniqueid: 1412866505.11
2014-10-09 14:55:05.475241 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 737
E.....@.@..t...............EmUYG....p......
..vn"c..Event: AsyncAGI
Privilege: agi,all
Timestamp: 1412866505.475152
SequenceNumber: 323
File: res_agi.c
Line: 1320
Func: launch_asyncagi
SubEvent: Start
Channel: SIP/192.168.246.1-0000000b
Env: agi_request%3A%20async%0Aagi_channel%3A%20SIP%2F192.168.246.1-0000000b%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201412866505.11%0Aagi_version%3A%2011.13.0%0Aagi_callerid%3A%20sipp%0Aagi_calleridname%3A%20sipp%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%201%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20adhearsion%0Aagi_extension%3A%201%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140621241370368%0A%0A
2014-10-09 14:55:05.530168 IP 192.168.246.1.58303 > 192.168.246.144.5038: tcp 172
E.....@.@...............mUYG..._.. .k:.....
"c....vqAction: agi
ActionID: c083f338-86f9-41f8-9c15-e4aa22d8fb39
Channel: SIP/192.168.246.1-0000000b
Command: EXEC RINGING
CommandID: fa39a9d5-924a-4753-8902-88a08cac04c7
2014-10-09 14:55:05.575615 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 243
E..'..@.@..E................mUZ.....n......
..v."c.
Event: AGIExec
Privilege: agi,all
Timestamp: 1412866505.575498
SequenceNumber: 346
File: res_agi.c
Line: 3445
Func: agi_handle_command
SubEvent: Start
Channel: SIP/192.168.246.1-0000000b
CommandId: 470325664
Command: EXEC RINGING
2014-10-09 14:55:05.576367 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 275
E..G..@.@..$................mUZ.....o......
..v."c..Event: AGIExec
Privilege: agi,all
Timestamp: 1412866505.576310
SequenceNumber: 347
File: res_agi.c
Line: 3486
Func: agi_handle_command
SubEvent: End
Channel: SIP/192.168.246.1-0000000b
CommandId: 470325664
Command: EXEC RINGING
ResultCode: 200
Result: Success
2014-10-09 14:55:05.576530 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 273
E..E..@.@..%................mUZ.....o......
..v."c..Event: AsyncAGI
Privilege: agi,all
Timestamp: 1412866505.576482
SequenceNumber: 348
File: res_agi.c
Line: 1360
Func: launch_asyncagi
SubEvent: Exec
Channel: SIP/192.168.246.1-0000000b
CommandID: fa39a9d5-924a-4753-8902-88a08cac04c7
Result: 200%20result%3D0%0A
2014-10-09 14:55:05.586134 IP 192.168.246.1.58303 > 192.168.246.144.5038: tcp 166
E....
@.@.80............mU[E...... ........
"c....v.Action: agi
ActionID: d24e4f49-179b-4e61-891a-3922818df006
Channel: SIP/192.168.246.1-0000000b
Command: ANSWER
CommandID: 9edbe7a1-3c31-4afb-9606-23cda1e37138
2014-10-09 14:55:05.679013 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 238
E.."..@.@..7..............".mU[.....n......
..v."c.kEvent: AGIExec
Privilege: agi,all
Timestamp: 1412866505.678283
SequenceNumber: 359
File: res_agi.c
Line: 3445
Func: agi_handle_command
SubEvent: Start
Channel: SIP/192.168.246.1-0000000b
CommandId: 1408681741
Command: ANSWER
2014-10-09 14:55:05.679127 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 321
E..u..@.@.................#.mU[.....oK.....
..v."c.nEvent: Newstate
Privilege: call,all
Timestamp: 1412866505.678316
SequenceNumber: 360
File: channel.c
Line: 7469
Func: ast_setstate
Channel: SIP/192.168.246.1-0000000b
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum:
ConnectedLineName:
Uniqueid: 1412866505.11
2014-10-09 14:55:06.196514 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 273
E..E..@.@.................k.mUb....lo......
..w""c.>Event: AsyncAGI
Privilege: agi,all
Timestamp: 1412866506.180649
SequenceNumber: 415
File: res_agi.c
Line: 1360
Func: launch_asyncagi
SubEvent: Exec
Channel: SIP/192.168.246.1-0000000b
CommandID: 9edbe7a1-3c31-4afb-9606-23cda1e37138
Result: 200%20result%3D0%0A
2014-10-09 14:55:06.196589 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 247
E..+..@.@.................l.mUb....lo......
..w""c.OEvent: AGIExec
Privilege: agi,all
Timestamp: 1412866506.180662
SequenceNumber: 416
File: res_agi.c
Line: 3445
Func: agi_handle_command
SubEvent: Start
Channel: SIP/192.168.246.1-0000000b
CommandId: 1138078742
Command: EXEC Congestion
2014-10-09 14:55:06.214434 IP 192.168.246.1.58303 > 192.168.246.144.5038: tcp 223
E...b.@.@.iS............mUb...w... ../.....
"c.^..w%Action: agi
ActionID: 8d534af0-dd1a-4f29-ae9d-86d145dab843
Channel: SIP/192.168.246.1-0000000b
Command: EXEC MixMonitor "/tmp/30e1d560-d014-4509-b3aa-d6651ef2ebba.wav"
CommandID: 2316fa0a-0d1c-4190-9354-174291039616
2014-10-09 14:56:06.226870 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 235
E.....@.@...................mUq6....n......
...."c..Event: SessionTimeout
Privilege: call,all
Timestamp: 1412866566.224255
SequenceNumber: 607
File: chan_sip.c
Line: 28945
Func: check_rtp_timeout
Source: RTPTimeout
Channel: SIP/192.168.246.1-0000000b
Uniqueid: 1412866505.11
2014-10-09 14:56:06.230307 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 286
E..R..@.@..................omUq6....o(.....
...."d..Event: AGIExec
Privilege: agi,all
Timestamp: 1412866566.230136
SequenceNumber: 608
File: res_agi.c
Line: 3486
Func: agi_handle_command
SubEvent: End
Channel: SIP/192.168.246.1-0000000b
CommandId: 1138078742
Command: EXEC Congestion
ResultCode: 200
Result: Unknown Result
2014-10-09 14:56:06.230590 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 274
E..F..@.@...................mUq6....o......
...."d..Event: AsyncAGI
Privilege: agi,all
Timestamp: 1412866566.230530
SequenceNumber: 609
File: res_agi.c
Line: 1360
Func: launch_asyncagi
SubEvent: Exec
Channel: SIP/192.168.246.1-0000000b
CommandID: 9d14bab5-8143-4384-8402-7685d5091ac3
Result: 200%20result%3D-1%0A
2014-10-09 14:56:06.230715 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 194
E.....@.@..<................mUq6....n......
...."d..Event: AsyncAGI
Privilege: agi,all
Timestamp: 1412866566.230665
SequenceNumber: 610
File: res_agi.c
Line: 1423
Func: launch_asyncagi
SubEvent: End
Channel: SIP/192.168.246.1-0000000b
2014-10-09 14:56:06.230909 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 250
E.....@.@..................amUq6....o......
...."d..Event: VarSet
Privilege: dialplan,all
Timestamp: 1412866566.230856
SequenceNumber: 611
File: pbx.c
Line: 11681
Func: pbx_builtin_setvar_helper
Channel: SIP/192.168.246.1-0000000b
Variable: AGISTATUS
Value: HANGUP
Uniqueid: 1412866505.11
2014-10-09 14:56:06.231396 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 224
E.....@.@..................[mUq6....n......
...."d..Event: SoftHangupRequest
Privilege: call,all
Timestamp: 1412866566.231313
SequenceNumber: 612
File: channel.c
Line: 2692
Func: ast_softhangup
Channel: SIP/192.168.246.1-0000000b
Uniqueid: 1412866505.11
Cause: 16
2014-10-09 14:56:06.231978 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 296
E..\..@.@................. ;mUq6....o2.....
...."d..Event: Newexten
Privilege: dialplan,all
Timestamp: 1412866566.231837
SequenceNumber: 613
File: pbx.c
Line: 4914
Func: pbx_extension_helper
Channel: SIP/192.168.246.1-0000000b
Context: adhearsion
Extension: h
Priority: 1
Application: AGI
AppData: agi:async
Uniqueid: 1412866505.11
2014-10-09 14:56:06.240968 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 737
E.....@.@.................!cmUq6....p......
...."d..Event: AsyncAGI
Privilege: agi,all
Timestamp: 1412866566.240852
SequenceNumber: 614
File: res_agi.c
Line: 1320
Func: launch_asyncagi
SubEvent: Start
Channel: SIP/192.168.246.1-0000000b
Env: agi_request%3A%20async%0Aagi_channel%3A%20SIP%2F192.168.246.1-0000000b%0Aagi_language%3A%20en%0Aagi_type%3A%20SIP%0Aagi_uniqueid%3A%201412866505.11%0Aagi_version%3A%2011.13.0%0Aagi_callerid%3A%20sipp%0Aagi_calleridname%3A%20sipp%0Aagi_callingpres%3A%200%0Aagi_callingani2%3A%200%0Aagi_callington%3A%200%0Aagi_callingtns%3A%200%0Aagi_dnid%3A%201%0Aagi_rdnis%3A%20unknown%0Aagi_context%3A%20adhearsion%0Aagi_extension%3A%20h%0Aagi_priority%3A%201%0Aagi_enhanced%3A%200.0%0Aagi_accountcode%3A%20%0Aagi_threadid%3A%20140621241370368%0A%0A
2014-10-09 14:56:06.241218 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 194
E.....@.@..7..............$DmUq6....n......
...."d..Event: AsyncAGI
Privilege: agi,all
Timestamp: 1412866566.241139
SequenceNumber: 615
File: res_agi.c
Line: 1423
Func: launch_asyncagi
SubEvent: End
Channel: SIP/192.168.246.1-0000000b
2014-10-09 14:56:06.241446 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 250
E.....@.@.................%.mUq6....o......
...."d..Event: VarSet
Privilege: dialplan,all
Timestamp: 1412866566.241371
SequenceNumber: 616
File: pbx.c
Line: 11681
Func: pbx_builtin_setvar_helper
Channel: SIP/192.168.246.1-0000000b
Variable: AGISTATUS
Value: HANGUP
Uniqueid: 1412866505.11
2014-10-09 14:56:06.243798 IP 192.168.246.144.5038 > 192.168.246.1.58303: tcp 341
E.....@.@.................&.mUq6....o_.....
...."d..Event: Hangup
Privilege: call,all
Timestamp: 1412866566.243703
SequenceNumber: 622
File: channel.c
Line: 2880
Func: ast_hangup
Channel: SIP/192.168.246.1-0000000b
Uniqueid: 1412866505.11
CallerIDNum: sipp
CallerIDName: sipp
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
AccountCode:
Cause: 0
Cause-txt: Unknown
Raw
asterisk_log.txt
<--- SIP read from UDP:192.168.246.1:8836 --->
INVITE sip:1@192.168.246.144:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.246.1:8836;branch=z9hG4bK-22407-2-0
From: "sipp" <sip:sipp@192.168.246.1>;tag=2
To: <sip:1@192.168.246.144:5060>
Call-ID: 2-22407@192.168.246.1
CSeq: 1 INVITE
Contact: <sip:sipp@192.168.246.1:8836;transport=UDP>
Max-Forwards: 100
User-Agent: SIPp/sippy_cup
Content-Type: application/sdp
Content-Length: 193
v=0
o=user1 53655765 2353687637 IN IP4 192.168.246.1
s=-
c=IN IP4 192.168.246.1
t=0 0
m=audio 6000 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
<------------->
--- (11 headers 9 lines) ---
Sending to 192.168.246.1:8836 (no NAT)
Sending to 192.168.246.1:8836 (no NAT)
Using INVITE request as basis request - 2-22407@192.168.246.1
No matching peer for 'sipp' from '192.168.246.1:8836'
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
Found RTP audio format 0
Found RTP audio format 101
Found audio description format PCMU for ID 0
Found audio description format telephone-event for ID 101
Capabilities: us - (ulaw|alaw|g729), peer - audio=(ulaw)/video=(nothing)/text=(nothing), combined - (ulaw)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
Peer audio RTP is at port 192.168.246.1:6000
Looking for 1 in adhearsion (domain 192.168.246.144)
list_route: hop: <sip:sipp@192.168.246.1:8836;transport=UDP>
<--- Transmitting (no NAT) to 192.168.246.1:8836 --->
SIP/2.0 100 Trying
v: SIP/2.0/UDP 192.168.246.1:8836;branch=z9hG4bK-22407-2-0;received=192.168.246.1
f: "sipp" <sip:sipp@192.168.246.1>;tag=2
t: <sip:1@192.168.246.144:5060>
i: 2-22407@192.168.246.1
CSeq: 1 INVITE
Server: Asterisk with Adhearsion
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
k: replaces, timer
m: <sip:1@192.168.246.144:5060>
l: 0
<------------>
-- Executing [1@adhearsion:1] AGI("SIP/192.168.246.1-0000000b", "agi:async") in new stack
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_request: async
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_channel: SIP/192.168.246.1-0000000b
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_language: en
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_type: SIP
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_uniqueid: 1412866505.11
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_version: 11.13.0
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_callerid: sipp
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_calleridname: sipp
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_callingpres: 0
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_callingani2: 0
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_callington: 0
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_callingtns: 0
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_dnid: 1
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_rdnis: unknown
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_context: adhearsion
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_extension: 1
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_priority: 1
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_enhanced: 0.0
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_accountcode:
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_threadid: 140621241370368
<SIP/192.168.246.1-0000000b>AGI Tx >>
-- AGI Script Executing Application: (RINGING) Options: ()
<--- Transmitting (no NAT) to 192.168.246.1:8836 --->
SIP/2.0 180 Ringing
v: SIP/2.0/UDP 192.168.246.1:8836;branch=z9hG4bK-22407-2-0;received=192.168.246.1
f: "sipp" <sip:sipp@192.168.246.1>;tag=2
t: <sip:1@192.168.246.144:5060>;tag=as1cf91649
i: 2-22407@192.168.246.1
CSeq: 1 INVITE
Server: Asterisk with Adhearsion
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
k: replaces, timer
m: <sip:1@192.168.246.144:5060>
l: 0
<------------>
<SIP/192.168.246.1-0000000b>AGI Tx >> 200 result=0
<--- Reliably Transmitting (no NAT) to 192.168.246.1:8836 --->
SIP/2.0 200 OK
v: SIP/2.0/UDP 192.168.246.1:8836;branch=z9hG4bK-22407-2-0;received=192.168.246.1
f: "sipp" <sip:sipp@192.168.246.1>;tag=2
t: <sip:1@192.168.246.144:5060>;tag=as1cf91649
i: 2-22407@192.168.246.1
CSeq: 1 INVITE
Server: Asterisk with Adhearsion
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
k: replaces, timer
m: <sip:1@192.168.246.144:5060>
c: application/sdp
l: 240
v=0
o=root 444675036 444675036 IN IP4 192.168.246.144
s=Asterisk PBX 11.13.0
c=IN IP4 192.168.246.144
t=0 0
m=audio 11292 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
<------------>
<--- SIP read from UDP:192.168.246.1:8836 --->
ACK sip:1@192.168.246.144:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.246.1:8836;branch=z9hG4bK-22407-2-5
From: "sipp" <sip:sipp@192.168.246.1>;tag=2
To: <sip:1@192.168.246.144:5060>;tag=as1cf91649
Call-ID: 2-22407@192.168.246.1
CSeq: 1 ACK
Contact: <sip:sipp@192.168.246.1:8836;transport=UDP>
Max-Forwards: 100
User-Agent: SIPp/sippy_cup
Content-Length: 0
<------------->
--- (10 headers 0 lines) ---
<------------>
<SIP/192.168.246.1-0000000b>AGI Tx >> 200 result=0
-- AGI Script Executing Application: (Congestion) Options: ()
[Oct 9 14:56:06] NOTICE[7897]: chan_sip.c:28942 check_rtp_timeout: Disconnecting call 'SIP/192.168.246.1-0000000b' for lack of RTP activity in 61 seconds
<SIP/192.168.246.1-0000000b>AGI Tx >> 200 result=-1
== Spawn extension (adhearsion, 1, 1) exited non-zero on 'SIP/192.168.246.1-0000000b'
-- Executing [h@adhearsion:1] AGI("SIP/192.168.246.1-0000000b", "agi:async") in new stack
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_request: async
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_channel: SIP/192.168.246.1-0000000b
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_language: en
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_type: SIP
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_uniqueid: 1412866505.11
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_version: 11.13.0
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_callerid: sipp
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_calleridname: sipp
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_callingpres: 0
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_callingani2: 0
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_callington: 0
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_callingtns: 0
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_dnid: 1
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_rdnis: unknown
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_context: adhearsion
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_extension: h
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_priority: 1
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_enhanced: 0.0
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_accountcode:
<SIP/192.168.246.1-0000000b>AGI Tx >> agi_threadid: 140621241370368
<SIP/192.168.246.1-0000000b>AGI Tx >>
== Spawn extension (adhearsion, h, 1) exited non-zero on 'SIP/192.168.246.1-0000000b'
Scheduling destruction of SIP dialog '2-22407@192.168.246.1' in 32000 ms (Method: ACK)
set_destination: Parsing <sip:sipp@192.168.246.1:8836;transport=UDP> for address/port to send to
set_destination: set destination to 192.168.246.1:8836
Reliably Transmitting (no NAT) to 192.168.246.1:8836:
BYE sip:sipp@192.168.246.1:8836;transport=UDP SIP/2.0
v: SIP/2.0/UDP 192.168.246.144:5060;branch=z9hG4bK1bd4ce5f
Max-Forwards: 70
f: <sip:1@192.168.246.144:5060>;tag=as1cf91649
t: "sipp" <sip:sipp@192.168.246.1>;tag=2
i: 2-22407@192.168.246.1
CSeq: 102 BYE
User-Agent: Asterisk with Adhearsion
X-Asterisk-HangupCause: Unknown
X-Asterisk-HangupCauseCode: 0
l: 0
---
<--- SIP read from UDP:192.168.246.1:8836 --->
SIP/2.0 200 OK
v: SIP/2.0/UDP 192.168.246.144:5060;branch=z9hG4bK1bd4ce5f
f: <sip:1@192.168.246.144:5060>;tag=as1cf91649
t: "sipp" <sip:sipp@192.168.246.1>;tag=2
i: 2-22407@192.168.246.1
CSeq: 102 BYE
Contact: <sip:sipp@192.168.246.1:8836;transport=UDP>
Max-Forwards: 100
User-Agent: SIPp/sippy_cup
Content-Length: 0
<------------->
--- (10 headers 0 lines) ---
SIP Response message for INCOMING dialog BYE arrived
Really destroying SIP dialog '2-22407@192.168.246.1' Method: ACK
default-ubuntu-1404*CLI>
Raw
call_controller.rb
class AsteriskRaceCondition < Adhearsion::CallController
def run
answer
execute 'MixMonitor', "/tmp/#{call.id}.wav"
end
end
Raw
sipp_test_scenario.yml
---
source: 192.168.246.1
destination: 192.168.246.144
max_concurrent: 100
calls_per_second: 10
number_of_calls: 10
steps:
- invite
- wait_for_answer
- ack_answer
- wait_for_hangup
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment