[Aug 07 10:05:05] INFO[10526]: test_case:158 __init__: Executing tests/rest_api/asterisk/logging/get_logging [Aug 07 10:05:05] DEBUG[10526]: test_conditions:143 register_observer: Registering: [Aug 07 10:05:05] DEBUG[10526]: test_conditions:143 register_observer: Registering: [Aug 07 10:05:05] DEBUG[10526]: test_conditions:143 register_observer: Registering: > [Aug 07 10:05:05] INFO[10526]: ari:317 __init__: WebSocketClientFactory(url=ws://127.0.0.1:8088/ari/events?app=testsuite&api_key=testsuite%3Atestsuite) [Aug 07 10:05:05] INFO[10526]: test_case:233 create_asterisk: Creating Asterisk instance 1 [Aug 07 10:05:05] DEBUG[10526]: test_runner:171 load_and_parse_module: Importing ari.WebSocketEventModule [Aug 07 10:05:05] INFO[10526]: test_case:368 _start_asterisk: Starting Asterisk instance 1 [Aug 07 10:05:05] DEBUG[10526]: asterisk:123 connectionMade: Asterisk 127.0.0.1 - connection made [Aug 07 10:05:06] DEBUG[10526]: asterisk:700 cli_exec: Executing ['/usr/sbin/asterisk', '-C', '/tmp/asterisk-testsuite/7349e17afe637e8a55c6bf1d28c940ae/run_1/ast1/etc/asterisk/asterisk.conf', '-rx', 'core waitfullybooted'] ... [Aug 07 10:05:08] DEBUG[10526]: asterisk:64 __cli_output_callback: Asterisk CLI 127.0.0.1 exited 0 [Aug 07 10:05:08] DEBUG[10526]: ari:344 reconnect: WebSocket attempt #1 [Aug 07 10:05:08] INFO[10526]: twisted:455 emit: Starting factory [Aug 07 10:05:08] DEBUG[10526]: ari:364 __init__: Made me a client protocol! [Aug 07 10:05:08] INFO[10526]: twisted:455 emit: [('debug', True, 'AriClientFactory'), ('debugCodePaths', True, 'AriClientFactory'), ('logOctets', True, 'AriClientFactory'), ('logFrames', True, 'AriClientFactory'), ('trackTimings', False, 'AriClientFactory'), ('allowHixie76', False, 'AriClientFactory'), ('utf8validateIncoming', True, 'AriClientFactory'), ('applyMask', True, 'AriClientFactory'), ('maxFramePayloadSize', 0, 'AriClientFactory'), ('maxMessagePayloadSize', 0, 'AriClientFactory'), ('autoFragmentSize', 0, 'AriClientFactory'), ('failByDrop', True, 'AriClientFactory'), ('echoCloseCodeReason', False, 'AriClientFactory'), ('openHandshakeTimeout', 5, 'AriClientFactory'), ('closeHandshakeTimeout', 1, 'AriClientFactory'), ('tcpNoDelay', True, 'AriClientFactory'), ('version', 18, 'AriClientFactory'), ('acceptMaskedServerFrames', False, 'AriClientFactory'), ('maskClientFrames', True, 'AriClientFactory'), ('serverConnectionDropTimeout', 1, 'AriClientFactory'), ('perMessageCompressionOffers', [], 'AriClientFactory'), ('perMessageCompressionAccept', at 0x90fcbfc>, 'AriClientFactory')] [Aug 07 10:05:08] INFO[10526]: twisted:455 emit: connection to 127.0.0.1:8088 established [Aug 07 10:05:08] INFO[10526]: twisted:455 emit: GET /ari/events?app=testsuite&api_key=testsuite%3Atestsuite HTTP/1.1 User-Agent: AutobahnPython/0.6.4 Host: 127.0.0.1:8088 Upgrade: WebSocket Connection: Upgrade Pragma: no-cache Cache-Control: no-cache Sec-WebSocket-Key: IhQr+FZq0Zp7zu0DwqJFIg== Sec-WebSocket-Protocol: ari Sec-WebSocket-Version: 13 [Aug 07 10:05:08] INFO[10526]: twisted:455 emit: TX Octets to 127.0.0.1:8088 : sync = False, octets = 474554202f6172692f6576656e74733f6170703d746573747375697465266170695f6b65793d74657374737569746525334174657374737569746520485454502f312e310d0a557365722d4167656e743a204175746f6261686e507974686f6e2f302e362e340d0a486f73743a203132372e302e302e313a383038380d0a557067726164653a20576562536f636b65740d0a436f6e6e656374696f6e3a20557067726164650d0a507261676d613a206e6f2d63616368650d0a43616368652d436f6e74726f6c3a206e6f2d63616368650d0a5365632d576562536f636b65742d4b65793a20496851722b465a71305a70377a75304477714a4649673d3d0d0a5365632d576562536f636b65742d50726f746f636f6c3a206172690d0a5365632d576562536f636b65742d56657273696f6e3a2031330d0a0d0a [Aug 07 10:05:08] INFO[10526]: twisted:455 emit: RX Octets from 127.0.0.1:8088 : octets = 485454502f312e312031303120537769746368696e672050726f746f636f6c730d0a557067726164653a20576562536f636b65740d0a436f6e6e656374696f6e3a20557067726164650d0a5365632d576562536f636b65742d4163636570743a20446b443631506430544d7a4161752b4b5533354a4e417142535a6f3d0d0a5365632d576562536f636b65742d50726f746f636f6c3a206172690d0a0d0a [Aug 07 10:05:08] INFO[10526]: twisted:455 emit: received HTTP response: HTTP/1.1 101 Switching Protocols Upgrade: WebSocket Connection: Upgrade Sec-WebSocket-Accept: DkD61Pd0TMzAau+KU35JNAqBSZo= Sec-WebSocket-Protocol: ari [Aug 07 10:05:08] INFO[10526]: twisted:455 emit: received HTTP status line in opening handshake : HTTP/1.1 101 Switching Protocols [Aug 07 10:05:08] INFO[10526]: twisted:455 emit: received HTTP headers in opening handshake : {'connection': u'Upgrade', 'upgrade': u'WebSocket', 'sec-websocket-protocol': u'ari', 'sec-websocket-accept': u'DkD61Pd0TMzAau+KU35JNAqBSZo='} [Aug 07 10:05:08] DEBUG[10526]: ari:370 onOpen: WebSocket Open [Aug 07 10:05:08] INFO[10526]: test_case:265 create_ami_factory: Creating AMIFactory 1 [Aug 07 10:05:08] INFO[10526]: twisted:455 emit: Starting factory [Aug 07 10:05:08] INFO[10526]: AMI:173 connectionMade: Connection Made [Aug 07 10:05:08] DEBUG[10526]: AMI:343 sendMessage: MSG OUT: {'action': 'login', 'username': 'user', 'secret': 'mysecret', 'actionid': 'asterisk-testsuite-32-centos-2.digium.internal-151999020-1'} [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Asterisk Call Manager/2.8.0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Response: Success' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ActionID: asterisk-testsuite-32-centos-2.digium.internal-151999020-1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Message: Authentication accepted' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:08] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:08] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'message': 'Authentication accepted', 'response': 'Success', 'actionid': 'asterisk-testsuite-32-centos-2.digium.internal-151999020-1'} [Aug 07 10:05:08] INFO[10526]: AMI:191 onComplete: Login Complete: {'message': 'Authentication accepted', 'response': 'Success', 'actionid': 'asterisk-testsuite-32-centos-2.digium.internal-151999020-1'} [Aug 07 10:05:08] INFO[10526]: test_case:502 _ami_connect: AMI Connect instance 1 [Aug 07 10:05:08] DEBUG[10526]: AMI:120 registerEvent: Registering function > to handle events of type 'Newchannel' [Aug 07 10:05:08] DEBUG[10526]: AMI:120 registerEvent: Registering function > to handle events of type 'Hangup' [Aug 07 10:05:08] INFO[10526]: ari:231 _spawn_channel: Creating channel Local/s@default [Aug 07 10:05:08] DEBUG[10526]: AMI:334 sendMessage: MSG OUT: [('action', 'originate'), ('channel', 'Local/s@default'), ('application', 'Echo'), ('async', 'False'), ['actionid', 'asterisk-testsuite-32-centos-2.digium.internal-151999020-2']] [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: FullyBooted' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: system,all' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Status: Fully Booted' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:08] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:08] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'privilege': 'system,all', 'status': 'Fully Booted', 'event': 'FullyBooted'} [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Response: Success' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ActionID: asterisk-testsuite-32-centos-2.digium.internal-151999020-2' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Message: Originate successfully queued' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:08] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:08] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'message': 'Originate successfully queued', 'response': 'Success', 'actionid': 'asterisk-testsuite-32-centos-2.digium.internal-151999020-2'} [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: Newchannel' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelState: 0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelStateDesc: Down' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDNum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDName: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineNum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineName: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Language: en' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AccountCode: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Priority: 1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Uniqueid: 1438959908.0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Linkedid: 1438959908.0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:08] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:08] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'connectedlinenum': '', 'linkedid': '1438959908.0', 'uniqueid': '1438959908.0', 'language': 'en', 'accountcode': '', 'channelstate': '0', 'exten': 's', 'calleridnum': '', 'priority': '1', 'connectedlinename': '', 'context': 'default', 'calleridname': '', 'privilege': 'call,all', 'event': 'Newchannel', 'channel': 'Local/s@default-00000000;1', 'channelstatedesc': 'Down'} [Aug 07 10:05:08] DEBUG[10526]: ari:187 _new_channel_handler: Tracking channel Local/s@default-00000000;1 [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: Newchannel' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;2' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelState: 4' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelStateDesc: Ring' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDNum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDName: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineNum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineName: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Language: en' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AccountCode: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Priority: 1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Uniqueid: 1438959908.1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Linkedid: 1438959908.0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:08] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:08] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'connectedlinenum': '', 'linkedid': '1438959908.0', 'uniqueid': '1438959908.1', 'language': 'en', 'accountcode': '', 'channelstate': '4', 'exten': 's', 'calleridnum': '', 'priority': '1', 'connectedlinename': '', 'context': 'default', 'calleridname': '', 'privilege': 'call,all', 'event': 'Newchannel', 'channel': 'Local/s@default-00000000;2', 'channelstatedesc': 'Ring'} [Aug 07 10:05:08] DEBUG[10526]: ari:187 _new_channel_handler: Tracking channel Local/s@default-00000000;2 [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: Newexten' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelState: 0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelStateDesc: Down' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDNum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDName: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineNum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineName: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Language: en' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AccountCode: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Priority: 1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Uniqueid: 1438959908.0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Linkedid: 1438959908.0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Extension: s' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Application: AppDial2' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AppData: (Outgoing Line)' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:08] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:08] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'connectedlinenum': '', 'linkedid': '1438959908.0', 'uniqueid': '1438959908.0', 'language': 'en', 'accountcode': '', 'channelstate': '0', 'exten': 's', 'calleridnum': '', 'priority': '1', 'extension': 's', 'connectedlinename': '', 'context': 'default', 'calleridname': '', 'privilege': 'call,all', 'appdata': '(Outgoing Line)', 'application': 'AppDial2', 'event': 'Newexten', 'channel': 'Local/s@default-00000000;1', 'channelstatedesc': 'Down'} [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: LocalBridge' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalOneChannel: Local/s@default-00000000;1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalOneChannelState: 0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalOneChannelStateDesc: Down' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalOneCallerIDNum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalOneCallerIDName: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalOneConnectedLineNum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalOneConnectedLineName: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalOneLanguage: en' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalOneAccountCode: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalOneContext: default' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalOneExten: s' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalOnePriority: 1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalOneUniqueid: 1438959908.0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalOneLinkedid: 1438959908.0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalTwoChannel: Local/s@default-00000000;2' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalTwoChannelState: 4' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalTwoChannelStateDesc: Ring' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalTwoCallerIDNum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalTwoCallerIDName: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalTwoConnectedLineNum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalTwoConnectedLineName: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalTwoLanguage: en' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalTwoAccountCode: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalTwoContext: default' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalTwoExten: s' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalTwoPriority: 1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalTwoUniqueid: 1438959908.1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalTwoLinkedid: 1438959908.0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LocalOptimization: Yes' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:08] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:08] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'localtwoconnectedlinename': '', 'localonelanguage': 'en', 'localonechannelstatedesc': 'Down', 'exten': 's', 'localtwoaccountcode': '', 'localtwocalleridname': '', 'event': 'LocalBridge', 'localtwoexten': 's', 'localtwolanguage': 'en', 'localtwopriority': '1', 'localoneaccountcode': '', 'localoneconnectedlinename': '', 'localonecontext': 'default', 'localonecalleridnum': '', 'localtwouniqueid': '1438959908.1', 'localoptimization': 'Yes', 'localtwochannelstatedesc': 'Ring', 'localtwocontext': 'default', 'localoneexten': 's', 'privilege': 'call,all', 'localonelinkedid': '1438959908.0', 'localonechannel': 'Local/s@default-00000000;1', 'localtwochannel': 'Local/s@default-00000000;2', 'localonecalleridname': '', 'localtwocalleridnum': '', 'localonepriority': '1', 'localtwochannelstate': '4', 'localoneconnectedlinenum': '', 'localonechannelstate': '0', 'context': 'default', 'localtwolinkedid': '1438959908.0', 'localtwoconnectedlinenum': '', 'localoneuniqueid': '1438959908.0'} [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: DialBegin' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestChannel: Local/s@default-00000000;1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestChannelState: 0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestChannelStateDesc: Down' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestCallerIDNum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestCallerIDName: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestConnectedLineNum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestConnectedLineName: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestLanguage: en' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestAccountCode: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestContext: default' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestExten: s' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestPriority: 1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestUniqueid: 1438959908.0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestLinkedid: 1438959908.0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DialString: s@default' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:08] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:08] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'destlanguage': 'en', 'destcontext': 'default', 'destconnectedlinenum': '', 'destconnectedlinename': '', 'destlinkedid': '1438959908.0', 'destuniqueid': '1438959908.0', 'event': 'DialBegin', 'destchannelstate': '0', 'dialstring': 's@default', 'destexten': 's', 'destchannel': 'Local/s@default-00000000;1', 'destchannelstatedesc': 'Down', 'privilege': 'call,all', 'destaccountcode': '', 'destcalleridnum': '', 'destpriority': '1', 'destcalleridname': ''} [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: TestEvent' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: reporting,all' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Type: StateChange' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'State: CallIDChange' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AppFile: channel_internal_api.c' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AppFunction: ast_channel_callid_set' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AppLine: 941' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'State: CallIDChange' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;2' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallID: [C-00000001]' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'PriorCallID: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:08] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:08] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'appfile': 'channel_internal_api.c', 'priorcallid': '', 'appline': '941', 'appfunction': 'ast_channel_callid_set', 'state': 'CallIDChange', 'callid': '[C-00000001]', 'privilege': 'reporting,all', 'type': 'StateChange', 'event': 'TestEvent', 'channel': 'Local/s@default-00000000;2'} [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: Newexten' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;2' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelState: 4' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelStateDesc: Ring' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDNum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDName: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineNum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineName: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Language: en' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AccountCode: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Priority: 1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Uniqueid: 1438959908.1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Linkedid: 1438959908.0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Extension: s' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Application: NoOp' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AppData: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:08] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:08] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'connectedlinenum': '', 'linkedid': '1438959908.0', 'uniqueid': '1438959908.1', 'language': 'en', 'accountcode': '', 'channelstate': '4', 'exten': 's', 'calleridnum': '', 'priority': '1', 'extension': 's', 'connectedlinename': '', 'context': 'default', 'calleridname': '', 'privilege': 'call,all', 'appdata': '', 'application': 'NoOp', 'event': 'Newexten', 'channel': 'Local/s@default-00000000;2', 'channelstatedesc': 'Ring'} [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: Newexten' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;2' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelState: 4' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelStateDesc: Ring' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDNum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDName: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineNum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineName: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Language: en' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AccountCode: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Priority: 2' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Uniqueid: 1438959908.1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Linkedid: 1438959908.0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Extension: s' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Application: Answer' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AppData: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:08] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:08] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'connectedlinenum': '', 'linkedid': '1438959908.0', 'uniqueid': '1438959908.1', 'language': 'en', 'accountcode': '', 'channelstate': '4', 'exten': 's', 'calleridnum': '', 'priority': '2', 'extension': 's', 'connectedlinename': '', 'context': 'default', 'calleridname': '', 'privilege': 'call,all', 'appdata': '', 'application': 'Answer', 'event': 'Newexten', 'channel': 'Local/s@default-00000000;2', 'channelstatedesc': 'Ring'} [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: Newstate' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;2' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelState: 6' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelStateDesc: Up' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDNum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDName: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineNum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineName: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Language: en' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AccountCode: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Priority: 2' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Uniqueid: 1438959908.1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Linkedid: 1438959908.0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:08] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:08] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'connectedlinenum': '', 'linkedid': '1438959908.0', 'uniqueid': '1438959908.1', 'language': 'en', 'accountcode': '', 'channelstate': '6', 'exten': 's', 'calleridnum': '', 'priority': '2', 'connectedlinename': '', 'context': 'default', 'calleridname': '', 'privilege': 'call,all', 'event': 'Newstate', 'channel': 'Local/s@default-00000000;2', 'channelstatedesc': 'Up'} [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: Newstate' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelState: 6' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelStateDesc: Up' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDNum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDName: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineNum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineName: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Language: en' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AccountCode: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Priority: 1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Uniqueid: 1438959908.0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Linkedid: 1438959908.0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:08] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:08] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'connectedlinenum': '', 'linkedid': '1438959908.0', 'uniqueid': '1438959908.0', 'language': 'en', 'accountcode': '', 'channelstate': '6', 'exten': 's', 'calleridnum': '', 'priority': '1', 'connectedlinename': '', 'context': 'default', 'calleridname': '', 'privilege': 'call,all', 'event': 'Newstate', 'channel': 'Local/s@default-00000000;1', 'channelstatedesc': 'Up'} [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: DialEnd' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestChannel: Local/s@default-00000000;1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestChannelState: 6' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestChannelStateDesc: Up' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestCallerIDNum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestCallerIDName: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestConnectedLineNum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestConnectedLineName: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestLanguage: en' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestAccountCode: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestContext: default' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestExten: s' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestPriority: 1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestUniqueid: 1438959908.0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DestLinkedid: 1438959908.0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'DialStatus: ANSWER' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:08] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:08] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'destlanguage': 'en', 'destcontext': 'default', 'destconnectedlinenum': '', 'destconnectedlinename': '', 'destlinkedid': '1438959908.0', 'destuniqueid': '1438959908.0', 'event': 'DialEnd', 'destchannelstate': '6', 'destexten': 's', 'dialstatus': 'ANSWER', 'destchannel': 'Local/s@default-00000000;1', 'destchannelstatedesc': 'Up', 'privilege': 'call,all', 'destaccountcode': '', 'destcalleridnum': '', 'destpriority': '1', 'destcalleridname': ''} [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: DeviceStateChange' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Device: Local/s@default' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'State: INUSE' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:08] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:08] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'privilege': 'call,all', 'device': 'Local/s@default', 'state': 'INUSE', 'event': 'DeviceStateChange'} [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: CEL' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'EventName: CHAN_START' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AccountCode: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDnum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDname: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDani: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDrdnis: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDdnid: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Application: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AppData: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'EventTime: 2015-08-07 10:05:08' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AMAFlags: DOCUMENTATION' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'UniqueID: 1438959908.0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LinkedID: 1438959908.0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Userfield: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Peer: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'PeerAccount: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Extra: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:08] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:08] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'linkedid': '1438959908.0', 'appdata': '', 'extra': '', 'exten': 's', 'amaflags': 'DOCUMENTATION', 'calleridrdnis': '', 'event': 'CEL', 'calleriddnid': '', 'calleridnum': '', 'application': '', 'calleridname': '', 'privilege': 'call,all', 'channel': 'Local/s@default-00000000;1', 'eventtime': '2015-08-07 10:05:08', 'eventname': 'CHAN_START', 'peeraccount': '', 'uniqueid': '1438959908.0', 'peer': '', 'accountcode': '', 'userfield': '', 'calleridani': '', 'context': 'default'} [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: DeviceStateChange' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Device: Local/s@default' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'State: INUSE' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:08] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:08] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'privilege': 'call,all', 'device': 'Local/s@default', 'state': 'INUSE', 'event': 'DeviceStateChange'} [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: CEL' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'EventName: CHAN_START' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AccountCode: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDnum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDname: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDani: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDrdnis: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDdnid: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;2' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Application: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AppData: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'EventTime: 2015-08-07 10:05:08' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AMAFlags: DOCUMENTATION' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'UniqueID: 1438959908.1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LinkedID: 1438959908.0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Userfield: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Peer: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'PeerAccount: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Extra: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:08] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:08] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'linkedid': '1438959908.0', 'appdata': '', 'extra': '', 'exten': 's', 'amaflags': 'DOCUMENTATION', 'calleridrdnis': '', 'event': 'CEL', 'calleriddnid': '', 'calleridnum': '', 'application': '', 'calleridname': '', 'privilege': 'call,all', 'channel': 'Local/s@default-00000000;2', 'eventtime': '2015-08-07 10:05:08', 'eventname': 'CHAN_START', 'peeraccount': '', 'uniqueid': '1438959908.1', 'peer': '', 'accountcode': '', 'userfield': '', 'calleridani': '', 'context': 'default'} [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: CEL' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'EventName: ANSWER' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AccountCode: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDnum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDname: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDani: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDrdnis: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDdnid: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;2' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Application: Answer' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AppData: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'EventTime: 2015-08-07 10:05:08' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AMAFlags: DOCUMENTATION' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'UniqueID: 1438959908.1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LinkedID: 1438959908.0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Userfield: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Peer: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'PeerAccount: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Extra: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:08] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:08] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'linkedid': '1438959908.0', 'appdata': '', 'extra': '', 'exten': 's', 'amaflags': 'DOCUMENTATION', 'calleridrdnis': '', 'event': 'CEL', 'calleriddnid': '', 'calleridnum': '', 'application': 'Answer', 'calleridname': '', 'privilege': 'call,all', 'channel': 'Local/s@default-00000000;2', 'eventtime': '2015-08-07 10:05:08', 'eventname': 'ANSWER', 'peeraccount': '', 'uniqueid': '1438959908.1', 'peer': '', 'accountcode': '', 'userfield': '', 'calleridani': '', 'context': 'default'} [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: CEL' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'EventName: ANSWER' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AccountCode: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDnum: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDname: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDani: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDrdnis: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDdnid: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;1' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Application: AppDial2' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AppData: (Outgoing Line)' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'EventTime: 2015-08-07 10:05:08' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AMAFlags: DOCUMENTATION' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'UniqueID: 1438959908.0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LinkedID: 1438959908.0' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Userfield: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Peer: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'PeerAccount: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Extra: ' [Aug 07 10:05:08] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:08] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:08] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'linkedid': '1438959908.0', 'appdata': '(Outgoing Line)', 'extra': '', 'exten': 's', 'amaflags': 'DOCUMENTATION', 'calleridrdnis': '', 'event': 'CEL', 'calleriddnid': '', 'calleridnum': '', 'application': 'AppDial2', 'calleridname': '', 'privilege': 'call,all', 'channel': 'Local/s@default-00000000;1', 'eventtime': '2015-08-07 10:05:08', 'eventname': 'ANSWER', 'peeraccount': '', 'uniqueid': '1438959908.0', 'peer': '', 'accountcode': '', 'userfield': '', 'calleridani': '', 'context': 'default'} [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: Newexten' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;2' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelState: 6' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelStateDesc: Up' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDNum: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDName: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineNum: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineName: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Language: en' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AccountCode: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Priority: 3' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Uniqueid: 1438959908.1' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Linkedid: 1438959908.0' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Extension: s' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Application: Stasis' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AppData: testsuite' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:09] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:09] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'connectedlinenum': '', 'linkedid': '1438959908.0', 'uniqueid': '1438959908.1', 'language': 'en', 'accountcode': '', 'channelstate': '6', 'exten': 's', 'calleridnum': '', 'priority': '3', 'extension': 's', 'connectedlinename': '', 'context': 'default', 'calleridname': '', 'privilege': 'call,all', 'appdata': 'testsuite', 'application': 'Stasis', 'event': 'Newexten', 'channel': 'Local/s@default-00000000;2', 'channelstatedesc': 'Up'} [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: VarSet' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: dialplan,all' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;2' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelState: 6' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelStateDesc: Up' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDNum: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDName: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineNum: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineName: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Language: en' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AccountCode: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Priority: 3' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Uniqueid: 1438959908.1' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Linkedid: 1438959908.0' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Variable: STASISSTATUS' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Value: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:09] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:09] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'connectedlinenum': '', 'linkedid': '1438959908.0', 'uniqueid': '1438959908.1', 'language': 'en', 'accountcode': '', 'channelstate': '6', 'exten': 's', 'calleridnum': '', 'value': '', 'priority': '3', 'variable': 'STASISSTATUS', 'connectedlinename': '', 'context': 'default', 'calleridname': '', 'privilege': 'dialplan,all', 'event': 'VarSet', 'channel': 'Local/s@default-00000000;2', 'channelstatedesc': 'Up'} [Aug 07 10:05:09] INFO[10526]: twisted:455 emit: RX Octets from 127.0.0.1:8088 : octets = 817e02197b0a20202274797065223a20225374617369735374617274222c0a20202274696d657374616d70223a2022323031352d30382d30375431303a30353a30392e3130362d30353030222c0a20202261726773223a205b5d2c0a2020226368616e6e656c223a207b0a20202020226964223a2022313433383935393930382e31222c0a20202020226e616d65223a20224c6f63616c2f734064656661756c742d30303030303030303b32222c0a20202020227374617465223a20225570222c0a202020202263616c6c6572223a207b0a202020202020226e616d65223a2022222c0a202020202020226e756d626572223a2022220a202020207d2c0a2020202022636f6e6e6563746564223a207b0a202020202020226e616d65223a2022222c0a202020202020226e756d626572223a2022220a202020207d2c0a20202020226163636f756e74636f6465223a2022222c0a20202020226469616c706c616e223a207b0a20202020202022636f6e74657874223a202264656661756c74222c0a20202020202022657874656e223a202273222c0a202020202020227072696f72697479223a20330a202020207d2c0a20202020226372656174696f6e74696d65223a2022323031352d30382d30375431303a30353a30382e3630312d30353030222c0a20202020226c616e6775616765223a2022656e220a20207d2c0a2020226170706c69636174696f6e223a2022746573747375697465220a7d [Aug 07 10:05:09] INFO[10526]: twisted:455 emit: RX Frame from 127.0.0.1:8088 : fin = True, rsv = 0, opcode = 1, mask = -, length = 537, payload = { "type": "StasisStart", "timestamp": "2015-08-07T10:05:09.106-0500", "args": [], "channel": { "id": "1438959908.1", "name": "Local/s@default-00000000;2", "state": "Up", "caller": { "name": "", "number": "" }, "connected": { "name": "", "number": "" }, "accountcode": "", "dialplan": { "context": "default", "exten": "s", "priority": 3 }, "creationtime": "2015-08-07T10:05:08.601-0500", "language": "en" }, "application": "testsuite" } [Aug 07 10:05:09] INFO[10526]: twisted:455 emit: Traffic statistics: {"incomingWebSocketFrames": 1, "outgoingWebSocketFrames": 0, "outgoingOctetsWireLevel": 0, "incomingOctetsAppLevel": 537, "incomingWebSocketMessages": 0, "outgoingWebSocketOverhead": null, "incomingOctetsWebSocketLevel": 537, "outgoingCompressionRatio": null, "outgoingWebSocketMessages": 0, "incomingOctetsWireLevel": 541, "incomingWebSocketOverhead": 0.0074487895716945996, "outgoingOctetsWebSocketLevel": 0, "outgoingOctetsAppLevel": 0, "incomingCompressionRatio": 1.0} [Aug 07 10:05:09] DEBUG[10526]: ari:383 onMessage: rxed: { "type": "StasisStart", "timestamp": "2015-08-07T10:05:09.106-0500", "args": [], "channel": { "id": "1438959908.1", "name": "Local/s@default-00000000;2", "state": "Up", "caller": { "name": "", "number": "" }, "connected": { "name": "", "number": "" }, "accountcode": "", "dialplan": { "context": "default", "exten": "s", "priority": 3 }, "creationtime": "2015-08-07T10:05:08.601-0500", "language": "en" }, "application": "testsuite" } [Aug 07 10:05:09] DEBUG[10526]: ari:292 on_event: Received event: u'StasisStart' [Aug 07 10:05:09] DEBUG[10526]: test_suite_utils:87 all_match: Pattern: {'application': 'testsuite', 'args': [], 'type': 'StasisStart'}, message {u'timestamp': u'2015-08-07T10:05:09.106-0500', u'args': [], u'type': u'StasisStart', u'channel': {u'accountcode': u'', u'name': u'Local/s@default-00000000;2', u'language': u'en', u'caller': {u'name': u'', u'number': u''}, u'creationtime': u'2015-08-07T10:05:08.601-0500', u'state': u'Up', u'connected': {u'name': u'', u'number': u''}, u'dialplan': {u'priority': 3, u'exten': u's', u'context': u'default'}, u'id': u'1438959908.1'}, u'application': u'testsuite'} [Aug 07 10:05:09] DEBUG[10526]: test_suite_utils:87 all_match: Pattern: testsuite, message testsuite [Aug 07 10:05:09] DEBUG[10526]: test_suite_utils:87 all_match: Pattern: [], message [] [Aug 07 10:05:09] DEBUG[10526]: test_suite_utils:87 all_match: Pattern: StasisStart, message StasisStart [Aug 07 10:05:09] INFO[10526]: requests.packages.urllib3.connectionpool:203 _new_conn: Starting new HTTP connection (1): 127.0.0.1 [Aug 07 10:05:09] DEBUG[10526]: requests.packages.urllib3.connectionpool:383 _make_request: "GET /ari/asterisk/logging HTTP/1.1" 405 33 [Aug 07 10:05:09] DEBUG[10526]: test_suite_utils:87 all_match: Pattern: [{'status': 'Enabled', 'configuration': 'DEBUG NOTICE WARNING ERROR VERBOSE DTMF FAX ', 'type': 'File', 'channel': '.*/ast1/var/log/asterisk/full'}, {'status': 'Enabled', 'configuration': 'NOTICE WARNING ERROR ', 'type': 'File', 'channel': '.*/ast1/var/log/asterisk/messages'}], message {u'message': u'Invalid method'} [Aug 07 10:05:09] INFO[10526]: requests.packages.urllib3.connectionpool:203 _new_conn: Starting new HTTP connection (1): 127.0.0.1 [Aug 07 10:05:09] DEBUG[10526]: requests.packages.urllib3.connectionpool:383 _make_request: "DELETE /ari/channels/1438959908.1 HTTP/1.1" 204 0 [Aug 07 10:05:09] INFO[10526]: ari:560 send: sent delete channels/{channel.id} {} response 204 [Aug 07 10:05:09] DEBUG[10526]: test_suite_utils:87 all_match: Pattern: {'error': '^InvalidMessage$'}, message {u'timestamp': u'2015-08-07T10:05:09.106-0500', u'args': [], u'type': u'StasisStart', u'channel': {u'accountcode': u'', u'name': u'Local/s@default-00000000;2', u'language': u'en', u'caller': {u'name': u'', u'number': u''}, u'creationtime': u'2015-08-07T10:05:08.601-0500', u'state': u'Up', u'connected': {u'name': u'', u'number': u''}, u'dialplan': {u'priority': 3, u'exten': u's', u'context': u'default'}, u'id': u'1438959908.1'}, u'application': u'testsuite'} [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: SoftHangupRequest' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;2' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelState: 6' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelStateDesc: Up' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDNum: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDName: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineNum: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineName: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Language: en' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AccountCode: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Priority: 3' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Uniqueid: 1438959908.1' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Linkedid: 1438959908.0' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Cause: 32' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:09] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:09] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'connectedlinenum': '', 'linkedid': '1438959908.0', 'uniqueid': '1438959908.1', 'language': 'en', 'accountcode': '', 'channelstate': '6', 'exten': 's', 'calleridnum': '', 'priority': '3', 'connectedlinename': '', 'context': 'default', 'calleridname': '', 'privilege': 'call,all', 'cause': '32', 'event': 'SoftHangupRequest', 'channel': 'Local/s@default-00000000;2', 'channelstatedesc': 'Up'} [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: VarSet' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: dialplan,all' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;2' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelState: 6' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelStateDesc: Up' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDNum: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDName: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineNum: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineName: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Language: en' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AccountCode: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Priority: 3' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Uniqueid: 1438959908.1' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Linkedid: 1438959908.0' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Variable: STASISSTATUS' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Value: SUCCESS' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:09] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:09] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'connectedlinenum': '', 'linkedid': '1438959908.0', 'uniqueid': '1438959908.1', 'language': 'en', 'accountcode': '', 'channelstate': '6', 'exten': 's', 'calleridnum': '', 'value': 'SUCCESS', 'priority': '3', 'variable': 'STASISSTATUS', 'connectedlinename': '', 'context': 'default', 'calleridname': '', 'privilege': 'dialplan,all', 'event': 'VarSet', 'channel': 'Local/s@default-00000000;2', 'channelstatedesc': 'Up'} [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: SoftHangupRequest' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;2' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelState: 6' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelStateDesc: Up' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDNum: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDName: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineNum: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineName: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Language: en' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AccountCode: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Priority: 3' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Uniqueid: 1438959908.1' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Linkedid: 1438959908.0' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Cause: 16' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:09] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:09] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'connectedlinenum': '', 'linkedid': '1438959908.0', 'uniqueid': '1438959908.1', 'language': 'en', 'accountcode': '', 'channelstate': '6', 'exten': 's', 'calleridnum': '', 'priority': '3', 'connectedlinename': '', 'context': 'default', 'calleridname': '', 'privilege': 'call,all', 'cause': '16', 'event': 'SoftHangupRequest', 'channel': 'Local/s@default-00000000;2', 'channelstatedesc': 'Up'} [Aug 07 10:05:09] INFO[10526]: twisted:455 emit: RX Octets from 127.0.0.1:8088 : octets = 817e02337b0a202022736f6674223a20747275652c0a2020226361757365223a2033322c0a20202274797065223a20224368616e6e656c48616e67757052657175657374222c0a20202274696d657374616d70223a2022323031352d30382d30375431303a30353a30392e3133382d30353030222c0a2020226368616e6e656c223a207b0a20202020226964223a2022313433383935393930382e31222c0a20202020226e616d65223a20224c6f63616c2f734064656661756c742d30303030303030303b32222c0a20202020227374617465223a20225570222c0a202020202263616c6c6572223a207b0a202020202020226e616d65223a2022222c0a202020202020226e756d626572223a2022220a202020207d2c0a2020202022636f6e6e6563746564223a207b0a202020202020226e616d65223a2022222c0a202020202020226e756d626572223a2022220a202020207d2c0a20202020226163636f756e74636f6465223a2022222c0a20202020226469616c706c616e223a207b0a20202020202022636f6e74657874223a202264656661756c74222c0a20202020202022657874656e223a202273222c0a202020202020227072696f72697479223a20330a202020207d2c0a20202020226372656174696f6e74696d65223a2022323031352d30382d30375431303a30353a30382e3630312d30353030222c0a20202020226c616e6775616765223a2022656e220a20207d2c0a2020226170706c69636174696f6e223a2022746573747375697465220a7d817e02097b0a20202274797065223a2022537461736973456e64222c0a20202274696d657374616d70223a2022323031352d30382d30375431303a30353a30392e3133392d30353030222c0a2020226368616e6e656c223a207b0a20202020226964223a2022313433383935393930382e31222c0a20202020226e616d65223a20224c6f63616c2f734064656661756c742d30303030303030303b32222c0a20202020227374617465223a20225570222c0a202020202263616c6c6572223a207b0a202020202020226e616d65223a2022222c0a202020202020226e756d626572223a2022220a202020207d2c0a2020202022636f6e6e6563746564223a207b0a202020202020226e616d65223a2022222c0a202020202020226e756d626572223a2022220a202020207d2c0a20202020226163636f756e74636f6465223a2022222c0a20202020226469616c706c616e223a207b0a20202020202022636f6e74657874223a202264656661756c74222c0a20202020202022657874656e223a202273222c0a202020202020227072696f72697479223a20330a202020207d2c0a20202020226372656174696f6e74696d65223a2022323031352d30382d30375431303a30353a30382e3630312d30353030222c0a20202020226c616e6775616765223a2022656e220a20207d2c0a2020226170706c69636174696f6e223a2022746573747375697465220a7d [Aug 07 10:05:09] INFO[10526]: twisted:455 emit: RX Frame from 127.0.0.1:8088 : fin = True, rsv = 0, opcode = 1, mask = -, length = 563, payload = { "soft": true, "cause": 32, "type": "ChannelHangupRequest", "timestamp": "2015-08-07T10:05:09.138-0500", "channel": { "id": "1438959908.1", "name": "Local/s@default-00000000;2", "state": "Up", "caller": { "name": "", "number": "" }, "connected": { "name": "", "number": "" }, "accountcode": "", "dialplan": { "context": "default", "exten": "s", "priority": 3 }, "creationtime": "2015-08-07T10:05:08.601-0500", "language": "en" }, "application": "testsuite" } [Aug 07 10:05:09] INFO[10526]: twisted:455 emit: Traffic statistics: {"incomingWebSocketFrames": 2, "outgoingWebSocketFrames": 0, "outgoingOctetsWireLevel": 0, "incomingOctetsAppLevel": 1100, "incomingWebSocketMessages": 1, "outgoingWebSocketOverhead": null, "incomingOctetsWebSocketLevel": 1100, "outgoingCompressionRatio": null, "outgoingWebSocketMessages": 0, "incomingOctetsWireLevel": 1633, "incomingWebSocketOverhead": 0.48454545454545456, "outgoingOctetsWebSocketLevel": 0, "outgoingOctetsAppLevel": 0, "incomingCompressionRatio": 1.0} [Aug 07 10:05:09] DEBUG[10526]: ari:383 onMessage: rxed: { "soft": true, "cause": 32, "type": "ChannelHangupRequest", "timestamp": "2015-08-07T10:05:09.138-0500", "channel": { "id": "1438959908.1", "name": "Local/s@default-00000000;2", "state": "Up", "caller": { "name": "", "number": "" }, "connected": { "name": "", "number": "" }, "accountcode": "", "dialplan": { "context": "default", "exten": "s", "priority": 3 }, "creationtime": "2015-08-07T10:05:08.601-0500", "language": "en" }, "application": "testsuite" } [Aug 07 10:05:09] DEBUG[10526]: ari:292 on_event: Received event: u'ChannelHangupRequest' [Aug 07 10:05:09] DEBUG[10526]: test_suite_utils:87 all_match: Pattern: {'application': 'testsuite', 'args': [], 'type': 'StasisStart'}, message {u'type': u'ChannelHangupRequest', u'soft': True, u'application': u'testsuite', u'timestamp': u'2015-08-07T10:05:09.138-0500', u'cause': 32, u'channel': {u'accountcode': u'', u'name': u'Local/s@default-00000000;2', u'language': u'en', u'caller': {u'name': u'', u'number': u''}, u'creationtime': u'2015-08-07T10:05:08.601-0500', u'state': u'Up', u'connected': {u'name': u'', u'number': u''}, u'dialplan': {u'priority': 3, u'exten': u's', u'context': u'default'}, u'id': u'1438959908.1'}} [Aug 07 10:05:09] DEBUG[10526]: test_suite_utils:87 all_match: Pattern: testsuite, message testsuite [Aug 07 10:05:09] DEBUG[10526]: test_suite_utils:87 all_match: Pattern: {'error': '^InvalidMessage$'}, message {u'type': u'ChannelHangupRequest', u'soft': True, u'application': u'testsuite', u'timestamp': u'2015-08-07T10:05:09.138-0500', u'cause': 32, u'channel': {u'accountcode': u'', u'name': u'Local/s@default-00000000;2', u'language': u'en', u'caller': {u'name': u'', u'number': u''}, u'creationtime': u'2015-08-07T10:05:08.601-0500', u'state': u'Up', u'connected': {u'name': u'', u'number': u''}, u'dialplan': {u'priority': 3, u'exten': u's', u'context': u'default'}, u'id': u'1438959908.1'}} [Aug 07 10:05:09] INFO[10526]: ari:298 on_event: Event had no matcher: {u'type': u'ChannelHangupRequest', u'soft': True, u'application': u'testsuite', u'timestamp': u'2015-08-07T10:05:09.138-0500', u'cause': 32, u'channel': {u'accountcode': u'', u'name': u'Local/s@default-00000000;2', u'language': u'en', u'caller': {u'name': u'', u'number': u''}, u'creationtime': u'2015-08-07T10:05:08.601-0500', u'state': u'Up', u'connected': {u'name': u'', u'number': u''}, u'dialplan': {u'priority': 3, u'exten': u's', u'context': u'default'}, u'id': u'1438959908.1'}} [Aug 07 10:05:09] INFO[10526]: twisted:455 emit: RX Frame from 127.0.0.1:8088 : fin = True, rsv = 0, opcode = 1, mask = -, length = 521, payload = { "type": "StasisEnd", "timestamp": "2015-08-07T10:05:09.139-0500", "channel": { "id": "1438959908.1", "name": "Local/s@default-00000000;2", "state": "Up", "caller": { "name": "", "number": "" }, "connected": { "name": "", "number": "" }, "accountcode": "", "dialplan": { "context": "default", "exten": "s", "priority": 3 }, "creationtime": "2015-08-07T10:05:08.601-0500", "language": "en" }, "application": "testsuite" } [Aug 07 10:05:09] INFO[10526]: twisted:455 emit: Traffic statistics: {"incomingWebSocketFrames": 3, "outgoingWebSocketFrames": 0, "outgoingOctetsWireLevel": 0, "incomingOctetsAppLevel": 1621, "incomingWebSocketMessages": 2, "outgoingWebSocketOverhead": null, "incomingOctetsWebSocketLevel": 1621, "outgoingCompressionRatio": null, "outgoingWebSocketMessages": 0, "incomingOctetsWireLevel": 1633, "incomingWebSocketOverhead": 0.0074028377544725476, "outgoingOctetsWebSocketLevel": 0, "outgoingOctetsAppLevel": 0, "incomingCompressionRatio": 1.0} [Aug 07 10:05:09] DEBUG[10526]: ari:383 onMessage: rxed: { "type": "StasisEnd", "timestamp": "2015-08-07T10:05:09.139-0500", "channel": { "id": "1438959908.1", "name": "Local/s@default-00000000;2", "state": "Up", "caller": { "name": "", "number": "" }, "connected": { "name": "", "number": "" }, "accountcode": "", "dialplan": { "context": "default", "exten": "s", "priority": 3 }, "creationtime": "2015-08-07T10:05:08.601-0500", "language": "en" }, "application": "testsuite" } [Aug 07 10:05:09] DEBUG[10526]: ari:292 on_event: Received event: u'StasisEnd' [Aug 07 10:05:09] DEBUG[10526]: test_suite_utils:87 all_match: Pattern: {'application': 'testsuite', 'args': [], 'type': 'StasisStart'}, message {u'timestamp': u'2015-08-07T10:05:09.139-0500', u'type': u'StasisEnd', u'channel': {u'accountcode': u'', u'name': u'Local/s@default-00000000;2', u'language': u'en', u'caller': {u'name': u'', u'number': u''}, u'creationtime': u'2015-08-07T10:05:08.601-0500', u'state': u'Up', u'connected': {u'name': u'', u'number': u''}, u'dialplan': {u'priority': 3, u'exten': u's', u'context': u'default'}, u'id': u'1438959908.1'}, u'application': u'testsuite'} [Aug 07 10:05:09] DEBUG[10526]: test_suite_utils:87 all_match: Pattern: testsuite, message testsuite [Aug 07 10:05:09] DEBUG[10526]: test_suite_utils:87 all_match: Pattern: {'error': '^InvalidMessage$'}, message {u'timestamp': u'2015-08-07T10:05:09.139-0500', u'type': u'StasisEnd', u'channel': {u'accountcode': u'', u'name': u'Local/s@default-00000000;2', u'language': u'en', u'caller': {u'name': u'', u'number': u''}, u'creationtime': u'2015-08-07T10:05:08.601-0500', u'state': u'Up', u'connected': {u'name': u'', u'number': u''}, u'dialplan': {u'priority': 3, u'exten': u's', u'context': u'default'}, u'id': u'1438959908.1'}, u'application': u'testsuite'} [Aug 07 10:05:09] INFO[10526]: ari:298 on_event: Event had no matcher: {u'timestamp': u'2015-08-07T10:05:09.139-0500', u'type': u'StasisEnd', u'channel': {u'accountcode': u'', u'name': u'Local/s@default-00000000;2', u'language': u'en', u'caller': {u'name': u'', u'number': u''}, u'creationtime': u'2015-08-07T10:05:08.601-0500', u'state': u'Up', u'connected': {u'name': u'', u'number': u''}, u'dialplan': {u'priority': 3, u'exten': u's', u'context': u'default'}, u'id': u'1438959908.1'}, u'application': u'testsuite'} [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: HangupRequest' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;1' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelState: 6' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelStateDesc: Up' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDNum: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDName: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineNum: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineName: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Language: en' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AccountCode: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Priority: 1' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Uniqueid: 1438959908.0' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Linkedid: 1438959908.0' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Cause: 16' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:09] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:09] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'connectedlinenum': '', 'linkedid': '1438959908.0', 'uniqueid': '1438959908.0', 'language': 'en', 'accountcode': '', 'channelstate': '6', 'exten': 's', 'calleridnum': '', 'priority': '1', 'connectedlinename': '', 'context': 'default', 'calleridname': '', 'privilege': 'call,all', 'cause': '16', 'event': 'HangupRequest', 'channel': 'Local/s@default-00000000;1', 'channelstatedesc': 'Up'} [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: Hangup' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;2' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelState: 6' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelStateDesc: Up' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDNum: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDName: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineNum: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineName: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Language: en' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AccountCode: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Priority: 3' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Uniqueid: 1438959908.1' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Linkedid: 1438959908.0' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Cause: 16' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Cause-txt: Normal Clearing' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:09] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:09] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'connectedlinenum': '', 'cause-txt': 'Normal Clearing', 'linkedid': '1438959908.0', 'uniqueid': '1438959908.1', 'language': 'en', 'accountcode': '', 'channelstate': '6', 'exten': 's', 'calleridnum': '', 'priority': '3', 'connectedlinename': '', 'context': 'default', 'calleridname': '', 'privilege': 'call,all', 'cause': '16', 'event': 'Hangup', 'channel': 'Local/s@default-00000000;2', 'channelstatedesc': 'Up'} [Aug 07 10:05:09] DEBUG[10526]: ari:200 _hangup_handler: Removing tracking for Local/s@default-00000000;2 [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: Hangup' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;1' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelState: 6' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ChannelStateDesc: Up' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDNum: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDName: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineNum: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'ConnectedLineName: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Language: en' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AccountCode: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Priority: 1' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Uniqueid: 1438959908.0' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Linkedid: 1438959908.0' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Cause: 16' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Cause-txt: Normal Clearing' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:09] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:09] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'connectedlinenum': '', 'cause-txt': 'Normal Clearing', 'linkedid': '1438959908.0', 'uniqueid': '1438959908.0', 'language': 'en', 'accountcode': '', 'channelstate': '6', 'exten': 's', 'calleridnum': '', 'priority': '1', 'connectedlinename': '', 'context': 'default', 'calleridname': '', 'privilege': 'call,all', 'cause': '16', 'event': 'Hangup', 'channel': 'Local/s@default-00000000;1', 'channelstatedesc': 'Up'} [Aug 07 10:05:09] DEBUG[10526]: ari:200 _hangup_handler: Removing tracking for Local/s@default-00000000;1 [Aug 07 10:05:09] INFO[10526]: ari:214 execute_test: All iterations executed [Aug 07 10:05:09] INFO[10526]: ari:216 execute_test: Stopping test [Aug 07 10:05:09] INFO[10526]: twisted:455 emit: dropping connection [Aug 07 10:05:09] INFO[10526]: test_case:411 __stop_instances: Stopping Asterisk instance 1 [Aug 07 10:05:09] DEBUG[10526]: asterisk:418 __send_stop_gracefully: sending stop gracefully [Aug 07 10:05:09] DEBUG[10526]: asterisk:700 cli_exec: Executing ['/usr/sbin/asterisk', '-C', '/tmp/asterisk-testsuite/7349e17afe637e8a55c6bf1d28c940ae/run_1/ast1/etc/asterisk/asterisk.conf', '-rx', 'core stop gracefully'] ... [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: DeviceStateChange' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Device: Local/s@default' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'State: NOT_INUSE' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:09] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:09] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'privilege': 'call,all', 'device': 'Local/s@default', 'state': 'NOT_INUSE', 'event': 'DeviceStateChange'} [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: DeviceStateChange' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Device: Local/s@default' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'State: NOT_INUSE' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:09] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:09] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'privilege': 'call,all', 'device': 'Local/s@default', 'state': 'NOT_INUSE', 'event': 'DeviceStateChange'} [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: CEL' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'EventName: HANGUP' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AccountCode: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDnum: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDname: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDani: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDrdnis: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDdnid: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;2' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Application: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AppData: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'EventTime: 2015-08-07 10:05:09' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AMAFlags: DOCUMENTATION' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'UniqueID: 1438959908.1' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LinkedID: 1438959908.0' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Userfield: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Peer: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'PeerAccount: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Extra: {"dialstatus":"","hangupcause":16,"hangupsource":""}' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:09] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:09] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'linkedid': '1438959908.0', 'appdata': '', 'extra': '{"dialstatus":"","hangupcause":16,"hangupsource":""}', 'exten': 's', 'amaflags': 'DOCUMENTATION', 'calleridrdnis': '', 'event': 'CEL', 'calleriddnid': '', 'calleridnum': '', 'application': '', 'calleridname': '', 'privilege': 'call,all', 'channel': 'Local/s@default-00000000;2', 'eventtime': '2015-08-07 10:05:09', 'eventname': 'HANGUP', 'peeraccount': '', 'uniqueid': '1438959908.1', 'peer': '', 'accountcode': '', 'userfield': '', 'calleridani': '', 'context': 'default'} [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: CEL' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'EventName: HANGUP' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AccountCode: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDnum: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDname: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDani: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDrdnis: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDdnid: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;1' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Application: AppDial2' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AppData: (Outgoing Line)' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'EventTime: 2015-08-07 10:05:09' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AMAFlags: DOCUMENTATION' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'UniqueID: 1438959908.0' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LinkedID: 1438959908.0' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Userfield: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Peer: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'PeerAccount: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Extra: {"dialstatus":"","hangupcause":16,"hangupsource":""}' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:09] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:09] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'linkedid': '1438959908.0', 'appdata': '(Outgoing Line)', 'extra': '{"dialstatus":"","hangupcause":16,"hangupsource":""}', 'exten': 's', 'amaflags': 'DOCUMENTATION', 'calleridrdnis': '', 'event': 'CEL', 'calleriddnid': '', 'calleridnum': '', 'application': 'AppDial2', 'calleridname': '', 'privilege': 'call,all', 'channel': 'Local/s@default-00000000;1', 'eventtime': '2015-08-07 10:05:09', 'eventname': 'HANGUP', 'peeraccount': '', 'uniqueid': '1438959908.0', 'peer': '', 'accountcode': '', 'userfield': '', 'calleridani': '', 'context': 'default'} [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: CEL' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'EventName: CHAN_END' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AccountCode: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDnum: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDname: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDani: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDrdnis: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDdnid: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;2' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Application: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AppData: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'EventTime: 2015-08-07 10:05:09' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AMAFlags: DOCUMENTATION' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'UniqueID: 1438959908.1' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LinkedID: 1438959908.0' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Userfield: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Peer: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'PeerAccount: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Extra: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:09] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:09] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'linkedid': '1438959908.0', 'appdata': '', 'extra': '', 'exten': 's', 'amaflags': 'DOCUMENTATION', 'calleridrdnis': '', 'event': 'CEL', 'calleriddnid': '', 'calleridnum': '', 'application': '', 'calleridname': '', 'privilege': 'call,all', 'channel': 'Local/s@default-00000000;2', 'eventtime': '2015-08-07 10:05:09', 'eventname': 'CHAN_END', 'peeraccount': '', 'uniqueid': '1438959908.1', 'peer': '', 'accountcode': '', 'userfield': '', 'calleridani': '', 'context': 'default'} [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: CEL' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'EventName: CHAN_END' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AccountCode: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDnum: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDname: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDani: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDrdnis: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDdnid: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;1' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Application: AppDial2' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AppData: (Outgoing Line)' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'EventTime: 2015-08-07 10:05:09' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AMAFlags: DOCUMENTATION' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'UniqueID: 1438959908.0' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LinkedID: 1438959908.0' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Userfield: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Peer: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'PeerAccount: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Extra: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:09] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:09] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'linkedid': '1438959908.0', 'appdata': '(Outgoing Line)', 'extra': '', 'exten': 's', 'amaflags': 'DOCUMENTATION', 'calleridrdnis': '', 'event': 'CEL', 'calleriddnid': '', 'calleridnum': '', 'application': 'AppDial2', 'calleridname': '', 'privilege': 'call,all', 'channel': 'Local/s@default-00000000;1', 'eventtime': '2015-08-07 10:05:09', 'eventname': 'CHAN_END', 'peeraccount': '', 'uniqueid': '1438959908.0', 'peer': '', 'accountcode': '', 'userfield': '', 'calleridani': '', 'context': 'default'} [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: CEL' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'EventName: LINKEDID_END' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AccountCode: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDnum: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDname: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDani: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDrdnis: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'CallerIDdnid: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Exten: s' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Context: default' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Channel: Local/s@default-00000000;1' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Application: AppDial2' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AppData: (Outgoing Line)' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'EventTime: 2015-08-07 10:05:09' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'AMAFlags: DOCUMENTATION' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'UniqueID: 1438959908.0' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'LinkedID: 1438959908.0' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Userfield: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Peer: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'PeerAccount: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Extra: ' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:09] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:09] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'linkedid': '1438959908.0', 'appdata': '(Outgoing Line)', 'extra': '', 'exten': 's', 'amaflags': 'DOCUMENTATION', 'calleridrdnis': '', 'event': 'CEL', 'calleriddnid': '', 'calleridnum': '', 'application': 'AppDial2', 'calleridname': '', 'privilege': 'call,all', 'channel': 'Local/s@default-00000000;1', 'eventtime': '2015-08-07 10:05:09', 'eventname': 'LINKEDID_END', 'peeraccount': '', 'uniqueid': '1438959908.0', 'peer': '', 'accountcode': '', 'userfield': '', 'calleridani': '', 'context': 'default'} [Aug 07 10:05:09] DEBUG[10526]: ari:375 onClose: WebSocket closed(False, 1006, connection was closed uncleanly (None)) [Aug 07 10:05:09] DEBUG[10526]: ari:130 on_ws_closed: WebSocket connection closed... [Aug 07 10:05:09] INFO[10526]: twisted:455 emit: connection to 127.0.0.1:8088 lost [Aug 07 10:05:09] INFO[10526]: twisted:455 emit: Stopping factory [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Event: Shutdown' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Privilege: system,all' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Shutdown: Cleanly' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: 'Restart: False' [Aug 07 10:05:09] DEBUG[10526]: AMI:160 lineReceived: Line In: '' [Aug 07 10:05:09] DEBUG[10526]: AMI:221 dispatchIncoming: Dispatch Incoming [Aug 07 10:05:09] DEBUG[10526]: AMI:248 dispatchIncoming: Incoming Message: {'privilege': 'system,all', 'restart': 'False', 'event': 'Shutdown', 'shutdown': 'Cleanly'} [Aug 07 10:05:09] INFO[10526]: twisted:455 emit: Stopping factory [Aug 07 10:05:10] DEBUG[10526]: asterisk:64 __cli_output_callback: Asterisk CLI 127.0.0.1 exited 0 [Aug 07 10:05:10] DEBUG[10526]: asterisk:427 __stop_gracefully_callback: Successfully stopped Asterisk 127.0.0.1 [Aug 07 10:05:10] INFO[10526]: test_case:432 __stop_reactor: Stopping Reactor [Aug 07 10:05:10] INFO[10526]: twisted:455 emit: Main loop terminated. [Aug 07 10:05:10] INFO[10526]: test_runner:326 main: Test run for tests/rest_api/asterisk/logging/get_logging completed with result False