[5.1.0-91~ocata] contrail-logs cmd not working

[Ankit Jain]

contrail-logs --object-type virtual-network --last 10m --module contrail-control
Error in query processing

test case also failing :

2018-05-10 15:20:05,185 - INFO - STARTING TEST : test_run_contrail_logs_cli_cmd_with_multiple_different_optional_args
2018-05-10 15:20:05,185 - INFO - TEST DESCRIPTION : 1.Test to verify contrail-logs cli cmd with multiple different optional type args is not broken
           2.Verify the command runs properly and its returning some output
           3.Do not verify the correctness of the output

2018-05-10 15:20:06,219 - WARNING - Test is running with cores: {'10.204.216.96': ['core.contrail-query-.1.nodem7.1525871829'], '10.204.216.103': ['core.contrail-query-.1.nodem14.1525940781']}
2018-05-10 15:20:10,400 - INFO - Initial checks done. Running the testcase now
2018-05-10 15:20:10,400 - INFO -
2018-05-10 15:20:10,400 - INFO - Running the following cmd:contrail-logs --object-type vrouter --start-time now-5m --end-time now

2018-05-10 15:20:23,391 - INFO - Output: Error in query processing

2018-05-10 15:20:23,391 - INFO - Running the following cmd:contrail-logs --object-type database-node --start-time now-10m --end-time now --raw --message-type NodeStatusUVE

2018-05-10 15:20:29,107 - INFO - Output: Error in query processing

2018-05-10 15:20:29,107 - INFO - Running the following cmd:contrail-logs --node-type Database --start-time now-2h --message-type CassandraStatusUVE

2018-05-10 15:20:36,361 - INFO - Output: Error in query processing
Error in query processing
Error in query processing
Error in query processing
Error in query processing
Error in query processing
Error in query processing
Error in query processing
Error in query processing
Error in query processing
Error in query processing
Error in query processing

2018-05-10 15:20:36,361 - INFO - Running the following cmd:contrail-logs --node-type Compute --start-time now-10m --json --message-type UveVMInterfaceAgentTrace

2018-05-10 15:20:37,548 - INFO - Output: Error in query processing

2018-05-10 15:20:37,548 - INFO - Running the following cmd:contrail-logs --start-time now-20m --end-time now --message-type SandeshModuleClientTrace --module contrail-vrouter-agent

2018-05-10 15:20:39,251 - INFO - Output: Error in query processing
Error in query processing

2018-05-10 15:20:39,251 - INFO - Running the following cmd:contrail-logs --node-type Config --raw --module contrail-api

2018-05-10 15:20:40,404 - INFO - Output: Error in query processing

2018-05-10 15:20:40,404 - INFO - Running the following cmd:contrail-logs --node-type Compute --last 5m --verbose --reverse --message-type UveVirtualNetworkAgentTrace --module contrail-vrouter-agent

2018-05-10 15:20:41,673 - INFO - Output: Performing query: {"sort": 2, "start_time": 1525945541024241, "sort_fields": ["MessageTS"], "filter": [[{"suffix": null, "value2": null, "name": "NodeType", "value": "Compute", "op": 1}]], "end_time": 1525945841024241, "select_fields": ["MessageTS", "Source", "ModuleId", "Category", "Messagetype", "SequenceNum", "Xmlmessage", "Type", "Level", "NodeType", "InstanceId"], "table": "MessageTable", "where": [[{"suffix": null, "value2": null, "name": "ModuleId", "value": "contrail-vrouter-agent", "op": 1}, {"suffix": null, "value2": null, "name": "Messagetype", "value": "UveVirtualNetworkAgentTrace", "op": 1}]]}
Error in query processing

2018-05-10 15:20:41,674 - INFO - Running the following cmd:contrail-logs --node-type Analytics --json --message-type AnalyticsApiStats --module contrail-analytics-api

2018-05-10 15:20:42,785 - INFO - Output: Error in query processing

2018-05-10 15:20:42,785 - INFO - Running the following cmd:contrail-logs --object-id 721462c6-eb4a-4313-a1da-48996cf2d056 --object-type virtual-machine --verbose --raw --json

2018-05-10 15:20:43,962 - INFO - Output: Performing query: {"sort": 1, "start_time": 1525945243360679, "sort_fields": ["MessageTS"], "end_time": 1525945843360679, "select_fields": ["MessageTS", "Source", "ModuleId", "Messagetype", "ObjectLog", "SystemLog"], "table": "ObjectVMTable", "where": [[{"suffix": null, "value2": null, "name": "ObjectId", "value": "721462c6-eb4a-4313-a1da-48996cf2d056", "op": 1}]]}
Error in query processing

2018-05-10 15:20:43,962 - INFO - Running the following cmd:contrail-logs --node-type Analytics --message-type AnalyticsApiStats --module contrail-analytics-api

2018-05-10 15:20:45,129 - INFO - Output: Error in query processing

2018-05-10 15:20:45,129 - INFO - Running the following cmd:contrail-logs --object-type virtual-network --last 10m --module contrail-control

2018-05-10 15:22:50,128 - ERROR - <class 'fabric.exceptions.CommandTimeout'>
Python 2.7.5: /usr/bin/python
Thu May 10 15:22:45 2018

A problem occurred in a Python script. Here is the sequence of
function calls leading up to the error, in the order they occurred.

 /contrail-test/tcutils/wrappers.py in wrapper(self=<serial_scripts.analytics.test_analytics_resourc...erent_optional_args[sanity,vcenter] id=0x6fd83d0>, *args=(), **kwargs={})
   76 log.info('Initial checks done. Running the testcase now')
   77 log.info('')
   78 result = function(self, *args, **kwargs)
   79 except KeyboardInterrupt:
   80 raise
result = None
function = <function test_run_contrail_logs_cli_cmd_with_multiple_different_optional_args>
self = <serial_scripts.analytics.test_analytics_resourc...erent_optional_args[sanity,vcenter] id=0x6fd83d0>
args = ()
kwargs = {}

 /contrail-test/serial_scripts/analytics/test_analytics_resource.py in test_run_contrail_logs_cli_cmd_with_multiple_different_optional_args(self=<serial_scripts.analytics.test_analytics_resourc...erent_optional_args[sanity,vcenter] id=0x6fd83d0>)
  165 ]
  166
  167 return self.test_cmd_output('contrail-logs', cmd_args_list, check_output=True)
  168
  169 @test.attr(type=['sanity', 'vcenter'])
self = <serial_scripts.analytics.test_analytics_resourc...erent_optional_args[sanity,vcenter] id=0x6fd83d0>
self.test_cmd_output = <bound method AnalyticsTestSanityWithMin.test_cm...rent_optional_args[sanity,vcenter] id=0x6fd83d0>>
cmd_args_list = [{'no_key': ['start-time now-5m', 'end-time now'], 'object-type': 'vrouter'}, {'message-type': 'NodeStatusUVE', 'no_key': ['start-time now-10m', 'end-time now', 'raw'], 'object-type': 'database-node'}, {'message-type': 'CassandraStatusUVE', 'no_key': ['start-time now-2h'], 'node-type': 'Database'}, {'message-type': 'UveVMInterfaceAgentTrace', 'no_key': ['start-time now-10m', 'json'], 'node-type': 'Compute'}, {'message-type': 'SandeshModuleClientTrace', 'module': 'contrail-vrouter-agent', 'no_key': ['start-time now-20m', 'end-time now']}, {'module': 'contrail-api', 'no_key': ['raw'], 'node-type': 'Config'}, {'message-type': 'UveVirtualNetworkAgentTrace', 'module': 'contrail-vrouter-agent', 'no_key': ['last 5m', 'verbose', 'reverse'], 'node-type': 'Compute'}, {'message-type': 'AnalyticsApiStats', 'module': 'contrail-analytics-api', 'no_key': ['json'], 'node-type': 'Analytics '}, {'no_key': ['verbose', 'raw', 'json'], 'object-id': u'721462c6-eb4a-4313-a1da-48996cf2d056', 'object-type': 'virtual-machine'}, {'message-type': 'AnalyticsApiStats', 'module': 'contrail-analytics-api', 'node-type': 'Analytics'}, {'module': 'contrail-control', 'no_key': ['last 10m'], 'object-type': 'virtual-network'}, {'module': 'contrail-analytics-api', 'node-type': 'Analytics', 'source': 'nodem7'}, {'no_key': ['help']}]
check_output undefined
builtinTrue = True

 /contrail-test/serial_scripts/analytics/base.py in test_cmd_output(self=<serial_scripts.analytics.test_analytics_resourc...erent_optional_args[sanity,vcenter] id=0x6fd83d0>, cmd_type='contrail-logs', cmd_args_list=[{'no_key': ['start-time now-5m', 'end-time now'], 'object-type': 'vrouter'}, {'message-type': 'NodeStatusUVE', 'no_key': ['start-time now-10m', 'end-time now', 'raw'], 'object-type': 'database-node'}, {'message-type': 'CassandraStatusUVE', 'no_key': ['start-time now-2h'], 'node-type': 'Database'}, {'message-type': 'UveVMInterfaceAgentTrace', 'no_key': ['start-time now-10m', 'json'], 'node-type': 'Compute'}, {'message-type': 'SandeshModuleClientTrace', 'module': 'contrail-vrouter-agent', 'no_key': ['start-time now-20m', 'end-time now']}, {'module': 'contrail-api', 'no_key': ['raw'], 'node-type': 'Config'}, {'message-type': 'UveVirtualNetworkAgentTrace', 'module': 'contrail-vrouter-agent', 'no_key': ['last 5m', 'verbose', 'reverse'], 'node-type': 'Compute'}, {'message-type': 'AnalyticsApiStats', 'module': 'contrail-analytics-api', 'no_key': ['json'], 'node-type': 'Analytics '}, {'no_key': ['verbose', 'raw', 'json'], 'object-id': u'721462c6-eb4a-4313-a1da-48996cf2d056', 'object-type': 'virtual-machine'}, {'message-type': 'AnalyticsApiStats', 'module': 'contrail-analytics-api', 'node-type': 'Analytics'}, {'module': 'contrail-control', 'no_key': ['last 10m'], 'object-type': 'virtual-network'}, {'module': 'contrail-analytics-api', 'node-type': 'Analytics', 'source': 'nodem7'}, {'no_key': ['help']}], check_output=True, form_cmd=True, as_sudo=False)
   51 cmd = self._form_cmd(cmd_type, cmd_args)
   52 self.logger.info("Running the following cmd:%s \n" %cmd)
   53 if not self.execute_cli_cmd(cmd, check_output, as_sudo=as_sudo):
   54 self.logger.error('%s command failed..' % cmd)
   55 failed_cmds.append(cmd)
self = <serial_scripts.analytics.test_analytics_resourc...erent_optional_args[sanity,vcenter] id=0x6fd83d0>
self.execute_cli_cmd = <bound method AnalyticsTestSanityWithMin.execute...rent_optional_args[sanity,vcenter] id=0x6fd83d0>>
cmd = 'contrail-logs --object-type virtual-network --last 10m --module contrail-control'
check_output = True
as_sudo = False

 /contrail-test/serial_scripts/analytics/base.py in execute_cli_cmd(self=<serial_scripts.analytics.test_analytics_resourc...erent_optional_args[sanity,vcenter] id=0x6fd83d0>, cmd='contrail-logs --object-type virtual-network --last 10m --module contrail-control', check_output=True, as_sudo=False)
   78 analytics = self.res.inputs.collector_ips[0]
   79 output = self.res.inputs.run_cmd_on_server(analytics, cmd,
   80 container='analytics-api', as_sudo=as_sudo)
   81 self.logger.info("Output: %s \n" % output)
   82 if output.failed:
container undefined
as_sudo = False

 /contrail-test/common/contrail_test_init.py in run_cmd_on_server(self=<common.contrail_test_init.TestInputs object>, server_ip='10.204.216.96', issue_cmd='contrail-logs --object-type virtual-network --last 10m --module contrail-control', username='root', password='c0ntrail123', pty=True, as_sudo=False, container='analytics_api_1', detach=None, shell_prefix='/bin/bash -c ')
 1378 container=container,
 1379 detach=detach,
 1380 shell_prefix=shell_prefix)
 1381 return output
 1382 # end run_cmd_on_server
shell_prefix = '/bin/bash -c '

 /contrail-test/tcutils/util.py in run_cmd_on_server(issue_cmd='contrail-logs --object-type virtual-network --last 10m --module contrail-control', server_ip='10.204.216.96', username='root', password='c0ntrail123', pty=True, as_sudo=False, as_daemon=False, logger=<logging.Logger object>, container='analytics_api_1', detach=None, pidfile=None, shell_prefix='/bin/bash -c ')
  812 updated_cmd = 'docker exec %s %s' % (container_args,issue_cmd)
  813 logger.debug('[%s]: Running cmd : %s' % (server_ip, updated_cmd))
  814 output = _run(updated_cmd, pty=pty)
  815 logger.debug('Output : %s' % (output))
  816 return output
output undefined
_run = <function sudo>
updated_cmd = "docker exec --privileged -it analytics_api_1 /...ual-network --last 10m --module contrail-control'"
pty = True

 /usr/lib/python2.7/site-packages/fabric/network.py in host_prompting_wrapper(*args=("docker exec --privileged -it analytics_api_1 /...ual-network --last 10m --module contrail-control'",), **kwargs={'pty': True})
  631 " host string for connection: ")
  632 env.update(to_dict(host_string))
  633 return func(*args, **kwargs)
  634 host_prompting_wrapper.undecorated = func
  635 return host_prompting_wrapper
func = <function sudo>
args = ("docker exec --privileged -it analytics_api_1 /...ual-network --last 10m --module contrail-control'",)
kwargs = {'pty': True}

 /usr/lib/python2.7/site-packages/fabric/operations.py in sudo(command="docker exec --privileged -it analytics_api_1 /...ual-network --last 10m --module contrail-control'", shell=True, pty=True, combine_stderr=None, user=None, quiet=False, warn_only=False, stdout=None, stderr=None, group=None, timeout=None, shell_escape=None)
 1093 user=user if user else env.sudo_user,
 1094 group=group, quiet=quiet, warn_only=warn_only, stdout=stdout,
 1095 stderr=stderr, timeout=timeout, shell_escape=shell_escape,
 1096 )
 1097
stderr = None
timeout = None
shell_escape = None

 /usr/lib/python2.7/site-packages/fabric/operations.py in _run_command(command="docker exec --privileged -it analytics_api_1 /...ual-network --last 10m --module contrail-control'", shell=True, pty=True, combine_stderr=None, sudo=True, user=None, quiet=False, warn_only=False, stdout=None, stderr=None, group=None, timeout=None, shell_escape=True)
  909 channel=default_channel(), command=wrapped_command, pty=pty,
  910 combine_stderr=combine_stderr, invoke_shell=False, stdout=stdout,
  911 stderr=stderr, timeout=timeout)
  912
  913 # Assemble output string
stderr = None
timeout = None

 /usr/lib/python2.7/site-packages/fabric/operations.py in _execute(channel=<paramiko.Channel 17 (open) window=2097145 -> <p...s128-ctr, 128 bits) (active; 1 open channel(s))>>, command='sudo -S -p \'sudo password:\' /bin/bash -l -c "do...al-network --last 10m --module contrail-control\'"', pty=True, combine_stderr=True, invoke_shell=False, stdout=<open file '<stdout>', mode 'w'>, stderr=<open file '<stderr>', mode 'w'>, timeout=120)
  793 # exception within, recv_exit_status())
  794 for worker in workers:
  795 worker.raise_if_needed()
  796 try:
  797 time.sleep(ssh.io_sleep)
worker = <fabric.thread_handling.ThreadHandler object>
worker.raise_if_needed = <bound method ThreadHandler.raise_if_needed of <fabric.thread_handling.ThreadHandler object>>

 /usr/lib/python2.7/site-packages/fabric/thread_handling.py in wrapper(*args=(<paramiko.Channel 17 (open) window=2097145 -> <p...s128-ctr, 128 bits) (active; 1 open channel(s))>>, 'recv'), **kwargs={'capture': ['\r', '\n', '\r', '\n', '\r', '\n', ' ', '\r', '\n', '\r', '\n', '\r', '\n'], 'stream': <open file '<stdout>', mode 'w'>, 'timeout': 120})
   10 def wrapper(*args, **kwargs):
   11 try:
   12 callable(*args, **kwargs)
   13 except BaseException:
   14 self.exception = sys.exc_info()
callable = <function output_loop>
args = (<paramiko.Channel 17 (open) window=2097145 -> <p...s128-ctr, 128 bits) (active; 1 open channel(s))>>, 'recv')
kwargs = {'capture': ['\r', '\n', '\r', '\n', '\r', '\n', ' ', '\r', '\n', '\r', '\n', '\r', '\n'], 'stream': <open file '<stdout>', mode 'w'>, 'timeout': 120}

 /usr/lib/python2.7/site-packages/fabric/io.py in output_loop(*args=(<paramiko.Channel 17 (open) window=2097145 -> <p...s128-ctr, 128 bits) (active; 1 open channel(s))>>, 'recv'), **kwargs={'capture': ['\r', '\n', '\r', '\n', '\r', '\n', ' ', '\r', '\n', '\r', '\n', '\r', '\n'], 'stream': <open file '<stdout>', mode 'w'>, 'timeout': 120})
   29
   30 def output_loop(*args, **kwargs):
   31 OutputLooper(*args, **kwargs).loop()
   32
   33
global OutputLooper = <class 'fabric.io.OutputLooper'>
args = (<paramiko.Channel 17 (open) window=2097145 -> <p...s128-ctr, 128 bits) (active; 1 open channel(s))>>, 'recv')
kwargs = {'capture': ['\r', '\n', '\r', '\n', '\r', '\n', ' ', '\r', '\n', '\r', '\n', '\r', '\n'], 'stream': <open file '<stdout>', mode 'w'>, 'timeout': 120}
).loop undefined

 /usr/lib/python2.7/site-packages/fabric/io.py in loop(self=<fabric.io.OutputLooper object>)
   84 elapsed = time.time() - start
   85 if self.timeout is not None and elapsed > self.timeout:
   86 raise CommandTimeout
   87 continue
   88 # Empty byte == EOS
global CommandTimeout = <class 'fabric.exceptions.CommandTimeout'>
<class 'fabric.exceptions.CommandTimeout'>:
    __class__ = <class 'fabric.exceptions.CommandTimeout'>
    __delattr__ = <method-wrapper '__delattr__' of CommandTimeout object>
    __dict__ = {}
    __doc__ = None
    __format__ = <built-in method __format__ of CommandTimeout object>
    __getattribute__ = <method-wrapper '__getattribute__' of CommandTimeout object>
    __getitem__ = <method-wrapper '__getitem__' of CommandTimeout object>
    __getslice__ = <method-wrapper '__getslice__' of CommandTimeout object>
    __hash__ = <method-wrapper '__hash__' of CommandTimeout object>
    __init__ = <method-wrapper '__init__' of CommandTimeout object>
    __module__ = 'fabric.exceptions'
    __new__ = <built-in method __new__ of type object>
    __reduce__ = <built-in method __reduce__ of CommandTimeout object>
    __reduce_ex__ = <built-in method __reduce_ex__ of CommandTimeout object>
    __repr__ = <method-wrapper '__repr__' of CommandTimeout object>
    __setattr__ = <method-wrapper '__setattr__' of CommandTimeout object>
    __setstate__ = <built-in method __setstate__ of CommandTimeout object>
    __sizeof__ = <built-in method __sizeof__ of CommandTimeout object>
    __str__ = <method-wrapper '__str__' of CommandTimeout object>
    __subclasshook__ = <built-in method __subclasshook__ of type object>
    __unicode__ = <built-in method __unicode__ of CommandTimeout object>
    __weakref__ = None
    args = ()
    message = ''

The above is a description of an error in a Python program. Here is
the original traceback:

Traceback (most recent call last):
  File "tcutils/wrappers.py", line 78, in wrapper
    result = function(self, *args, **kwargs)
  File "serial_scripts/analytics/test_analytics_resource.py", line 167, in test_run_contrail_logs_cli_cmd_with_multiple_different_optional_args
    return self.test_cmd_output('contrail-logs', cmd_args_list, check_output=True)
  File "/contrail-test/serial_scripts/analytics/base.py", line 53, in test_cmd_output
    if not self.execute_cli_cmd(cmd, check_output, as_sudo=as_sudo):
  File "/contrail-test/serial_scripts/analytics/base.py", line 80, in execute_cli_cmd
    container='analytics-api', as_sudo=as_sudo)
  File "common/contrail_test_init.py", line 1380, in run_cmd_on_server
    shell_prefix=shell_prefix)
  File "tcutils/util.py", line 814, in run_cmd_on_server
    output = _run(updated_cmd, pty=pty)
  File "/usr/lib/python2.7/site-packages/fabric/network.py", line 633, in host_prompting_wrapper
    return func(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/fabric/operations.py", line 1095, in sudo
    stderr=stderr, timeout=timeout, shell_escape=shell_escape,
  File "/usr/lib/python2.7/site-packages/fabric/operations.py", line 911, in _run_command
    stderr=stderr, timeout=timeout)
  File "/usr/lib/python2.7/site-packages/fabric/operations.py", line 795, in _execute
    worker.raise_if_needed()
  File "/usr/lib/python2.7/site-packages/fabric/thread_handling.py", line 12, in wrapper
    callable(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/fabric/io.py", line 31, in output_loop
    OutputLooper(*args, **kwargs).loop()
  File "/usr/lib/python2.7/site-packages/fabric/io.py", line 86, in loop
    raise CommandTimeout
CommandTimeout

2018-05-10 15:22:50,131 - ERROR - Cores found(2): {'10.204.216.96': ['core.contrail-query-.1.nodem7.1525945845'], '10.204.216.103': ['core.contrail-query-.1.nodem14.1525945922']}
2018-05-10 15:22:50,131 - INFO -
2018-05-10 15:22:50,131 - INFO - END TEST : test_run_contrail_logs_cli_cmd_with_multiple_different_optional_args : FAILED[0:02:45]
2018-05-10 15:22:50,131 - INFO - --------------------------------------------------------------------------------
2018-05-10 15:22:50,135 - INFO - Deleting VM ctest-vn1_vm2-71183977
2018-05-10 15:22:50,396 - INFO - Deleting VM ctest-vn1_vm1-00092340
2018-05-10 15:22:50,630 - INFO - Deleting VN ctest-vn1-60530942
2018-05-10 15:22:50,703 - WARNING - Deleting VN ctest-vn1-60530942 failed..Will retry
2018-05-10 15:22:56,139 - INFO - Validated that VN ctest-vn1-60530942 is not found in API Server
tcutils/agent/vna_introspect_utils.py:109: FutureWarning: The behavior of this method will change in future versions. Use specific 'len(elem)' or 'elem is not None' test instead.
  if not vnl:
2018-05-10 15:22:56,161 - INFO - Validated that VN ctest-vn1-60530942 is not in any agent
2018-05-10 15:22:56,168 - INFO - Validated that all vrouters do not have the route table for VN default-domain:ctest-AnalyticsTestSanityWithMin-80301946:ctest-vn1-60530942
2018-05-10 15:22:56,183 - INFO - Validated that Routing instances and Config db in Control-nodes does not have VN ctest-vn1-60530942 info
2018-05-10 15:22:56,520 - INFO - Deleted project: ctest-AnalyticsTestSanityWithMin-80301946, ID : 1b812e34-4fb6-4beb-9854-7a806454fbd1

[Sundaresan Rajangam (srajanga)]

1. Provide the o/p of top from analyticsdatabase_cassandra_1
2. Provide the query-engine and cassandra logs

[Ankit Jain (ankitja)]

The bug is not seen in [5.1.0-109~ocata]..Will monitor this.