[Jul 03 13:19:55] INFO[2210]: test_case:150 __init__: Executing tests/rest_api/channels/ring [Jul 03 13:19:55] INFO[2210]: ari:303 __init__: WebSocketClientFactory(url=ws://127.0.0.1:8088/ari/events?app=testsuite&api_key=testsuite%3Atestsuite) [Jul 03 13:19:55] INFO[2210]: test_case:227 create_asterisk: Creating Asterisk instance 1 [Jul 03 13:19:55] INFO[2210]: test_case:357 _start_asterisk: Starting Asterisk instance 1 [Jul 03 13:19:57] INFO[2210]: twisted:443 emit: Starting factory [Jul 03 13:19:57] INFO[2210]: twisted:443 emit: connection to 127.0.0.1:8088 established [Jul 03 13:19:57] INFO[2210]: twisted:443 emit: GET /ari/events?app=testsuite&api_key=testsuite%3Atestsuite HTTP/1.1 User-Agent: AutobahnPython/0.5.14 Host: 127.0.0.1:8088 Upgrade: WebSocket Connection: Upgrade Pragma: no-cache Cache-Control: no-cache Sec-WebSocket-Key: fEMUvVj6Ep7XAEvID4EsGg== Sec-WebSocket-Protocol: ari Sec-WebSocket-Version: 8 [Jul 03 13:19:57] INFO[2210]: twisted:443 emit: TX Octets to 127.0.0.1:8088 : sync = False, octets = 474554202f6172692f6576656e74733f6170703d746573747375697465266170695f6b65793d74657374737569746525334174657374737569746520485454502f312e310d0a557365722d4167656e743a204175746f6261686e507974686f6e2f302e352e31340d0a486f73743a203132372e302e302e313a383038380d0a557067726164653a20576562536f636b65740d0a436f6e6e656374696f6e3a20557067726164650d0a507261676d613a206e6f2d63616368650d0a43616368652d436f6e74726f6c3a206e6f2d63616368650d0a5365632d576562536f636b65742d4b65793a2066454d5576566a3645703758414576494434457347673d3d0d0a5365632d576562536f636b65742d50726f746f636f6c3a206172690d0a5365632d576562536f636b65742d56657273696f6e3a20380d0a0d0a [Jul 03 13:19:57] INFO[2210]: twisted:443 emit: RX Octets from 127.0.0.1:8088 : octets = 485454502f312e312031303120537769746368696e672050726f746f636f6c730d0a557067726164653a20576562536f636b65740d0a436f6e6e656374696f6e3a20557067726164650d0a5365632d576562536f636b65742d4163636570743a204f577964415578456a766b714f6e494e6f4a4f623239304b3332453d0d0a5365632d576562536f636b65742d50726f746f636f6c3a206172690d0a0d0a [Jul 03 13:19:57] INFO[2210]: twisted:443 emit: received HTTP response: HTTP/1.1 101 Switching Protocols Upgrade: WebSocket Connection: Upgrade Sec-WebSocket-Accept: OWydAUxEjvkqOnINoJOb290K32E= Sec-WebSocket-Protocol: ari [Jul 03 13:19:57] INFO[2210]: twisted:443 emit: received HTTP status line in opening handshake : HTTP/1.1 101 Switching Protocols [Jul 03 13:19:57] INFO[2210]: twisted:443 emit: received HTTP headers in opening handshake : {'connection': u'Upgrade', 'upgrade': u'WebSocket', 'sec-websocket-protocol': u'ari', 'sec-websocket-accept': u'OWydAUxEjvkqOnINoJOb290K32E='} [Jul 03 13:19:57] INFO[2210]: test_case:259 create_ami_factory: Creating AMIFactory 1 [Jul 03 13:19:57] INFO[2210]: twisted:443 emit: Starting factory [Jul 03 13:19:57] INFO[2210]: AMI:163 connectionMade: Connection Made [Jul 03 13:19:57] INFO[2210]: AMI:178 onComplete: Login Complete: {'message': 'Authentication accepted', 'response': 'Success', 'actionid': 'co-op-02-140624187351912-1'} [Jul 03 13:19:57] INFO[2210]: test_case:491 _ami_connect: AMI Connect instance 1 [Jul 03 13:19:57] INFO[2210]: ari:252 _spawn_channel: Creating channel Local/s@default [Jul 03 13:19:57] INFO[2210]: ari:434 post: POST http://127.0.0.1:8088/ari/channels {'app': 'testsuite', 'endpoint': 'Local/s@default', 'channelId': 'testsuite-default-id'} [Jul 03 13:19:57] INFO[2210]: urllib3.connectionpool:258 _new_conn: Starting new HTTP connection (1): 127.0.0.1 [Jul 03 13:19:57] INFO[2210]: twisted:443 emit: RX Octets from 127.0.0.1:8088 : octets = 817e01807b226170706c69636174696f6e223a22746573747375697465222c2274797065223a225374617369735374617274222c2274696d657374616d70223a22323031342d30372d30335431333a31393a35372e3036322d30353030222c2261726773223a5b5d2c226368616e6e656c223a7b226964223a227465737473756974652d64656661756c742d69643b32222c227374617465223a2252696e67222c226e616d65223a224c6f63616c2f734064656661756c742d30303030303030303b32222c2263616c6c6572223a7b226e616d65223a22222c226e756d626572223a22227d2c22636f6e6e6563746564223a7b226e616d65223a22222c226e756d626572223a22227d2c226163636f756e74636f6465223a22222c226469616c706c616e223a7b22636f6e74657874223a2264656661756c74222c22657874656e223a2273222c227072696f72697479223a327d2c226372656174696f6e74696d65223a22323031342d30372d30335431333a31393a35372e3036312d30353030227d7d [Jul 03 13:19:57] INFO[2210]: twisted:443 emit: RX Frame from 127.0.0.1:8088 : fin = True, rsv = 0, opcode = 1, mask = -, length = 384, payload = {"application":"testsuite","type":"StasisStart","timestamp":"2014-07-03T13:19:57.062-0500","args":[],"channel":{"id":"testsuite-default-id;2","state":"Ring","name":"Local/s@default-00000000;2","caller":{"name":"","number":""},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"s","priority":2},"creationtime":"2014-07-03T13:19:57.061-0500"}} [Jul 03 13:19:57] INFO[2210]: ari:434 post: POST http://127.0.0.1:8088/ari/channels {'app': 'testsuite', 'endpoint': 'Local/ring@default', 'channelId': 'my-id'} [Jul 03 13:19:57] INFO[2210]: urllib3.connectionpool:258 _new_conn: Starting new HTTP connection (1): 127.0.0.1 [Jul 03 13:19:57] INFO[2210]: ari:408 get: GET http://127.0.0.1:8088/ari/channels {} [Jul 03 13:19:57] INFO[2210]: urllib3.connectionpool:258 _new_conn: Starting new HTTP connection (1): 127.0.0.1 [Jul 03 13:19:57] INFO[2210]: ari:447 delete: DELETE http://127.0.0.1:8088/ari/channels/testsuite-default-id;2 {} [Jul 03 13:19:57] INFO[2210]: urllib3.connectionpool:258 _new_conn: Starting new HTTP connection (1): 127.0.0.1 [Jul 03 13:19:57] INFO[2210]: twisted:443 emit: RX Octets from 127.0.0.1:8088 : octets = 817e01967b226368616e6e656c223a7b226964223a227465737473756974652d64656661756c742d69643b32222c227374617465223a2252696e67222c226e616d65223a224c6f63616c2f734064656661756c742d30303030303030303b32222c2263616c6c6572223a7b226e616d65223a22222c226e756d626572223a22227d2c22636f6e6e6563746564223a7b226e616d65223a22222c226e756d626572223a22227d2c226163636f756e74636f6465223a22222c226469616c706c616e223a7b22636f6e74657874223a2264656661756c74222c22657874656e223a2273222c227072696f72697479223a327d2c226372656174696f6e74696d65223a22323031342d30372d30335431333a31393a35372e3036312d30353030227d2c226361757365223a33322c2274696d657374616d70223a22323031342d30372d30335431333a31393a35372e3038322d30353030222c22736f6674223a747275652c2274797065223a224368616e6e656c48616e67757052657175657374222c226170706c69636174696f6e223a22746573747375697465227d817e01747b226170706c69636174696f6e223a22746573747375697465222c2274797065223a22537461736973456e64222c2274696d657374616d70223a22323031342d30372d30335431333a31393a35372e3038322d30353030222c226368616e6e656c223a7b226964223a227465737473756974652d64656661756c742d69643b32222c227374617465223a2252696e67222c226e616d65223a224c6f63616c2f734064656661756c742d30303030303030303b32222c2263616c6c6572223a7b226e616d65223a22222c226e756d626572223a22227d2c22636f6e6e6563746564223a7b226e616d65223a22222c226e756d626572223a22227d2c226163636f756e74636f6465223a22222c226469616c706c616e223a7b22636f6e74657874223a2264656661756c74222c22657874656e223a2273222c227072696f72697479223a327d2c226372656174696f6e74696d65223a22323031342d30372d30335431333a31393a35372e3036312d30353030227d7d817e01887b226361757365223a31362c226170706c69636174696f6e223a22746573747375697465222c2274797065223a224368616e6e656c48616e67757052657175657374222c2274696d657374616d70223a22323031342d30372d30335431333a31393a35372e3038322d30353030222c226368616e6e656c223a7b226964223a227465737473756974652d64656661756c742d6964222c227374617465223a22446f776e222c226e616d65223a224c6f63616c2f734064656661756c742d30303030303030303b31222c2263616c6c6572223a7b226e616d65223a22222c226e756d626572223a22227d2c22636f6e6e6563746564223a7b226e616d65223a22222c226e756d626572223a22227d2c226163636f756e74636f6465223a22222c226469616c706c616e223a7b22636f6e74657874223a2264656661756c74222c22657874656e223a2273222c227072696f72697479223a317d2c226372656174696f6e74696d65223a22323031342d30372d30335431333a31393a35372e3036302d30353030227d7d817e01a27b2274797065223a224368616e6e656c44657374726f796564222c2274696d657374616d70223a22323031342d30372d30335431333a31393a35372e3038382d30353030222c226170706c69636174696f6e223a22746573747375697465222c2263617573655f747874223a224e6f726d616c20436c656172696e67222c226368616e6e656c223a7b226964223a227465737473756974652d64656661756c742d6964222c227374617465223a22446f776e222c226e616d65223a224c6f63616c2f734064656661756c742d30303030303030303b31222c2263616c6c6572223a7b226e616d65223a22222c226e756d626572223a22227d2c22636f6e6e6563746564223a7b226e616d65223a22222c226e756d626572223a22227d2c226163636f756e74636f6465223a22222c226469616c706c616e223a7b22636f6e74657874223a2264656661756c74222c22657874656e223a2273222c227072696f72697479223a317d2c226372656174696f6e74696d65223a22323031342d30372d30335431333a31393a35372e3036302d30353030227d2c226361757365223a31367d [Jul 03 13:19:57] INFO[2210]: twisted:443 emit: RX Frame from 127.0.0.1:8088 : fin = True, rsv = 0, opcode = 1, mask = -, length = 406, payload = {"channel":{"id":"testsuite-default-id;2","state":"Ring","name":"Local/s@default-00000000;2","caller":{"name":"","number":""},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"s","priority":2},"creationtime":"2014-07-03T13:19:57.061-0500"},"cause":32,"timestamp":"2014-07-03T13:19:57.082-0500","soft":true,"type":"ChannelHangupRequest","application":"testsuite"} [Jul 03 13:19:57] INFO[2210]: ari:284 on_event: Event had no matcher: {u'soft': True, u'timestamp': u'2014-07-03T13:19:57.082-0500', u'application': u'testsuite', u'type': u'ChannelHangupRequest', u'cause': 32, u'channel': {u'accountcode': u'', u'name': u'Local/s@default-00000000;2', u'caller': {u'name': u'', u'number': u''}, u'creationtime': u'2014-07-03T13:19:57.061-0500', u'state': u'Ring', u'connected': {u'name': u'', u'number': u''}, u'dialplan': {u'priority': 2, u'exten': u's', u'context': u'default'}, u'id': u'testsuite-default-id;2'}} [Jul 03 13:19:57] INFO[2210]: twisted:443 emit: RX Frame from 127.0.0.1:8088 : fin = True, rsv = 0, opcode = 1, mask = -, length = 372, payload = {"application":"testsuite","type":"StasisEnd","timestamp":"2014-07-03T13:19:57.082-0500","channel":{"id":"testsuite-default-id;2","state":"Ring","name":"Local/s@default-00000000;2","caller":{"name":"","number":""},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"s","priority":2},"creationtime":"2014-07-03T13:19:57.061-0500"}} [Jul 03 13:19:57] INFO[2210]: twisted:443 emit: RX Frame from 127.0.0.1:8088 : fin = True, rsv = 0, opcode = 1, mask = -, length = 392, payload = {"cause":16,"application":"testsuite","type":"ChannelHangupRequest","timestamp":"2014-07-03T13:19:57.082-0500","channel":{"id":"testsuite-default-id","state":"Down","name":"Local/s@default-00000000;1","caller":{"name":"","number":""},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"s","priority":1},"creationtime":"2014-07-03T13:19:57.060-0500"}} [Jul 03 13:19:57] INFO[2210]: ari:284 on_event: Event had no matcher: {u'application': u'testsuite', u'cause': 16, u'channel': {u'accountcode': u'', u'name': u'Local/s@default-00000000;1', u'caller': {u'name': u'', u'number': u''}, u'creationtime': u'2014-07-03T13:19:57.060-0500', u'state': u'Down', u'connected': {u'name': u'', u'number': u''}, u'dialplan': {u'priority': 1, u'exten': u's', u'context': u'default'}, u'id': u'testsuite-default-id'}, u'timestamp': u'2014-07-03T13:19:57.082-0500', u'type': u'ChannelHangupRequest'} [Jul 03 13:19:57] INFO[2210]: twisted:443 emit: RX Frame from 127.0.0.1:8088 : fin = True, rsv = 0, opcode = 1, mask = -, length = 418, payload = {"type":"ChannelDestroyed","timestamp":"2014-07-03T13:19:57.088-0500","application":"testsuite","cause_txt":"Normal Clearing","channel":{"id":"testsuite-default-id","state":"Down","name":"Local/s@default-00000000;1","caller":{"name":"","number":""},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"s","priority":1},"creationtime":"2014-07-03T13:19:57.060-0500"},"cause":16} [Jul 03 13:19:57] INFO[2210]: ari:284 on_event: Event had no matcher: {u'timestamp': u'2014-07-03T13:19:57.088-0500', u'application': u'testsuite', u'type': u'ChannelDestroyed', u'cause': 16, u'cause_txt': u'Normal Clearing', u'channel': {u'accountcode': u'', u'name': u'Local/s@default-00000000;1', u'caller': {u'name': u'', u'number': u''}, u'creationtime': u'2014-07-03T13:19:57.060-0500', u'state': u'Down', u'connected': {u'name': u'', u'number': u''}, u'dialplan': {u'priority': 1, u'exten': u's', u'context': u'default'}, u'id': u'testsuite-default-id'}} [Jul 03 13:20:27] WARNING[2210]: test_case:441 _reactor_timeout: Reactor timeout: '30' seconds [Jul 03 13:20:27] INFO[2210]: test_case:400 __stop_instances: Stopping Asterisk instance 1 [Jul 03 13:20:27] INFO[2210]: ari:202 execute_test: All iterations executed; stopping [Jul 03 13:20:27] INFO[2210]: twisted:443 emit: RX Octets from 127.0.0.1:8088 : octets = 817e01907b2274797065223a224368616e6e656c44657374726f796564222c2274696d657374616d70223a22323031342d30372d30335431333a32303a32372e3130382d30353030222c226170706c69636174696f6e223a22746573747375697465222c2263617573655f747874223a22556e6b6e6f776e222c226368616e6e656c223a7b226964223a226d792d6964222c227374617465223a22446f776e222c226e616d65223a224c6f63616c2f72696e674064656661756c742d30303030303030313b31222c2263616c6c6572223a7b226e616d65223a22222c226e756d626572223a22227d2c22636f6e6e6563746564223a7b226e616d65223a22222c226e756d626572223a22227d2c226163636f756e74636f6465223a22222c226469616c706c616e223a7b22636f6e74657874223a2264656661756c74222c22657874656e223a2272696e67222c227072696f72697479223a317d2c226372656174696f6e74696d65223a22323031342d30372d30335431333a31393a35372e3037372d30353030227d2c226361757365223a307d [Jul 03 13:20:27] INFO[2210]: twisted:443 emit: RX Frame from 127.0.0.1:8088 : fin = True, rsv = 0, opcode = 1, mask = -, length = 400, payload = {"type":"ChannelDestroyed","timestamp":"2014-07-03T13:20:27.108-0500","application":"testsuite","cause_txt":"Unknown","channel":{"id":"my-id","state":"Down","name":"Local/ring@default-00000001;1","caller":{"name":"","number":""},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"ring","priority":1},"creationtime":"2014-07-03T13:19:57.077-0500"},"cause":0} [Jul 03 13:20:28] INFO[2210]: twisted:443 emit: connection to 127.0.0.1:8088 lost [Jul 03 13:20:28] INFO[2210]: twisted:443 emit: Stopping factory [Jul 03 13:20:28] INFO[2210]: twisted:443 emit: Stopping factory [Jul 03 13:20:28] INFO[2210]: test_case:421 __stop_reactor: Stopping Reactor [Jul 03 13:20:28] INFO[2210]: twisted:443 emit: Main loop terminated. [Jul 03 13:20:28] INFO[2210]: test_runner:311 main: Test run for tests/rest_api/channels/ring completed with result False