[4.0.1.0-82 ubuntu 14-04 mitaka] contrail-logs cmd with optional args is failing

[Ankit Jain]

The following sanity test case is failing due to "Error in query processing"

 test_run_contrail_logs_cli_cmd_with_multiple_different_optional_args : FAILED[0:02:17]

Logs:

It seems contrail-logs with --message-type NodeStatusUVE is failing as shown below:

root@nodem14(analytics):/# contrail-logs --object-type database-node --start-time now-1m --end-time now --message-type NodeStatusUVE
Error in query processing

root@nodem14(analytics):/var/log/contrail# contrail-logs --object-type database-node --start-time now-10m --end-time now --raw --message-type NodeStatusUVE --verbose

Performing query: {"sort": 1, "start_time": 1505903484873641, "sort_fields": ["MessageTS"], "end_time": 1505904084873641, "select_fields": ["MessageTS", "Source", "ModuleId", "Messagetype", "ObjectLog", "SystemLog"], "table": "ObjectDatabaseInfo", "where": [[{"suffix": null, "value2": null, "name": "Messagetype", "value": "NodeStatusUVE", "op": 1}]]}

Error in query processing

root@nodem14(analytics):/# contrail-logs --object-type database-node --start-time now-1m --end-time now
Error in query processing
root@nodem14(analytics):/# contrail-logs --object-type database-node --start-time now-1m --end-time now
2017 Sep 21 13:14:06.767703 nodem7 [:contrail-database-nodemgr:] : DatabaseUsage: [DatabaseUsageInfo: name = nodem7, [database_usage: [disk_space_used_1k = 21115740, disk_space_available_1k = 1991038180, analytics_db_size_1k = 753188]]]
2017 Sep 21 13:14:09.484101 nodem7 [:contrail-database-nodemgr:] : NodeStatusUVE: [NodeStatus: name = nodem7, disk_usage_info: {/dev/dm-0: [partition_type = ext4, partition_space_used_1k = 21116456, partition_space_available_1k = 1991037464, percentage_partition_space_used = 1], }, process_mem_cpu_usage: {zookeeper: [mem_virt = 38729636, cpu_share = 0.0, mem_res = 465448], cassandra: [mem_virt = 13502140, cpu_share = 0.2, mem_res = 10265080], contrail-database-nodemgr: [mem_virt = 152816, cpu_share = 0.01, mem_res = 29576], kafka: [mem_virt = 18292748, cpu_share = 0.23, mem_res = 1355208], }, [SysMemInfo: total = 264037868, used = 74106548, free = 189931320, buffers = 315096, cached = 18546152, node_type = database-node], [SysCpuInfo: one_min_avg = 1.42, five_min_avg = 1.97, fifteen_min_avg = 2.11, cpu_share = 0.13, node_type = database-node]]
2017 Sep 21 13:14:19.186700 nodem6 [:contrail-database-nodemgr:] : DatabaseUsage: [DatabaseUsageInfo: name = nodem6, [database_usage: [disk_space_used_1k = 21278736, disk_space_available_1k = 1990875184, analytics_db_size_1k = 827424]]]
2017 Sep 21 13:14:22.033395 nodem6 [:contrail-database-nodemgr:] : NodeStatusUVE: [NodeStatus: name = nodem6, disk_usage_info: {/dev/dm-0: [partition_type = ext4, partition_space_used_1k = 21278816, partition_space_available_1k = 1990875104, percentage_partition_space_used = 1], }, process_mem_cpu_usage: {zookeeper: [mem_virt = 38330252, cpu_share = 0.0, mem_res = 455728], cassandra: [mem_virt = 13442788, cpu_share = 0.17, mem_res = 10135696], contrail-database-nodemgr: [mem_virt = 152688, cpu_share = 0.01, mem_res = 29464], kafka: [mem_virt = 18226184, cpu_share = 0.17, mem_res = 1318216], }, [SysMemInfo: total = 264037880, used = 77454180, free = 186583700, buffers = 315144, cached = 21878724, node_type = database-node], [SysCpuInfo: one_min_avg = 2.26, five_min_avg = 2.08, fifteen_min_avg = 2.11, cpu_share = 0.14, node_type = database-node]]
2017 Sep 21 13:14:36.126286 nodem14 [:contrail-database-nodemgr:] : DatabaseUsage: [DatabaseUsageInfo: name = nodem14, [database_usage: [disk_space_used_1k = 49702664, disk_space_available_1k = 1962451256, analytics_db_size_1k = 909100]]]
2017 Sep 21 13:14:38.857991 nodem14 [:contrail-database-nodemgr:] : NodeStatusUVE: [NodeStatus: name = nodem14, disk_usage_info: {/dev/dm-0: [partition_type = ext4, partition_space_used_1k = 49703492, partition_space_available_1k = 1962450428, percentage_partition_space_used = 2], }, process_mem_cpu_usage: {zookeeper: [mem_virt = 38330252, cpu_share = 0.0, mem_res = 324524], cassandra: [mem_virt = 13607360, cpu_share = 0.23, mem_res = 10121280], contrail-database-nodemgr: [mem_virt = 152828, cpu_share = 0.01, mem_res = 29516], kafka: [mem_virt = 18494488, cpu_share = 0.19, mem_res = 1332084], }, [SysMemInfo: total = 264037868, used = 97502912, free = 166534956, buffers = 432628, cached = 40884300, node_type = database-node], [SysCpuInfo: one_min_avg = 1.74, five_min_avg = 2.64, fifteen_min_avg = 2.5, cpu_share = 0.13, node_type = database-node]]
root@nodem14(analytics):/# contrail-logs --object-type database-node --start-time now-1m --end-time now --message-type NodeStatusUVE
Error in query processing
root@nodem14(analytics):/# contrail-logs --object-type database-node --start-time now-1m --end-time now --message-type NodeStatusUVE
Error in query processing
root@nodem14(analytics):/# contrail-logs --object-type database-node --start-time now-5m --end-time now --message-type NodeStatusUVE
Error in query processing
root@nodem14(analytics):/# contrail-logs --object-type database-node --start-time now-5m --end-time now --message-type NodeStatusUVE

Expected output should be something like tihs:

contrail-logs --object-type database-node --start-time now-1m --end-time now --raw --message-type NodeStatusUVE --verbose
Performing query: {"sort": 1, "start_time": 1505907065433439, "sort_fields": ["MessageTS"], "end_time": 1505907125433439, "select_fields": ["MessageTS", "Source", "ModuleId", "Messagetype", "ObjectLog", "SystemLog"], "table": "ObjectDatabaseInfo", "where": [[{"suffix": null, "value2": null, "name": "Messagetype", "value": "NodeStatusUVE", "op": 1}]]}
2017 Sep 20 17:01:05.558681 nodei4 [:contrail-database-nodemgr:] : NodeStatusUVE: <NodeStatusUVE type="sandesh"><data type="struct" identifier="1"><NodeStatus><name type="string" identifier="1" key="ObjectDatabaseInfo">nodei4</name><disk_usage_info type="map" identifier="6" tags=""><map key="string" value="struct" size="2"><element>/dev/sda1</element><DiskPartitionUsageStats><partition_type type="string" identifier="1">ext2</partition_type><partition_space_used_1k type="u64" identifier="3">68944</partition_space_used_1k><partition_space_available_1k type="u64" identifier="4">159587</partition_space_available_1k><percentage_partition_space_used type="u16" identifier="5">30</percentage_partition_space_used></DiskPartitionUsageStats><element>/dev/mapper/nodei4--vg-root</element><DiskPartitionUsageStats><partition_type type="string" identifier="1">ext4</partition_type><partition_space_used_1k type="u64" identifier="3">70417728</partition_space_used_1k><partition_space_available_1k type="u64" identifier="4">836260516</partition_space_available_1k><percentage_partition_space_used type="u16" identifier="5">8</percentage_partition_space_used></DiskPartitionUsageStats></map></disk_usage_info><process_mem_cpu_usage type="map" identifier="10" tags=".__key,.cpu_share"><map key="string" value="struct" size="4"><element>zookeeper</element><ProcessCpuInfo><mem_virt type="u32" identifier="3">35345960</mem_virt><cpu_share type="double" identifier="4">0.01</cpu_share><mem_res type="u32" identifier="5">184368</mem_res></ProcessCpuInfo><element>cassandra</element><ProcessCpuInfo><mem_virt type="u32" identifier="3">12061140</mem_virt><cpu_share type="double" identifier="4">0.61</cpu_share><mem_res type="u32" identifier="5">9865580</mem_res></ProcessCpuInfo><element>contrail-database-nodemgr</element><ProcessCpuInfo><mem_virt type="u32" identifier="3">171040</mem_virt><cpu_share type="double" identifier="4">0.01</cpu_share><mem_res type="u32" identifier="5">30568</mem_res></ProcessCpuInfo><element>kafka</element><ProcessCpuInfo><mem_virt type="u32" identifier="3">8946228</mem_virt><cpu_share type="double" identifier="4">0.12</cpu_share><mem_res type="u32" identifier="5">1042992</mem_res></ProcessCpuInfo></map></process_mem_cpu_usage><system_mem_usage type="struct" identifier="13" tags=".node_type"><SysMemInfo><total type="u32" identifier="1">197799916</total><used type="u32" identifier="2">36008416</used><free type="u32" identifier="3">161791500</free><buffers type="u32" identifier="4">178844</buffers><cached type="u32" identifier="5">1275264</cached><node_type type="string" identifier="6">database-node</node_type></SysMemInfo></system_mem_usage><system_cpu_usage type="struct" identifier="14" tags=".node_type,.cpu_share"><SysCpuInfo><one_min_avg type="double" identifier="1">3.64</one_min_avg><five_min_avg type="double" identifier="2">3.44</five_min_avg><fifteen_min_avg type="double" identifier="3">2.96</fifteen_min_avg><cpu_share type="double" identifier="4">0.3</cpu_share><node_type type="string" identifier="5">database-node</node_type></SysCpuInfo></system_cpu_usage></NodeStatus></data></NodeStatusUVE>

[Sudheendra Rao (sudheendra-k)]

the problem is not seen in the latest builds, so removing the sanity blocker.

[Santosh Gupta (sangupta)]

Its not due to multiple optional args as apparent in the bug description. Its some issue in backend.
Its working fine on my setup, please provide system in this state and logs.

[Ankit Jain (ankitja)]

Hi Santosh,

The issue is seen again in the latest sanity result. 4.1.0.0-38

Please use the setup nodei31 for debugging.

The issue may not be seen in every run, so please execute the cmd couple of times as shown below.
When I tried the cmd manually, it failed in the second run.

root@nodei31(analytics):/# contrail-logs --object-type database-node --start-time now-1m --end-time now --message-type NodeStatusUVE
2017 Nov 08 15:22:15.524912 nodei31 [:contrail-database-nodemgr:] : NodeStatusUVE: [NodeStatus: name = nodei31, disk_usage_info: {/dev/dm-0: [partition_type = ext4, partition_space_used_1k = 96628032, partition_space_available_1k = 810050212, percentage_partition_space_used = 11], }, process_mem_cpu_usage: {zookeeper: [mem_virt = 37448840, cpu_share = 0.0, mem_res = 343728], cassandra: [mem_virt = 13183364, cpu_share = 0.21, mem_res = 9899372], contrail-database-nodemgr: [mem_virt = 152688, cpu_share = 0.01, mem_res = 29448], kafka: [mem_virt = 20830836, cpu_share = 0.19, mem_res = 1376696], }, [SysMemInfo: total = 197797908, used = 83972964, free = 113824944, buffers = 434140, cached = 33769676, node_type = database-node], [SysCpuInfo: one_min_avg = 2.61, five_min_avg = 2.27, fifteen_min_avg = 1.82, cpu_share = 0.14, node_type = database-node]]
root@nodei31(analytics):/# contrail-logs --object-type database-node --start-time now-1m --end-time now
2017 Nov 08 15:22:12.238569 nodei31 [:contrail-database-nodemgr:] : DatabaseUsage: [DatabaseUsageInfo: name = nodei31, [database_usage: [disk_space_used_1k = 96628024, disk_space_available_1k = 810050220, analytics_db_size_1k = 1040540]]]
2017 Nov 08 15:22:15.524912 nodei31 [:contrail-database-nodemgr:] : NodeStatusUVE: [NodeStatus: name = nodei31, disk_usage_info: {/dev/dm-0: [partition_type = ext4, partition_space_used_1k = 96628032, partition_space_available_1k = 810050212, percentage_partition_space_used = 11], }, process_mem_cpu_usage: {zookeeper: [mem_virt = 37448840, cpu_share = 0.0, mem_res = 343728], cassandra: [mem_virt = 13183364, cpu_share = 0.21, mem_res = 9899372], contrail-database-nodemgr: [mem_virt = 152688, cpu_share = 0.01, mem_res = 29448], kafka: [mem_virt = 20830836, cpu_share = 0.19, mem_res = 1376696], }, [SysMemInfo: total = 197797908, used = 83972964, free = 113824944, buffers = 434140, cached = 33769676, node_type = database-node], [SysCpuInfo: one_min_avg = 2.61, five_min_avg = 2.27, fifteen_min_avg = 1.82, cpu_share = 0.14, node_type = database-node]]
root@nodei31(analytics):/# contrail-logs --object-type database-node --start-time now-1m --end-time now
2017 Nov 08 15:22:12.238569 nodei31 [:contrail-database-nodemgr:] : DatabaseUsage: [DatabaseUsageInfo: name = nodei31, [database_usage: [disk_space_used_1k = 96628024, disk_space_available_1k = 810050220, analytics_db_size_1k = 1040540]]]
2017 Nov 08 15:22:15.524912 nodei31 [:contrail-database-nodemgr:] : NodeStatusUVE: [NodeStatus: name = nodei31, disk_usage_info: {/dev/dm-0: [partition_type = ext4, partition_space_used_1k = 96628032, partition_space_available_1k = 810050212, percentage_partition_space_used = 11], }, process_mem_cpu_usage: {zookeeper: [mem_virt = 37448840, cpu_share = 0.0, mem_res = 343728], c...

[Ankit Jain (ankitja)]

Also, CLI hangs indefinitely, when it happens. It used to show "Error in query processing" earlier.

If you are not able to reproduce, please keep trying, keep executing until you see the issue.