[Jun 21 03:18:00] INFO[2668]: test_case:158 __init__: Executing tests/funcs/func_talkdetect
[Jun 21 03:18:00] INFO[2668]: ari:317 __init__: WebSocketClientFactory(url=ws://127.0.0.1:8088/ari/events?app=testsuite&api_key=testsuite%3Atestsuite)
[Jun 21 03:18:00] INFO[2668]: test_case:233 create_asterisk: Creating Asterisk instance 1
[Jun 21 03:18:00] ERROR[2668]: version:219 parse_version_string: Unable to parse token '9015bb4
' in version string 'GIT-13-9015bb4
'
[Jun 21 03:18:00] INFO[2668]: test_case:368 _start_asterisk: Starting Asterisk instance 1
[Jun 21 03:18:00] WARNING[2668]: asterisk:127 errReceived: Asterisk 127.0.0.1 received error: FD 32766 exceeds the maximum size of ast_fdset!

[Jun 21 03:18:04] INFO[2668]: twisted:455 emit: Starting factory <ari.AriClientFactory instance at 0x2b94c20>
[Jun 21 03:18:04] INFO[2668]: twisted:455 emit: 
[('debug', True, 'AriClientFactory'),
 ('debugCodePaths', False, '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',
  <function <lambda> at 0x2414398>,
  'AriClientFactory')]
[Jun 21 03:18:04] INFO[2668]: twisted:455 emit: connection to 127.0.0.1:8088 established
[Jun 21 03:18:04] INFO[2668]: 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: 9zv46WgL5M6nmUcwDtZw1w==
Sec-WebSocket-Protocol: ari
Sec-WebSocket-Version: 13


[Jun 21 03:18:04] INFO[2668]: twisted:455 emit: TX Octets to 127.0.0.1:8088 : sync = False, octets = 474554202f6172692f6576656e74733f6170703d746573747375697465266170695f6b65793d74657374737569746525334174657374737569746520485454502f312e310d0a557365722d4167656e743a204175746f6261686e507974686f6e2f302e362e340d0a486f73743a203132372e302e302e313a383038380d0a557067726164653a20576562536f636b65740d0a436f6e6e656374696f6e3a20557067726164650d0a507261676d613a206e6f2d63616368650d0a43616368652d436f6e74726f6c3a206e6f2d63616368650d0a5365632d576562536f636b65742d4b65793a20397a76343657674c354d366e6d55637744745a7731773d3d0d0a5365632d576562536f636b65742d50726f746f636f6c3a206172690d0a5365632d576562536f636b65742d56657273696f6e3a2031330d0a0d0a
[Jun 21 03:18:04] INFO[2668]: twisted:455 emit: RX Octets from 127.0.0.1:8088 : octets = 485454502f312e312031303120537769746368696e672050726f746f636f6c730d0a557067726164653a20576562536f636b65740d0a436f6e6e656374696f6e3a20557067726164650d0a5365632d576562536f636b65742d4163636570743a2055516b48443656336a6568466c44473554596761445856534c6c593d0d0a5365632d576562536f636b65742d50726f746f636f6c3a206172690d0a0d0a
[Jun 21 03:18:04] INFO[2668]: twisted:455 emit: received HTTP response:

HTTP/1.1 101 Switching Protocols
Upgrade: WebSocket
Connection: Upgrade
Sec-WebSocket-Accept: UQkHD6V3jehFlDG5TYgaDXVSLlY=
Sec-WebSocket-Protocol: ari




[Jun 21 03:18:04] INFO[2668]: twisted:455 emit: received HTTP status line in opening handshake : HTTP/1.1 101 Switching Protocols
[Jun 21 03:18:04] INFO[2668]: twisted:455 emit: received HTTP headers in opening handshake : {'connection': u'Upgrade', 'upgrade': u'WebSocket', 'sec-websocket-protocol': u'ari', 'sec-websocket-accept': u'UQkHD6V3jehFlDG5TYgaDXVSLlY='}
[Jun 21 03:18:04] INFO[2668]: test_case:265 create_ami_factory: Creating AMIFactory 1
[Jun 21 03:18:04] INFO[2668]: twisted:455 emit: Starting factory <starpy.manager.AMIFactory instance at 0x2bb5d88>
[Jun 21 03:18:04] INFO[2668]: AMI:173 connectionMade: Connection Made
[Jun 21 03:18:04] INFO[2668]: AMI:191 onComplete: Login Complete: {'message': 'Authentication accepted', 'response': 'Success', 'actionid': 'asterisk-testsuite-64-centos-2.digium.internal-45833968-1'}
[Jun 21 03:18:04] INFO[2668]: test_case:502 _ami_connect: AMI Connect instance 1
[Jun 21 03:18:04] INFO[2668]: ari:231 _spawn_channel: Creating channel Local/stasis_app@default
[Jun 21 03:18:05] INFO[2668]: twisted:455 emit: RX Octets from 127.0.0.1:8088 : octets = 817e023e7b0a20202274797065223a20225374617369735374617274222c0a20202274696d657374616d70223a2022323031352d30362d32315430333a31383a30352e3233352d30353030222c0a20202261726773223a205b0a2020202022737562736372696265220a20205d2c0a2020226368616e6e656c223a207b0a20202020226964223a2022313433343837343638342e32222c0a20202020226e616d65223a20224c6f63616c2f7374617369735f6170704064656661756c742d30303030303030303b32222c0a20202020227374617465223a20225570222c0a202020202263616c6c6572223a207b0a202020202020226e616d65223a2022222c0a202020202020226e756d626572223a2022220a202020207d2c0a2020202022636f6e6e6563746564223a207b0a202020202020226e616d65223a2022222c0a202020202020226e756d626572223a2022220a202020207d2c0a20202020226163636f756e74636f6465223a2022222c0a20202020226469616c706c616e223a207b0a20202020202022636f6e74657874223a202264656661756c74222c0a20202020202022657874656e223a20227374617369735f617070222c0a202020202020227072696f72697479223a20330a202020207d2c0a20202020226372656174696f6e74696d65223a2022323031352d30362d32315430333a31383a30342e3733312d30353030222c0a20202020226c616e6775616765223a2022656e220a20207d2c0a2020226170706c69636174696f6e223a2022746573747375697465220a7d
[Jun 21 03:18:05] INFO[2668]: twisted:455 emit: RX Frame from 127.0.0.1:8088 : fin = True, rsv = 0, opcode = 1, mask = -, length = 574, payload = {
  "type": "StasisStart",
  "timestamp": "2015-06-21T03:18:05.235-0500",
  "args": [
    "subscribe"
  ],
  "channel": {
    "id": "1434874684.2",
    "name": "Local/stasis_app@default-00000000;2",
    "state": "Up",
    "caller": {
      "name": "",
      "number": ""
    },
    "connected": {
      "name": "",
      "number": ""
    },
    "accountcode": "",
    "dialplan": {
      "context": "default",
      "exten": "stasis_app",
      "priority": 3
    },
    "creationtime": "2015-06-21T03:18:04.731-0500",
    "language": "en"
  },
  "application": "testsuite"
}
[Jun 21 03:18:05] INFO[2668]: twisted:455 emit: Traffic statistics:
{"incomingWebSocketFrames": 1, "outgoingWebSocketFrames": 0, "outgoingOctetsWireLevel": 0, "incomingOctetsAppLevel": 574, "incomingWebSocketMessages": 0, "outgoingWebSocketOverhead": null, "incomingOctetsWebSocketLevel": 574, "outgoingCompressionRatio": null, "outgoingWebSocketMessages": 0, "incomingOctetsWireLevel": 578, "incomingWebSocketOverhead": 0.0069686411149825784, "outgoingOctetsWebSocketLevel": 0, "outgoingOctetsAppLevel": 0, "incomingCompressionRatio": 1.0}
[Jun 21 03:18:34] WARNING[2668]: test_case:452 _reactor_timeout: Reactor timeout: '30' seconds
[Jun 21 03:18:34] INFO[2668]: test_case:411 __stop_instances: Stopping Asterisk instance 1
[Jun 21 03:18:34] INFO[2668]: twisted:455 emit: connection to 127.0.0.1:8088 lost
[Jun 21 03:18:34] INFO[2668]: twisted:455 emit: Stopping factory <ari.AriClientFactory instance at 0x2b94c20>
[Jun 21 03:18:44] WARNING[2668]: asterisk:440 __send_kill: Sending KILL to Asterisk 127.0.0.1
[Jun 21 03:18:44] ERROR[2668]: ari:631 on_stop: Expected 2 <= count <= 2; was 1 ({'match': {'application': 'testsuite', 'args': ['subscribe'], 'type': 'StasisStart'}})
[Jun 21 03:18:44] ERROR[2668]: ari:631 on_stop: Expected 4 <= count <= 4; was 0 ({'match': {'application': 'testsuite', 'args': ['playback'], 'type': 'StasisStart'}})
[Jun 21 03:18:44] ERROR[2668]: ari:631 on_stop: Expected 1 <= count <= inf; was 0 ({'match': {'type': 'PlaybackFinished'}})
[Jun 21 03:18:44] ERROR[2668]: ari:631 on_stop: Expected 6 <= count <= 6; was 0 ({'match': {'type': 'ChannelTalkingStarted'}})
[Jun 21 03:18:44] ERROR[2668]: ari:631 on_stop: Expected 6 <= count <= 6; was 0 ({'match': {'duration': '[1-9](\\d+)?', 'type': 'ChannelTalkingFinished'}})
[Jun 21 03:18:44] WARNING[2668]: ami:192 __check_result: Event occurred 0 times, which is out of the allowable range
[Jun 21 03:18:44] WARNING[2668]: ami:193 __check_result: Event description: {'count': '6', 'requirements': {'match': {'Channel': 'Local/stasis_app@default-00000000;1'}}, 'conditions': {'match': {'Event': 'ChannelTalkingStart'}}, 'type': 'headermatch'}
[Jun 21 03:18:44] WARNING[2668]: ami:192 __check_result: Event occurred 0 times, which is out of the allowable range
[Jun 21 03:18:44] WARNING[2668]: ami:193 __check_result: Event description: {'count': '6', 'requirements': {'match': {'Duration': '[1-9](\\d+)?', 'Channel': 'Local/stasis_app@default-00000000;1'}}, 'conditions': {'match': {'Event': 'ChannelTalkingStop'}}, 'type': 'headermatch'}
[Jun 21 03:18:44] INFO[2668]: test_case:432 __stop_reactor: Stopping Reactor
[Jun 21 03:18:44] INFO[2668]: twisted:455 emit: Stopping factory <starpy.manager.AMIFactory instance at 0x2bb5d88>
[Jun 21 03:18:44] INFO[2668]: twisted:455 emit: Main loop terminated.
[Jun 21 03:18:44] INFO[2668]: test_runner:326 main: Test run for tests/funcs/func_talkdetect completed with result False